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) } }