From 4d7b5fc0e72d42287237acfdd26fb48c2ba8724b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sandor=20Sz=C3=BCcs?= Date: Mon, 6 Nov 2023 15:36:34 +0100 Subject: [PATCH] Feature: tracing set route id to ingress spans (#2714) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feature: set Tag "skipper.route_id" to `route.Id` in all ingress spans including shunt and loopback routes Signed-off-by: Sandor Szücs --- proxy/context.go | 4 +- proxy/proxy.go | 17 ++++- proxy/tracing_test.go | 146 +++++++++++++++++++++++++++++++++++++++++- 3 files changed, 162 insertions(+), 5 deletions(-) diff --git a/proxy/context.go b/proxy/context.go index 418d76ed64..468dc4ac98 100644 --- a/proxy/context.go +++ b/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) diff --git a/proxy/proxy.go b/proxy/proxy.go index 3498185683..7b6923cb2e 100644 --- a/proxy/proxy.go +++ b/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 { diff --git a/proxy/tracing_test.go b/proxy/tracing_test.go index 7962358f82..10c55b96eb 100644 --- a/proxy/tracing_test.go +++ b/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) -> `, 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) -> ; +%s: Path("/loop1") -> setPath("/shunt") -> ; +%s: Path("/loop2") -> setPath("/loop1") -> ; +`, 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 {