Add service tag to logs

This commit is contained in:
Taras Kushnir
2025-09-12 14:14:32 +03:00
parent 74ea495ce9
commit cfbc134a2d
9 changed files with 52 additions and 25 deletions

View File

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

View File

@@ -12,6 +12,7 @@ const (
SecretContextKey
RateLimitKeyContextKey
SessionIDContextKey
ServiceContextKey
TimeContextKey
// Add new fields _above_
CONTEXT_KEYS_COUNT

View File

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

View File

@@ -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

View File

@@ -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) {

View File

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

View File

@@ -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 {

View File

@@ -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 {

View File

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