|
| 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 | +funcTestRequestLogger_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 | +funcTestLoggerMiddleware_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 | +defercancel() |
| 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:=rangesink.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:=rangerequiredFields { |
| 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 | +funcTestLoggerMiddleware_WebSocket(t*testing.T) { |
| 101 | +t.Parallel() |
| 102 | +ctx,cancel:=context.WithTimeout(context.Background(),testutil.WaitShort) |
| 103 | +defercancel() |
| 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(chanstruct{}) |
| 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 | +deferconn.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 | +deferclose(done) |
| 133 | +sw:=&tracing.StatusWriter{ResponseWriter:rw} |
| 134 | +wrappedHandler.ServeHTTP(sw,r) |
| 135 | +}) |
| 136 | + |
| 137 | +srv:=httptest.NewServer(customHandler) |
| 138 | +defersrv.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 | +deferconn.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 | +typefakeSinkstruct { |
| 160 | +entries []slog.SinkEntry |
| 161 | +newEntrieschan slog.SinkEntry |
| 162 | +} |
| 163 | + |
| 164 | +func (s*fakeSink)LogEntry(_ context.Context,e slog.SinkEntry) { |
| 165 | +s.entries=append(s.entries,e) |
| 166 | +ifs.newEntries!=nil { |
| 167 | +select { |
| 168 | +cases.newEntries<-e: |
| 169 | +default: |
| 170 | +} |
| 171 | +} |
| 172 | +} |
| 173 | + |
| 174 | +func (*fakeSink)Sync() {} |