Feature: tracing set route id to ingress spans (zalando#2714)

* feature: set Tag "skipper.route_id" to `route.Id` in all ingress spans including shunt and loopback routes

Signed-off-by: Sandor Szücs <[email protected]>

Author: szuecs

proxy/context.go

@@ -296,7 +296,9 @@ func (c *context) Split() (filters.FilterContext, error) {
 }
 
 func (c *context) Loopback() {
-	err := c.proxy.do(c)
+	loopSpan := c.Tracer().StartSpan(c.proxy.tracing.initialOperationName, opentracing.ChildOf(c.ParentSpan().Context()))
+	defer loopSpan.Finish()
+	err := c.proxy.do(c, loopSpan)
 	if c.response != nil && c.response.Body != nil {
 		if _, err := io.Copy(io.Discard, c.response.Body); err != nil {
 			c.Logger().Errorf("context: error while discarding remainder response body: %v.", err)

proxy/proxy.go

@@ -1024,7 +1024,7 @@ func stack() []byte {
 	}
 }
 
-func (p *Proxy) do(ctx *context) (err error) {
+func (p *Proxy) do(ctx *context, parentSpan ot.Span) (err error) {
 	defer func() {
 		if r := recover(); r != nil {
 			p.onPanicSometimes.Do(func() {
@@ -1068,6 +1068,7 @@ func (p *Proxy) do(ctx *context) (err error) {
 		p.makeErrorResponse(ctx, errRouteLookupFailed)
 		return errRouteLookupFailed
 	}
+	parentSpan.SetTag(SkipperRouteIDTag, route.Id)
 
 	ctx.applyRoute(route, params, p.flags.PreserveHost())
 
@@ -1086,7 +1087,16 @@ func (p *Proxy) do(ctx *context) (err error) {
 		ctx.ensureDefaultResponse()
 	} else if ctx.route.BackendType == eskip.LoopBackend {
 		loopCTX := ctx.clone()
-		if err := p.do(loopCTX); err != nil {
+		loopSpan := tracing.CreateSpan("loopback", ctx.request.Context(), p.tracing.tracer)
+		p.tracing.
+			setTag(loopSpan, SpanKindTag, SpanKindServer).
+			setTag(loopSpan, SkipperRouteIDTag, ctx.route.Id)
+		p.setCommonSpanInfo(ctx.Request().URL, ctx.Request(), loopSpan)
+		ctx.parentSpan = loopSpan
+
+		defer loopSpan.Finish()
+
+		if err := p.do(loopCTX, loopSpan); err != nil {
 			// in case of error we have to copy the response in this recursion unwinding
 			ctx.response = loopCTX.response
 			if err != nil {
@@ -1442,6 +1452,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	ctx.startServe = time.Now()
 	ctx.tracer = p.tracing.tracer
 	ctx.initialSpan = span
+	ctx.parentSpan = span
 
 	defer func() {
 		if ctx.response != nil && ctx.response.Body != nil {
@@ -1452,7 +1463,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		}
 	}()
 
-	err := p.do(ctx)
+	err := p.do(ctx, span)
 
 	// writeTimeout() filter
 	if d, ok := ctx.StateBag()[filters.WriteTimeout].(time.Duration); ok {

proxy/tracing_test.go

@@ -84,7 +84,8 @@ func TestTracingIngressSpan(t *testing.T) {
 	})
 	defer s.Close()
 
-	doc := fmt.Sprintf(`hello: Path("/hello") -> setPath("/bye") -> setQuery("void") -> "%s"`, s.URL)
+	routeID := "ingressRoute"
+	doc := fmt.Sprintf(`%s: Path("/hello") -> setPath("/bye") -> setQuery("void") -> "%s"`, routeID, s.URL)
 
 	tracer := mocktracer.New()
 	params := Params{
@@ -126,6 +127,7 @@ func TestTracingIngressSpan(t *testing.T) {
 
 	verifyTag(t, span, SpanKindTag, SpanKindServer)
 	verifyTag(t, span, ComponentTag, "skipper")
+	verifyTag(t, span, SkipperRouteIDTag, routeID)
 	// to save memory we dropped the URL tag from ingress span
 	//verifyTag(t, span, HTTPUrlTag, "/hello?world") // For server requests there is no scheme://host:port, see https://golang.org/pkg/net/http/#Request
 	verifyTag(t, span, HTTPMethodTag, "GET")
@@ -137,6 +139,139 @@ func TestTracingIngressSpan(t *testing.T) {
 	verifyHasTag(t, span, HTTPRemoteIPTag)
 }
 
+func TestTracingIngressSpanShunt(t *testing.T) {
+	routeID := "ingressShuntRoute"
+	doc := fmt.Sprintf(`%s: Path("/hello") -> setPath("/bye") -> setQuery("void") -> status(205) -> <shunt>`, routeID)
+
+	tracer := mocktracer.New()
+	params := Params{
+		OpenTracing: &OpenTracingParams{
+			Tracer: tracer,
+		},
+		Flags: FlagsNone,
+	}
+
+	t.Setenv("HOSTNAME", "ingress-shunt.tracing.test")
+
+	tp, err := newTestProxyWithParams(doc, params)
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer tp.close()
+
+	ps := httptest.NewServer(tp.proxy)
+	defer ps.Close()
+
+	req, err := http.NewRequest("GET", ps.URL+"/hello?world", nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	req.Header.Set("X-Flow-Id", "test-flow-id")
+
+	rsp, err := ps.Client().Do(req)
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer rsp.Body.Close()
+	io.Copy(io.Discard, rsp.Body)
+
+	// client may get response before proxy finishes span
+	time.Sleep(10 * time.Millisecond)
+
+	span, ok := findSpan(tracer, "ingress")
+	if !ok {
+		t.Fatal("ingress span not found")
+	}
+
+	verifyTag(t, span, SpanKindTag, SpanKindServer)
+	verifyTag(t, span, ComponentTag, "skipper")
+	verifyTag(t, span, SkipperRouteIDTag, routeID)
+	// to save memory we dropped the URL tag from ingress span
+	//verifyTag(t, span, HTTPUrlTag, "/hello?world") // For server requests there is no scheme://host:port, see https://golang.org/pkg/net/http/#Request
+	verifyTag(t, span, HTTPMethodTag, "GET")
+	verifyTag(t, span, HostnameTag, "ingress-shunt.tracing.test")
+	verifyTag(t, span, HTTPPathTag, "/hello")
+	verifyTag(t, span, HTTPHostTag, ps.Listener.Addr().String())
+	verifyTag(t, span, FlowIDTag, "test-flow-id")
+	verifyTag(t, span, HTTPStatusCodeTag, uint16(205))
+	verifyHasTag(t, span, HTTPRemoteIPTag)
+}
+
+func TestTracingIngressSpanLoopback(t *testing.T) {
+	shuntRouteID := "ingressShuntRoute"
+	loop1RouteID := "loop1Route"
+	loop2RouteID := "loop2Route"
+	routeIDs := []string{loop2RouteID, loop1RouteID, shuntRouteID}
+	paths := map[string]string{
+		loop2RouteID: "/loop2",
+		loop1RouteID: "/loop1",
+		shuntRouteID: "/shunt",
+	}
+
+	doc := fmt.Sprintf(`
+%s: Path("/shunt") -> setPath("/bye") -> setQuery("void") -> status(204) -> <shunt>;
+%s: Path("/loop1") -> setPath("/shunt") -> <loopback>;
+%s: Path("/loop2") -> setPath("/loop1") -> <loopback>;
+`, shuntRouteID, loop1RouteID, loop2RouteID)
+
+	tracer := mocktracer.New()
+	params := Params{
+		OpenTracing: &OpenTracingParams{
+			Tracer: tracer,
+		},
+		Flags: FlagsNone,
+	}
+
+	t.Setenv("HOSTNAME", "ingress-loop.tracing.test")
+
+	tp, err := newTestProxyWithParams(doc, params)
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer tp.close()
+
+	ps := httptest.NewServer(tp.proxy)
+	defer ps.Close()
+
+	req, err := http.NewRequest("GET", ps.URL+"/loop2", nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	req.Header.Set("X-Flow-Id", "test-flow-id")
+
+	rsp, err := ps.Client().Do(req)
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer rsp.Body.Close()
+	io.Copy(io.Discard, rsp.Body)
+	t.Logf("got response %d", rsp.StatusCode)
+
+	// client may get response before proxy finishes span
+	time.Sleep(10 * time.Millisecond)
+
+	sp, ok := findSpanByRouteID(tracer, loop2RouteID)
+	if !ok {
+		t.Fatalf("span for route %q not found", loop2RouteID)
+	}
+	verifyTag(t, sp, HTTPStatusCodeTag, uint16(204))
+
+	for _, rid := range routeIDs {
+		span, ok := findSpanByRouteID(tracer, rid)
+		if !ok {
+			t.Fatalf("span for route %q not found", rid)
+		}
+		verifyTag(t, span, SpanKindTag, SpanKindServer)
+		verifyTag(t, span, ComponentTag, "skipper")
+		verifyTag(t, span, SkipperRouteIDTag, rid)
+		verifyTag(t, span, HTTPMethodTag, "GET")
+		verifyTag(t, span, HostnameTag, "ingress-loop.tracing.test")
+		verifyTag(t, span, HTTPPathTag, paths[rid])
+		verifyTag(t, span, HTTPHostTag, ps.Listener.Addr().String())
+		verifyTag(t, span, FlowIDTag, "test-flow-id")
+	}
+}
+
 func TestTracingSpanName(t *testing.T) {
 	traceContent := fmt.Sprintf("%x", md5.New().Sum([]byte(time.Now().String())))
 	s := startTestServer(nil, 0, func(r *http.Request) {
@@ -562,6 +697,15 @@ func findSpan(tracer *mocktracer.MockTracer, name string) (*mocktracer.MockSpan,
 	return nil, false
 }
 
+func findSpanByRouteID(tracer *mocktracer.MockTracer, routeID string) (*mocktracer.MockSpan, bool) {
+	for _, s := range tracer.FinishedSpans() {
+		if s.Tag(SkipperRouteIDTag) == routeID {
+			return s, true
+		}
+	}
+	return nil, false
+}
+
 func verifyTag(t *testing.T, span *mocktracer.MockSpan, name string, expected interface{}) {
 	t.Helper()
 	if got := span.Tag(name); got != expected {