diff --git a/cmd/bridge/main.go b/cmd/bridge/main.go index fd43d05f..8bbb4380 100644 --- a/cmd/bridge/main.go +++ b/cmd/bridge/main.go @@ -260,8 +260,9 @@ func main() { }) } - // Wrap with auth middleware. + // Wrap with middlewares: request logging first, then auth. handler := auth.AuthMiddleware(store, mgr, dbpool)(mux) + handler = bridge.RequestLoggingMiddleware()(handler) server := &http.Server{ Addr: ":" + cfg.Port, diff --git a/internal/bridge/middleware.go b/internal/bridge/middleware.go new file mode 100644 index 00000000..c36e99b6 --- /dev/null +++ b/internal/bridge/middleware.go @@ -0,0 +1,174 @@ +// Copyright 2026 Brian Bouterse +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package bridge + +import ( + "log" + "net/http" + "strings" + "time" +) + +// responseWriter wraps http.ResponseWriter to capture status code and response size +type responseWriter struct { + http.ResponseWriter + statusCode int + size int +} + +func (rw *responseWriter) WriteHeader(statusCode int) { + rw.statusCode = statusCode + rw.ResponseWriter.WriteHeader(statusCode) +} + +func (rw *responseWriter) Write(b []byte) (int, error) { + if rw.statusCode == 0 { + rw.statusCode = http.StatusOK + } + size, err := rw.ResponseWriter.Write(b) + rw.size += size + return size, err +} + +// RequestLoggingMiddleware logs HTTP request details for debugging +func RequestLoggingMiddleware() func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + start := time.Now() + + // Create wrapped response writer to capture status and size + wrapped := &responseWriter{ResponseWriter: w, statusCode: 0, size: 0} + + // Log request details + logRequest(r) + + // Process request + next.ServeHTTP(wrapped, r) + + // Log response details + duration := time.Since(start) + logResponse(r, wrapped.statusCode, wrapped.size, duration) + }) + } +} + +// logRequest logs incoming HTTP request details +func logRequest(r *http.Request) { + // Get basic request info + method := r.Method + path := r.URL.Path + query := r.URL.RawQuery + userAgent := r.Header.Get("User-Agent") + contentType := r.Header.Get("Content-Type") + contentLength := r.Header.Get("Content-Length") + + // Get authentication context if present + user := r.Header.Get("X-Alcove-User") + team := r.Header.Get("X-Alcove-Team-ID") + isAdmin := r.Header.Get("X-Alcove-Admin") == "true" + + // Build log message + logMsg := []string{ + "request", + "method=" + method, + "path=" + path, + } + + if query != "" { + logMsg = append(logMsg, "query="+query) + } + + if user != "" { + logMsg = append(logMsg, "user="+user) + } + + if team != "" { + logMsg = append(logMsg, "team="+team) + } + + if isAdmin { + logMsg = append(logMsg, "admin=true") + } + + if contentType != "" { + logMsg = append(logMsg, "content_type="+contentType) + } + + if contentLength != "" { + logMsg = append(logMsg, "content_length="+contentLength) + } + + if userAgent != "" { + logMsg = append(logMsg, "user_agent="+userAgent) + } + + // Add remote address + remoteAddr := r.RemoteAddr + if forwarded := r.Header.Get("X-Forwarded-For"); forwarded != "" { + remoteAddr = forwarded + } + logMsg = append(logMsg, "remote_addr="+remoteAddr) + + log.Printf("http: %s", strings.Join(logMsg, " ")) +} + +// logResponse logs HTTP response details +func logResponse(r *http.Request, statusCode, size int, duration time.Duration) { + // Build log message + logMsg := []string{ + "response", + "method=" + r.Method, + "path=" + r.URL.Path, + "status=" + http.StatusText(statusCode) + "(" + itoa(statusCode) + ")", + "size=" + itoa(size) + "b", + "duration=" + duration.String(), + } + + // Add user context if present + if user := r.Header.Get("X-Alcove-User"); user != "" { + logMsg = append(logMsg, "user="+user) + } + + log.Printf("http: %s", strings.Join(logMsg, " ")) +} + +// itoa converts int to string (simple alternative to strconv.Itoa) +func itoa(i int) string { + if i == 0 { + return "0" + } + + // Handle negative numbers + negative := i < 0 + if negative { + i = -i + } + + // Convert to string + var buf [20]byte // enough for 64-bit int + pos := len(buf) + for i > 0 { + pos-- + buf[pos] = byte(i%10) + '0' + i /= 10 + } + + if negative { + pos-- + buf[pos] = '-' + } + + return string(buf[pos:]) +} \ No newline at end of file diff --git a/internal/bridge/middleware_test.go b/internal/bridge/middleware_test.go new file mode 100644 index 00000000..4397f53f --- /dev/null +++ b/internal/bridge/middleware_test.go @@ -0,0 +1,192 @@ +// Copyright 2026 Brian Bouterse +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package bridge + +import ( + "bytes" + "log" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" +) + +func TestRequestLoggingMiddleware(t *testing.T) { + // Capture log output + var logOutput bytes.Buffer + log.SetOutput(&logOutput) + defer func() { + log.SetOutput(os.Stderr) + }() + + // Create test handler + handler := RequestLoggingMiddleware()(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.Write([]byte("test response")) + })) + + // Test basic request + t.Run("basic request", func(t *testing.T) { + logOutput.Reset() + + req := httptest.NewRequest("GET", "/api/v1/health", nil) + req.Header.Set("User-Agent", "test-agent") + req.Header.Set("Content-Type", "application/json") + + rr := httptest.NewRecorder() + handler.ServeHTTP(rr, req) + + logStr := logOutput.String() + + // Check request log + if !strings.Contains(logStr, "http: request method=GET path=/api/v1/health") { + t.Errorf("Expected request log, got: %s", logStr) + } + + // Check response log + if !strings.Contains(logStr, "http: response method=GET path=/api/v1/health status=OK(200)") { + t.Errorf("Expected response log, got: %s", logStr) + } + + // Check that user agent is logged + if !strings.Contains(logStr, "user_agent=test-agent") { + t.Errorf("Expected user agent in log, got: %s", logStr) + } + }) + + // Test request with authentication context + t.Run("authenticated request", func(t *testing.T) { + logOutput.Reset() + + req := httptest.NewRequest("POST", "/api/v1/sessions", strings.NewReader(`{"prompt":"test"}`)) + req.Header.Set("X-Alcove-User", "testuser") + req.Header.Set("X-Alcove-Team-ID", "team123") + req.Header.Set("X-Alcove-Admin", "true") + req.Header.Set("Content-Type", "application/json") + + rr := httptest.NewRecorder() + handler.ServeHTTP(rr, req) + + logStr := logOutput.String() + + // Check authentication context + if !strings.Contains(logStr, "user=testuser") { + t.Errorf("Expected user in log, got: %s", logStr) + } + + if !strings.Contains(logStr, "team=team123") { + t.Errorf("Expected team in log, got: %s", logStr) + } + + if !strings.Contains(logStr, "admin=true") { + t.Errorf("Expected admin flag in log, got: %s", logStr) + } + }) + + // Test request with query parameters + t.Run("request with query", func(t *testing.T) { + logOutput.Reset() + + req := httptest.NewRequest("GET", "/api/v1/sessions?status=running&page=1", nil) + + rr := httptest.NewRecorder() + handler.ServeHTTP(rr, req) + + logStr := logOutput.String() + + // Check query parameters are logged + if !strings.Contains(logStr, "query=status=running&page=1") { + t.Errorf("Expected query params in log, got: %s", logStr) + } + }) + + // Test forwarded headers + t.Run("forwarded headers", func(t *testing.T) { + logOutput.Reset() + + req := httptest.NewRequest("GET", "/api/v1/health", nil) + req.Header.Set("X-Forwarded-For", "192.168.1.100") + + rr := httptest.NewRecorder() + handler.ServeHTTP(rr, req) + + logStr := logOutput.String() + + // Check forwarded IP is logged + if !strings.Contains(logStr, "remote_addr=192.168.1.100") { + t.Errorf("Expected forwarded IP in log, got: %s", logStr) + } + }) +} + +func TestResponseWriter(t *testing.T) { + t.Run("captures status code and size", func(t *testing.T) { + rr := httptest.NewRecorder() + rw := &responseWriter{ResponseWriter: rr} + + rw.WriteHeader(http.StatusNotFound) + n, err := rw.Write([]byte("not found")) + + if err != nil { + t.Fatalf("Write failed: %v", err) + } + + if n != 9 { + t.Errorf("Expected 9 bytes written, got %d", n) + } + + if rw.statusCode != http.StatusNotFound { + t.Errorf("Expected status code 404, got %d", rw.statusCode) + } + + if rw.size != 9 { + t.Errorf("Expected size 9, got %d", rw.size) + } + }) + + t.Run("defaults to 200 OK", func(t *testing.T) { + rr := httptest.NewRecorder() + rw := &responseWriter{ResponseWriter: rr} + + rw.Write([]byte("ok")) + + if rw.statusCode != http.StatusOK { + t.Errorf("Expected status code 200, got %d", rw.statusCode) + } + }) +} + +func TestItoa(t *testing.T) { + tests := []struct { + input int + expected string + }{ + {0, "0"}, + {1, "1"}, + {42, "42"}, + {123, "123"}, + {-1, "-1"}, + {-42, "-42"}, + {-123, "-123"}, + } + + for _, test := range tests { + result := itoa(test.input) + if result != test.expected { + t.Errorf("itoa(%d) = %s, expected %s", test.input, result, test.expected) + } + } +} \ No newline at end of file