Fix #402

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,

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:])
+}

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)
+		}
+	}
+}