feat: add access log middleware with health-check exclusion
- commit
- aa3dd1da75886ce08e7098f6f759507ee5c215e8
- author
- brice · · 2026-04-03 15:15 UTC
- committer
- brice · · 2026-04-03 15:16 UTC
- parent
- 24781f9
- signature
- GPG Verified
CD88F9E564E0102646FB6077A1A07C7C7C3E349D· arch-gpg Verified for the committer email
3 files · +291 -7
A internal/adapters/in/http/middleware/accesslog.go +107 -0
| @@ -0,0 +1,107 @@ | |||
| 1 | + | package middleware | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "net" | |
| 5 | + | "net/http" | |
| 6 | + | "strings" | |
| 7 | + | "time" | |
| 8 | + | ||
| 9 | + | "github.com/bnema/zerowrap" | |
| 10 | + | ||
| 11 | + | "github.com/bnema/gordon/internal/adapters/out/accesslog" | |
| 12 | + | ) | |
| 13 | + | ||
| 14 | + | // loopbackNets contains the loopback ranges used for health-check exclusion. | |
| 15 | + | var loopbackNets = func() []*net.IPNet { | |
| 16 | + | _, ipv4Loopback, _ := net.ParseCIDR("127.0.0.0/8") | |
| 17 | + | _, ipv6Loopback, _ := net.ParseCIDR("::1/128") | |
| 18 | + | return []*net.IPNet{ipv4Loopback, ipv6Loopback} | |
| 19 | + | }() | |
| 20 | + | ||
| 21 | + | // isLoopback reports whether the given IP string is a loopback address. | |
| 22 | + | func isLoopback(ip string) bool { | |
| 23 | + | parsed := net.ParseIP(ip) | |
| 24 | + | if parsed == nil { | |
| 25 | + | return false | |
| 26 | + | } | |
| 27 | + | for _, n := range loopbackNets { | |
| 28 | + | if n.Contains(parsed) { | |
| 29 | + | return true | |
| 30 | + | } | |
| 31 | + | } | |
| 32 | + | return false | |
| 33 | + | } | |
| 34 | + | ||
| 35 | + | // AccessLogWriter is the interface the middleware needs from the output adapter. | |
| 36 | + | // *accesslog.Writer satisfies this interface. | |
| 37 | + | type AccessLogWriter interface { | |
| 38 | + | Write(entry accesslog.Entry) error | |
| 39 | + | } | |
| 40 | + | ||
| 41 | + | // AccessLogger is a middleware that writes one access-log entry per HTTP request | |
| 42 | + | // to the provided writer. It runs alongside (not instead of) RequestLogger. | |
| 43 | + | // | |
| 44 | + | // When excludeHealthChecks is true, requests from the Gordon health prober | |
| 45 | + | // (UA prefix "Gordon-HealthCheck/") or from loopback IPs are not logged. | |
| 46 | + | // | |
| 47 | + | // Write failures are reported as warnings through the application logger and | |
| 48 | + | // never fail the HTTP response. | |
| 49 | + | func AccessLogger(writer AccessLogWriter, excludeHealthChecks bool, log zerowrap.Logger, trustedNets ...[]*net.IPNet) func(http.Handler) http.Handler { | |
| 50 | + | var nets []*net.IPNet | |
| 51 | + | if len(trustedNets) > 0 { | |
| 52 | + | nets = trustedNets[0] | |
| 53 | + | } | |
| 54 | + | ||
| 55 | + | return func(next http.Handler) http.Handler { | |
| 56 | + | return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 57 | + | start := time.Now() | |
| 58 | + | ||
| 59 | + | // Ensure a request ID exists before calling inner handlers so both | |
| 60 | + | // this middleware and RequestLogger share the same value. | |
| 61 | + | requestID, r := ensureRequestID(w, r) | |
| 62 | + | ||
| 63 | + | // Wrap the response writer to capture status code and bytes written. | |
| 64 | + | rw := NewResponseWriter(w) | |
| 65 | + | ||
| 66 | + | // Resolve client IP before calling the inner handler so we see the | |
| 67 | + | // original remote address before any mutation. | |
| 68 | + | clientIP := GetClientIP(r, nets) | |
| 69 | + | ||
| 70 | + | next.ServeHTTP(rw, r) | |
| 71 | + | ||
| 72 | + | // Apply health-check exclusion after the response so we always allow | |
| 73 | + | // the request to complete, we just don't log it. | |
| 74 | + | if excludeHealthChecks { | |
| 75 | + | if strings.HasPrefix(r.UserAgent(), "Gordon-HealthCheck/") || isLoopback(clientIP) { | |
| 76 | + | return | |
| 77 | + | } | |
| 78 | + | } | |
| 79 | + | ||
| 80 | + | durationMS := float64(time.Since(start).Microseconds()) / 1000.0 | |
| 81 | + | ||
| 82 | + | entry := accesslog.Entry{ | |
| 83 | + | Time: time.Now().UTC(), | |
| 84 | + | ClientIP: clientIP, | |
| 85 | + | Method: r.Method, | |
| 86 | + | Host: r.Host, | |
| 87 | + | Path: r.URL.Path, | |
| 88 | + | Query: r.URL.RawQuery, | |
| 89 | + | Status: rw.StatusCode(), | |
| 90 | + | BytesSent: rw.BytesWritten(), | |
| 91 | + | DurationMS: durationMS, | |
| 92 | + | UserAgent: r.UserAgent(), | |
| 93 | + | Referer: r.Referer(), | |
| 94 | + | RequestID: requestID, | |
| 95 | + | Proto: r.Proto, | |
| 96 | + | } | |
| 97 | + | ||
| 98 | + | if err := writer.Write(entry); err != nil { | |
| 99 | + | log.Warn(). | |
| 100 | + | Str(zerowrap.FieldLayer, "adapter"). | |
| 101 | + | Str(zerowrap.FieldAdapter, "http"). | |
| 102 | + | Err(err). | |
| 103 | + | Msg("access log write failed") | |
| 104 | + | } | |
| 105 | + | }) | |
| 106 | + | } | |
| 107 | + | } | |
| @@ -0,0 +1,107 @@ | |||||
| 1 | + | package middleware | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "net" | |||
| 5 | + | "net/http" | |||
| 6 | + | "strings" | |||
| 7 | + | "time" | |||
| 8 | + | ||||
| 9 | + | "github.com/bnema/zerowrap" | |||
| 10 | + | ||||
| 11 | + | "github.com/bnema/gordon/internal/adapters/out/accesslog" | |||
| 12 | + | ) | |||
| 13 | + | ||||
| 14 | + | // loopbackNets contains the loopback ranges used for health-check exclusion. | |||
| 15 | + | var loopbackNets = func() []*net.IPNet { | |||
| 16 | + | _, ipv4Loopback, _ := net.ParseCIDR("127.0.0.0/8") | |||
| 17 | + | _, ipv6Loopback, _ := net.ParseCIDR("::1/128") | |||
| 18 | + | return []*net.IPNet{ipv4Loopback, ipv6Loopback} | |||
| 19 | + | }() | |||
| 20 | + | ||||
| 21 | + | // isLoopback reports whether the given IP string is a loopback address. | |||
| 22 | + | func isLoopback(ip string) bool { | |||
| 23 | + | parsed := net.ParseIP(ip) | |||
| 24 | + | if parsed == nil { | |||
| 25 | + | return false | |||
| 26 | + | } | |||
| 27 | + | for _, n := range loopbackNets { | |||
| 28 | + | if n.Contains(parsed) { | |||
| 29 | + | return true | |||
| 30 | + | } | |||
| 31 | + | } | |||
| 32 | + | return false | |||
| 33 | + | } | |||
| 34 | + | ||||
| 35 | + | // AccessLogWriter is the interface the middleware needs from the output adapter. | |||
| 36 | + | // *accesslog.Writer satisfies this interface. | |||
| 37 | + | type AccessLogWriter interface { | |||
| 38 | + | Write(entry accesslog.Entry) error | |||
| 39 | + | } | |||
| 40 | + | ||||
| 41 | + | // AccessLogger is a middleware that writes one access-log entry per HTTP request | |||
| 42 | + | // to the provided writer. It runs alongside (not instead of) RequestLogger. | |||
| 43 | + | // | |||
| 44 | + | // When excludeHealthChecks is true, requests from the Gordon health prober | |||
| 45 | + | // (UA prefix "Gordon-HealthCheck/") or from loopback IPs are not logged. | |||
| 46 | + | // | |||
| 47 | + | // Write failures are reported as warnings through the application logger and | |||
| 48 | + | // never fail the HTTP response. | |||
| 49 | + | func AccessLogger(writer AccessLogWriter, excludeHealthChecks bool, log zerowrap.Logger, trustedNets ...[]*net.IPNet) func(http.Handler) http.Handler { | |||
| 50 | + | var nets []*net.IPNet | |||
| 51 | + | if len(trustedNets) > 0 { | |||
| 52 | + | nets = trustedNets[0] | |||
| 53 | + | } | |||
| 54 | + | ||||
| 55 | + | return func(next http.Handler) http.Handler { | |||
| 56 | + | return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 57 | + | start := time.Now() | |||
| 58 | + | ||||
| 59 | + | // Ensure a request ID exists before calling inner handlers so both | |||
| 60 | + | // this middleware and RequestLogger share the same value. | |||
| 61 | + | requestID, r := ensureRequestID(w, r) | |||
| 62 | + | ||||
| 63 | + | // Wrap the response writer to capture status code and bytes written. | |||
| 64 | + | rw := NewResponseWriter(w) | |||
| 65 | + | ||||
| 66 | + | // Resolve client IP before calling the inner handler so we see the | |||
| 67 | + | // original remote address before any mutation. | |||
| 68 | + | clientIP := GetClientIP(r, nets) | |||
| 69 | + | ||||
| 70 | + | next.ServeHTTP(rw, r) | |||
| 71 | + | ||||
| 72 | + | // Apply health-check exclusion after the response so we always allow | |||
| 73 | + | // the request to complete, we just don't log it. | |||
| 74 | + | if excludeHealthChecks { | |||
| 75 | + | if strings.HasPrefix(r.UserAgent(), "Gordon-HealthCheck/") || isLoopback(clientIP) { | |||
| 76 | + | return | |||
| 77 | + | } | |||
| 78 | + | } | |||
| 79 | + | ||||
| 80 | + | durationMS := float64(time.Since(start).Microseconds()) / 1000.0 | |||
| 81 | + | ||||
| 82 | + | entry := accesslog.Entry{ | |||
| 83 | + | Time: time.Now().UTC(), | |||
| 84 | + | ClientIP: clientIP, | |||
| 85 | + | Method: r.Method, | |||
| 86 | + | Host: r.Host, | |||
| 87 | + | Path: r.URL.Path, | |||
| 88 | + | Query: r.URL.RawQuery, | |||
| 89 | + | Status: rw.StatusCode(), | |||
| 90 | + | BytesSent: rw.BytesWritten(), | |||
| 91 | + | DurationMS: durationMS, | |||
| 92 | + | UserAgent: r.UserAgent(), | |||
| 93 | + | Referer: r.Referer(), | |||
| 94 | + | RequestID: requestID, | |||
| 95 | + | Proto: r.Proto, | |||
| 96 | + | } | |||
| 97 | + | ||||
| 98 | + | if err := writer.Write(entry); err != nil { | |||
| 99 | + | log.Warn(). | |||
| 100 | + | Str(zerowrap.FieldLayer, "adapter"). | |||
| 101 | + | Str(zerowrap.FieldAdapter, "http"). | |||
| 102 | + | Err(err). | |||
| 103 | + | Msg("access log write failed") | |||
| 104 | + | } | |||
| 105 | + | }) | |||
| 106 | + | } | |||
| 107 | + | } | |||
A internal/adapters/in/http/middleware/accesslog_test.go +170 -0
| @@ -0,0 +1,170 @@ | |||
| 1 | + | package middleware | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "fmt" | |
| 5 | + | "net/http" | |
| 6 | + | "net/http/httptest" | |
| 7 | + | "testing" | |
| 8 | + | ||
| 9 | + | "github.com/stretchr/testify/assert" | |
| 10 | + | "github.com/stretchr/testify/require" | |
| 11 | + | ||
| 12 | + | "github.com/bnema/gordon/internal/adapters/out/accesslog" | |
| 13 | + | ) | |
| 14 | + | ||
| 15 | + | // mockAccessLogWriter records written entries and optionally returns an error. | |
| 16 | + | type mockAccessLogWriter struct { | |
| 17 | + | entries []accesslog.Entry | |
| 18 | + | err error | |
| 19 | + | } | |
| 20 | + | ||
| 21 | + | func (m *mockAccessLogWriter) Write(entry accesslog.Entry) error { | |
| 22 | + | m.entries = append(m.entries, entry) | |
| 23 | + | return m.err | |
| 24 | + | } | |
| 25 | + | ||
| 26 | + | func TestAccessLogger_EmitsEntryPerRequest(t *testing.T) { | |
| 27 | + | mock := &mockAccessLogWriter{} | |
| 28 | + | log := testLogger() | |
| 29 | + | ||
| 30 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 31 | + | w.WriteHeader(http.StatusOK) | |
| 32 | + | _, _ = w.Write([]byte("hello")) | |
| 33 | + | })) | |
| 34 | + | ||
| 35 | + | req := httptest.NewRequest(http.MethodGet, "/some/path?foo=bar", nil) | |
| 36 | + | req.RemoteAddr = "192.168.1.100:12345" | |
| 37 | + | req.Header.Set("User-Agent", "test-agent") | |
| 38 | + | req.Header.Set("Referer", "https://example.com") | |
| 39 | + | req.RequestURI = "/some/path?foo=bar" | |
| 40 | + | req.Host = "example.com" | |
| 41 | + | req.Proto = "HTTP/1.1" | |
| 42 | + | rw := httptest.NewRecorder() | |
| 43 | + | ||
| 44 | + | handler.ServeHTTP(rw, req) | |
| 45 | + | ||
| 46 | + | require.Len(t, mock.entries, 1) | |
| 47 | + | e := mock.entries[0] | |
| 48 | + | assert.Equal(t, http.MethodGet, e.Method) | |
| 49 | + | assert.Equal(t, "/some/path", e.Path) | |
| 50 | + | assert.Equal(t, "foo=bar", e.Query) | |
| 51 | + | assert.Equal(t, "example.com", e.Host) | |
| 52 | + | assert.Equal(t, http.StatusOK, e.Status) | |
| 53 | + | assert.Equal(t, 5, e.BytesSent) | |
| 54 | + | assert.Equal(t, "test-agent", e.UserAgent) | |
| 55 | + | assert.Equal(t, "https://example.com", e.Referer) | |
| 56 | + | assert.Equal(t, "HTTP/1.1", e.Proto) | |
| 57 | + | assert.NotEmpty(t, e.RequestID) | |
| 58 | + | assert.Equal(t, "192.168.1.100", e.ClientIP) | |
| 59 | + | } | |
| 60 | + | ||
| 61 | + | func TestAccessLogger_RequestIDReused(t *testing.T) { | |
| 62 | + | mock := &mockAccessLogWriter{} | |
| 63 | + | log := testLogger() | |
| 64 | + | ||
| 65 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 66 | + | w.WriteHeader(http.StatusOK) | |
| 67 | + | })) | |
| 68 | + | ||
| 69 | + | req := httptest.NewRequest(http.MethodGet, "/", nil) | |
| 70 | + | req.Header.Set("X-Request-ID", "fixed-id-123") | |
| 71 | + | rw := httptest.NewRecorder() | |
| 72 | + | ||
| 73 | + | handler.ServeHTTP(rw, req) | |
| 74 | + | ||
| 75 | + | require.Len(t, mock.entries, 1) | |
| 76 | + | assert.Equal(t, "fixed-id-123", mock.entries[0].RequestID) | |
| 77 | + | } | |
| 78 | + | ||
| 79 | + | func TestAccessLogger_ExcludeHealthCheckUA(t *testing.T) { | |
| 80 | + | mock := &mockAccessLogWriter{} | |
| 81 | + | log := testLogger() | |
| 82 | + | ||
| 83 | + | handler := AccessLogger(mock, true, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 84 | + | w.WriteHeader(http.StatusOK) | |
| 85 | + | })) | |
| 86 | + | ||
| 87 | + | req := httptest.NewRequest(http.MethodGet, "/health", nil) | |
| 88 | + | req.Header.Set("User-Agent", "Gordon-HealthCheck/1.0") | |
| 89 | + | rw := httptest.NewRecorder() | |
| 90 | + | ||
| 91 | + | handler.ServeHTTP(rw, req) | |
| 92 | + | ||
| 93 | + | assert.Empty(t, mock.entries, "health-check request should not be logged") | |
| 94 | + | } | |
| 95 | + | ||
| 96 | + | func TestAccessLogger_ExcludeLoopbackIP(t *testing.T) { | |
| 97 | + | mock := &mockAccessLogWriter{} | |
| 98 | + | log := testLogger() | |
| 99 | + | ||
| 100 | + | handler := AccessLogger(mock, true, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 101 | + | w.WriteHeader(http.StatusOK) | |
| 102 | + | })) | |
| 103 | + | ||
| 104 | + | req := httptest.NewRequest(http.MethodGet, "/health", nil) | |
| 105 | + | req.RemoteAddr = "127.0.0.1:54321" | |
| 106 | + | rw := httptest.NewRecorder() | |
| 107 | + | ||
| 108 | + | handler.ServeHTTP(rw, req) | |
| 109 | + | ||
| 110 | + | assert.Empty(t, mock.entries, "loopback request should not be logged") | |
| 111 | + | } | |
| 112 | + | ||
| 113 | + | func TestAccessLogger_NoExcludeWhenDisabled(t *testing.T) { | |
| 114 | + | mock := &mockAccessLogWriter{} | |
| 115 | + | log := testLogger() | |
| 116 | + | ||
| 117 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 118 | + | w.WriteHeader(http.StatusOK) | |
| 119 | + | })) | |
| 120 | + | ||
| 121 | + | req := httptest.NewRequest(http.MethodGet, "/health", nil) | |
| 122 | + | req.Header.Set("User-Agent", "Gordon-HealthCheck/1.0") | |
| 123 | + | rw := httptest.NewRecorder() | |
| 124 | + | ||
| 125 | + | handler.ServeHTTP(rw, req) | |
| 126 | + | ||
| 127 | + | assert.Len(t, mock.entries, 1, "health-check request should be logged when excludeHealthChecks=false") | |
| 128 | + | } | |
| 129 | + | ||
| 130 | + | func TestAccessLogger_WriteFailureDoesNotAffectResponse(t *testing.T) { | |
| 131 | + | mock := &mockAccessLogWriter{err: fmt.Errorf("disk full")} | |
| 132 | + | log := testLogger() | |
| 133 | + | ||
| 134 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 135 | + | w.WriteHeader(http.StatusOK) | |
| 136 | + | _, _ = w.Write([]byte("ok")) | |
| 137 | + | })) | |
| 138 | + | ||
| 139 | + | req := httptest.NewRequest(http.MethodGet, "/", nil) | |
| 140 | + | rw := httptest.NewRecorder() | |
| 141 | + | ||
| 142 | + | // Should not panic or change the response. | |
| 143 | + | handler.ServeHTTP(rw, req) | |
| 144 | + | ||
| 145 | + | assert.Equal(t, http.StatusOK, rw.Code) | |
| 146 | + | assert.Equal(t, "ok", rw.Body.String()) | |
| 147 | + | } | |
| 148 | + | ||
| 149 | + | func TestAccessLogger_PanicRecoveryChain_Captures500(t *testing.T) { | |
| 150 | + | mock := &mockAccessLogWriter{} | |
| 151 | + | log := testLogger() | |
| 152 | + | ||
| 153 | + | // Chain: AccessLogger (outer) → PanicRecovery → panicking handler | |
| 154 | + | panicHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |
| 155 | + | panic("test panic") | |
| 156 | + | }) | |
| 157 | + | chain := AccessLogger(mock, false, log)(PanicRecovery(log)(panicHandler)) | |
| 158 | + | ||
| 159 | + | req := httptest.NewRequest(http.MethodGet, "/crash", nil) | |
| 160 | + | rw := httptest.NewRecorder() | |
| 161 | + | ||
| 162 | + | chain.ServeHTTP(rw, req) | |
| 163 | + | ||
| 164 | + | // PanicRecovery should have written 500. | |
| 165 | + | assert.Equal(t, http.StatusInternalServerError, rw.Code) | |
| 166 | + | ||
| 167 | + | // AccessLogger must have captured the 500. | |
| 168 | + | require.Len(t, mock.entries, 1) | |
| 169 | + | assert.Equal(t, http.StatusInternalServerError, mock.entries[0].Status) | |
| 170 | + | } | |
| @@ -0,0 +1,170 @@ | |||||
| 1 | + | package middleware | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "fmt" | |||
| 5 | + | "net/http" | |||
| 6 | + | "net/http/httptest" | |||
| 7 | + | "testing" | |||
| 8 | + | ||||
| 9 | + | "github.com/stretchr/testify/assert" | |||
| 10 | + | "github.com/stretchr/testify/require" | |||
| 11 | + | ||||
| 12 | + | "github.com/bnema/gordon/internal/adapters/out/accesslog" | |||
| 13 | + | ) | |||
| 14 | + | ||||
| 15 | + | // mockAccessLogWriter records written entries and optionally returns an error. | |||
| 16 | + | type mockAccessLogWriter struct { | |||
| 17 | + | entries []accesslog.Entry | |||
| 18 | + | err error | |||
| 19 | + | } | |||
| 20 | + | ||||
| 21 | + | func (m *mockAccessLogWriter) Write(entry accesslog.Entry) error { | |||
| 22 | + | m.entries = append(m.entries, entry) | |||
| 23 | + | return m.err | |||
| 24 | + | } | |||
| 25 | + | ||||
| 26 | + | func TestAccessLogger_EmitsEntryPerRequest(t *testing.T) { | |||
| 27 | + | mock := &mockAccessLogWriter{} | |||
| 28 | + | log := testLogger() | |||
| 29 | + | ||||
| 30 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 31 | + | w.WriteHeader(http.StatusOK) | |||
| 32 | + | _, _ = w.Write([]byte("hello")) | |||
| 33 | + | })) | |||
| 34 | + | ||||
| 35 | + | req := httptest.NewRequest(http.MethodGet, "/some/path?foo=bar", nil) | |||
| 36 | + | req.RemoteAddr = "192.168.1.100:12345" | |||
| 37 | + | req.Header.Set("User-Agent", "test-agent") | |||
| 38 | + | req.Header.Set("Referer", "https://example.com") | |||
| 39 | + | req.RequestURI = "/some/path?foo=bar" | |||
| 40 | + | req.Host = "example.com" | |||
| 41 | + | req.Proto = "HTTP/1.1" | |||
| 42 | + | rw := httptest.NewRecorder() | |||
| 43 | + | ||||
| 44 | + | handler.ServeHTTP(rw, req) | |||
| 45 | + | ||||
| 46 | + | require.Len(t, mock.entries, 1) | |||
| 47 | + | e := mock.entries[0] | |||
| 48 | + | assert.Equal(t, http.MethodGet, e.Method) | |||
| 49 | + | assert.Equal(t, "/some/path", e.Path) | |||
| 50 | + | assert.Equal(t, "foo=bar", e.Query) | |||
| 51 | + | assert.Equal(t, "example.com", e.Host) | |||
| 52 | + | assert.Equal(t, http.StatusOK, e.Status) | |||
| 53 | + | assert.Equal(t, 5, e.BytesSent) | |||
| 54 | + | assert.Equal(t, "test-agent", e.UserAgent) | |||
| 55 | + | assert.Equal(t, "https://example.com", e.Referer) | |||
| 56 | + | assert.Equal(t, "HTTP/1.1", e.Proto) | |||
| 57 | + | assert.NotEmpty(t, e.RequestID) | |||
| 58 | + | assert.Equal(t, "192.168.1.100", e.ClientIP) | |||
| 59 | + | } | |||
| 60 | + | ||||
| 61 | + | func TestAccessLogger_RequestIDReused(t *testing.T) { | |||
| 62 | + | mock := &mockAccessLogWriter{} | |||
| 63 | + | log := testLogger() | |||
| 64 | + | ||||
| 65 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 66 | + | w.WriteHeader(http.StatusOK) | |||
| 67 | + | })) | |||
| 68 | + | ||||
| 69 | + | req := httptest.NewRequest(http.MethodGet, "/", nil) | |||
| 70 | + | req.Header.Set("X-Request-ID", "fixed-id-123") | |||
| 71 | + | rw := httptest.NewRecorder() | |||
| 72 | + | ||||
| 73 | + | handler.ServeHTTP(rw, req) | |||
| 74 | + | ||||
| 75 | + | require.Len(t, mock.entries, 1) | |||
| 76 | + | assert.Equal(t, "fixed-id-123", mock.entries[0].RequestID) | |||
| 77 | + | } | |||
| 78 | + | ||||
| 79 | + | func TestAccessLogger_ExcludeHealthCheckUA(t *testing.T) { | |||
| 80 | + | mock := &mockAccessLogWriter{} | |||
| 81 | + | log := testLogger() | |||
| 82 | + | ||||
| 83 | + | handler := AccessLogger(mock, true, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 84 | + | w.WriteHeader(http.StatusOK) | |||
| 85 | + | })) | |||
| 86 | + | ||||
| 87 | + | req := httptest.NewRequest(http.MethodGet, "/health", nil) | |||
| 88 | + | req.Header.Set("User-Agent", "Gordon-HealthCheck/1.0") | |||
| 89 | + | rw := httptest.NewRecorder() | |||
| 90 | + | ||||
| 91 | + | handler.ServeHTTP(rw, req) | |||
| 92 | + | ||||
| 93 | + | assert.Empty(t, mock.entries, "health-check request should not be logged") | |||
| 94 | + | } | |||
| 95 | + | ||||
| 96 | + | func TestAccessLogger_ExcludeLoopbackIP(t *testing.T) { | |||
| 97 | + | mock := &mockAccessLogWriter{} | |||
| 98 | + | log := testLogger() | |||
| 99 | + | ||||
| 100 | + | handler := AccessLogger(mock, true, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 101 | + | w.WriteHeader(http.StatusOK) | |||
| 102 | + | })) | |||
| 103 | + | ||||
| 104 | + | req := httptest.NewRequest(http.MethodGet, "/health", nil) | |||
| 105 | + | req.RemoteAddr = "127.0.0.1:54321" | |||
| 106 | + | rw := httptest.NewRecorder() | |||
| 107 | + | ||||
| 108 | + | handler.ServeHTTP(rw, req) | |||
| 109 | + | ||||
| 110 | + | assert.Empty(t, mock.entries, "loopback request should not be logged") | |||
| 111 | + | } | |||
| 112 | + | ||||
| 113 | + | func TestAccessLogger_NoExcludeWhenDisabled(t *testing.T) { | |||
| 114 | + | mock := &mockAccessLogWriter{} | |||
| 115 | + | log := testLogger() | |||
| 116 | + | ||||
| 117 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 118 | + | w.WriteHeader(http.StatusOK) | |||
| 119 | + | })) | |||
| 120 | + | ||||
| 121 | + | req := httptest.NewRequest(http.MethodGet, "/health", nil) | |||
| 122 | + | req.Header.Set("User-Agent", "Gordon-HealthCheck/1.0") | |||
| 123 | + | rw := httptest.NewRecorder() | |||
| 124 | + | ||||
| 125 | + | handler.ServeHTTP(rw, req) | |||
| 126 | + | ||||
| 127 | + | assert.Len(t, mock.entries, 1, "health-check request should be logged when excludeHealthChecks=false") | |||
| 128 | + | } | |||
| 129 | + | ||||
| 130 | + | func TestAccessLogger_WriteFailureDoesNotAffectResponse(t *testing.T) { | |||
| 131 | + | mock := &mockAccessLogWriter{err: fmt.Errorf("disk full")} | |||
| 132 | + | log := testLogger() | |||
| 133 | + | ||||
| 134 | + | handler := AccessLogger(mock, false, log)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 135 | + | w.WriteHeader(http.StatusOK) | |||
| 136 | + | _, _ = w.Write([]byte("ok")) | |||
| 137 | + | })) | |||
| 138 | + | ||||
| 139 | + | req := httptest.NewRequest(http.MethodGet, "/", nil) | |||
| 140 | + | rw := httptest.NewRecorder() | |||
| 141 | + | ||||
| 142 | + | // Should not panic or change the response. | |||
| 143 | + | handler.ServeHTTP(rw, req) | |||
| 144 | + | ||||
| 145 | + | assert.Equal(t, http.StatusOK, rw.Code) | |||
| 146 | + | assert.Equal(t, "ok", rw.Body.String()) | |||
| 147 | + | } | |||
| 148 | + | ||||
| 149 | + | func TestAccessLogger_PanicRecoveryChain_Captures500(t *testing.T) { | |||
| 150 | + | mock := &mockAccessLogWriter{} | |||
| 151 | + | log := testLogger() | |||
| 152 | + | ||||
| 153 | + | // Chain: AccessLogger (outer) → PanicRecovery → panicking handler | |||
| 154 | + | panicHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { | |||
| 155 | + | panic("test panic") | |||
| 156 | + | }) | |||
| 157 | + | chain := AccessLogger(mock, false, log)(PanicRecovery(log)(panicHandler)) | |||
| 158 | + | ||||
| 159 | + | req := httptest.NewRequest(http.MethodGet, "/crash", nil) | |||
| 160 | + | rw := httptest.NewRecorder() | |||
| 161 | + | ||||
| 162 | + | chain.ServeHTTP(rw, req) | |||
| 163 | + | ||||
| 164 | + | // PanicRecovery should have written 500. | |||
| 165 | + | assert.Equal(t, http.StatusInternalServerError, rw.Code) | |||
| 166 | + | ||||
| 167 | + | // AccessLogger must have captured the 500. | |||
| 168 | + | require.Len(t, mock.entries, 1) | |||
| 169 | + | assert.Equal(t, http.StatusInternalServerError, mock.entries[0].Status) | |||
| 170 | + | } | |||
M internal/adapters/in/http/middleware/logging.go +14 -7
| @@ -67,6 +67,19 @@ func (rw *ResponseWriter) Unwrap() http.ResponseWriter { | |||
| 67 | 67 | return rw.ResponseWriter | |
| 68 | 68 | } | |
| 69 | 69 | ||
| 70 | + | // ensureRequestID returns the X-Request-ID from the request if present, or generates | |
| 71 | + | // a new one. It sets X-Request-ID on both the request and response headers and returns | |
| 72 | + | // the ID along with the (potentially updated) request. | |
| 73 | + | func ensureRequestID(w http.ResponseWriter, r *http.Request) (string, *http.Request) { | |
| 74 | + | requestID := r.Header.Get("X-Request-ID") | |
| 75 | + | if requestID == "" { | |
| 76 | + | requestID = generateRequestID() | |
| 77 | + | r.Header.Set("X-Request-ID", requestID) | |
| 78 | + | } | |
| 79 | + | w.Header().Set("X-Request-ID", requestID) | |
| 80 | + | return requestID, r | |
| 81 | + | } | |
| 82 | + | ||
| 70 | 83 | // RequestLogger is a middleware that logs HTTP requests using zerowrap. | |
| 71 | 84 | // It also attaches the logger to the request context for downstream handlers. | |
| 72 | 85 | // The trustedNets parameter controls which proxy headers are trusted for IP extraction. | |
| @@ -81,13 +94,7 @@ func RequestLogger(log zerowrap.Logger, trustedNets ...[]*net.IPNet) func(http.H | |||
| 81 | 94 | start := time.Now() | |
| 82 | 95 | ||
| 83 | 96 | // Generate or reuse X-Request-ID for request tracing | |
| 84 | - | requestID := r.Header.Get("X-Request-ID") | |
| 85 | - | if requestID == "" { | |
| 86 | - | requestID = generateRequestID() | |
| 87 | - | // Set on the incoming request so downstream handlers can read it | |
| 88 | - | r.Header.Set("X-Request-ID", requestID) | |
| 89 | - | } | |
| 90 | - | w.Header().Set("X-Request-ID", requestID) | |
| 97 | + | requestID, r := ensureRequestID(w, r) | |
| 91 | 98 | ||
| 92 | 99 | // Wrap the response writer to capture status and bytes | |
| 93 | 100 | rw := NewResponseWriter(w) | |
| @@ -67,6 +67,19 @@ func (rw *ResponseWriter) Unwrap() http.ResponseWriter { | |||||
| 67 | return rw.ResponseWriter | 67 | return rw.ResponseWriter | ||
| 68 | } | 68 | } | ||
| 69 | 69 | ||||
| 70 | + | // ensureRequestID returns the X-Request-ID from the request if present, or generates | |||
| 71 | + | // a new one. It sets X-Request-ID on both the request and response headers and returns | |||
| 72 | + | // the ID along with the (potentially updated) request. | |||
| 73 | + | func ensureRequestID(w http.ResponseWriter, r *http.Request) (string, *http.Request) { | |||
| 74 | + | requestID := r.Header.Get("X-Request-ID") | |||
| 75 | + | if requestID == "" { | |||
| 76 | + | requestID = generateRequestID() | |||
| 77 | + | r.Header.Set("X-Request-ID", requestID) | |||
| 78 | + | } | |||
| 79 | + | w.Header().Set("X-Request-ID", requestID) | |||
| 80 | + | return requestID, r | |||
| 81 | + | } | |||
| 82 | + | ||||
| 70 | // RequestLogger is a middleware that logs HTTP requests using zerowrap. | 83 | // RequestLogger is a middleware that logs HTTP requests using zerowrap. | ||
| 71 | // It also attaches the logger to the request context for downstream handlers. | 84 | // It also attaches the logger to the request context for downstream handlers. | ||
| 72 | // The trustedNets parameter controls which proxy headers are trusted for IP extraction. | 85 | // The trustedNets parameter controls which proxy headers are trusted for IP extraction. | ||
| @@ -81,13 +94,7 @@ func RequestLogger(log zerowrap.Logger, trustedNets ...[]*net.IPNet) func(http.H | |||||
| 81 | start := time.Now() | 94 | start := time.Now() | ||
| 82 | 95 | ||||
| 83 | // Generate or reuse X-Request-ID for request tracing | 96 | // Generate or reuse X-Request-ID for request tracing | ||
| 84 | - | requestID := r.Header.Get("X-Request-ID") | 97 | + | requestID, r := ensureRequestID(w, r) |
| 85 | - | if requestID == "" { | |||
| 86 | - | requestID = generateRequestID() | |||
| 87 | - | // Set on the incoming request so downstream handlers can read it | |||
| 88 | - | r.Header.Set("X-Request-ID", requestID) | |||
| 89 | - | } | |||
| 90 | - | w.Header().Set("X-Request-ID", requestID) | |||
| 91 | 98 | ||||
| 92 | // Wrap the response writer to capture status and bytes | 99 | // Wrap the response writer to capture status and bytes | ||
| 93 | rw := NewResponseWriter(w) | 100 | rw := NewResponseWriter(w) | ||