Provide TraceID in the logs

Signed-off-by: Roman Zavodskikh <[email protected]>

filters/auth/tokeninfo.go

@@ -357,7 +357,7 @@ func (f *tokeninfoFilter) Request(ctx filters.FilterContext) {
 			if err == errInvalidToken {
 				reason = invalidToken
 			} else {
-				log.Errorf("Error while calling tokeninfo: %v.", err)
+				log.Errorf("Error while calling tokeninfo: %v, traceID: %s", err, ctx.GetTraceID())
 			}
 
 			unauthorized(ctx, "", reason, "", "")
@@ -380,7 +380,7 @@ func (f *tokeninfoFilter) Request(ctx filters.FilterContext) {
 	case checkOAuthTokeninfoAllKV:
 		allowed = f.validateAllKV(authMap)
 	default:
-		log.Errorf("Wrong tokeninfoFilter type: %s.", f)
+		log.Errorf("Wrong tokeninfoFilter type: %s., traceID: %s", f, ctx.GetTraceID())
 	}
 
 	if !allowed {

filters/auth/tokenintrospection.go

@@ -433,7 +433,7 @@ func (f *tokenintrospectFilter) Request(ctx filters.FilterContext) {
 			if err == errInvalidToken {
 				reason = invalidToken
 			} else {
-				log.Errorf("Error while calling token introspection: %v.", err)
+				log.Errorf("Error while calling token introspection: %v, traceID: %s", err, ctx.GetTraceID())
 			}
 
 			unauthorized(ctx, "", reason, f.authClient.url.Hostname(), "")
@@ -446,7 +446,7 @@ func (f *tokenintrospectFilter) Request(ctx filters.FilterContext) {
 	sub, err := info.Sub()
 	if err != nil {
 		if err != errInvalidTokenintrospectionData {
-			log.Errorf("Error while reading token: %v.", err)
+			log.Errorf("Error while reading token: %v, traceID: %s", err, ctx.GetTraceID())
 		}
 
 		unauthorized(ctx, sub, invalidSub, f.authClient.url.Hostname(), "")
@@ -469,7 +469,7 @@ func (f *tokenintrospectFilter) Request(ctx filters.FilterContext) {
 	case checkOAuthTokenintrospectionAllKV, checkSecureOAuthTokenintrospectionAllKV:
 		allowed = f.validateAllKV(info)
 	default:
-		log.Errorf("Wrong tokenintrospectionFilter type: %s.", f)
+		log.Errorf("Wrong tokenintrospectionFilter type: %s, traceID: %s", f, ctx.GetTraceID())
 	}
 
 	if !allowed {

filters/builtin/decompress.go

@@ -4,13 +4,14 @@ import (
 	"compress/flate"
 	"compress/gzip"
 	"fmt"
-	"github.com/andybalholm/brotli"
 	"io"
 	"net/http"
 	"runtime"
 	"strings"
 	"sync"
 
+	"github.com/andybalholm/brotli"
+
 	log "github.com/sirupsen/logrus"
 	"github.com/zalando/skipper/filters"
 )
@@ -235,7 +236,7 @@ func (d decompress) Response(ctx filters.FilterContext) {
 		sb[DecompressionNotPossible] = true
 		sb[DecompressionError] = err
 
-		log.Errorf("Error while initializing decompression: %v", err)
+		log.Errorf("Error while initializing decompression: %v, traceID: %s", err, ctx.GetTraceID())
 		return
 	}
 

filters/filters.go

@@ -117,6 +117,8 @@ type FilterContext interface {
 
 	// Performs a new route lookup and executes the matched route if any
 	Loopback()
+
+	GetTraceID() string
 }
 
 // Metrics provides possibility to use custom metrics from filter implementations. The custom metrics will

filters/filtertest/filtertest.go

@@ -59,6 +59,13 @@ func (fc *Context) Tracer() opentracing.Tracer {
 func (fc *Context) ParentSpan() opentracing.Span {
 	return opentracing.StartSpan("test_span")
 }
+func (fc *Context) GetTraceID() string {
+	if fc == nil || fc.FRequest == nil {
+		return ""
+	}
+
+	return fc.FRequest.Header.Get("Ot-Tracer-Traceid")
+}
 
 func (fc *Context) Serve(resp *http.Response) {
 	fc.FServedWithResponse = true

filters/log/log.go

@@ -172,7 +172,7 @@ func (al *auditLog) Response(ctx filters.FilterContext) {
 	enc := json.NewEncoder(al.writer)
 	err := enc.Encode(&doc)
 	if err != nil {
-		log.Errorf("Failed to json encode auditDoc: %v", err)
+		log.Errorf("Failed to json encode auditDoc: %v, traceID: %s", err, ctx.GetTraceID())
 	}
 }
 

filters/ratelimit/ratelimit.go

@@ -460,12 +460,12 @@ func getStatusCodeArg(args []interface{}, index int) (int, error) {
 func (f *filter) Request(ctx filters.FilterContext) {
 	rateLimiter := f.provider.get(f.settings)
 	if rateLimiter == nil {
-		log.Errorf("RateLimiter is nil for settings: %s", f.settings)
+		log.Errorf("RateLimiter is nil for settings: %s, traceID: %s", f.settings, ctx.GetTraceID())
 		return
 	}
 
 	if f.settings.Lookuper == nil {
-		log.Errorf("Lookuper is nil for settings: %s", f.settings)
+		log.Errorf("Lookuper is nil for settings: %s, traceID: %s", f.settings, ctx.GetTraceID())
 		return
 	}
 

filters/scheduler/fifo.go

@@ -122,7 +122,7 @@ func (f *fifoFilter) Request(ctx filters.FilterContext) {
 			return
 
 		default:
-			log.Errorf("Unknown error in fifo() please create an issue https://github.com/zalando/skipper/issues/new/choose: %v", err)
+			log.Errorf("Unknown error in fifo() please create an issue https://github.com/zalando/skipper/issues/new/choose: %v, traceID: %s", err, ctx.GetTraceID())
 			ctx.Serve(&http.Response{
 				StatusCode: http.StatusInternalServerError,
 				Status:     "Unknown error in fifo https://opensource.zalando.com/skipper/operation/operation/#scheduler, please create an issue https://github.com/zalando/skipper/issues/new/choose",

filters/scheduler/lifo.go

@@ -326,7 +326,7 @@ func request(q *scheduler.Queue, key string, ctx filters.FilterContext) {
 				Status:     "Queue timeout - https://opensource.zalando.com/skipper/operation/operation/#scheduler",
 			})
 		default:
-			log.Errorf("Unknown error for route based LIFO: %v for host %s", err, ctx.Request().Host)
+			log.Errorf("Unknown error for route based LIFO: %v for host %s, traceID: %s", err, ctx.Request().Host, ctx.GetTraceID())
 			ctx.Serve(&http.Response{StatusCode: http.StatusInternalServerError})
 		}
 		return

filters/tee/teeloopback.go

@@ -40,7 +40,7 @@ func NewTeeLoopback() filters.Spec {
 func (f *teeLoopbackFilter) Request(ctx filters.FilterContext) {
 	cc, err := ctx.Split()
 	if err != nil {
-		log.Errorf("teeloopback: failed to split the context request: %v", err)
+		log.Errorf("teeloopback: failed to split the context request: %v, traceID: %s", err, ctx.GetTraceID())
 		return
 	}
 	cc.Request().Header.Set(teepredicate.HeaderKey, f.teeKey)

proxy/context.go

@@ -206,6 +206,14 @@ func (c *context) Metrics() filters.Metrics            { return c.metrics }
 func (c *context) Tracer() opentracing.Tracer          { return c.tracer }
 func (c *context) ParentSpan() opentracing.Span        { return c.parentSpan }
 
+func (c *context) GetTraceID() string {
+	if c == nil || c.request == nil {
+		return ""
+	}
+
+	return c.request.Header.Get("Ot-Tracer-Traceid")
+}
+
 func (c *context) Serve(r *http.Response) {
 	r.Request = c.Request()
 

proxy/proxy.go

@@ -812,7 +812,7 @@ func (p *Proxy) makeUpgradeRequest(ctx *context, req *http.Request) error {
 
 	upgradeProxy.serveHTTP(ctx.responseWriter, req)
 	ctx.successfulUpgrade = true
-	p.log.Debugf("finished upgraded protocol %s session", getUpgradeRequest(ctx.request))
+	p.log.Debugf("finished upgraded protocol %s session, traceID: %s", getUpgradeRequest(ctx.request), ctx.GetTraceID())
 	return nil
 }
 
@@ -1067,7 +1067,7 @@ func (p *Proxy) do(ctx *context) (err error) {
 			p.metrics.IncRoutingFailures()
 		}
 
-		p.log.Debugf("could not find a route for %v", ctx.request.URL)
+		p.log.Debugf("could not find a route for %v, traceID: %s", ctx.request.URL, ctx.GetTraceID())
 		p.makeErrorResponse(ctx, errRouteLookupFailed)
 		return errRouteLookupFailed
 	}
@@ -1077,13 +1077,13 @@ func (p *Proxy) do(ctx *context) (err error) {
 	processedFilters := p.applyFiltersToRequest(ctx.route.Filters, ctx)
 
 	if ctx.deprecatedShunted() {
-		p.log.Debugf("deprecated shunting detected in route: %s", ctx.route.Id)
+		p.log.Debugf("deprecated shunting detected in route: %s, traceID: %s", ctx.route.Id, ctx.GetTraceID())
 		return &proxyError{handled: true}
 	} else if ctx.shunted() || ctx.route.Shunt || ctx.route.BackendType == eskip.ShuntBackend {
 		// consume the body to prevent goroutine leaks
 		if ctx.request.Body != nil {
 			if _, err := io.Copy(io.Discard, ctx.request.Body); err != nil {
-				p.log.Errorf("error while discarding remainder request body: %v.", err)
+				p.log.Errorf("error while discarding remainder request body: %v, traceID: %s", err, ctx.GetTraceID())
 			}
 		}
 		ctx.ensureDefaultResponse()
@@ -1206,7 +1206,7 @@ func (p *Proxy) serveResponse(ctx *context) {
 	if err := ctx.Request().Context().Err(); err != nil {
 		// deadline exceeded or canceled in stdlib, client closed request
 		// see https://github.com/zalando/skipper/pull/864
-		p.log.Debugf("Client request: %v", err)
+		p.log.Debugf("Client request: %v, traceID: %s", err, ctx.GetTraceID())
 		ctx.response.StatusCode = 499
 		p.tracing.setTag(ctx.proxySpan, ClientRequestStateTag, ClientRequestCanceled)
 	}
@@ -1221,7 +1221,7 @@ func (p *Proxy) serveResponse(ctx *context) {
 	p.tracing.logStreamEvent(ctx.proxySpan, StreamBodyEvent, strconv.FormatInt(n, 10))
 	if err != nil {
 		p.metrics.IncErrorsStreaming(ctx.route.Id)
-		p.log.Debugf("error while copying the response stream: %v", err)
+		p.log.Debugf("error while copying the response stream: %v, traceID: %s", err, ctx.GetTraceID())
 		p.tracing.setTag(ctx.proxySpan, ErrorTag, true)
 		p.tracing.setTag(ctx.proxySpan, StreamBodyEvent, StreamBodyError)
 		p.tracing.logStreamEvent(ctx.proxySpan, StreamBodyEvent, fmt.Sprintf("Failed to stream response: %v", err))
@@ -1580,7 +1580,7 @@ func (p *Proxy) applyFiltersOnError(ctx *context, filters []*routing.RouteFilter
 		if ehf, ok := fi.Filter.(errorHandlerFilter); !ok || !ehf.HandleErrorResponse() {
 			continue
 		}
-		p.log.Debugf("filter %s handles error", fi.Name)
+		p.log.Debugf("filter %s handles error, traceID: %s", fi.Name, ctx.GetTraceID())
 
 		start := time.Now()
 		filterTracing.logStart(fi.Name)

script/script_test.go

@@ -42,6 +42,14 @@ func (l *luaContext) ParentSpan() opentracing.Span          { return nil }
 func (l *luaContext) Split() (filters.FilterContext, error) { return nil, nil }
 func (l *luaContext) Loopback()                             {}
 
+func (l *luaContext) GetTraceID() string {
+	if l == nil || l.request == nil {
+		return ""
+	}
+
+	return l.request.Header.Get("Ot-Tracer-Traceid")
+}
+
 type testContext struct {
 	script         string
 	params         []string