From 54cfb3a1d6f58a21ec5796c44774f5cee11f816e Mon Sep 17 00:00:00 2001 From: Michael Suchacz <203725896+ibetitsmike@users.noreply.github.com> Date: Tue, 8 Apr 2025 10:30:05 +0200 Subject: [PATCH 1/2] feat: log long-lived connections acceptance (#17219) Closes #16904 --- Makefile | 9 +- coderd/httpmw/logger.go | 97 +++++++++---- coderd/httpmw/logger_internal_test.go | 174 ++++++++++++++++++++++++ coderd/httpmw/loggermock/loggermock.go | 70 ++++++++++ coderd/provisionerjobs.go | 3 + coderd/provisionerjobs_internal_test.go | 7 + coderd/workspaceagents.go | 9 ++ enterprise/coderd/provisionerdaemons.go | 4 + 8 files changed, 348 insertions(+), 25 deletions(-) create mode 100644 coderd/httpmw/logger_internal_test.go create mode 100644 coderd/httpmw/loggermock/loggermock.go diff --git a/Makefile b/Makefile index d71b1173f36b7..725273fdfe702 100644 --- a/Makefile +++ b/Makefile @@ -563,8 +563,8 @@ GEN_FILES := \ site/e2e/provisionerGenerated.ts \ examples/examples.gen.json \ $(TAILNETTEST_MOCKS) \ - coderd/database/pubsub/psmock/psmock.go - + coderd/database/pubsub/psmock/psmock.go \ + coderd/httpmw/loggermock/loggermock.go # all gen targets should be added here and to gen/mark-fresh gen: gen/db $(GEN_FILES) @@ -598,6 +598,7 @@ gen/mark-fresh: examples/examples.gen.json \ $(TAILNETTEST_MOCKS) \ coderd/database/pubsub/psmock/psmock.go \ + coderd/httpmw/loggermock/loggermock.go \ " for file in $$files; do @@ -629,6 +630,10 @@ coderd/database/dbmock/dbmock.go: coderd/database/db.go coderd/database/querier. coderd/database/pubsub/psmock/psmock.go: coderd/database/pubsub/pubsub.go go generate ./coderd/database/pubsub/psmock +coderd/httpmw/loggermock/loggermock.go: coderd/httpmw/logger.go + go generate ./coderd/httpmw/loggermock/ + touch "$@" + $(TAILNETTEST_MOCKS): tailnet/coordinator.go tailnet/service.go go generate ./tailnet/tailnettest/ diff --git a/coderd/httpmw/logger.go b/coderd/httpmw/logger.go index 79e95cf859d8e..0da964407b3e4 100644 --- a/coderd/httpmw/logger.go +++ b/coderd/httpmw/logger.go @@ -35,42 +35,93 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler { slog.F("start", start), ) - next.ServeHTTP(sw, r) + logContext := NewRequestLogger(httplog, r.Method, start) - end := time.Now() + ctx := WithRequestLogger(r.Context(), logContext) + + next.ServeHTTP(sw, r.WithContext(ctx)) // Don't log successful health check requests. if r.URL.Path == "/api/v2" && sw.Status == http.StatusOK { return } - httplog = httplog.With( - slog.F("took", end.Sub(start)), - slog.F("status_code", sw.Status), - slog.F("latency_ms", float64(end.Sub(start)/time.Millisecond)), - ) - - // For status codes 400 and higher we + // For status codes 500 and higher we // want to log the response body. if sw.Status >= http.StatusInternalServerError { - httplog = httplog.With( + logContext.WithFields( slog.F("response_body", string(sw.ResponseBody())), ) } - // We should not log at level ERROR for 5xx status codes because 5xx - // includes proxy errors etc. It also causes slogtest to fail - // instantly without an error message by default. - logLevelFn := httplog.Debug - if sw.Status >= http.StatusInternalServerError { - logLevelFn = httplog.Warn - } - - // We already capture most of this information in the span (minus - // the response body which we don't want to capture anyways). - tracing.RunWithoutSpan(r.Context(), func(ctx context.Context) { - logLevelFn(ctx, r.Method) - }) + logContext.WriteLog(r.Context(), sw.Status) }) } } + +type RequestLogger interface { + WithFields(fields ...slog.Field) + WriteLog(ctx context.Context, status int) +} + +type SlogRequestLogger struct { + log slog.Logger + written bool + message string + start time.Time +} + +var _ RequestLogger = &SlogRequestLogger{} + +func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger { + return &SlogRequestLogger{ + log: log, + written: false, + message: message, + start: start, + } +} + +func (c *SlogRequestLogger) WithFields(fields ...slog.Field) { + c.log = c.log.With(fields...) +} + +func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) { + if c.written { + return + } + c.written = true + end := time.Now() + + logger := c.log.With( + slog.F("took", end.Sub(c.start)), + slog.F("status_code", status), + slog.F("latency_ms", float64(end.Sub(c.start)/time.Millisecond)), + ) + // We already capture most of this information in the span (minus + // the response body which we don't want to capture anyways). + tracing.RunWithoutSpan(ctx, func(ctx context.Context) { + // We should not log at level ERROR for 5xx status codes because 5xx + // includes proxy errors etc. It also causes slogtest to fail + // instantly without an error message by default. + if status >= http.StatusInternalServerError { + logger.Warn(ctx, c.message) + } else { + logger.Debug(ctx, c.message) + } + }) +} + +type logContextKey struct{} + +func WithRequestLogger(ctx context.Context, rl RequestLogger) context.Context { + return context.WithValue(ctx, logContextKey{}, rl) +} + +func RequestLoggerFromContext(ctx context.Context) RequestLogger { + val := ctx.Value(logContextKey{}) + if logCtx, ok := val.(RequestLogger); ok { + return logCtx + } + return nil +} diff --git a/coderd/httpmw/logger_internal_test.go b/coderd/httpmw/logger_internal_test.go new file mode 100644 index 0000000000000..d3035e50d98c9 --- /dev/null +++ b/coderd/httpmw/logger_internal_test.go @@ -0,0 +1,174 @@ +package httpmw + +import ( + "context" + "net/http" + "net/http/httptest" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "cdr.dev/slog" + "github.com/coder/coder/v2/coderd/tracing" + "github.com/coder/coder/v2/testutil" + "github.com/coder/websocket" +) + +func TestRequestLogger_WriteLog(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()) + + // Add custom fields + logCtx.WithFields( + slog.F("custom_field", "custom_value"), + ) + + // Write log for 200 status + 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, "custom_value") + + // Attempt to write again (should be skipped). + logCtx.WriteLog(ctx, http.StatusInternalServerError) + + require.Len(t, sink.entries, 1, "log was written twice") +} + +func TestLoggerMiddleware_SingleRequest(t *testing.T) { + t.Parallel() + + sink := &fakeSink{} + logger := slog.Make(sink) + logger = logger.Leveled(slog.LevelDebug) + + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + // Create a test handler to simulate an HTTP request + testHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { + rw.WriteHeader(http.StatusOK) + _, _ = rw.Write([]byte("OK")) + }) + + // Wrap the test handler with the Logger middleware + loggerMiddleware := Logger(logger) + wrappedHandler := loggerMiddleware(testHandler) + + // Create a test HTTP request + req, err := http.NewRequestWithContext(ctx, http.MethodGet, "/test-path", nil) + require.NoError(t, err, "failed to create request") + + sw := &tracing.StatusWriter{ResponseWriter: httptest.NewRecorder()} + + // Serve the request + wrappedHandler.ServeHTTP(sw, req) + + require.Len(t, sink.entries, 1, "log was written twice") + + require.Equal(t, sink.entries[0].Message, "GET") + + fieldsMap := make(map[string]interface{}) + for _, field := range sink.entries[0].Fields { + fieldsMap[field.Name] = field.Value + } + + // Check that the log contains the expected fields + requiredFields := []string{"host", "path", "proto", "remote_addr", "start", "took", "status_code", "latency_ms"} + for _, field := range requiredFields { + _, exists := fieldsMap[field] + require.True(t, exists, "field %q is missing in log fields", field) + } + + require.Len(t, sink.entries[0].Fields, len(requiredFields), "log should contain only the required fields") + + // Check value of the status code + require.Equal(t, fieldsMap["status_code"], http.StatusOK) +} + +func TestLoggerMiddleware_WebSocket(t *testing.T) { + t.Parallel() + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + sink := &fakeSink{ + newEntries: make(chan slog.SinkEntry, 2), + } + logger := slog.Make(sink) + logger = logger.Leveled(slog.LevelDebug) + done := make(chan struct{}) + wg := sync.WaitGroup{} + // Create a test handler to simulate a WebSocket connection + testHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { + conn, err := websocket.Accept(rw, r, nil) + if !assert.NoError(t, err, "failed to accept websocket") { + return + } + defer conn.Close(websocket.StatusGoingAway, "") + + requestLgr := RequestLoggerFromContext(r.Context()) + requestLgr.WriteLog(r.Context(), http.StatusSwitchingProtocols) + // Block so we can be sure the end of the middleware isn't being called. + wg.Wait() + }) + + // Wrap the test handler with the Logger middleware + loggerMiddleware := Logger(logger) + wrappedHandler := loggerMiddleware(testHandler) + + // RequestLogger expects the ResponseWriter to be *tracing.StatusWriter + customHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { + defer close(done) + sw := &tracing.StatusWriter{ResponseWriter: rw} + wrappedHandler.ServeHTTP(sw, r) + }) + + srv := httptest.NewServer(customHandler) + defer srv.Close() + wg.Add(1) + // nolint: bodyclose + conn, _, err := websocket.Dial(ctx, srv.URL, nil) + require.NoError(t, err, "failed to dial WebSocket") + defer conn.Close(websocket.StatusNormalClosure, "") + + // Wait for the log from within the handler + newEntry := testutil.RequireRecvCtx(ctx, t, sink.newEntries) + require.Equal(t, newEntry.Message, "GET") + + // Signal the websocket handler to return (and read to handle the close frame) + wg.Done() + _, _, err = conn.Read(ctx) + require.ErrorAs(t, err, &websocket.CloseError{}, "websocket read should fail with close error") + + // Wait for the request to finish completely and verify we only logged once + _ = testutil.RequireRecvCtx(ctx, t, done) + require.Len(t, sink.entries, 1, "log was written twice") +} + +type fakeSink struct { + entries []slog.SinkEntry + newEntries chan slog.SinkEntry +} + +func (s *fakeSink) LogEntry(_ context.Context, e slog.SinkEntry) { + s.entries = append(s.entries, e) + if s.newEntries != nil { + select { + case s.newEntries <- e: + default: + } + } +} + +func (*fakeSink) Sync() {} diff --git a/coderd/httpmw/loggermock/loggermock.go b/coderd/httpmw/loggermock/loggermock.go new file mode 100644 index 0000000000000..47818ca11d9e6 --- /dev/null +++ b/coderd/httpmw/loggermock/loggermock.go @@ -0,0 +1,70 @@ +// Code generated by MockGen. DO NOT EDIT. +// Source: github.com/coder/coder/v2/coderd/httpmw (interfaces: RequestLogger) +// +// Generated by this command: +// +// mockgen -destination=loggermock/loggermock.go -package=loggermock . RequestLogger +// + +// Package loggermock is a generated GoMock package. +package loggermock + +import ( + context "context" + reflect "reflect" + + slog "cdr.dev/slog" + gomock "go.uber.org/mock/gomock" +) + +// MockRequestLogger is a mock of RequestLogger interface. +type MockRequestLogger struct { + ctrl *gomock.Controller + recorder *MockRequestLoggerMockRecorder + isgomock struct{} +} + +// MockRequestLoggerMockRecorder is the mock recorder for MockRequestLogger. +type MockRequestLoggerMockRecorder struct { + mock *MockRequestLogger +} + +// NewMockRequestLogger creates a new mock instance. +func NewMockRequestLogger(ctrl *gomock.Controller) *MockRequestLogger { + mock := &MockRequestLogger{ctrl: ctrl} + mock.recorder = &MockRequestLoggerMockRecorder{mock} + return mock +} + +// EXPECT returns an object that allows the caller to indicate expected use. +func (m *MockRequestLogger) EXPECT() *MockRequestLoggerMockRecorder { + return m.recorder +} + +// WithFields mocks base method. +func (m *MockRequestLogger) WithFields(fields ...slog.Field) { + m.ctrl.T.Helper() + varargs := []any{} + for _, a := range fields { + varargs = append(varargs, a) + } + m.ctrl.Call(m, "WithFields", varargs...) +} + +// WithFields indicates an expected call of WithFields. +func (mr *MockRequestLoggerMockRecorder) WithFields(fields ...any) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithFields", reflect.TypeOf((*MockRequestLogger)(nil).WithFields), fields...) +} + +// WriteLog mocks base method. +func (m *MockRequestLogger) WriteLog(ctx context.Context, status int) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "WriteLog", ctx, status) +} + +// WriteLog indicates an expected call of WriteLog. +func (mr *MockRequestLoggerMockRecorder) WriteLog(ctx, status any) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WriteLog", reflect.TypeOf((*MockRequestLogger)(nil).WriteLog), ctx, status) +} diff --git a/coderd/provisionerjobs.go b/coderd/provisionerjobs.go index 591c60855a65e..0ad0766714b8a 100644 --- a/coderd/provisionerjobs.go +++ b/coderd/provisionerjobs.go @@ -536,6 +536,9 @@ func (f *logFollower) follow() { return } + // Log the request immediately instead of after it completes. + httpmw.RequestLoggerFromContext(f.ctx).WriteLog(f.ctx, http.StatusAccepted) + // no need to wait if the job is done if f.complete { return diff --git a/coderd/provisionerjobs_internal_test.go b/coderd/provisionerjobs_internal_test.go index af5a7d66a6f4c..c2c0a60c75ba0 100644 --- a/coderd/provisionerjobs_internal_test.go +++ b/coderd/provisionerjobs_internal_test.go @@ -19,6 +19,8 @@ import ( "github.com/coder/coder/v2/coderd/database/dbmock" "github.com/coder/coder/v2/coderd/database/dbtime" "github.com/coder/coder/v2/coderd/database/pubsub" + "github.com/coder/coder/v2/coderd/httpmw" + "github.com/coder/coder/v2/coderd/httpmw/loggermock" "github.com/coder/coder/v2/codersdk" "github.com/coder/coder/v2/provisionersdk" "github.com/coder/coder/v2/testutil" @@ -305,11 +307,16 @@ func Test_logFollower_EndOfLogs(t *testing.T) { JobStatus: database.ProvisionerJobStatusRunning, } + mockLogger := loggermock.NewMockRequestLogger(ctrl) + mockLogger.EXPECT().WriteLog(gomock.Any(), http.StatusAccepted).Times(1) + ctx = httpmw.WithRequestLogger(ctx, mockLogger) + // we need an HTTP server to get a websocket srv := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { uut := newLogFollower(ctx, logger, mDB, ps, rw, r, job, 0) uut.follow() })) + defer srv.Close() // job was incomplete when we create the logFollower, and still incomplete when it queries diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index 026c3581ff14d..ae534ca922161 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -462,6 +462,9 @@ func (api *API) workspaceAgentLogs(rw http.ResponseWriter, r *http.Request) { t := time.NewTicker(recheckInterval) defer t.Stop() + // Log the request immediately instead of after it completes. + httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + go func() { defer func() { logger.Debug(ctx, "end log streaming loop") @@ -742,6 +745,9 @@ func (api *API) derpMapUpdates(rw http.ResponseWriter, r *http.Request) { encoder := wsjson.NewEncoder[*tailcfg.DERPMap](ws, websocket.MessageBinary) defer encoder.Close(websocket.StatusGoingAway) + // Log the request immediately instead of after it completes. + httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + go func(ctx context.Context) { // TODO(mafredri): Is this too frequent? Use separate ping disconnect timeout? t := time.NewTicker(api.AgentConnectionUpdateFrequency) @@ -1105,6 +1111,9 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ sendTicker := time.NewTicker(sendInterval) defer sendTicker.Stop() + // Log the request immediately instead of after it completes. + httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + // Send initial metadata. sendMetadata() diff --git a/enterprise/coderd/provisionerdaemons.go b/enterprise/coderd/provisionerdaemons.go index f4335438654b5..8df58098ea3fe 100644 --- a/enterprise/coderd/provisionerdaemons.go +++ b/enterprise/coderd/provisionerdaemons.go @@ -381,6 +381,10 @@ func (api *API) provisionerDaemonServe(rw http.ResponseWriter, r *http.Request) logger.Debug(ctx, "drpc server error", slog.Error(err)) }, }) + + // Log the request immediately instead of after it completes. + httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + err = server.Serve(ctx, session) srvCancel() logger.Info(ctx, "provisioner daemon disconnected", slog.Error(err)) From f89f5f2a2bb518d0c072614c49fa64452fd0baad Mon Sep 17 00:00:00 2001 From: Michael Suchacz <203725896+ibetitsmike@users.noreply.github.com> Date: Tue, 15 Apr 2025 13:27:23 +0200 Subject: [PATCH 2/2] feat: extend request logs with auth & DB info (#17304) Closes #16903 --- Makefile | 9 +- coderd/coderd.go | 3 +- coderd/database/dbauthz/dbauthz.go | 28 +++- coderd/database/queries.sql.go | 6 +- coderd/database/queries/users.sql | 4 +- coderd/httpmw/apikey.go | 2 + coderd/httpmw/{ => loggermw}/logger.go | 78 +++++++++- .../{ => loggermw}/logger_internal_test.go | 141 +++++++++++++++++- .../{ => loggermw}/loggermock/loggermock.go | 15 +- coderd/httpmw/workspaceagentparam.go | 11 ++ coderd/httpmw/workspaceparam.go | 15 ++ coderd/provisionerjobs.go | 3 +- coderd/provisionerjobs_internal_test.go | 6 +- coderd/rbac/authz.go | 25 ++++ coderd/workspaceagents.go | 7 +- enterprise/coderd/provisionerdaemons.go | 3 +- enterprise/wsproxy/wsproxy.go | 3 +- tailnet/test/integration/integration.go | 4 +- 18 files changed, 330 insertions(+), 33 deletions(-) rename coderd/httpmw/{ => loggermw}/logger.go (62%) rename coderd/httpmw/{ => loggermw}/logger_internal_test.go (56%) rename coderd/httpmw/{ => loggermw}/loggermock/loggermock.go (77%) diff --git a/Makefile b/Makefile index 725273fdfe702..85feb33f8daef 100644 --- a/Makefile +++ b/Makefile @@ -564,7 +564,7 @@ GEN_FILES := \ examples/examples.gen.json \ $(TAILNETTEST_MOCKS) \ coderd/database/pubsub/psmock/psmock.go \ - coderd/httpmw/loggermock/loggermock.go + coderd/httpmw/loggermw/loggermock/loggermock.go # all gen targets should be added here and to gen/mark-fresh gen: gen/db $(GEN_FILES) @@ -598,7 +598,7 @@ gen/mark-fresh: examples/examples.gen.json \ $(TAILNETTEST_MOCKS) \ coderd/database/pubsub/psmock/psmock.go \ - coderd/httpmw/loggermock/loggermock.go \ + coderd/httpmw/loggermw/loggermock/loggermock.go \ " for file in $$files; do @@ -630,9 +630,8 @@ coderd/database/dbmock/dbmock.go: coderd/database/db.go coderd/database/querier. coderd/database/pubsub/psmock/psmock.go: coderd/database/pubsub/pubsub.go go generate ./coderd/database/pubsub/psmock -coderd/httpmw/loggermock/loggermock.go: coderd/httpmw/logger.go - go generate ./coderd/httpmw/loggermock/ - touch "$@" +coderd/httpmw/loggermw/loggermock/loggermock.go: coderd/httpmw/loggermw/logger.go + go generate ./coderd/httpmw/loggermw/loggermock/ $(TAILNETTEST_MOCKS): tailnet/coordinator.go tailnet/service.go go generate ./tailnet/tailnettest/ diff --git a/coderd/coderd.go b/coderd/coderd.go index be558797389b9..f6848164cd534 100644 --- a/coderd/coderd.go +++ b/coderd/coderd.go @@ -63,6 +63,7 @@ import ( "github.com/coder/coder/v2/coderd/healthcheck/derphealth" "github.com/coder/coder/v2/coderd/httpapi" "github.com/coder/coder/v2/coderd/httpmw" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/coderd/metricscache" "github.com/coder/coder/v2/coderd/notifications" "github.com/coder/coder/v2/coderd/portsharing" @@ -787,7 +788,7 @@ func New(options *Options) *API { tracing.Middleware(api.TracerProvider), httpmw.AttachRequestID, httpmw.ExtractRealIP(api.RealIPConfig), - httpmw.Logger(api.Logger), + loggermw.Logger(api.Logger), rolestore.CustomRoleMW, prometheusMW, // Build-Version is helpful for debugging. diff --git a/coderd/database/dbauthz/dbauthz.go b/coderd/database/dbauthz/dbauthz.go index 0ba9e20216b41..25d4073fb944b 100644 --- a/coderd/database/dbauthz/dbauthz.go +++ b/coderd/database/dbauthz/dbauthz.go @@ -24,6 +24,7 @@ import ( "github.com/coder/coder/v2/coderd/database" "github.com/coder/coder/v2/coderd/database/dbtime" "github.com/coder/coder/v2/coderd/httpapi/httpapiconstraints" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/coderd/rbac" "github.com/coder/coder/v2/coderd/util/slice" "github.com/coder/coder/v2/provisionersdk" @@ -162,6 +163,7 @@ func ActorFromContext(ctx context.Context) (rbac.Subject, bool) { var ( subjectProvisionerd = rbac.Subject{ + Type: rbac.SubjectTypeProvisionerd, FriendlyName: "Provisioner Daemon", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -193,6 +195,7 @@ var ( }.WithCachedASTValue() subjectAutostart = rbac.Subject{ + Type: rbac.SubjectTypeAutostart, FriendlyName: "Autostart", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -216,6 +219,7 @@ var ( // See unhanger package. subjectHangDetector = rbac.Subject{ + Type: rbac.SubjectTypeHangDetector, FriendlyName: "Hang Detector", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -236,6 +240,7 @@ var ( // See cryptokeys package. subjectCryptoKeyRotator = rbac.Subject{ + Type: rbac.SubjectTypeCryptoKeyRotator, FriendlyName: "Crypto Key Rotator", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -254,6 +259,7 @@ var ( // See cryptokeys package. subjectCryptoKeyReader = rbac.Subject{ + Type: rbac.SubjectTypeCryptoKeyReader, FriendlyName: "Crypto Key Reader", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -271,6 +277,7 @@ var ( }.WithCachedASTValue() subjectNotifier = rbac.Subject{ + Type: rbac.SubjectTypeNotifier, FriendlyName: "Notifier", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -288,6 +295,7 @@ var ( }.WithCachedASTValue() subjectSystemRestricted = rbac.Subject{ + Type: rbac.SubjectTypeSystemRestricted, FriendlyName: "System", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -323,6 +331,7 @@ var ( }.WithCachedASTValue() subjectSystemReadProvisionerDaemons = rbac.Subject{ + Type: rbac.SubjectTypeSystemReadProvisionerDaemons, FriendlyName: "Provisioner Daemons Reader", ID: uuid.Nil.String(), Roles: rbac.Roles([]rbac.Role{ @@ -343,47 +352,47 @@ var ( // AsProvisionerd returns a context with an actor that has permissions required // for provisionerd to function. func AsProvisionerd(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectProvisionerd) + return As(ctx, subjectProvisionerd) } // AsAutostart returns a context with an actor that has permissions required // for autostart to function. func AsAutostart(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectAutostart) + return As(ctx, subjectAutostart) } // AsHangDetector returns a context with an actor that has permissions required // for unhanger.Detector to function. func AsHangDetector(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectHangDetector) + return As(ctx, subjectHangDetector) } // AsKeyRotator returns a context with an actor that has permissions required for rotating crypto keys. func AsKeyRotator(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyRotator) + return As(ctx, subjectCryptoKeyRotator) } // AsKeyReader returns a context with an actor that has permissions required for reading crypto keys. func AsKeyReader(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyReader) + return As(ctx, subjectCryptoKeyReader) } // AsNotifier returns a context with an actor that has permissions required for // creating/reading/updating/deleting notifications. func AsNotifier(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectNotifier) + return As(ctx, subjectNotifier) } // AsSystemRestricted returns a context with an actor that has permissions // required for various system operations (login, logout, metrics cache). func AsSystemRestricted(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectSystemRestricted) + return As(ctx, subjectSystemRestricted) } // AsSystemReadProvisionerDaemons returns a context with an actor that has permissions // to read provisioner daemons. func AsSystemReadProvisionerDaemons(ctx context.Context) context.Context { - return context.WithValue(ctx, authContextKey{}, subjectSystemReadProvisionerDaemons) + return As(ctx, subjectSystemReadProvisionerDaemons) } var AsRemoveActor = rbac.Subject{ @@ -401,6 +410,9 @@ func As(ctx context.Context, actor rbac.Subject) context.Context { // should be removed from the context. return context.WithValue(ctx, authContextKey{}, nil) } + if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil { + rlogger.WithAuthContext(actor) + } return context.WithValue(ctx, authContextKey{}, actor) } diff --git a/coderd/database/queries.sql.go b/coderd/database/queries.sql.go index 86db8fb66956a..3fec2f94d361e 100644 --- a/coderd/database/queries.sql.go +++ b/coderd/database/queries.sql.go @@ -10687,10 +10687,10 @@ func (q *sqlQuerier) GetActiveUserCount(ctx context.Context) (int64, error) { const getAuthorizationUserRoles = `-- name: GetAuthorizationUserRoles :one SELECT - -- username is returned just to help for logging purposes + -- username and email are returned just to help for logging purposes -- status is used to enforce 'suspended' users, as all roles are ignored -- when suspended. - id, username, status, + id, username, status, email, -- All user roles, including their org roles. array_cat( -- All users are members @@ -10731,6 +10731,7 @@ type GetAuthorizationUserRolesRow struct { ID uuid.UUID `db:"id" json:"id"` Username string `db:"username" json:"username"` Status UserStatus `db:"status" json:"status"` + Email string `db:"email" json:"email"` Roles []string `db:"roles" json:"roles"` Groups []string `db:"groups" json:"groups"` } @@ -10744,6 +10745,7 @@ func (q *sqlQuerier) GetAuthorizationUserRoles(ctx context.Context, userID uuid. &i.ID, &i.Username, &i.Status, + &i.Email, pq.Array(&i.Roles), pq.Array(&i.Groups), ) diff --git a/coderd/database/queries/users.sql b/coderd/database/queries/users.sql index 1f30a2c2c1d24..5e9ffbe50cd31 100644 --- a/coderd/database/queries/users.sql +++ b/coderd/database/queries/users.sql @@ -244,10 +244,10 @@ WHERE -- This function returns roles for authorization purposes. Implied member roles -- are included. SELECT - -- username is returned just to help for logging purposes + -- username and email are returned just to help for logging purposes -- status is used to enforce 'suspended' users, as all roles are ignored -- when suspended. - id, username, status, + id, username, status, email, -- All user roles, including their org roles. array_cat( -- All users are members diff --git a/coderd/httpmw/apikey.go b/coderd/httpmw/apikey.go index 38ba74031ba46..2600962e39171 100644 --- a/coderd/httpmw/apikey.go +++ b/coderd/httpmw/apikey.go @@ -465,7 +465,9 @@ func UserRBACSubject(ctx context.Context, db database.Store, userID uuid.UUID, s } actor := rbac.Subject{ + Type: rbac.SubjectTypeUser, FriendlyName: roles.Username, + Email: roles.Email, ID: userID.String(), Roles: rbacRoles, Groups: roles.Groups, diff --git a/coderd/httpmw/logger.go b/coderd/httpmw/loggermw/logger.go similarity index 62% rename from coderd/httpmw/logger.go rename to coderd/httpmw/loggermw/logger.go index 0da964407b3e4..9eeb07a5f10e5 100644 --- a/coderd/httpmw/logger.go +++ b/coderd/httpmw/loggermw/logger.go @@ -1,13 +1,17 @@ -package httpmw +package loggermw import ( "context" "fmt" "net/http" + "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" ) @@ -62,6 +66,7 @@ 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 { @@ -69,6 +74,9 @@ type SlogRequestLogger struct { 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{} @@ -79,6 +87,7 @@ func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestL written: false, message: message, start: start, + actors: make(map[rbac.SubjectType]rbac.Subject), } } @@ -86,6 +95,52 @@ 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.SubjectTypeHangDetector, + rbac.SubjectTypeNotifier, + rbac.SubjectTypePrebuildsOrchestrator, + rbac.SubjectTypeProvisionerd, + rbac.SubjectTypeResourceMonitor, + rbac.SubjectTypeSystemReadProvisionerDaemons, + rbac.SubjectTypeSystemRestricted, +} + func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) { if c.written { return @@ -93,11 +148,32 @@ 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() + logger := c.log.With( slog.F("took", end.Sub(c.start)), slog.F("status_code", status), slog.F("latency_ms", float64(end.Sub(c.start)/time.Millisecond)), ) + + // If the request is routed, add the route parameters to the log. + if chiCtx := chi.RouteContext(ctx); chiCtx != nil { + urlParams := chiCtx.URLParams + routeParamsFields := make([]slog.Field, 0, len(urlParams.Keys)) + + for k, v := range urlParams.Keys { + if urlParams.Values[k] != "" { + routeParamsFields = append(routeParamsFields, slog.F("params_"+v, urlParams.Values[k])) + } + } + + if len(routeParamsFields) > 0 { + logger = logger.With(routeParamsFields...) + } + } + // We already capture most of this information in the span (minus // the response body which we don't want to capture anyways). tracing.RunWithoutSpan(ctx, func(ctx context.Context) { diff --git a/coderd/httpmw/logger_internal_test.go b/coderd/httpmw/loggermw/logger_internal_test.go similarity index 56% rename from coderd/httpmw/logger_internal_test.go rename to coderd/httpmw/loggermw/logger_internal_test.go index d3035e50d98c9..e88f8a69c178e 100644 --- a/coderd/httpmw/logger_internal_test.go +++ b/coderd/httpmw/loggermw/logger_internal_test.go @@ -1,13 +1,16 @@ -package httpmw +package loggermw import ( "context" "net/http" "net/http/httptest" + "slices" + "strings" "sync" "testing" "time" + "github.com/go-chi/chi/v5" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -79,7 +82,7 @@ func TestLoggerMiddleware_SingleRequest(t *testing.T) { require.Equal(t, sink.entries[0].Message, "GET") - fieldsMap := make(map[string]interface{}) + fieldsMap := make(map[string]any) for _, field := range sink.entries[0].Fields { fieldsMap[field.Name] = field.Value } @@ -156,6 +159,140 @@ func TestLoggerMiddleware_WebSocket(t *testing.T) { require.Len(t, sink.entries, 1, "log was written twice") } +func TestRequestLogger_HTTPRouteParams(t *testing.T) { + t.Parallel() + + sink := &fakeSink{} + logger := slog.Make(sink) + logger = logger.Leveled(slog.LevelDebug) + + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + chiCtx := chi.NewRouteContext() + chiCtx.URLParams.Add("workspace", "test-workspace") + chiCtx.URLParams.Add("agent", "test-agent") + + ctx = context.WithValue(ctx, chi.RouteCtxKey, chiCtx) + + // Create a test handler to simulate an HTTP request + testHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { + rw.WriteHeader(http.StatusOK) + _, _ = rw.Write([]byte("OK")) + }) + + // Wrap the test handler with the Logger middleware + loggerMiddleware := Logger(logger) + wrappedHandler := loggerMiddleware(testHandler) + + // Create a test HTTP request + req, err := http.NewRequestWithContext(ctx, http.MethodGet, "/test-path/}", nil) + require.NoError(t, err, "failed to create request") + + sw := &tracing.StatusWriter{ResponseWriter: httptest.NewRecorder()} + + // Serve the request + wrappedHandler.ServeHTTP(sw, req) + + fieldsMap := make(map[string]any) + for _, field := range sink.entries[0].Fields { + fieldsMap[field.Name] = field.Value + } + + // Check that the log contains the expected fields + requiredFields := []string{"workspace", "agent"} + for _, field := range requiredFields { + _, exists := fieldsMap["params_"+field] + require.True(t, exists, "field %q is missing in log fields", field) + } +} + +func TestRequestLogger_RouteParamsLogging(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + params map[string]string + expectedFields []string + }{ + { + name: "EmptyParams", + params: map[string]string{}, + expectedFields: []string{}, + }, + { + name: "SingleParam", + params: map[string]string{ + "workspace": "test-workspace", + }, + expectedFields: []string{"params_workspace"}, + }, + { + name: "MultipleParams", + params: map[string]string{ + "workspace": "test-workspace", + "agent": "test-agent", + "user": "test-user", + }, + expectedFields: []string{"params_workspace", "params_agent", "params_user"}, + }, + { + name: "EmptyValueParam", + params: map[string]string{ + "workspace": "test-workspace", + "agent": "", + }, + expectedFields: []string{"params_workspace"}, + }, + } + + for _, tt := range tests { + tt := tt + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + sink := &fakeSink{} + logger := slog.Make(sink) + logger = logger.Leveled(slog.LevelDebug) + + // Create a route context with the test parameters + chiCtx := chi.NewRouteContext() + for key, value := range tt.params { + chiCtx.URLParams.Add(key, value) + } + + ctx := context.WithValue(context.Background(), chi.RouteCtxKey, chiCtx) + logCtx := NewRequestLogger(logger, "GET", time.Now()) + + // Write the log + logCtx.WriteLog(ctx, http.StatusOK) + + require.Len(t, sink.entries, 1, "expected exactly one log entry") + + // Convert fields to map for easier checking + fieldsMap := make(map[string]any) + for _, field := range sink.entries[0].Fields { + fieldsMap[field.Name] = field.Value + } + + // Verify expected fields are present + for _, field := range tt.expectedFields { + value, exists := fieldsMap[field] + require.True(t, exists, "field %q should be present in log", field) + require.Equal(t, tt.params[strings.TrimPrefix(field, "params_")], value, "field %q has incorrect value", field) + } + + // Verify no unexpected fields are present + for field := range fieldsMap { + if field == "took" || field == "status_code" || field == "latency_ms" { + continue // Skip standard fields + } + require.True(t, slices.Contains(tt.expectedFields, field), "unexpected field %q in log", field) + } + }) + } +} + type fakeSink struct { entries []slog.SinkEntry newEntries chan slog.SinkEntry diff --git a/coderd/httpmw/loggermock/loggermock.go b/coderd/httpmw/loggermw/loggermock/loggermock.go similarity index 77% rename from coderd/httpmw/loggermock/loggermock.go rename to coderd/httpmw/loggermw/loggermock/loggermock.go index 47818ca11d9e6..008f862107ae6 100644 --- a/coderd/httpmw/loggermock/loggermock.go +++ b/coderd/httpmw/loggermw/loggermock/loggermock.go @@ -1,5 +1,5 @@ // Code generated by MockGen. DO NOT EDIT. -// Source: github.com/coder/coder/v2/coderd/httpmw (interfaces: RequestLogger) +// Source: github.com/coder/coder/v2/coderd/httpmw/loggermw (interfaces: RequestLogger) // // Generated by this command: // @@ -14,6 +14,7 @@ import ( reflect "reflect" slog "cdr.dev/slog" + rbac "github.com/coder/coder/v2/coderd/rbac" gomock "go.uber.org/mock/gomock" ) @@ -41,6 +42,18 @@ func (m *MockRequestLogger) EXPECT() *MockRequestLoggerMockRecorder { return m.recorder } +// WithAuthContext mocks base method. +func (m *MockRequestLogger) WithAuthContext(actor rbac.Subject) { + m.ctrl.T.Helper() + m.ctrl.Call(m, "WithAuthContext", actor) +} + +// WithAuthContext indicates an expected call of WithAuthContext. +func (mr *MockRequestLoggerMockRecorder) WithAuthContext(actor any) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithAuthContext", reflect.TypeOf((*MockRequestLogger)(nil).WithAuthContext), actor) +} + // WithFields mocks base method. func (m *MockRequestLogger) WithFields(fields ...slog.Field) { m.ctrl.T.Helper() diff --git a/coderd/httpmw/workspaceagentparam.go b/coderd/httpmw/workspaceagentparam.go index a47ce3c377ae0..434e057c0eccc 100644 --- a/coderd/httpmw/workspaceagentparam.go +++ b/coderd/httpmw/workspaceagentparam.go @@ -6,8 +6,11 @@ import ( "github.com/go-chi/chi/v5" + "cdr.dev/slog" + "github.com/coder/coder/v2/coderd/database" "github.com/coder/coder/v2/coderd/httpapi" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/codersdk" ) @@ -81,6 +84,14 @@ func ExtractWorkspaceAgentParam(db database.Store) func(http.Handler) http.Handl ctx = context.WithValue(ctx, workspaceAgentParamContextKey{}, agent) chi.RouteContext(ctx).URLParams.Add("workspace", build.WorkspaceID.String()) + + if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil { + rlogger.WithFields( + slog.F("workspace_name", resource.Name), + slog.F("agent_name", agent.Name), + ) + } + next.ServeHTTP(rw, r.WithContext(ctx)) }) } diff --git a/coderd/httpmw/workspaceparam.go b/coderd/httpmw/workspaceparam.go index 21e8dcfd62863..0c4e4f77354fc 100644 --- a/coderd/httpmw/workspaceparam.go +++ b/coderd/httpmw/workspaceparam.go @@ -9,8 +9,11 @@ import ( "github.com/go-chi/chi/v5" "github.com/google/uuid" + "cdr.dev/slog" + "github.com/coder/coder/v2/coderd/database" "github.com/coder/coder/v2/coderd/httpapi" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/codersdk" ) @@ -48,6 +51,11 @@ func ExtractWorkspaceParam(db database.Store) func(http.Handler) http.Handler { } ctx = context.WithValue(ctx, workspaceParamContextKey{}, workspace) + + if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil { + rlogger.WithFields(slog.F("workspace_name", workspace.Name)) + } + next.ServeHTTP(rw, r.WithContext(ctx)) }) } @@ -154,6 +162,13 @@ func ExtractWorkspaceAndAgentParam(db database.Store) func(http.Handler) http.Ha ctx = context.WithValue(ctx, workspaceParamContextKey{}, workspace) ctx = context.WithValue(ctx, workspaceAgentParamContextKey{}, agent) + + if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil { + rlogger.WithFields( + slog.F("workspace_name", workspace.Name), + slog.F("agent_name", agent.Name), + ) + } next.ServeHTTP(rw, r.WithContext(ctx)) }) } diff --git a/coderd/provisionerjobs.go b/coderd/provisionerjobs.go index 0ad0766714b8a..3096d2b47debb 100644 --- a/coderd/provisionerjobs.go +++ b/coderd/provisionerjobs.go @@ -20,6 +20,7 @@ import ( "github.com/coder/coder/v2/coderd/database/pubsub" "github.com/coder/coder/v2/coderd/httpapi" "github.com/coder/coder/v2/coderd/httpmw" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/coderd/rbac" "github.com/coder/coder/v2/coderd/rbac/policy" "github.com/coder/coder/v2/coderd/util/slice" @@ -537,7 +538,7 @@ func (f *logFollower) follow() { } // Log the request immediately instead of after it completes. - httpmw.RequestLoggerFromContext(f.ctx).WriteLog(f.ctx, http.StatusAccepted) + loggermw.RequestLoggerFromContext(f.ctx).WriteLog(f.ctx, http.StatusAccepted) // no need to wait if the job is done if f.complete { diff --git a/coderd/provisionerjobs_internal_test.go b/coderd/provisionerjobs_internal_test.go index c2c0a60c75ba0..f3bc2eb1dea99 100644 --- a/coderd/provisionerjobs_internal_test.go +++ b/coderd/provisionerjobs_internal_test.go @@ -19,8 +19,8 @@ import ( "github.com/coder/coder/v2/coderd/database/dbmock" "github.com/coder/coder/v2/coderd/database/dbtime" "github.com/coder/coder/v2/coderd/database/pubsub" - "github.com/coder/coder/v2/coderd/httpmw" - "github.com/coder/coder/v2/coderd/httpmw/loggermock" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" + "github.com/coder/coder/v2/coderd/httpmw/loggermw/loggermock" "github.com/coder/coder/v2/codersdk" "github.com/coder/coder/v2/provisionersdk" "github.com/coder/coder/v2/testutil" @@ -309,7 +309,7 @@ func Test_logFollower_EndOfLogs(t *testing.T) { mockLogger := loggermock.NewMockRequestLogger(ctrl) mockLogger.EXPECT().WriteLog(gomock.Any(), http.StatusAccepted).Times(1) - ctx = httpmw.WithRequestLogger(ctx, mockLogger) + ctx = loggermw.WithRequestLogger(ctx, mockLogger) // we need an HTTP server to get a websocket srv := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { diff --git a/coderd/rbac/authz.go b/coderd/rbac/authz.go index aaba7d6eae3af..02268e052d2e2 100644 --- a/coderd/rbac/authz.go +++ b/coderd/rbac/authz.go @@ -57,6 +57,23 @@ func hashAuthorizeCall(actor Subject, action policy.Action, object Object) [32]b return hashOut } +// SubjectType represents the type of subject in the RBAC system. +type SubjectType string + +const ( + SubjectTypeUser SubjectType = "user" + SubjectTypeProvisionerd SubjectType = "provisionerd" + SubjectTypeAutostart SubjectType = "autostart" + SubjectTypeHangDetector SubjectType = "hang_detector" + SubjectTypeResourceMonitor SubjectType = "resource_monitor" + SubjectTypeCryptoKeyRotator SubjectType = "crypto_key_rotator" + SubjectTypeCryptoKeyReader SubjectType = "crypto_key_reader" + SubjectTypePrebuildsOrchestrator SubjectType = "prebuilds_orchestrator" + SubjectTypeSystemReadProvisionerDaemons SubjectType = "system_read_provisioner_daemons" + SubjectTypeSystemRestricted SubjectType = "system_restricted" + SubjectTypeNotifier SubjectType = "notifier" +) + // Subject is a struct that contains all the elements of a subject in an rbac // authorize. type Subject struct { @@ -66,6 +83,14 @@ type Subject struct { // external workspace proxy or other service type actor. FriendlyName string + // Email is entirely optional and is used for logging and debugging + // It is not used in any functional way. + Email string + + // Type indicates what kind of subject this is (user, system, provisioner, etc.) + // It is not used in any functional way, only for logging. + Type SubjectType + ID string Roles ExpandableRoles Groups []string diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index ae534ca922161..390caeb7c2ac3 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -31,6 +31,7 @@ import ( "github.com/coder/coder/v2/coderd/externalauth" "github.com/coder/coder/v2/coderd/httpapi" "github.com/coder/coder/v2/coderd/httpmw" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/coderd/jwtutils" "github.com/coder/coder/v2/coderd/rbac" "github.com/coder/coder/v2/coderd/rbac/policy" @@ -463,7 +464,7 @@ func (api *API) workspaceAgentLogs(rw http.ResponseWriter, r *http.Request) { defer t.Stop() // Log the request immediately instead of after it completes. - httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + loggermw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) go func() { defer func() { @@ -746,7 +747,7 @@ func (api *API) derpMapUpdates(rw http.ResponseWriter, r *http.Request) { defer encoder.Close(websocket.StatusGoingAway) // Log the request immediately instead of after it completes. - httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + loggermw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) go func(ctx context.Context) { // TODO(mafredri): Is this too frequent? Use separate ping disconnect timeout? @@ -1112,7 +1113,7 @@ func (api *API) watchWorkspaceAgentMetadata(rw http.ResponseWriter, r *http.Requ defer sendTicker.Stop() // Log the request immediately instead of after it completes. - httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + loggermw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) // Send initial metadata. sendMetadata() diff --git a/enterprise/coderd/provisionerdaemons.go b/enterprise/coderd/provisionerdaemons.go index 8df58098ea3fe..ccd893bb25e82 100644 --- a/enterprise/coderd/provisionerdaemons.go +++ b/enterprise/coderd/provisionerdaemons.go @@ -24,6 +24,7 @@ import ( "github.com/coder/coder/v2/coderd/database/dbtime" "github.com/coder/coder/v2/coderd/httpapi" "github.com/coder/coder/v2/coderd/httpmw" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/coderd/provisionerdserver" "github.com/coder/coder/v2/coderd/rbac" "github.com/coder/coder/v2/coderd/rbac/policy" @@ -383,7 +384,7 @@ func (api *API) provisionerDaemonServe(rw http.ResponseWriter, r *http.Request) }) // Log the request immediately instead of after it completes. - httpmw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) + loggermw.RequestLoggerFromContext(ctx).WriteLog(ctx, http.StatusAccepted) err = server.Serve(ctx, session) srvCancel() diff --git a/enterprise/wsproxy/wsproxy.go b/enterprise/wsproxy/wsproxy.go index af4d5064f4531..81b800c536a0f 100644 --- a/enterprise/wsproxy/wsproxy.go +++ b/enterprise/wsproxy/wsproxy.go @@ -32,6 +32,7 @@ import ( "github.com/coder/coder/v2/coderd/cryptokeys" "github.com/coder/coder/v2/coderd/httpapi" "github.com/coder/coder/v2/coderd/httpmw" + "github.com/coder/coder/v2/coderd/httpmw/loggermw" "github.com/coder/coder/v2/coderd/tracing" "github.com/coder/coder/v2/coderd/workspaceapps" "github.com/coder/coder/v2/codersdk" @@ -336,7 +337,7 @@ func New(ctx context.Context, opts *Options) (*Server, error) { tracing.Middleware(s.TracerProvider), httpmw.AttachRequestID, httpmw.ExtractRealIP(s.Options.RealIPConfig), - httpmw.Logger(s.Logger), + loggermw.Logger(s.Logger), prometheusMW, corsMW, diff --git a/tailnet/test/integration/integration.go b/tailnet/test/integration/integration.go index 87f0cdcf4e148..d2d960807b142 100644 --- a/tailnet/test/integration/integration.go +++ b/tailnet/test/integration/integration.go @@ -33,7 +33,7 @@ import ( "cdr.dev/slog" "github.com/coder/coder/v2/coderd/httpapi" - "github.com/coder/coder/v2/coderd/httpmw" + "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/tailnet" @@ -200,7 +200,7 @@ func (o SimpleServerOptions) Router(t *testing.T, logger slog.Logger) *chi.Mux { }) }, tracing.StatusWriterMiddleware, - httpmw.Logger(logger), + loggermw.Logger(logger), ) r.Route("/derp", func(r chi.Router) {