- Notifications
You must be signed in to change notification settings - Fork923
feat: log long-lived connections acceptance#17219
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to ourterms of service andprivacy statement. We’ll occasionally send you account related emails.
Already on GitHub?Sign in to your account
Merged
ibetitsmike merged 40 commits intomainfrommike/16904-request-logging-on-long-lived-connection-openingApr 8, 2025
Uh oh!
There was an error while loading.Please reload this page.
Merged
Changes fromall commits
Commits
Show all changes
40 commits Select commitHold shift + click to select a range
0e397ed initial implementation of RequestLoggerContext and example usage in P…
ibetitsmikec384706 fix empty RequestLoggerContext
ibetitsmike686f4db referenced httplog while creating RequestLoggerContext
ibetitsmike7edb8c3 refactored fields extension on the logger
ibetitsmike5feb4e4 fixed log formatting
ibetitsmike7500ef5 typo comment fix
ibetitsmike66e2c3e added logging to long lived connection opening functions
ibetitsmike4e5f36e added logging to other places
ibetitsmikeb7822b3 updated comments
ibetitsmikea772430 renamed context fetcher
ibetitsmike2a1dbe3 refactored logging in the logger middleware and added tests for logger
ibetitsmike5a0fa05 removed unecessary helpers
ibetitsmike30bb53d added test for an http request
ibetitsmike89e987e linting fixes
ibetitsmike1649116 added handling of internal test circumventing RequestLoggerContext in…
ibetitsmike7ea2dd6 reverted the original behavior of logging WARN on Status Code >=500
ibetitsmike338fd20 refactored logger to remove extending it with fields permanently
ibetitsmike2708286 Removed nil checks when fetching RequestLogger
ibetitsmikeca3c4d3 refactored tests to use a fakesink to verify the written messages
ibetitsmikedfa2f4f added WebSocket test to verify early logging
ibetitsmike845ff0f fix lint for response body leak
ibetitsmike1f7acfb reverted bodyclose lint fix
ibetitsmike58aa736 fix for race condition in the test
ibetitsmike2c63b32 linter fixes
ibetitsmiked268a3c actually added logging early to test early logging
ibetitsmike8f550c5 added a WaitGroup in logger internal tests to remove the race condition
ibetitsmike81e1527 refactor after code review
ibetitsmikeb9e2b61 added checking the logger fields in the test
ibetitsmikedeb1a41 refactored mock request logger to fit current codebase
ibetitsmike09e46d0 added mocked files to Makefile
ibetitsmike9b16cf9 format fix
ibetitsmike2e331a3 fixed path in Makefile
ibetitsmike7e9f083 fixed Makefile path
ibetitsmikeb82776f fixed nested path in Makefile
ibetitsmike3d44727 Merge branch 'main' into mike/16904-request-logging-on-long-lived-con…
ibetitsmikecb118a9 added additional checks
ibetitsmike754cee6 refactored the WebSocket test to actually read and close the connection
ibetitsmiked28f2bd Merge branch 'main' into mike/16904-request-logging-on-long-lived-con…
ibetitsmike57a49d5 Merge branch 'main' into mike/16904-request-logging-on-long-lived-con…
ibetitsmikecb130de Merge branch 'main' into mike/16904-request-logging-on-long-lived-con…
ibetitsmikeFile filter
Filter by extension
Conversations
Failed to load comments.
Loading
Uh oh!
There was an error while loading.Please reload this page.
Jump to
Jump to file
Failed to load files.
Loading
Uh oh!
There was an error while loading.Please reload this page.
Diff view
Diff view
There are no files selected for viewing
8 changes: 7 additions & 1 deletionMakefile
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
97 changes: 74 additions & 23 deletionscoderd/httpmw/logger.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -35,42 +35,93 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler { | ||
| slog.F("start", start), | ||
| ) | ||
| logContext := NewRequestLogger(httplog, r.Method, start) | ||
| ctx := WithRequestLogger(r.Context(), logContext) | ||
| next.ServeHTTP(sw, r.WithContext(ctx)) | ||
ibetitsmike marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. | ||
| // Don't log successful health check requests. | ||
| if r.URL.Path == "/api/v2" && sw.Status == http.StatusOK { | ||
| return | ||
| } | ||
| // For status codes 500 and higher we | ||
| // want to log the response body. | ||
| if sw.Status >= http.StatusInternalServerError { | ||
| logContext.WithFields( | ||
| slog.F("response_body", string(sw.ResponseBody())), | ||
| ) | ||
| } | ||
| 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 | ||
| } | ||
ibetitsmike marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. | ||
| 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 | ||
| } | ||
174 changes: 174 additions & 0 deletionscoderd/httpmw/logger_internal_test.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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) { | ||
ibetitsmike marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. | ||
| 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() {} | ||
70 changes: 70 additions & 0 deletionscoderd/httpmw/loggermock/loggermock.go
Some generated files are not rendered by default. Learn more abouthow customized files appear on GitHub.
Oops, something went wrong.
Uh oh!
There was an error while loading.Please reload this page.
Oops, something went wrong.
Uh oh!
There was an error while loading.Please reload this page.
Oops, something went wrong.
Uh oh!
There was an error while loading.Please reload this page.
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.