diff --git a/pkg/api/server.go b/pkg/api/server.go index 9d27ba5d..0eaad24c 100644 --- a/pkg/api/server.go +++ b/pkg/api/server.go @@ -168,7 +168,8 @@ func (s *Server) Shutdown() { func (s *Server) setupWithPrefix(domain string, router *http.ServeMux, corsHandler, security alice.Constructor) { prefix := domain + "/" slog.Debug("Setting up the API routes", "prefix", prefix) - publicChain := alice.New(common.Recovered, security, s.Metrics.Handler) + svc := common.ServiceMiddleware("api") + publicChain := alice.New(svc, common.Recovered, security, s.Metrics.Handler) // NOTE: auth middleware provides rate limiting internally puzzleChain := publicChain.Append(s.RateLimiter.RateLimit, monitoring.Traced, common.TimeoutHandler(1*time.Second)) router.Handle(http.MethodGet+" "+prefix+common.PuzzleEndpoint, puzzleChain.Append(corsHandler, s.Auth.Sitekey).ThenFunc(s.puzzleHandler)) diff --git a/pkg/common/context.go b/pkg/common/context.go index ba299b8c..54e7049e 100644 --- a/pkg/common/context.go +++ b/pkg/common/context.go @@ -12,6 +12,7 @@ const ( SecretContextKey RateLimitKeyContextKey SessionIDContextKey + ServiceContextKey TimeContextKey // Add new fields _above_ CONTEXT_KEYS_COUNT diff --git a/pkg/common/job.go b/pkg/common/job.go index 57ddee49..62d49fbe 100644 --- a/pkg/common/job.go +++ b/pkg/common/job.go @@ -37,23 +37,23 @@ func (StubOneOffJob) NewParams() any { return struct{}{} } func (StubOneOffJob) RunOnce(context.Context, any) error { return nil } func RunOneOffJob(ctx context.Context, j OneOffJob, params any) { - jlog := slog.With("name", j.Name()) + ctx = context.WithValue(ctx, TraceIDContextKey, j.Name()) defer func() { if rvr := recover(); rvr != nil { - jlog.ErrorContext(ctx, "One-off job crashed", "panic", rvr, "stack", string(debug.Stack())) + slog.ErrorContext(ctx, "One-off job crashed", "panic", rvr, "stack", string(debug.Stack())) } }() time.Sleep(j.InitialPause()) - jlog.DebugContext(ctx, "Running one-off job") + slog.DebugContext(ctx, "Running one-off job") if err := j.RunOnce(ctx, params); err != nil { - jlog.ErrorContext(ctx, "One-off job failed", ErrAttr(err)) + slog.ErrorContext(ctx, "One-off job failed", ErrAttr(err)) } - jlog.DebugContext(ctx, "One-off job finished") + slog.DebugContext(ctx, "One-off job finished") } // safe wrapper (with recover()) over `go f()` @@ -74,15 +74,15 @@ func RunAdHocFunc(ctx context.Context, f func(ctx context.Context) error) { } func RunPeriodicJob(ctx context.Context, j PeriodicJob) { - jlog := slog.With("name", j.Name()) + ctx = context.WithValue(ctx, TraceIDContextKey, j.Name()) defer func() { if rvr := recover(); rvr != nil { - jlog.ErrorContext(ctx, "Periodic job crashed", "panic", rvr, "stack", string(debug.Stack())) + slog.ErrorContext(ctx, "Periodic job crashed", "panic", rvr, "stack", string(debug.Stack())) } }() - jlog.DebugContext(ctx, "Starting periodic job") + slog.DebugContext(ctx, "Starting periodic job") for running := true; running; { interval := j.Interval() @@ -93,27 +93,27 @@ func RunPeriodicJob(ctx context.Context, j PeriodicJob) { running = false // introduction of jitter is supposed to help in case we have multiple workers to distribute the load case <-time.After(interval + time.Duration(randv2.Int64N(int64(jitter)))): - jlog.Log(ctx, LevelTrace, "Running periodic job once", "interval", interval.String(), "jitter", jitter.String()) + slog.Log(ctx, LevelTrace, "Running periodic job once", "interval", interval.String(), "jitter", jitter.String()) _ = j.RunOnce(ctx, j.NewParams()) } } - jlog.DebugContext(ctx, "Periodic job finished") + slog.DebugContext(ctx, "Periodic job finished") } func RunPeriodicJobOnce(ctx context.Context, j PeriodicJob, params any) error { - jlog := slog.With("name", j.Name()) + ctx = context.WithValue(ctx, TraceIDContextKey, j.Name()) defer func() { if rvr := recover(); rvr != nil { - jlog.ErrorContext(ctx, "Periodic job crashed", "panic", rvr, "stack", string(debug.Stack())) + slog.ErrorContext(ctx, "Periodic job crashed", "panic", rvr, "stack", string(debug.Stack())) } }() - jlog.Log(ctx, LevelTrace, "Running periodic job once") + slog.Log(ctx, LevelTrace, "Running periodic job once") err := j.RunOnce(ctx, params) if err != nil { - jlog.ErrorContext(ctx, "Periodic job failed", ErrAttr(err)) + slog.ErrorContext(ctx, "Periodic job failed", ErrAttr(err)) } return err } diff --git a/pkg/common/log.go b/pkg/common/log.go index ee68ccf1..70d7eb92 100644 --- a/pkg/common/log.go +++ b/pkg/common/log.go @@ -25,6 +25,10 @@ func (h *contextHandler) Handle(ctx context.Context, r slog.Record) error { if sid, ok := ctx.Value(SessionIDContextKey).(string); ok && (len(sid) > 0) { r.AddAttrs(SessionIDAttr(sid)) } + + if svc, ok := ctx.Value(ServiceContextKey).(string); ok && (len(svc) > 0) { + r.AddAttrs(ServiceAttr(svc)) + } } return h.Handler.Handle(ctx, r) @@ -130,6 +134,13 @@ func SessionIDAttr(sid string) slog.Attr { } } +func ServiceAttr(svc string) slog.Attr { + return slog.Attr{ + Key: "service", + Value: slog.StringValue(svc), + } +} + type FmtLogger struct { Ctx context.Context Level slog.Level diff --git a/pkg/common/middlewares.go b/pkg/common/middlewares.go index 7f47b330..b5a9d140 100644 --- a/pkg/common/middlewares.go +++ b/pkg/common/middlewares.go @@ -64,6 +64,15 @@ func Recovered(next http.Handler) http.Handler { }) } +func ServiceMiddleware(svc string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + r = r.WithContext(context.WithValue(r.Context(), ServiceContextKey, svc)) + next.ServeHTTP(w, r) + }) + } +} + func TimeoutHandler(timeout time.Duration) func(next http.Handler) http.Handler { return func(next http.Handler) http.Handler { h := func(w http.ResponseWriter, r *http.Request) { diff --git a/pkg/db/utils.go b/pkg/db/utils.go index ecb140cb..d21ad987 100644 --- a/pkg/db/utils.go +++ b/pkg/db/utils.go @@ -327,6 +327,7 @@ func (sf *StoreArrayReader[TKey, T]) Read(ctx context.Context) ([]*T, error) { } if t, ok := data.([]*T); ok { + slog.Log(ctx, common.LevelTrace, "Found array in cache", "key", sf.Key, "count", len(t)) return t, nil } diff --git a/pkg/maintenance/jobs.go b/pkg/maintenance/jobs.go index c16d997a..f2671edd 100644 --- a/pkg/maintenance/jobs.go +++ b/pkg/maintenance/jobs.go @@ -22,7 +22,7 @@ func NewJobs(store db.Implementor) *jobs { } j.maintenanceCtx, j.maintenanceCancel = context.WithCancel( - context.WithValue(context.Background(), common.TraceIDContextKey, "maintenance")) + context.WithValue(context.Background(), common.ServiceContextKey, "maintenance")) return j } @@ -86,9 +86,11 @@ func (j *jobs) UpdateConfig(cfg common.ConfigStore) { func (j *jobs) Setup(mux *http.ServeMux, cfg common.ConfigStore) { j.apiKey = cfg.Get(common.LocalAPIKeyKey).Value() + svc := common.ServiceMiddleware("local") + const maxBytes = 256 * 1024 - mux.Handle(http.MethodPost+" /maintenance/periodic/{job}", common.Recovered(http.MaxBytesHandler(j.security(http.HandlerFunc(j.handlePeriodicJob)), maxBytes))) - mux.Handle(http.MethodPost+" /maintenance/oneoff/{job}", common.Recovered(http.MaxBytesHandler(j.security(http.HandlerFunc(j.handleOneoffJob)), maxBytes))) + mux.Handle(http.MethodPost+" /maintenance/periodic/{job}", svc(common.Recovered(http.MaxBytesHandler(j.security(http.HandlerFunc(j.handlePeriodicJob)), maxBytes)))) + mux.Handle(http.MethodPost+" /maintenance/oneoff/{job}", svc(common.Recovered(http.MaxBytesHandler(j.security(http.HandlerFunc(j.handleOneoffJob)), maxBytes)))) } func (j *jobs) security(next http.Handler) http.Handler { diff --git a/pkg/portal/server.go b/pkg/portal/server.go index 3aeb0393..63d4e4dc 100644 --- a/pkg/portal/server.go +++ b/pkg/portal/server.go @@ -207,8 +207,9 @@ func (s *Server) MiddlewarePublicChain(rg *RouteGenerator, security alice.Constr ) ratelimiter := s.RateLimiter.RateLimitExFunc(defaultLeakyBucketCap, defaultLeakInterval) + svc := common.ServiceMiddleware("portal") - return alice.New(common.Recovered, security, s.Metrics.HandlerIDFunc(rg.LastPath), ratelimiter, monitoring.Logged) + return alice.New(svc, common.Recovered, security, s.Metrics.HandlerIDFunc(rg.LastPath), ratelimiter, monitoring.Logged) } func (s *Server) MiddlewarePrivateRead(public alice.Chain) alice.Chain { diff --git a/pkg/session/manager.go b/pkg/session/manager.go index a30b0a48..72fd6cd7 100644 --- a/pkg/session/manager.go +++ b/pkg/session/manager.go @@ -31,7 +31,7 @@ func (m *Manager) SessionStart(w http.ResponseWriter, r *http.Request) (session sid := m.sessionID() session = common.NewSession(sid, m.Store) if err = m.Store.Init(ctx, session); err != nil { - slog.ErrorContext(ctx, "Failed to register session", "sid", sid, common.ErrAttr(err)) + slog.ErrorContext(ctx, "Failed to register session", common.SessionIDAttr(sid), common.ErrAttr(err)) } cookie := http.Cookie{ Name: m.CookieName, @@ -45,16 +45,17 @@ func (m *Manager) SessionStart(w http.ResponseWriter, r *http.Request) (session w.Header().Add("Cache-Control", `no-cache="Set-Cookie"`) } else { sid, _ := url.QueryUnescape(cookie.Value) - slog.Log(ctx, common.LevelTrace, "Session cookie found in the request", "sid", sid, "path", r.URL.Path, "method", r.Method) + sslog := slog.With(common.SessionIDAttr(sid)) + sslog.Log(ctx, common.LevelTrace, "Session cookie found in the request", "path", r.URL.Path, "method", r.Method) session, err = m.Store.Read(ctx, sid) if err == common.ErrSessionMissing { - slog.WarnContext(ctx, "Session from cookie is missing", "sid", sid) + sslog.WarnContext(ctx, "Session from cookie is missing") session = common.NewSession(sid, m.Store) if err = m.Store.Init(ctx, session); err != nil { - slog.ErrorContext(ctx, "Failed to register session with existing cookie", "sid", sid, common.ErrAttr(err)) + sslog.ErrorContext(ctx, "Failed to register session with existing cookie", common.ErrAttr(err)) } } else if err != nil { - slog.ErrorContext(ctx, "Failed to read session from store", common.ErrAttr(err)) + sslog.ErrorContext(ctx, "Failed to read session from store", common.ErrAttr(err)) } } return @@ -67,7 +68,7 @@ func (m *Manager) SessionDestroy(w http.ResponseWriter, r *http.Request) { return } else { ctx := r.Context() - slog.Log(ctx, common.LevelTrace, "Session cookie found in the request", "sid", cookie.Value, "path", r.URL.Path, "method", r.Method) + slog.Log(ctx, common.LevelTrace, "Session cookie found in the request", common.SessionIDAttr(cookie.Value), "path", r.URL.Path, "method", r.Method) if err := m.Store.Destroy(ctx, cookie.Value); err != nil { slog.ErrorContext(ctx, "Failed to delete session from storage", common.ErrAttr(err)) }