|
| 1 | +package httpmw |
| 2 | + |
| 3 | +import ( |
| 4 | + "context" |
| 5 | + "net/http" |
| 6 | + "net/http/httptest" |
| 7 | + "sync" |
| 8 | + "testing" |
| 9 | + "time" |
| 10 | + |
| 11 | + "github.com/stretchr/testify/assert" |
| 12 | + "github.com/stretchr/testify/require" |
| 13 | + |
| 14 | + "cdr.dev/slog" |
| 15 | + "github.com/coder/coder/v2/coderd/tracing" |
| 16 | + "github.com/coder/coder/v2/testutil" |
| 17 | + "github.com/coder/websocket" |
| 18 | +) |
| 19 | + |
| 20 | +func TestRequestLogger_WriteLog(t *testing.T) { |
| 21 | + t.Parallel() |
| 22 | + ctx := context.Background() |
| 23 | + |
| 24 | + sink := &fakeSink{} |
| 25 | + logger := slog.Make(sink) |
| 26 | + logger = logger.Leveled(slog.LevelDebug) |
| 27 | + logCtx := NewRequestLogger(logger, "GET", time.Now()) |
| 28 | + |
| 29 | + // Add custom fields |
| 30 | + logCtx.WithFields( |
| 31 | + slog.F("custom_field", "custom_value"), |
| 32 | + ) |
| 33 | + |
| 34 | + // Write log for 200 status |
| 35 | + logCtx.WriteLog(ctx, http.StatusOK) |
| 36 | + |
| 37 | + require.Len(t, sink.entries, 1, "log was written twice") |
| 38 | + |
| 39 | + require.Equal(t, sink.entries[0].Message, "GET") |
| 40 | + |
| 41 | + require.Equal(t, sink.entries[0].Fields[0].Value, "custom_value") |
| 42 | + |
| 43 | + // Attempt to write again (should be skipped). |
| 44 | + logCtx.WriteLog(ctx, http.StatusInternalServerError) |
| 45 | + |
| 46 | + require.Len(t, sink.entries, 1, "log was written twice") |
| 47 | +} |
| 48 | + |
| 49 | +func TestLoggerMiddleware_SingleRequest(t *testing.T) { |
| 50 | + t.Parallel() |
| 51 | + |
| 52 | + sink := &fakeSink{} |
| 53 | + logger := slog.Make(sink) |
| 54 | + logger = logger.Leveled(slog.LevelDebug) |
| 55 | + |
| 56 | + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) |
| 57 | + defer cancel() |
| 58 | + |
| 59 | + // Create a test handler to simulate an HTTP request |
| 60 | + testHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { |
| 61 | + rw.WriteHeader(http.StatusOK) |
| 62 | + _, _ = rw.Write([]byte("OK")) |
| 63 | + }) |
| 64 | + |
| 65 | + // Wrap the test handler with the Logger middleware |
| 66 | + loggerMiddleware := Logger(logger) |
| 67 | + wrappedHandler := loggerMiddleware(testHandler) |
| 68 | + |
| 69 | + // Create a test HTTP request |
| 70 | + req, err := http.NewRequestWithContext(ctx, http.MethodGet, "/test-path", nil) |
| 71 | + require.NoError(t, err, "failed to create request") |
| 72 | + |
| 73 | + sw := &tracing.StatusWriter{ResponseWriter: httptest.NewRecorder()} |
| 74 | + |
| 75 | + // Serve the request |
| 76 | + wrappedHandler.ServeHTTP(sw, req) |
| 77 | + |
| 78 | + require.Len(t, sink.entries, 1, "log was written twice") |
| 79 | + |
| 80 | + require.Equal(t, sink.entries[0].Message, "GET") |
| 81 | + |
| 82 | + fieldsMap := make(map[string]interface{}) |
| 83 | + for _, field := range sink.entries[0].Fields { |
| 84 | + fieldsMap[field.Name] = field.Value |
| 85 | + } |
| 86 | + |
| 87 | + // Check that the log contains the expected fields |
| 88 | + requiredFields := []string{"host", "path", "proto", "remote_addr", "start", "took", "status_code", "latency_ms"} |
| 89 | + for _, field := range requiredFields { |
| 90 | + _, exists := fieldsMap[field] |
| 91 | + require.True(t, exists, "field %q is missing in log fields", field) |
| 92 | + } |
| 93 | + |
| 94 | + require.Len(t, sink.entries[0].Fields, len(requiredFields), "log should contain only the required fields") |
| 95 | + |
| 96 | + // Check value of the status code |
| 97 | + require.Equal(t, fieldsMap["status_code"], http.StatusOK) |
| 98 | +} |
| 99 | + |
| 100 | +func TestLoggerMiddleware_WebSocket(t *testing.T) { |
| 101 | + t.Parallel() |
| 102 | + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) |
| 103 | + defer cancel() |
| 104 | + |
| 105 | + sink := &fakeSink{ |
| 106 | + newEntries: make(chan slog.SinkEntry, 2), |
| 107 | + } |
| 108 | + logger := slog.Make(sink) |
| 109 | + logger = logger.Leveled(slog.LevelDebug) |
| 110 | + done := make(chan struct{}) |
| 111 | + wg := sync.WaitGroup{} |
| 112 | + // Create a test handler to simulate a WebSocket connection |
| 113 | + testHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { |
| 114 | + conn, err := websocket.Accept(rw, r, nil) |
| 115 | + if !assert.NoError(t, err, "failed to accept websocket") { |
| 116 | + return |
| 117 | + } |
| 118 | + defer conn.Close(websocket.StatusGoingAway, "") |
| 119 | + |
| 120 | + requestLgr := RequestLoggerFromContext(r.Context()) |
| 121 | + requestLgr.WriteLog(r.Context(), http.StatusSwitchingProtocols) |
| 122 | + // Block so we can be sure the end of the middleware isn't being called. |
| 123 | + wg.Wait() |
| 124 | + }) |
| 125 | + |
| 126 | + // Wrap the test handler with the Logger middleware |
| 127 | + loggerMiddleware := Logger(logger) |
| 128 | + wrappedHandler := loggerMiddleware(testHandler) |
| 129 | + |
| 130 | + // RequestLogger expects the ResponseWriter to be *tracing.StatusWriter |
| 131 | + customHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { |
| 132 | + defer close(done) |
| 133 | + sw := &tracing.StatusWriter{ResponseWriter: rw} |
| 134 | + wrappedHandler.ServeHTTP(sw, r) |
| 135 | + }) |
| 136 | + |
| 137 | + srv := httptest.NewServer(customHandler) |
| 138 | + defer srv.Close() |
| 139 | + wg.Add(1) |
| 140 | + // nolint: bodyclose |
| 141 | + conn, _, err := websocket.Dial(ctx, srv.URL, nil) |
| 142 | + require.NoError(t, err, "failed to dial WebSocket") |
| 143 | + defer conn.Close(websocket.StatusNormalClosure, "") |
| 144 | + |
| 145 | + // Wait for the log from within the handler |
| 146 | + newEntry := testutil.RequireRecvCtx(ctx, t, sink.newEntries) |
| 147 | + require.Equal(t, newEntry.Message, "GET") |
| 148 | + |
| 149 | + // Signal the websocket handler to return (and read to handle the close frame) |
| 150 | + wg.Done() |
| 151 | + _, _, err = conn.Read(ctx) |
| 152 | + require.ErrorAs(t, err, &websocket.CloseError{}, "websocket read should fail with close error") |
| 153 | + |
| 154 | + // Wait for the request to finish completely and verify we only logged once |
| 155 | + _ = testutil.RequireRecvCtx(ctx, t, done) |
| 156 | + require.Len(t, sink.entries, 1, "log was written twice") |
| 157 | +} |
| 158 | + |
| 159 | +type fakeSink struct { |
| 160 | + entries []slog.SinkEntry |
| 161 | + newEntries chan slog.SinkEntry |
| 162 | +} |
| 163 | + |
| 164 | +func (s *fakeSink) LogEntry(_ context.Context, e slog.SinkEntry) { |
| 165 | + s.entries = append(s.entries, e) |
| 166 | + if s.newEntries != nil { |
| 167 | + select { |
| 168 | + case s.newEntries <- e: |
| 169 | + default: |
| 170 | + } |
| 171 | + } |
| 172 | +} |
| 173 | + |
| 174 | +func (*fakeSink) Sync() {} |
0 commit comments