Provide TraceID in the logs

Signed-off-by: Roman Zavodskikh <[email protected]>
zalando · Apr 19, 2023 · 64882d5 · 64882d5
1 parent 3c60b4e
commit 64882d5
Show file tree

Hide file tree

Showing 27 changed files with 127 additions and 73 deletions.
diff --git 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/forwardtoken.go b/filters/auth/forwardtoken.go
@@ -4,7 +4,6 @@ import (
 	"encoding/json"
 	"fmt"
 
-	log "github.com/sirupsen/logrus"
 	"github.com/zalando/skipper/filters"
 	"golang.org/x/net/http/httpguts"
 )
@@ -82,13 +81,13 @@ func (f *forwardTokenFilter) Request(ctx filters.FilterContext) {
 		case tokenIntrospectionInfo:
 			tiMap = retainKeys(typedTiMap, f.RetainJsonKeys)
 		default:
-			log.Errorf("Unexpected input type[%T] for `forwardToken` filter. Unable to apply mask", typedTiMap)
+			ctx.Logger().Errorf("Unexpected input type[%T] for `forwardToken` filter. Unable to apply mask", typedTiMap)
 		}
 	}
 
 	payload, err := json.Marshal(tiMap)
 	if err != nil {
-		log.Errorf("Error while marshaling token: %v.", err)
+		ctx.Logger().Errorf("Error while marshaling token: %v.", err)
 		return
 	}
 	request := ctx.Request()

diff --git a/filters/auth/forwardtokenfield.go b/filters/auth/forwardtokenfield.go
@@ -3,7 +3,6 @@ package auth
 import (
 	"fmt"
 
-	log "github.com/sirupsen/logrus"
 	"github.com/zalando/skipper/filters"
 	"golang.org/x/net/http/httpguts"
 )
@@ -71,7 +70,7 @@ func (f *forwardTokenFieldFilter) Request(ctx filters.FilterContext) {
 	}, ctx, payload)
 
 	if err != nil {
-		log.Error(err)
+		ctx.Logger().Errorf(err.Error())
 		return
 	}
 }

diff --git a/filters/auth/grant.go b/filters/auth/grant.go
@@ -7,7 +7,6 @@ import (
 	"net/http"
 	"time"
 
-	log "github.com/sirupsen/logrus"
 	"github.com/zalando/skipper/filters"
 	"golang.org/x/oauth2"
 )
@@ -65,7 +64,7 @@ func loginRedirectWithOverride(ctx filters.FilterContext, config *OAuthConfig, o
 
 	authConfig, err := config.GetConfig(req)
 	if err != nil {
-		log.Debugf("Failed to obtain auth config: %v", err)
+		ctx.Logger().Debugf("Failed to obtain auth config: %v", err)
 		ctx.Serve(&http.Response{
 			StatusCode: http.StatusForbidden,
 		})
@@ -80,7 +79,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
 	}
@@ -198,15 +197,15 @@ func (f *grantFilter) Request(ctx filters.FilterContext) {
 	tokeninfo, err := f.config.TokeninfoClient.getTokeninfo(token.AccessToken, ctx)
 	if err != nil {
 		if err != errInvalidToken {
-			log.Errorf("Failed to call tokeninfo: %v.", err)
+			ctx.Logger().Errorf("Failed to call tokeninfo: %v.", err)
 		}
 		loginRedirect(ctx, f.config)
 		return
 	}
 
 	err = f.setupToken(token, tokeninfo, ctx)
 	if err != nil {
-		log.Errorf("Failed to create token container: %v.", err)
+		ctx.Logger().Errorf("Failed to create token container: %v.", err)
 		loginRedirect(ctx, f.config)
 		return
 	}
@@ -224,7 +223,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
@@ -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
@@ -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().Errorf(accessTokenRevokeError.Error())
 		}
 	}
 
 	if c.RefreshToken != "" {
 		refreshTokenRevokeError = f.revokeTokenType(authConfig, refreshTokenType, c.RefreshToken)
 		if refreshTokenRevokeError != nil {
-			log.Error(refreshTokenRevokeError)
+			ctx.Logger().Errorf(refreshTokenRevokeError.Error())
 		}
 	}
 

diff --git 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
@@ -390,21 +390,21 @@ 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
 	}
 
 	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().Errorf(err.Error())
 		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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
 	}