From 862a6a2fa625100b690c5a48a9b12e7a7dd42041 Mon Sep 17 00:00:00 2001 From: Marcus Efraimsson Date: Tue, 20 Sep 2022 18:32:06 +0200 Subject: [PATCH] Logging: Introduce API for contextual logging (#55198) Introduces a FromContext method on the log.Logger interface that allows contextual key/value pairs to be attached, e.g. per request, so that any logger using this API will automatically get the per request context attached. The proposal makes the traceID available for contextual logger , if available, and would allow logs originating from a certain HTTP request to be correlated with traceID. In addition, when tracing not enabled, skip adding traceID=00000000000000000000000000000000 to logs. --- pkg/api/pluginproxy/ds_auth_provider.go | 18 +++-- pkg/api/pluginproxy/ds_proxy.go | 22 +++--- pkg/api/pluginproxy/pluginproxy.go | 7 +- pkg/infra/log/interface.go | 13 +++- pkg/infra/log/log.go | 27 +++++++ pkg/infra/log/log_test.go | 74 +++++++++++++++++++ pkg/infra/log/logtest/fake.go | 18 +++++ pkg/infra/tracing/opentelemetry_tracing.go | 6 +- pkg/infra/tracing/tracing.go | 8 ++ pkg/middleware/logger.go | 6 -- pkg/services/auth/auth_token.go | 32 ++++---- pkg/services/sqlstore/database_wrapper.go | 3 +- pkg/services/sqlstore/session.go | 3 +- pkg/services/sqlstore/transactions.go | 8 +- .../api/alerting/api_alertmanager_test.go | 3 - .../alerting/api_notification_channel_test.go | 1 - pkg/util/proxyutil/reverse_proxy.go | 8 +- 17 files changed, 202 insertions(+), 55 deletions(-) diff --git a/pkg/api/pluginproxy/ds_auth_provider.go b/pkg/api/pluginproxy/ds_auth_provider.go index 4a70b9db8d7..493dfa0fd75 100644 --- a/pkg/api/pluginproxy/ds_auth_provider.go +++ b/pkg/api/pluginproxy/ds_auth_provider.go @@ -30,16 +30,18 @@ func ApplyRoute(ctx context.Context, req *http.Request, proxyPath string, route SecureJsonData: ds.DecryptedSecureJSONData, } + ctxLogger := logger.FromContext(ctx) + if len(route.URL) > 0 { interpolatedURL, err := interpolateString(route.URL, data) if err != nil { - logger.Error("Error interpolating proxy url", "error", err) + ctxLogger.Error("Error interpolating proxy url", "error", err) return } routeURL, err := url.Parse(interpolatedURL) if err != nil { - logger.Error("Error parsing plugin route url", "error", err) + ctxLogger.Error("Error parsing plugin route url", "error", err) return } @@ -50,29 +52,29 @@ func ApplyRoute(ctx context.Context, req *http.Request, proxyPath string, route } if err := addQueryString(req, route, data); err != nil { - logger.Error("Failed to render plugin URL query string", "error", err) + ctxLogger.Error("Failed to render plugin URL query string", "error", err) } if err := addHeaders(&req.Header, route, data); err != nil { - logger.Error("Failed to render plugin headers", "error", err) + ctxLogger.Error("Failed to render plugin headers", "error", err) } if err := setBodyContent(req, route, data); err != nil { - logger.Error("Failed to set plugin route body content", "error", err) + ctxLogger.Error("Failed to set plugin route body content", "error", err) } if tokenProvider, err := getTokenProvider(ctx, cfg, ds, route, data); err != nil { - logger.Error("Failed to resolve auth token provider", "error", err) + ctxLogger.Error("Failed to resolve auth token provider", "error", err) } else if tokenProvider != nil { if token, err := tokenProvider.GetAccessToken(); err != nil { - logger.Error("Failed to get access token", "error", err) + ctxLogger.Error("Failed to get access token", "error", err) } else { req.Header.Set("Authorization", fmt.Sprintf("Bearer %s", token)) } } if cfg.DataProxyLogging { - logger.Debug("Requesting", "url", req.URL.String()) + ctxLogger.Debug("Requesting", "url", req.URL.String()) } } diff --git a/pkg/api/pluginproxy/ds_proxy.go b/pkg/api/pluginproxy/ds_proxy.go index 9e21ef163f7..89ab1d0a972 100644 --- a/pkg/api/pluginproxy/ds_proxy.go +++ b/pkg/api/pluginproxy/ds_proxy.go @@ -86,7 +86,6 @@ func (proxy *DataSourceProxy) HandleRequest() { return } - traceID := tracing.TraceIDFromContext(proxy.ctx.Req.Context(), false) proxyErrorLogger := logger.New( "userId", proxy.ctx.UserID, "orgId", proxy.ctx.OrgID, @@ -94,7 +93,6 @@ func (proxy *DataSourceProxy) HandleRequest() { "path", proxy.ctx.Req.URL.Path, "remote_addr", proxy.ctx.RemoteAddr(), "referer", proxy.ctx.Req.Referer(), - "traceID", traceID, ) transport, err := proxy.dataSourcesService.GetHTTPTransport(proxy.ctx.Req.Context(), proxy.ds, proxy.clientProvider) @@ -112,7 +110,8 @@ func (proxy *DataSourceProxy) HandleRequest() { } _ = resp.Body.Close() - proxyErrorLogger.Info("Authentication to data source failed", "body", string(body), "statusCode", + ctxLogger := proxyErrorLogger.FromContext(resp.Request.Context()) + ctxLogger.Info("Authentication to data source failed", "body", string(body), "statusCode", resp.StatusCode) msg := "Authentication to data source failed" *resp = http.Response{ @@ -167,11 +166,13 @@ func (proxy *DataSourceProxy) director(req *http.Request) { reqQueryVals := req.URL.Query() + ctxLogger := logger.FromContext(req.Context()) + switch proxy.ds.Type { case datasources.DS_INFLUXDB_08: password, err := proxy.dataSourcesService.DecryptedPassword(req.Context(), proxy.ds) if err != nil { - logger.Error("Error interpolating proxy url", "error", err) + ctxLogger.Error("Error interpolating proxy url", "error", err) return } @@ -182,7 +183,7 @@ func (proxy *DataSourceProxy) director(req *http.Request) { case datasources.DS_INFLUXDB: password, err := proxy.dataSourcesService.DecryptedPassword(req.Context(), proxy.ds) if err != nil { - logger.Error("Error interpolating proxy url", "error", err) + ctxLogger.Error("Error interpolating proxy url", "error", err) return } req.URL.RawPath = util.JoinURLFragments(proxy.targetUrl.Path, proxy.proxyPath) @@ -199,7 +200,7 @@ func (proxy *DataSourceProxy) director(req *http.Request) { unescapedPath, err := url.PathUnescape(req.URL.RawPath) if err != nil { - logger.Error("Failed to unescape raw path", "rawPath", req.URL.RawPath, "error", err) + ctxLogger.Error("Failed to unescape raw path", "rawPath", req.URL.RawPath, "error", err) return } @@ -208,7 +209,7 @@ func (proxy *DataSourceProxy) director(req *http.Request) { if proxy.ds.BasicAuth { password, err := proxy.dataSourcesService.DecryptedBasicAuthPassword(req.Context(), proxy.ds) if err != nil { - logger.Error("Error interpolating proxy url", "error", err) + ctxLogger.Error("Error interpolating proxy url", "error", err) return } req.Header.Set("Authorization", util.GetBasicAuthHeader(proxy.ds.BasicAuthUser, @@ -230,7 +231,7 @@ func (proxy *DataSourceProxy) director(req *http.Request) { if proxy.ds.JsonData != nil { jsonData, err = proxy.ds.JsonData.Map() if err != nil { - logger.Error("Failed to get json data as map", "jsonData", proxy.ds.JsonData, "error", err) + ctxLogger.Error("Failed to get json data as map", "jsonData", proxy.ds.JsonData, "error", err) return } } @@ -238,7 +239,7 @@ func (proxy *DataSourceProxy) director(req *http.Request) { if proxy.matchedRoute != nil { decryptedValues, err := proxy.dataSourcesService.DecryptedValues(req.Context(), proxy.ds) if err != nil { - logger.Error("Error interpolating proxy url", "error", err) + ctxLogger.Error("Error interpolating proxy url", "error", err) return } @@ -331,7 +332,8 @@ func (proxy *DataSourceProxy) logRequest() { } } - logger.Info("Proxying incoming request", + ctxLogger := logger.FromContext(proxy.ctx.Req.Context()) + ctxLogger.Info("Proxying incoming request", "userid", proxy.ctx.UserID, "orgid", proxy.ctx.OrgID, "username", proxy.ctx.Login, diff --git a/pkg/api/pluginproxy/pluginproxy.go b/pkg/api/pluginproxy/pluginproxy.go index ef8498c6097..d89c5c78a4f 100644 --- a/pkg/api/pluginproxy/pluginproxy.go +++ b/pkg/api/pluginproxy/pluginproxy.go @@ -85,7 +85,6 @@ func (proxy *PluginProxy) HandleRequest() { return } - traceID := tracing.TraceIDFromContext(proxy.ctx.Req.Context(), false) proxyErrorLogger := logger.New( "userId", proxy.ctx.UserID, "orgId", proxy.ctx.OrgID, @@ -93,7 +92,6 @@ func (proxy *PluginProxy) HandleRequest() { "path", proxy.ctx.Req.URL.Path, "remote_addr", proxy.ctx.RemoteAddr(), "referer", proxy.ctx.Req.Referer(), - "traceID", traceID, ) reverseProxy := proxyutil.NewReverseProxy( @@ -164,7 +162,7 @@ func (proxy PluginProxy) director(req *http.Request) { } if err := setBodyContent(req, proxy.matchedRoute, data); err != nil { - logger.Error("Failed to set plugin route body content", "error", err) + logger.FromContext(req.Context()).Error("Failed to set plugin route body content", "error", err) } } @@ -182,7 +180,8 @@ func (proxy PluginProxy) logRequest() { } } - logger.Info("Proxying incoming request", + ctxLogger := logger.FromContext(proxy.ctx.Req.Context()) + ctxLogger.Info("Proxying incoming request", "userid", proxy.ctx.UserID, "orgid", proxy.ctx.OrgID, "username", proxy.ctx.Login, diff --git a/pkg/infra/log/interface.go b/pkg/infra/log/interface.go index 009d4e5a39c..d753f98b736 100644 --- a/pkg/infra/log/interface.go +++ b/pkg/infra/log/interface.go @@ -1,5 +1,7 @@ package log +import "context" + type Lvl int const ( @@ -16,9 +18,18 @@ type Logger interface { Log(keyvals ...interface{}) error - // Log a message at the given level with context key/value pairs + // Debug logs a message with debug level and key/value pairs, if any. Debug(msg string, ctx ...interface{}) + + // Info logs a message with info level and key/value pairs, if any. Info(msg string, ctx ...interface{}) + + // Warn logs a message with warning level and key/value pairs, if any. Warn(msg string, ctx ...interface{}) + + // Error logs a message with error level and key/value pairs, if any. Error(msg string, ctx ...interface{}) + + // FromContext returns a new contextual Logger that has this logger's context plus the given context. + FromContext(ctx context.Context) Logger } diff --git a/pkg/infra/log/log.go b/pkg/infra/log/log.go index b74e9b91c5c..9d43d812095 100644 --- a/pkg/infra/log/log.go +++ b/pkg/infra/log/log.go @@ -5,6 +5,7 @@ package log import ( + "context" "fmt" "io" "os" @@ -31,6 +32,7 @@ var ( root *logManager now = time.Now logTimeFormat = time.RFC3339Nano + ctxLogProviders = []ContextualLogProviderFunc{} ) const ( @@ -190,6 +192,22 @@ func (cl *ConcreteLogger) log(msg string, logLevel level.Value, args ...interfac return cl.Log(append([]interface{}{level.Key(), logLevel, "msg", msg}, args...)...) } +func (cl *ConcreteLogger) FromContext(ctx context.Context) Logger { + args := []interface{}{} + + for _, p := range ctxLogProviders { + if pArgs, exists := p(ctx); exists { + args = append(args, pArgs...) + } + } + + if len(args) > 0 { + return cl.New(args...) + } + + return cl +} + func (cl *ConcreteLogger) New(ctx ...interface{}) *ConcreteLogger { if len(ctx) == 0 { root.New() @@ -243,6 +261,15 @@ func WithSuffix(ctxLogger *ConcreteLogger, ctx ...interface{}) *ConcreteLogger { return with(ctxLogger, gokitlog.WithSuffix, ctx) } +// ContextualLogProviderFunc contextual log provider function definition. +type ContextualLogProviderFunc func(ctx context.Context) ([]interface{}, bool) + +// RegisterContextualLogProvider registers a ContextualLogProviderFunc +// that will be used to provide context when Logger.FromContext is called. +func RegisterContextualLogProvider(mw ContextualLogProviderFunc) { + ctxLogProviders = append(ctxLogProviders, mw) +} + var logLevels = map[string]level.Option{ "trace": level.AllowDebug(), "debug": level.AllowDebug(), diff --git a/pkg/infra/log/log_test.go b/pkg/infra/log/log_test.go index fd7dc4090c7..18d7b06b2e0 100644 --- a/pkg/infra/log/log_test.go +++ b/pkg/infra/log/log_test.go @@ -1,6 +1,7 @@ package log import ( + "context" "fmt" "testing" "time" @@ -109,6 +110,79 @@ func TestLogger(t *testing.T) { require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger") }) }) + + newLoggerScenario(t, "Logger with contextual arguments", func(t *testing.T, sCtx *scenarioContext) { + ctx := context.Background() + rootLogger := New("root") + rootLoggerCtx := rootLogger.FromContext(ctx) + rootLoggerCtx.Debug("hello root") + childLogger := rootLogger.New("childKey", "childValue") + childLoggerCtx := childLogger.FromContext(ctx) + childLoggerCtx.Error("hello child") + + RegisterContextualLogProvider(func(ctx context.Context) ([]interface{}, bool) { + return []interface{}{"ctxKey", "ctxValue"}, true + }) + + rootLoggerCtx = rootLogger.FromContext(ctx) + rootLoggerCtx.Debug("hello contextual root") + childLoggerCtx = childLogger.FromContext(ctx) + childLoggerCtx.Error("hello contextual child") + + newRootLogger := New("root") + newRootLogger.Debug("hello root") + + require.Len(t, sCtx.loggedArgs, 5) + require.Len(t, sCtx.loggedArgs[0], 8) + require.Equal(t, "logger", sCtx.loggedArgs[0][0].(string)) + require.Equal(t, "root", sCtx.loggedArgs[0][1].(string)) + require.Equal(t, "t", sCtx.loggedArgs[0][2].(string)) + require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[0][3].(fmt.Stringer).String()) + require.Equal(t, level.Key().(string), sCtx.loggedArgs[0][4].(string)) + require.Equal(t, level.DebugValue(), sCtx.loggedArgs[0][5].(level.Value)) + require.Equal(t, "msg", sCtx.loggedArgs[0][6].(string)) + require.Equal(t, "hello root", sCtx.loggedArgs[0][7].(string)) + + require.Len(t, sCtx.loggedArgs[1], 10) + require.Equal(t, "logger", sCtx.loggedArgs[1][0].(string)) + require.Equal(t, "root", sCtx.loggedArgs[1][1].(string)) + require.Equal(t, "childKey", sCtx.loggedArgs[1][2].(string)) + require.Equal(t, "childValue", sCtx.loggedArgs[1][3].(string)) + require.Equal(t, "t", sCtx.loggedArgs[1][4].(string)) + require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[1][5].(fmt.Stringer).String()) + require.Equal(t, level.Key().(string), sCtx.loggedArgs[1][6].(string)) + require.Equal(t, level.ErrorValue(), sCtx.loggedArgs[1][7].(level.Value)) + require.Equal(t, "msg", sCtx.loggedArgs[1][8].(string)) + require.Equal(t, "hello child", sCtx.loggedArgs[1][9].(string)) + + require.Len(t, sCtx.loggedArgs[2], 10) + require.Equal(t, "logger", sCtx.loggedArgs[2][0].(string)) + require.Equal(t, "root", sCtx.loggedArgs[2][1].(string)) + require.Equal(t, "ctxKey", sCtx.loggedArgs[2][2].(string)) + require.Equal(t, "ctxValue", sCtx.loggedArgs[2][3].(string)) + require.Equal(t, "t", sCtx.loggedArgs[2][4].(string)) + require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[2][5].(fmt.Stringer).String()) + require.Equal(t, level.Key().(string), sCtx.loggedArgs[2][6].(string)) + require.Equal(t, level.DebugValue(), sCtx.loggedArgs[2][7].(level.Value)) + require.Equal(t, "msg", sCtx.loggedArgs[2][8].(string)) + require.Equal(t, "hello contextual root", sCtx.loggedArgs[2][9].(string)) + + require.Len(t, sCtx.loggedArgs[3], 12) + require.Equal(t, "logger", sCtx.loggedArgs[3][0].(string)) + require.Equal(t, "root", sCtx.loggedArgs[3][1].(string)) + require.Equal(t, "childKey", sCtx.loggedArgs[3][2].(string)) + require.Equal(t, "childValue", sCtx.loggedArgs[3][3].(string)) + require.Equal(t, "ctxKey", sCtx.loggedArgs[3][4].(string)) + require.Equal(t, "ctxValue", sCtx.loggedArgs[3][5].(string)) + require.Equal(t, "t", sCtx.loggedArgs[3][6].(string)) + require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[3][7].(fmt.Stringer).String()) + require.Equal(t, level.Key().(string), sCtx.loggedArgs[3][8].(string)) + require.Equal(t, level.ErrorValue(), sCtx.loggedArgs[3][9].(level.Value)) + require.Equal(t, "msg", sCtx.loggedArgs[3][10].(string)) + require.Equal(t, "hello contextual child", sCtx.loggedArgs[3][11].(string)) + + require.Len(t, sCtx.loggedArgs[4], 8) + }) } func TestWithPrefix(t *testing.T) { diff --git a/pkg/infra/log/logtest/fake.go b/pkg/infra/log/logtest/fake.go index a65f6789382..f6fb41115e5 100644 --- a/pkg/infra/log/logtest/fake.go +++ b/pkg/infra/log/logtest/fake.go @@ -1,6 +1,8 @@ package logtest import ( + "context" + "github.com/grafana/grafana/pkg/infra/log" ) @@ -48,3 +50,19 @@ func (f *Fake) Error(msg string, ctx ...interface{}) { f.ErrorLogs.Message = msg f.ErrorLogs.Ctx = ctx } + +func (f *Fake) DebugCtx(_ context.Context, msg string, args ...interface{}) { + f.Debug(msg, args...) +} + +func (f *Fake) InfoCtx(_ context.Context, msg string, args ...interface{}) { + f.Info(msg, args...) +} + +func (f *Fake) WarnCtx(_ context.Context, msg string, args ...interface{}) { + f.Warn(msg, args...) +} + +func (f *Fake) FromContext(_ context.Context) log.Logger { + return f.New() +} diff --git a/pkg/infra/tracing/opentelemetry_tracing.go b/pkg/infra/tracing/opentelemetry_tracing.go index bfa9dfa90b1..b51dddac107 100644 --- a/pkg/infra/tracing/opentelemetry_tracing.go +++ b/pkg/infra/tracing/opentelemetry_tracing.go @@ -278,7 +278,11 @@ func (ots *Opentelemetry) Start(ctx context.Context, spanName string, opts ...tr opentelemetrySpan := OpentelemetrySpan{ span: span, } - ctx = context.WithValue(ctx, traceKey{}, traceValue{span.SpanContext().TraceID().String(), span.SpanContext().IsSampled()}) + + if traceID := span.SpanContext().TraceID(); traceID.IsValid() { + ctx = context.WithValue(ctx, traceKey{}, traceValue{traceID.String(), span.SpanContext().IsSampled()}) + } + return ctx, opentelemetrySpan } diff --git a/pkg/infra/tracing/tracing.go b/pkg/infra/tracing/tracing.go index f78d84c563a..e125f0e501b 100644 --- a/pkg/infra/tracing/tracing.go +++ b/pkg/infra/tracing/tracing.go @@ -33,6 +33,14 @@ func ProvideService(cfg *setting.Cfg) (Tracer, error) { return nil, err } + log.RegisterContextualLogProvider(func(ctx context.Context) ([]interface{}, bool) { + if traceID := TraceIDFromContext(ctx, false); traceID != "" { + return []interface{}{"traceID", traceID}, true + } + + return nil, false + }) + if ts.enabled { return ts, ts.initJaegerGlobalTracer() } diff --git a/pkg/middleware/logger.go b/pkg/middleware/logger.go index 06abe72bcb5..321daa210d0 100644 --- a/pkg/middleware/logger.go +++ b/pkg/middleware/logger.go @@ -21,7 +21,6 @@ import ( "time" "github.com/grafana/grafana/pkg/infra/log" - "github.com/grafana/grafana/pkg/infra/tracing" "github.com/grafana/grafana/pkg/models" "github.com/grafana/grafana/pkg/services/contexthandler" "github.com/grafana/grafana/pkg/services/featuremgmt" @@ -74,11 +73,6 @@ func Logger(cfg *setting.Cfg) web.Middleware { logParams = append(logParams, "handler", handler) } - traceID := tracing.TraceIDFromContext(ctx.Req.Context(), false) - if traceID != "" { - logParams = append(logParams, "traceID", traceID) - } - if status >= 500 { ctx.Logger.Error("Request Completed", logParams...) } else { diff --git a/pkg/services/auth/auth_token.go b/pkg/services/auth/auth_token.go index f2b7c44eaae..d9c516482dc 100644 --- a/pkg/services/auth/auth_token.go +++ b/pkg/services/auth/auth_token.go @@ -109,7 +109,8 @@ func (s *UserAuthTokenService) CreateToken(ctx context.Context, user *user.User, userAuthToken.UnhashedToken = token - s.log.Debug("user auth token created", "tokenId", userAuthToken.Id, "userId", userAuthToken.UserId, "clientIP", userAuthToken.ClientIp, "userAgent", userAuthToken.UserAgent, "authToken", userAuthToken.AuthToken) + ctxLogger := s.log.FromContext(ctx) + ctxLogger.Debug("user auth token created", "tokenId", userAuthToken.Id, "userId", userAuthToken.UserId, "clientIP", userAuthToken.ClientIp, "userAgent", userAuthToken.UserAgent, "authToken", userAuthToken.AuthToken) var userToken models.UserToken err = userAuthToken.toUserToken(&userToken) @@ -138,8 +139,10 @@ func (s *UserAuthTokenService) LookupToken(ctx context.Context, unhashedToken st return nil, models.ErrUserTokenNotFound } + ctxLogger := s.log.FromContext(ctx) + if model.RevokedAt > 0 { - s.log.Debug("user token has been revoked", "user ID", model.UserId, "token ID", model.Id) + ctxLogger.Debug("user token has been revoked", "user ID", model.UserId, "token ID", model.Id) return nil, &models.TokenRevokedError{ UserID: model.UserId, TokenID: model.Id, @@ -147,7 +150,7 @@ func (s *UserAuthTokenService) LookupToken(ctx context.Context, unhashedToken st } if model.CreatedAt <= s.createdAfterParam() || model.RotatedAt <= s.rotatedAfterParam() { - s.log.Debug("user token has expired", "user ID", model.UserId, "token ID", model.Id) + ctxLogger.Debug("user token has expired", "user ID", model.UserId, "token ID", model.Id) return nil, &models.TokenExpiredError{ UserID: model.UserId, TokenID: model.Id, @@ -175,9 +178,9 @@ func (s *UserAuthTokenService) LookupToken(ctx context.Context, unhashedToken st } if affectedRows == 0 { - s.log.Debug("prev seen token unchanged", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) + ctxLogger.Debug("prev seen token unchanged", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) } else { - s.log.Debug("prev seen token", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) + ctxLogger.Debug("prev seen token", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) } } @@ -205,9 +208,9 @@ func (s *UserAuthTokenService) LookupToken(ctx context.Context, unhashedToken st } if affectedRows == 0 { - s.log.Debug("seen wrong token", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) + ctxLogger.Debug("seen wrong token", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) } else { - s.log.Debug("seen token", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) + ctxLogger.Debug("seen token", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "authToken", model.AuthToken) } } @@ -244,7 +247,8 @@ func (s *UserAuthTokenService) TryRotateToken(ctx context.Context, token *models return false, nil } - s.log.Debug("token needs rotation", "tokenId", model.Id, "authTokenSeen", model.AuthTokenSeen, "rotatedAt", rotatedAt) + ctxLogger := s.log.FromContext(ctx) + ctxLogger.Debug("token needs rotation", "tokenId", model.Id, "authTokenSeen", model.AuthTokenSeen, "rotatedAt", rotatedAt) clientIPStr := clientIP.String() if len(clientIP) == 0 { @@ -286,7 +290,7 @@ func (s *UserAuthTokenService) TryRotateToken(ctx context.Context, token *models return false, err } - s.log.Debug("auth token rotated", "affected", affected, "auth_token_id", model.Id, "userId", model.UserId) + ctxLogger.Debug("auth token rotated", "affected", affected, "auth_token_id", model.Id, "userId", model.UserId) if affected > 0 { model.UnhashedToken = newToken if err := model.toUserToken(token); err != nil { @@ -327,12 +331,14 @@ func (s *UserAuthTokenService) RevokeToken(ctx context.Context, token *models.Us return err } + ctxLogger := s.log.FromContext(ctx) + if rowsAffected == 0 { - s.log.Debug("user auth token not found/revoked", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent) + ctxLogger.Debug("user auth token not found/revoked", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent) return models.ErrUserTokenNotFound } - s.log.Debug("user auth token revoked", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "soft", soft) + ctxLogger.Debug("user auth token revoked", "tokenId", model.Id, "userId", model.UserId, "clientIP", model.ClientIp, "userAgent", model.UserAgent, "soft", soft) return nil } @@ -350,7 +356,7 @@ func (s *UserAuthTokenService) RevokeAllUserTokens(ctx context.Context, userId i return err } - s.log.Debug("all user tokens for user revoked", "userId", userId, "count", affected) + s.log.FromContext(ctx).Debug("all user tokens for user revoked", "userId", userId, "count", affected) return err }) @@ -380,7 +386,7 @@ func (s *UserAuthTokenService) BatchRevokeAllUserTokens(ctx context.Context, use return err } - s.log.Debug("all user tokens for given users revoked", "usersCount", len(userIds), "count", affected) + s.log.FromContext(ctx).Debug("all user tokens for given users revoked", "usersCount", len(userIds), "count", affected) return err }) diff --git a/pkg/services/sqlstore/database_wrapper.go b/pkg/services/sqlstore/database_wrapper.go index dbcb7674a57..279e0e122f6 100644 --- a/pkg/services/sqlstore/database_wrapper.go +++ b/pkg/services/sqlstore/database_wrapper.go @@ -104,7 +104,8 @@ func (h *databaseQueryWrapper) instrument(ctx context.Context, status string, qu span.AddEvents([]string{"error"}, []tracing.EventValue{{Str: err.Error()}}) } - h.log.Debug("query finished", "status", status, "elapsed time", elapsed, "sql", query, "error", err) + ctxLogger := h.log.FromContext(ctx) + ctxLogger.Debug("query finished", "status", status, "elapsed time", elapsed, "sql", query, "error", err) } // OnError will be called if any error happens diff --git a/pkg/services/sqlstore/session.go b/pkg/services/sqlstore/session.go index 4a8d27367eb..20b31043fa6 100644 --- a/pkg/services/sqlstore/session.go +++ b/pkg/services/sqlstore/session.go @@ -47,7 +47,8 @@ func startSessionOrUseExisting(ctx context.Context, engine *xorm.Engine, beginTr sess, ok := value.(*DBSession) if ok { - sessionLogger.Debug("reusing existing session", "transaction", sess.transactionOpen) + ctxLogger := sessionLogger.FromContext(ctx) + ctxLogger.Debug("reusing existing session", "transaction", sess.transactionOpen) sess.Session = sess.Session.Context(ctx) return sess, false, nil } diff --git a/pkg/services/sqlstore/transactions.go b/pkg/services/sqlstore/transactions.go index c82029362c2..baf3efd2c94 100644 --- a/pkg/services/sqlstore/transactions.go +++ b/pkg/services/sqlstore/transactions.go @@ -48,8 +48,10 @@ func inTransactionWithRetryCtx(ctx context.Context, engine *xorm.Engine, bus bus err = callback(sess) + ctxLogger := tsclogger.FromContext(ctx) + if !isNew { - tsclogger.Debug("skip committing the transaction because it belongs to a session created in the outer scope") + ctxLogger.Debug("skip committing the transaction because it belongs to a session created in the outer scope") // Do not commit the transaction if the session was reused. return err } @@ -62,7 +64,7 @@ func inTransactionWithRetryCtx(ctx context.Context, engine *xorm.Engine, bus bus } time.Sleep(time.Millisecond * time.Duration(10)) - sqlog.Info("Database locked, sleeping then retrying", "error", err, "retry", retry) + ctxLogger.Info("Database locked, sleeping then retrying", "error", err, "retry", retry) return inTransactionWithRetryCtx(ctx, engine, bus, callback, retry+1) } @@ -79,7 +81,7 @@ func inTransactionWithRetryCtx(ctx context.Context, engine *xorm.Engine, bus bus if len(sess.events) > 0 { for _, e := range sess.events { if err = bus.Publish(ctx, e); err != nil { - tsclogger.Error("Failed to publish event after commit.", "error", err) + ctxLogger.Error("Failed to publish event after commit.", "error", err) } } } diff --git a/pkg/tests/api/alerting/api_alertmanager_test.go b/pkg/tests/api/alerting/api_alertmanager_test.go index 1fbc16b9e01..4068a53b89d 100644 --- a/pkg/tests/api/alerting/api_alertmanager_test.go +++ b/pkg/tests/api/alerting/api_alertmanager_test.go @@ -1075,7 +1075,6 @@ func TestAlertRuleCRUD(t *testing.T) { require.NoError(t, err) assert.Equal(t, res.Message, tc.expectedMessage) - assert.NotEmpty(t, res.TraceID) assert.Equal(t, http.StatusBadRequest, status) }) @@ -2330,7 +2329,6 @@ func TestEval(t *testing.T) { } if tc.expectedMessage() != "" { assert.Equal(t, tc.expectedMessage(), res.Message) - assert.NotEmpty(t, res.TraceID) } }) } @@ -2513,7 +2511,6 @@ func TestEval(t *testing.T) { } if tc.expectedMessage() != "" { require.Equal(t, tc.expectedMessage(), res.Message) - require.NotEmpty(t, res.TraceID) } }) } diff --git a/pkg/tests/api/alerting/api_notification_channel_test.go b/pkg/tests/api/alerting/api_notification_channel_test.go index 93722898c81..b49295b3717 100644 --- a/pkg/tests/api/alerting/api_notification_channel_test.go +++ b/pkg/tests/api/alerting/api_notification_channel_test.go @@ -63,7 +63,6 @@ func TestTestReceivers(t *testing.T) { res := Response{} err = json.Unmarshal(b, &res) require.NoError(t, err) - require.NotEmpty(t, res.TraceID) }) t.Run("assert working receiver returns OK", func(t *testing.T) { diff --git a/pkg/util/proxyutil/reverse_proxy.go b/pkg/util/proxyutil/reverse_proxy.go index 3ce5d3b4011..58969dc29ee 100644 --- a/pkg/util/proxyutil/reverse_proxy.go +++ b/pkg/util/proxyutil/reverse_proxy.go @@ -96,20 +96,22 @@ type timeoutError interface { // If any other error we return http.StatusBadGateway. func errorHandler(logger glog.Logger) func(http.ResponseWriter, *http.Request, error) { return func(w http.ResponseWriter, r *http.Request, err error) { + ctxLogger := logger.FromContext(r.Context()) + if errors.Is(err, context.Canceled) { - logger.Debug("Proxy request cancelled by client") + ctxLogger.Debug("Proxy request cancelled by client") w.WriteHeader(StatusClientClosedRequest) return } // nolint:errorlint if timeoutErr, ok := err.(timeoutError); ok && timeoutErr.Timeout() { - logger.Error("Proxy request timed out", "err", err) + ctxLogger.Error("Proxy request timed out", "err", err) w.WriteHeader(http.StatusGatewayTimeout) return } - logger.Error("Proxy request failed", "err", err) + ctxLogger.Error("Proxy request failed", "err", err) w.WriteHeader(http.StatusBadGateway) } }