From ff6edc53830ce47997776739a50eccc0b54ff53f Mon Sep 17 00:00:00 2001 From: Tobias Gesellchen Date: Tue, 28 Apr 2026 15:28:25 +0200 Subject: [PATCH] feat: log [UNHANDLED] for routes with no local handler (#190) feat: log [UNHANDLED] for routes with no local handler Every request that falls through to HandleNotFound now emits an [UNHANDLED] METHOD path log line, making it immediately visible when a speaker calls an endpoint we have not implemented. When proxyLogBody is enabled the request body is also included (truncated to 512 bytes) and restored before forwarding, so the proxy still sees the full payload. Co-Authored-By: Claude Sonnet 4.6 Co-authored-by: Claude Sonnet 4.6 --- pkg/service/handlers/handlers_proxy.go | 18 ++++ pkg/service/handlers/handlers_proxy_test.go | 97 +++++++++++++++++++++ 2 files changed, 115 insertions(+) diff --git a/pkg/service/handlers/handlers_proxy.go b/pkg/service/handlers/handlers_proxy.go index 95f6771..f74910f 100644 --- a/pkg/service/handlers/handlers_proxy.go +++ b/pkg/service/handlers/handlers_proxy.go @@ -104,7 +104,25 @@ func (s *Server) ServeProxy(target *url.URL) http.HandlerFunc { } // HandleNotFound handles requests that don't match any route. +// It always logs [UNHANDLED] so unimplemented endpoints are visible in plain output. +// When proxyLogBody is enabled it also logs the request body (truncated to 512 bytes). func (s *Server) HandleNotFound(w http.ResponseWriter, r *http.Request) { + if s.proxyLogBody && r.Body != nil { + body, _ := io.ReadAll(r.Body) + r.Body = io.NopCloser(bytes.NewBuffer(body)) + + preview := body + truncated := "" + if len(preview) > 512 { + preview = preview[:512] + truncated = "…" + } + + log.Printf("[UNHANDLED] %s %s body(%d bytes): %s%s", r.Method, r.URL.Path, len(body), preview, truncated) + } else { + log.Printf("[UNHANDLED] %s %s", r.Method, r.URL.Path) + } + s.HandleBoseProxy(w, r) } diff --git a/pkg/service/handlers/handlers_proxy_test.go b/pkg/service/handlers/handlers_proxy_test.go index cea3035..00f94ac 100644 --- a/pkg/service/handlers/handlers_proxy_test.go +++ b/pkg/service/handlers/handlers_proxy_test.go @@ -3,6 +3,7 @@ package handlers import ( "bytes" "io" + "log" "net/http" "net/http/httptest" "os" @@ -14,6 +15,102 @@ import ( "github.com/gesellix/bose-soundtouch/pkg/service/proxy" ) +func TestHandleNotFound_UnhandledLogging(t *testing.T) { + // backend absorbs proxied requests so the test doesn't hit the real Bose upstream + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + defer backend.Close() + + backendHost := strings.TrimPrefix(backend.URL, "http://") + + captureLog := func(fn func()) string { + var buf bytes.Buffer + log.SetOutput(&buf) + defer log.SetOutput(os.Stderr) + fn() + return buf.String() + } + + t.Run("always logs [UNHANDLED] with method and path", func(t *testing.T) { + ds := datastore.NewDataStore(t.TempDir()) + server := NewServer(ds, nil, "http://localhost", false, false, false) + + req := httptest.NewRequest("GET", "/some/unknown/path", nil) + req.Host = backendHost + + logged := captureLog(func() { + server.HandleNotFound(httptest.NewRecorder(), req) + }) + + if !strings.Contains(logged, "[UNHANDLED]") { + t.Errorf("expected [UNHANDLED] in log, got: %s", logged) + } + if !strings.Contains(logged, "GET") || !strings.Contains(logged, "/some/unknown/path") { + t.Errorf("expected method and path in log, got: %s", logged) + } + }) + + t.Run("includes body in log when proxyLogBody is true", func(t *testing.T) { + ds := datastore.NewDataStore(t.TempDir()) + server := NewServer(ds, nil, "http://localhost", false, true, false) + + req := httptest.NewRequest("POST", "/marge/unknown", bytes.NewBufferString("")) + req.Host = backendHost + + logged := captureLog(func() { + server.HandleNotFound(httptest.NewRecorder(), req) + }) + + if !strings.Contains(logged, "") { + t.Errorf("expected body in log when proxyLogBody=true, got: %s", logged) + } + }) + + t.Run("omits body from log when proxyLogBody is false", func(t *testing.T) { + ds := datastore.NewDataStore(t.TempDir()) + server := NewServer(ds, nil, "http://localhost", false, false, false) + + req := httptest.NewRequest("POST", "/marge/unknown", bytes.NewBufferString("")) + req.Host = backendHost + + logged := captureLog(func() { + server.HandleNotFound(httptest.NewRecorder(), req) + }) + + if strings.Contains(logged, "") { + t.Errorf("expected body omitted when proxyLogBody=false, got: %s", logged) + } + if !strings.Contains(logged, "[UNHANDLED]") { + t.Errorf("expected [UNHANDLED] even without body, got: %s", logged) + } + }) + + t.Run("body is still forwarded to proxy after being read for logging", func(t *testing.T) { + var receivedBody string + forwardCheck := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + b, _ := io.ReadAll(r.Body) + receivedBody = string(b) + w.WriteHeader(http.StatusOK) + })) + defer forwardCheck.Close() + + ds := datastore.NewDataStore(t.TempDir()) + server := NewServer(ds, nil, "http://localhost", false, true, false) + + req := httptest.NewRequest("POST", "/marge/unknown", bytes.NewBufferString("")) + req.Host = strings.TrimPrefix(forwardCheck.URL, "http://") + + captureLog(func() { + server.HandleNotFound(httptest.NewRecorder(), req) + }) + + if receivedBody != "" { + t.Errorf("expected body forwarded to proxy, got: %q", receivedBody) + } + }) +} + func TestHandleProxyRequest_RequestBodyRecording(t *testing.T) { t.Setenv("RECORDER_ASYNC", "false") tmpDir, err := os.MkdirTemp("", "proxy-request-body-test")