- Notifications
You must be signed in to change notification settings - Fork1k
feat: log long-lived connections acceptance (cherry-pick #17219)#17495
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
Uh oh!
There was an error while loading.Please reload this page.
Merged
Changes fromall commits
Commits
File 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
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) { | ||
| 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.