From 687ff60d611a1b81875893f91542cb855be2057e Mon Sep 17 00:00:00 2001 From: Asher Date: Wed, 19 Nov 2025 15:14:03 -0900 Subject: [PATCH] chore: add debug logging and recovery to agent api --- agent/api.go | 8 ++ coderd/coderd.go | 3 +- coderd/httpmw/loggermw/logger.go | 87 ++---------------- coderd/httpmw/loggermw/logger_full.go | 88 +++++++++++++++++++ .../httpmw/loggermw/logger_internal_test.go | 26 ++++++ coderd/httpmw/loggermw/logger_slim.go | 26 ++++++ enterprise/wsproxy/wsproxy.go | 3 +- {coderd/httpmw => httpmw}/recover.go | 0 {coderd/httpmw => httpmw}/recover_test.go | 2 +- 9 files changed, 162 insertions(+), 81 deletions(-) create mode 100644 coderd/httpmw/loggermw/logger_full.go create mode 100644 coderd/httpmw/loggermw/logger_slim.go rename {coderd/httpmw => httpmw}/recover.go (100%) rename {coderd/httpmw => httpmw}/recover_test.go (96%) diff --git a/agent/api.go b/agent/api.go index f417a046c24a6..b426272a7fe8d 100644 --- a/agent/api.go +++ b/agent/api.go @@ -9,11 +9,19 @@ import ( "github.com/google/uuid" "github.com/coder/coder/v2/coderd/httpapi" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" + "github.com/coder/coder/v2/coderd/tracing" "github.com/coder/coder/v2/codersdk" + "github.com/coder/coder/v2/httpmw" ) func (a *agent) apiHandler() http.Handler { r := chi.NewRouter() + r.Use( + httpmw.Recover(a.logger), + tracing.StatusWriterMiddleware, + loggermw.Logger(a.logger), + ) r.Get("/", func(rw http.ResponseWriter, r *http.Request) { httpapi.Write(r.Context(), rw, http.StatusOK, codersdk.Response{ Message: "Hello from the agent!", diff --git a/coderd/coderd.go b/coderd/coderd.go index a9683ace20004..ae55b50894ad7 100644 --- a/coderd/coderd.go +++ b/coderd/coderd.go @@ -99,6 +99,7 @@ import ( "github.com/coder/coder/v2/coderd/workspacestats" "github.com/coder/coder/v2/codersdk" "github.com/coder/coder/v2/codersdk/healthsdk" + sharedhttpmw "github.com/coder/coder/v2/httpmw" "github.com/coder/coder/v2/provisionersdk" "github.com/coder/coder/v2/site" "github.com/coder/coder/v2/tailnet" @@ -860,7 +861,7 @@ func New(options *Options) *API { prometheusMW := httpmw.Prometheus(options.PrometheusRegistry) r.Use( - httpmw.Recover(api.Logger), + sharedhttpmw.Recover(api.Logger), httpmw.WithProfilingLabels, tracing.StatusWriterMiddleware, tracing.Middleware(api.TracerProvider), diff --git a/coderd/httpmw/loggermw/logger.go b/coderd/httpmw/loggermw/logger.go index 37e15b3bfcf81..edd878efa9825 100644 --- a/coderd/httpmw/loggermw/logger.go +++ b/coderd/httpmw/loggermw/logger.go @@ -7,19 +7,17 @@ import ( "net/url" "strconv" "strings" - "sync" "time" "github.com/go-chi/chi/v5" "cdr.dev/slog" "github.com/coder/coder/v2/coderd/httpapi" - "github.com/coder/coder/v2/coderd/rbac" "github.com/coder/coder/v2/coderd/tracing" ) var ( - safeParams = []string{"page", "limit", "offset"} + safeParams = []string{"page", "limit", "offset", "path"} countParams = []string{"ids", "template_ids"} ) @@ -124,85 +122,18 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler { } } -type RequestLogger interface { - WithFields(fields ...slog.Field) - WriteLog(ctx context.Context, status int) - WithAuthContext(actor rbac.Subject) -} - type SlogRequestLogger struct { - log slog.Logger - written bool - message string - start time.Time - // Protects actors map for concurrent writes. - mu sync.RWMutex - actors map[rbac.SubjectType]rbac.Subject -} - -var _ RequestLogger = &SlogRequestLogger{} - -func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger { - return &SlogRequestLogger{ - log: log, - written: false, - message: message, - start: start, - actors: make(map[rbac.SubjectType]rbac.Subject), - } + log slog.Logger + written bool + message string + start time.Time + addFields func() } func (c *SlogRequestLogger) WithFields(fields ...slog.Field) { c.log = c.log.With(fields...) } -func (c *SlogRequestLogger) WithAuthContext(actor rbac.Subject) { - c.mu.Lock() - defer c.mu.Unlock() - c.actors[actor.Type] = actor -} - -func (c *SlogRequestLogger) addAuthContextFields() { - c.mu.RLock() - defer c.mu.RUnlock() - - usr, ok := c.actors[rbac.SubjectTypeUser] - if ok { - c.log = c.log.With( - slog.F("requestor_id", usr.ID), - slog.F("requestor_name", usr.FriendlyName), - slog.F("requestor_email", usr.Email), - ) - } else { - // If there is no user, we log the requestor name for the first - // actor in a defined order. - for _, v := range actorLogOrder { - subj, ok := c.actors[v] - if !ok { - continue - } - c.log = c.log.With( - slog.F("requestor_name", subj.FriendlyName), - ) - break - } - } -} - -var actorLogOrder = []rbac.SubjectType{ - rbac.SubjectTypeAutostart, - rbac.SubjectTypeCryptoKeyReader, - rbac.SubjectTypeCryptoKeyRotator, - rbac.SubjectTypeJobReaper, - rbac.SubjectTypeNotifier, - rbac.SubjectTypePrebuildsOrchestrator, - rbac.SubjectTypeSubAgentAPI, - rbac.SubjectTypeProvisionerd, - rbac.SubjectTypeResourceMonitor, - rbac.SubjectTypeSystemReadProvisionerDaemons, - rbac.SubjectTypeSystemRestricted, -} - func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) { if c.written { return @@ -210,9 +141,9 @@ func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) { c.written = true end := time.Now() - // Right before we write the log, we try to find the user in the actors - // and add the fields to the log. - c.addAuthContextFields() + if c.addFields != nil { + c.addFields() + } logger := c.log.With( slog.F("took", end.Sub(c.start)), diff --git a/coderd/httpmw/loggermw/logger_full.go b/coderd/httpmw/loggermw/logger_full.go new file mode 100644 index 0000000000000..8240289c50177 --- /dev/null +++ b/coderd/httpmw/loggermw/logger_full.go @@ -0,0 +1,88 @@ +//go:build !slim + +package loggermw + +import ( + "context" + "sync" + "time" + + "cdr.dev/slog" + "github.com/coder/coder/v2/coderd/rbac" +) + +type RequestLogger interface { + WithFields(fields ...slog.Field) + WriteLog(ctx context.Context, status int) + WithAuthContext(actor rbac.Subject) +} + +type RbacSlogRequestLogger struct { + SlogRequestLogger + // Protects actors map for concurrent writes. + mu sync.RWMutex + actors map[rbac.SubjectType]rbac.Subject +} + +var _ RequestLogger = &RbacSlogRequestLogger{} + +func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger { + rlogger := &RbacSlogRequestLogger{ + SlogRequestLogger: SlogRequestLogger{ + log: log, + written: false, + message: message, + start: start, + }, + actors: make(map[rbac.SubjectType]rbac.Subject), + } + rlogger.addFields = rlogger.addAuthContextFields + return rlogger +} + +func (c *RbacSlogRequestLogger) WithAuthContext(actor rbac.Subject) { + c.mu.Lock() + defer c.mu.Unlock() + c.actors[actor.Type] = actor +} + +var actorLogOrder = []rbac.SubjectType{ + rbac.SubjectTypeAutostart, + rbac.SubjectTypeCryptoKeyReader, + rbac.SubjectTypeCryptoKeyRotator, + rbac.SubjectTypeJobReaper, + rbac.SubjectTypeNotifier, + rbac.SubjectTypePrebuildsOrchestrator, + rbac.SubjectTypeSubAgentAPI, + rbac.SubjectTypeProvisionerd, + rbac.SubjectTypeResourceMonitor, + rbac.SubjectTypeSystemReadProvisionerDaemons, + rbac.SubjectTypeSystemRestricted, +} + +func (c *RbacSlogRequestLogger) addAuthContextFields() { + c.mu.RLock() + defer c.mu.RUnlock() + + usr, ok := c.actors[rbac.SubjectTypeUser] + if ok { + c.log = c.log.With( + slog.F("requestor_id", usr.ID), + slog.F("requestor_name", usr.FriendlyName), + slog.F("requestor_email", usr.Email), + ) + } else { + // If there is no user, we log the requestor name for the first + // actor in a defined order. + for _, v := range actorLogOrder { + subj, ok := c.actors[v] + if !ok { + continue + } + c.log = c.log.With( + slog.F("requestor_name", subj.FriendlyName), + ) + break + } + } +} diff --git a/coderd/httpmw/loggermw/logger_internal_test.go b/coderd/httpmw/loggermw/logger_internal_test.go index bf090464241a0..5f22de7477d92 100644 --- a/coderd/httpmw/loggermw/logger_internal_test.go +++ b/coderd/httpmw/loggermw/logger_internal_test.go @@ -16,6 +16,7 @@ import ( "github.com/stretchr/testify/require" "cdr.dev/slog" + "github.com/coder/coder/v2/coderd/rbac" "github.com/coder/coder/v2/coderd/tracing" "github.com/coder/coder/v2/testutil" "github.com/coder/websocket" @@ -363,6 +364,31 @@ func TestSafeQueryParams(t *testing.T) { } } +func TestRequestLogger_AuthContext(t *testing.T) { + t.Parallel() + ctx := context.Background() + + sink := &fakeSink{} + logger := slog.Make(sink) + logger = logger.Leveled(slog.LevelDebug) + logCtx := NewRequestLogger(logger, "GET", time.Now()) + + logCtx.WithAuthContext(rbac.Subject{ + ID: "test-user-id", + FriendlyName: "test name", + Email: "test@coder.com", + Type: rbac.SubjectTypeUser, + }) + + logCtx.WriteLog(ctx, http.StatusOK) + + require.Len(t, sink.entries, 1, "log was written twice") + require.Equal(t, sink.entries[0].Message, "GET") + require.Equal(t, sink.entries[0].Fields[0].Value, "test-user-id") + require.Equal(t, sink.entries[0].Fields[1].Value, "test name") + require.Equal(t, sink.entries[0].Fields[2].Value, "test@coder.com") +} + type fakeSink struct { entries []slog.SinkEntry newEntries chan slog.SinkEntry diff --git a/coderd/httpmw/loggermw/logger_slim.go b/coderd/httpmw/loggermw/logger_slim.go new file mode 100644 index 0000000000000..36470265e50df --- /dev/null +++ b/coderd/httpmw/loggermw/logger_slim.go @@ -0,0 +1,26 @@ +//go:build slim + +package loggermw + +import ( + "context" + "time" + + "cdr.dev/slog" +) + +type RequestLogger interface { + WithFields(fields ...slog.Field) + WriteLog(ctx context.Context, status int) +} + +var _ RequestLogger = &SlogRequestLogger{} + +func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger { + return &SlogRequestLogger{ + log: log, + written: false, + message: message, + start: start, + } +} diff --git a/enterprise/wsproxy/wsproxy.go b/enterprise/wsproxy/wsproxy.go index 734f6b2b594c8..ecd5df9cde17a 100644 --- a/enterprise/wsproxy/wsproxy.go +++ b/enterprise/wsproxy/wsproxy.go @@ -39,6 +39,7 @@ import ( "github.com/coder/coder/v2/enterprise/derpmesh" "github.com/coder/coder/v2/enterprise/replicasync" "github.com/coder/coder/v2/enterprise/wsproxy/wsproxysdk" + sharedhttpmw "github.com/coder/coder/v2/httpmw" "github.com/coder/coder/v2/site" "github.com/coder/coder/v2/tailnet" ) @@ -328,7 +329,7 @@ func New(ctx context.Context, opts *Options) (*Server, error) { // Persistent middlewares to all routes r.Use( // TODO: @emyrk Should we standardize these in some other package? - httpmw.Recover(s.Logger), + sharedhttpmw.Recover(s.Logger), httpmw.WithProfilingLabels, tracing.StatusWriterMiddleware, tracing.Middleware(s.TracerProvider), diff --git a/coderd/httpmw/recover.go b/httpmw/recover.go similarity index 100% rename from coderd/httpmw/recover.go rename to httpmw/recover.go diff --git a/coderd/httpmw/recover_test.go b/httpmw/recover_test.go similarity index 96% rename from coderd/httpmw/recover_test.go rename to httpmw/recover_test.go index d4d4227ff15ef..89c6140d02070 100644 --- a/coderd/httpmw/recover_test.go +++ b/httpmw/recover_test.go @@ -7,8 +7,8 @@ import ( "github.com/stretchr/testify/require" - "github.com/coder/coder/v2/coderd/httpmw" "github.com/coder/coder/v2/coderd/tracing" + "github.com/coder/coder/v2/httpmw" "github.com/coder/coder/v2/testutil" )