diff --git a/filters/auth/auth.go b/filters/auth/auth.go index ddcd702354..5d818b9637 100644 --- a/filters/auth/auth.go +++ b/filters/auth/auth.go @@ -6,7 +6,6 @@ import ( "net/http" "strings" - log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" logfilter "github.com/zalando/skipper/filters/log" ) @@ -107,12 +106,12 @@ func reject( debuginfo string, ) { if debuginfo == "" { - log.Debugf( + ctx.Logger().Debugf( "Rejected: status: %d, username: %s, reason: %s.", status, username, reason, ) } else { - log.Debugf( + ctx.Logger().Debugf( "Rejected: status: %d, username: %s, reason: %s, info: %s.", status, username, reason, debuginfo, ) diff --git a/filters/auth/grant.go b/filters/auth/grant.go index 019a3dfa4a..b0223ce328 100644 --- a/filters/auth/grant.go +++ b/filters/auth/grant.go @@ -80,7 +80,7 @@ func loginRedirectWithOverride(ctx filters.FilterContext, config *OAuthConfig, o state, err := config.flowState.createState(original) if err != nil { - log.Errorf("Failed to create login redirect: %v", err) + ctx.Logger().Errorf("Failed to create login redirect: %v", err) serverError(ctx) return } @@ -224,7 +224,7 @@ func (f *grantFilter) Response(ctx filters.FilterContext) { c, err := createCookie(f.config, ctx.Request().Host, token) if err != nil { - log.Errorf("Failed to generate cookie: %v.", err) + ctx.Logger().Errorf("Failed to generate cookie: %v.", err) return } diff --git a/filters/auth/grantcallback.go b/filters/auth/grantcallback.go index f95469d73d..8b046853ea 100644 --- a/filters/auth/grantcallback.go +++ b/filters/auth/grantcallback.go @@ -4,7 +4,6 @@ import ( "net/http" "net/url" - log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" "golang.org/x/oauth2" ) @@ -86,14 +85,14 @@ func (f *grantCallbackFilter) Request(ctx filters.FilterContext) { token, err := f.exchangeAccessToken(req, code) if err != nil { - log.Errorf("Failed to exchange access token: %v.", err) + ctx.Logger().Errorf("Failed to exchange access token: %v.", err) serverError(ctx) return } c, err := createCookie(f.config, req.Host, token) if err != nil { - log.Errorf("Failed to create OAuth grant cookie: %v.", err) + ctx.Logger().Errorf("Failed to create OAuth grant cookie: %v.", err) serverError(ctx) return } diff --git a/filters/auth/grantlogout.go b/filters/auth/grantlogout.go index 7ba53c501a..a854f34e37 100644 --- a/filters/auth/grantlogout.go +++ b/filters/auth/grantlogout.go @@ -8,7 +8,6 @@ import ( "net/url" "strings" - log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" "golang.org/x/oauth2" ) @@ -157,14 +156,14 @@ func (f *grantLogoutFilter) Request(ctx filters.FilterContext) { if c.AccessToken != "" { accessTokenRevokeError = f.revokeTokenType(authConfig, accessTokenType, c.AccessToken) if accessTokenRevokeError != nil { - log.Error(accessTokenRevokeError) + ctx.Logger().Error(accessTokenRevokeError) } } if c.RefreshToken != "" { refreshTokenRevokeError = f.revokeTokenType(authConfig, refreshTokenType, c.RefreshToken) if refreshTokenRevokeError != nil { - log.Error(refreshTokenRevokeError) + ctx.Logger().Error(refreshTokenRevokeError) } } diff --git a/filters/auth/jwt_validation.go b/filters/auth/jwt_validation.go index 07a005cea8..d9f4dbecb2 100644 --- a/filters/auth/jwt_validation.go +++ b/filters/auth/jwt_validation.go @@ -134,7 +134,7 @@ func (f *jwtValidationFilter) Request(ctx filters.FilterContext) { claims, err := parseToken(token, f.jwksUri) if err != nil { - log.Errorf("Error while parsing jwt token : %v.", err) + ctx.Logger().Errorf("Error while parsing jwt token : %v.", err) unauthorized(ctx, "", invalidToken, "", "") return } diff --git a/filters/auth/oidc.go b/filters/auth/oidc.go index 80d19f0856..e357b1bb12 100644 --- a/filters/auth/oidc.go +++ b/filters/auth/oidc.go @@ -390,7 +390,7 @@ func (f *tokenOidcFilter) internalServerError(ctx filters.FilterContext) { func (f *tokenOidcFilter) doOauthRedirect(ctx filters.FilterContext, cookies []*http.Cookie) { nonce, err := f.encrypter.CreateNonce() if err != nil { - log.Errorf("Failed to create nonce: %v.", err) + ctx.Logger().Errorf("Failed to create nonce: %v.", err) f.internalServerError(ctx) return } @@ -398,13 +398,13 @@ func (f *tokenOidcFilter) doOauthRedirect(ctx filters.FilterContext, cookies []* redirectUrl := ctx.Request().URL.String() statePlain, err := createState(nonce, redirectUrl) if err != nil { - log.Errorf("Failed to create oauth2 state: %v.", err) + ctx.Logger().Errorf("Failed to create oauth2 state: %v.", err) f.internalServerError(ctx) return } stateEnc, err := f.encrypter.Encrypt(statePlain) if err != nil { - log.Errorf("Failed to encrypt data block: %v.", err) + ctx.Logger().Errorf("Failed to encrypt data block: %v.", err) f.internalServerError(ctx) return } @@ -431,7 +431,7 @@ func (f *tokenOidcFilter) doOauthRedirect(ctx filters.FilterContext, cookies []* for _, cookie := range cookies { rsp.Header.Add("Set-Cookie", cookie.String()) } - log.Debugf("serve redirect: plaintextState:%s to Location: %s", statePlain, rsp.Header.Get("Location")) + ctx.Logger().Debugf("serve redirect: plaintextState:%s to Location: %s", statePlain, rsp.Header.Get("Location")) ctx.Serve(rsp) } @@ -520,7 +520,7 @@ func mergerCookies(cookies []*http.Cookie) *http.Cookie { } func (f *tokenOidcFilter) doDownstreamRedirect(ctx filters.FilterContext, oidcState []byte, maxAge time.Duration, redirectUrl string) { - log.Debugf("Doing Downstream Redirect to :%s", redirectUrl) + ctx.Logger().Debugf("Doing Downstream Redirect to :%s", redirectUrl) r := &http.Response{ StatusCode: http.StatusTemporaryRedirect, Header: http.Header{ @@ -582,7 +582,7 @@ func (f *tokenOidcFilter) callbackEndpoint(ctx filters.FilterContext) { oauthState, err := f.getCallbackState(ctx) if err != nil { if _, ok := err.(*requestError); !ok { - log.Errorf("Error while retrieving callback state: %v.", err) + ctx.Logger().Errorf("Error while retrieving callback state: %v.", err) } unauthorized( @@ -599,7 +599,7 @@ func (f *tokenOidcFilter) callbackEndpoint(ctx filters.FilterContext) { oauth2Token, err = f.getTokenWithExchange(oauthState, ctx) if err != nil { if _, ok := err.(*requestError); !ok { - log.Errorf("Error while getting token in callback: %v.", err) + ctx.Logger().Errorf("Error while getting token in callback: %v.", err) } unauthorized( @@ -634,7 +634,7 @@ func (f *tokenOidcFilter) callbackEndpoint(ctx filters.FilterContext) { oidcIDToken, err = f.getidtoken(ctx, oauth2Token) if err != nil { if _, ok := err.(*requestError); !ok { - log.Errorf("Error while getting id token: %v", err) + ctx.Logger().Errorf("Error while getting id token: %v", err) } unauthorized( @@ -663,7 +663,7 @@ func (f *tokenOidcFilter) callbackEndpoint(ctx filters.FilterContext) { oidcIDToken, err = f.getidtoken(ctx, oauth2Token) if err != nil { if _, ok := err.(*requestError); !ok { - log.Errorf("Error while getting id token: %v", err) + ctx.Logger().Errorf("Error while getting id token: %v", err) } unauthorized( @@ -679,7 +679,7 @@ func (f *tokenOidcFilter) callbackEndpoint(ctx filters.FilterContext) { claimsMap, sub, err = f.tokenClaims(ctx, oauth2Token) if err != nil { if _, ok := err.(*requestError); !ok { - log.Errorf("Failed to get claims with error: %v", err) + ctx.Logger().Errorf("Failed to get claims with error: %v", err) } unauthorized( @@ -825,7 +825,7 @@ func (f *tokenOidcFilter) Request(ctx filters.FilterContext) { // adding upstream headers err = setHeaders(f.upstreamHeaders, ctx, container) if err != nil { - log.Error(err) + ctx.Logger().Error(err) f.internalServerError(ctx) return } @@ -916,7 +916,7 @@ func (f *tokenOidcFilter) getCallbackState(ctx filters.FilterContext) (*OauthSta return nil, requestErrorf("token from state query is invalid: %v", err) } - log.Debugf("len(stateQueryPlain): %d, stateQueryEnc: %d, stateQueryEncHex: %d", len(stateQueryPlain), len(stateQueryEnc), len(stateQueryEncHex)) + ctx.Logger().Debugf("len(stateQueryPlain): %d, stateQueryEnc: %d, stateQueryEncHex: %d", len(stateQueryPlain), len(stateQueryEnc), len(stateQueryEncHex)) state, err := extractState(stateQueryPlain) if err != nil { diff --git a/filters/auth/oidc_introspection.go b/filters/auth/oidc_introspection.go index 0df39284b8..d3d8c3fefa 100644 --- a/filters/auth/oidc_introspection.go +++ b/filters/auth/oidc_introspection.go @@ -115,7 +115,7 @@ func (filter *oidcIntrospectionFilter) Request(ctx filters.FilterContext) { token, ok := ctx.StateBag()[oidcClaimsCacheKey].(tokenContainer) if !ok || &token == (&tokenContainer{}) || len(token.Claims) == 0 { - log.Errorf("Error retrieving %s for OIDC token introspection", oidcClaimsCacheKey) + ctx.Logger().Errorf("Error retrieving %s for OIDC token introspection", oidcClaimsCacheKey) unauthorized(ctx, "", missingToken, r.Host, oidcClaimsCacheKey+" is unavailable in StateBag") return } diff --git a/filters/auth/tokeninfo.go b/filters/auth/tokeninfo.go index ed0b0897e8..b7626ca5a8 100644 --- a/filters/auth/tokeninfo.go +++ b/filters/auth/tokeninfo.go @@ -6,7 +6,6 @@ import ( "time" "github.com/opentracing/opentracing-go" - log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" ) @@ -357,7 +356,7 @@ func (f *tokeninfoFilter) Request(ctx filters.FilterContext) { if err == errInvalidToken { reason = invalidToken } else { - log.Errorf("Error while calling tokeninfo: %v.", err) + ctx.Logger().Errorf("Error while calling tokeninfo: %v", err) } unauthorized(ctx, "", reason, "", "") @@ -380,7 +379,7 @@ func (f *tokeninfoFilter) Request(ctx filters.FilterContext) { case checkOAuthTokeninfoAllKV: allowed = f.validateAllKV(authMap) default: - log.Errorf("Wrong tokeninfoFilter type: %s.", f) + ctx.Logger().Errorf("Wrong tokeninfoFilter type: %s.", f) } if !allowed { diff --git a/filters/auth/tokenintrospection.go b/filters/auth/tokenintrospection.go index 10a2250f6b..1495a2a4eb 100644 --- a/filters/auth/tokenintrospection.go +++ b/filters/auth/tokenintrospection.go @@ -10,7 +10,6 @@ import ( "time" "github.com/opentracing/opentracing-go" - log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" ) @@ -433,7 +432,7 @@ func (f *tokenintrospectFilter) Request(ctx filters.FilterContext) { if err == errInvalidToken { reason = invalidToken } else { - log.Errorf("Error while calling token introspection: %v.", err) + ctx.Logger().Errorf("Error while calling token introspection: %v", err) } unauthorized(ctx, "", reason, f.authClient.url.Hostname(), "") @@ -446,7 +445,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) + ctx.Logger().Errorf("Error while reading token: %v", err) } unauthorized(ctx, sub, invalidSub, f.authClient.url.Hostname(), "") @@ -469,7 +468,7 @@ func (f *tokenintrospectFilter) Request(ctx filters.FilterContext) { case checkOAuthTokenintrospectionAllKV, checkSecureOAuthTokenintrospectionAllKV: allowed = f.validateAllKV(info) default: - log.Errorf("Wrong tokenintrospectionFilter type: %s.", f) + ctx.Logger().Errorf("Wrong tokenintrospectionFilter type: %s", f) } if !allowed { diff --git a/filters/auth/webhook.go b/filters/auth/webhook.go index acfa052db0..e17711f17d 100644 --- a/filters/auth/webhook.go +++ b/filters/auth/webhook.go @@ -7,7 +7,6 @@ import ( "time" "github.com/opentracing/opentracing-go" - log "github.com/sirupsen/logrus" "golang.org/x/net/http/httpguts" "github.com/zalando/skipper/filters" @@ -113,7 +112,7 @@ func copyHeader(to, from http.Header) { func (f *webhookFilter) Request(ctx filters.FilterContext) { resp, err := f.authClient.getWebhook(ctx) if err != nil { - log.Errorf("Failed to make authentication webhook request: %v.", err) + ctx.Logger().Errorf("Failed to make authentication webhook request: %v.", err) } // forbidden diff --git a/filters/builtin/decompress.go b/filters/builtin/decompress.go index adfd41ac46..3d3a80e6b5 100644 --- a/filters/builtin/decompress.go +++ b/filters/builtin/decompress.go @@ -4,14 +4,14 @@ import ( "compress/flate" "compress/gzip" "fmt" - "github.com/andybalholm/brotli" "io" "net/http" "runtime" "strings" "sync" - log "github.com/sirupsen/logrus" + "github.com/andybalholm/brotli" + "github.com/zalando/skipper/filters" ) @@ -235,7 +235,7 @@ func (d decompress) Response(ctx filters.FilterContext) { sb[DecompressionNotPossible] = true sb[DecompressionError] = err - log.Errorf("Error while initializing decompression: %v", err) + ctx.Logger().Errorf("Error while initializing decompression: %v", err) return } diff --git a/filters/filters.go b/filters/filters.go index 783a138b72..e22d6f7ea1 100644 --- a/filters/filters.go +++ b/filters/filters.go @@ -117,6 +117,8 @@ type FilterContext interface { // Performs a new route lookup and executes the matched route if any Loopback() + + Logger() *log.Entry } // Metrics provides possibility to use custom metrics from filter implementations. The custom metrics will diff --git a/filters/filtertest/filtertest.go b/filters/filtertest/filtertest.go index 0528c8c08d..91184debee 100644 --- a/filters/filtertest/filtertest.go +++ b/filters/filtertest/filtertest.go @@ -5,10 +5,14 @@ FilterContext interfaces used during tests. package filtertest import ( + "fmt" "net/http" + "github.com/lightstep/lightstep-tracer-go" "github.com/opentracing/opentracing-go" "github.com/zalando/skipper/filters" + + log "github.com/sirupsen/logrus" ) // Noop filter, used to verify the filter name and the args in the route. @@ -60,6 +64,42 @@ func (fc *Context) ParentSpan() opentracing.Span { return opentracing.StartSpan("test_span") } +func (fc *Context) Logger() *log.Entry { + traceId := fc.getTraceID() + if traceId == "" { + return log.WithFields(log.Fields{}) + } else { + return log.WithFields(log.Fields{"trace_id": traceId}) + } +} + +func (fc *Context) getTraceID() string { + if fc == nil { + return "" + } + if fc.FRequest == nil { + return "" + } + + span := opentracing.SpanFromContext(fc.FRequest.Context()) + if span == nil { + return "" + } + + spanContext := span.Context() + if spanContext == nil { + return "" + } + + switch spanContextType := spanContext.(type) { + case lightstep.SpanContext: + _ = spanContextType + return fmt.Sprintf("0x%x", spanContextType.TraceID) + } + + return "" +} + func (fc *Context) Serve(resp *http.Response) { fc.FServedWithResponse = true fc.FResponse = resp diff --git a/filters/log/log.go b/filters/log/log.go index 59995b5613..96266bc7b5 100644 --- a/filters/log/log.go +++ b/filters/log/log.go @@ -13,8 +13,6 @@ import ( "regexp" "strings" - log "github.com/sirupsen/logrus" - "github.com/zalando/skipper/filters" "github.com/zalando/skipper/jwt" ) @@ -172,7 +170,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) + ctx.Logger().Errorf("Failed to json encode auditDoc: %v", err) } } diff --git a/filters/ratelimit/ratelimit.go b/filters/ratelimit/ratelimit.go index 800356f67f..b722d5895e 100644 --- a/filters/ratelimit/ratelimit.go +++ b/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) + ctx.Logger().Errorf("RateLimiter is nil for settings: %s", f.settings) return } if f.settings.Lookuper == nil { - log.Errorf("Lookuper is nil for settings: %s", f.settings) + ctx.Logger().Errorf("Lookuper is nil for settings: %s", f.settings) return } diff --git a/filters/scheduler/fifo.go b/filters/scheduler/fifo.go index 65fe1ce683..9a999487ef 100644 --- a/filters/scheduler/fifo.go +++ b/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) + ctx.Logger().Errorf("Unknown error in fifo() please create an issue https://github.com/zalando/skipper/issues/new/choose: %v", err) 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", diff --git a/filters/scheduler/lifo.go b/filters/scheduler/lifo.go index 9cd22bf11c..149d564f66 100644 --- a/filters/scheduler/lifo.go +++ b/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) + ctx.Logger().Errorf("Unknown error for route based LIFO: %v for host %s", err, ctx.Request().Host) ctx.Serve(&http.Response{StatusCode: http.StatusInternalServerError}) } return diff --git a/filters/tee/teeloopback.go b/filters/tee/teeloopback.go index 82da05c7b1..7743cabc7f 100644 --- a/filters/tee/teeloopback.go +++ b/filters/tee/teeloopback.go @@ -1,7 +1,6 @@ package tee import ( - log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" teepredicate "github.com/zalando/skipper/predicates/tee" ) @@ -40,7 +39,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) + ctx.Logger().Errorf("teeloopback: failed to split the context request: %v", err) return } cc.Request().Header.Set(teepredicate.HeaderKey, f.teeKey) diff --git a/proxy/context.go b/proxy/context.go index f23979337f..50ecd8026b 100644 --- a/proxy/context.go +++ b/proxy/context.go @@ -4,15 +4,19 @@ import ( "bytes" stdlibcontext "context" "errors" + "fmt" "io" "net/http" "net/url" "time" + "github.com/lightstep/lightstep-tracer-go" "github.com/opentracing/opentracing-go" "github.com/zalando/skipper/filters" "github.com/zalando/skipper/metrics" "github.com/zalando/skipper/routing" + + log "github.com/sirupsen/logrus" ) const unknownHost = "_unknownhost_" @@ -206,6 +210,42 @@ 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) Logger() *log.Entry { + traceId := c.getTraceID() + if traceId == "" { + return log.WithFields(log.Fields{}) + } else { + return log.WithFields(log.Fields{"trace_id": traceId}) + } +} + +func (c *context) getTraceID() string { + if c == nil { + return "" + } + if c.request == nil { + return "" + } + + span := opentracing.SpanFromContext(c.request.Context()) + if span == nil { + return "" + } + + spanContext := span.Context() + if spanContext == nil { + return "" + } + + switch spanContextType := spanContext.(type) { + case lightstep.SpanContext: + _ = spanContextType + return fmt.Sprintf("0x%x", spanContext.(lightstep.SpanContext).TraceID) + } + + return "" +} + func (c *context) Serve(r *http.Response) { r.Request = c.Request() diff --git a/script/script_test.go b/script/script_test.go index 1d4154ce5f..5fd2fc54be 100644 --- a/script/script_test.go +++ b/script/script_test.go @@ -13,6 +13,8 @@ import ( "github.com/opentracing/opentracing-go" log "github.com/sirupsen/logrus" "github.com/zalando/skipper/filters" + + lightstep "github.com/lightstep/lightstep-tracer-go" ) type luaContext struct { @@ -42,6 +44,42 @@ 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) Logger() *log.Entry { + traceId := l.getTraceID() + if traceId == "" { + return log.WithFields(log.Fields{}) + } else { + return log.WithFields(log.Fields{"trace_id": traceId}) + } +} + +func (l *luaContext) getTraceID() string { + if l == nil { + return "" + } + if l.request == nil { + return "" + } + + span := opentracing.SpanFromContext(l.request.Context()) + if span == nil { + return "" + } + + spanContext := span.Context() + if spanContext == nil { + return "(nil span context)" + } + + switch spanContextType := spanContext.(type) { + case lightstep.SpanContext: + _ = spanContextType + return fmt.Sprintf("0x%x", spanContext.(lightstep.SpanContext).TraceID) + } + + return "(unknown span context type)" +} + type testContext struct { script string params []string