From fc301e54cd7db1fd3123e70da2adfab9e8932574 Mon Sep 17 00:00:00 2001 From: Ravi Agarwal Date: Mon, 9 Nov 2026 22:41:57 +0000 Subject: [PATCH] fix(handler): log opaque cache keys on failures --- internal/strategy/handler/handler.go | 4 +- internal/strategy/handler/log_safety_test.go | 117 +++++++++++++++++++ 2 files changed, 119 insertions(+), 2 deletions(-) create mode 100644 internal/strategy/handler/log_safety_test.go diff --git a/internal/strategy/handler/handler.go b/internal/strategy/handler/handler.go index 48bb4d86..84d3e01d 100644 --- a/internal/strategy/handler/handler.go +++ b/internal/strategy/handler/handler.go @@ -172,14 +172,14 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { served, err := h.serveCached(w, r, key) if err != nil { - logger.ErrorContext(ctx, "Failed to serve from cache", "cache_key", parts.Path, "error", err) + logger.ErrorContext(ctx, "Failed to serve from cache", "cache_key", key.String(), "error", err) } if served { return } if err := h.fetchAndCache(w, r, key); err != nil { - logger.ErrorContext(ctx, "Failed to fetch and cache", "cache_key", parts.Path, "error", err) + logger.ErrorContext(ctx, "Failed to fetch and cache", "cache_key", key.String(), "error", err) } } diff --git a/internal/strategy/handler/log_safety_test.go b/internal/strategy/handler/log_safety_test.go new file mode 100644 index 00000000..72cb7bbb --- /dev/null +++ b/internal/strategy/handler/log_safety_test.go @@ -0,0 +1,117 @@ +package handler_test + +import ( + "bytes" + "encoding/json" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + "time" + + "github.com/alecthomas/errors" + + "github.com/block/cachew/internal/cache" + "github.com/block/cachew/internal/logging" + "github.com/block/cachew/internal/strategy/handler" +) + +type disconnectedResponseWriter struct { + *httptest.ResponseRecorder +} + +func (w disconnectedResponseWriter) Write([]byte) (int, error) { + return 0, io.ErrClosedPipe +} + +func TestErrorLogsDoNotExposeSignedCacheURL(t *testing.T) { + const requestURL = "https://downloads.example.invalid/object?X-Amz-Credential=synthetic-credential&X-Amz-Signature=synthetic-signature&X-Amz-Security-Token=synthetic-session-token" + payload := strings.Repeat("cached download", 64<<10) + + for _, cacheHit := range []bool{false, true} { + name := "CacheWriteFailure" + if cacheHit { + name = "CachedResponseFailure" + } + t.Run(name, func(t *testing.T) { + var logs bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logs, &slog.HandlerOptions{Level: slog.LevelInfo})) + ctx := logging.ContextWithLogger(t.Context(), logger) + mem := mustNewMemoryCache(t) + key := cache.NewKey(requestURL) + var c cache.Cache = failingWriteCache{Cache: mem} + recorder := httptest.NewRecorder() + var response http.ResponseWriter = recorder + wantError := "metadata too large" + wantCacheResult := handler.CacheResultMiss + + if cacheHit { + writer, err := mem.Create(ctx, key, http.Header{}, time.Hour) + if err != nil { + t.Fatal(err) + } + if _, err := io.WriteString(writer, payload); err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + c = mem + response = disconnectedResponseWriter{recorder} + wantError = io.ErrClosedPipe.Error() + wantCacheResult = handler.CacheResultHit + } + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + if cacheHit { + t.Error("cache hit unexpectedly fetched upstream") + } + _, _ = io.WriteString(w, payload) + })) + t.Cleanup(backend.Close) + h := handler.New(backend.Client(), c). + Transform(func(r *http.Request) (*http.Request, error) { + return http.NewRequestWithContext(r.Context(), http.MethodGet, backend.URL, nil) + }) + h.ServeHTTP(response, httptest.NewRequest(http.MethodGet, requestURL, nil).WithContext(ctx)) + + var record struct { + Level string `json:"level"` + CacheKey string `json:"cache_key"` + Error string `json:"error"` + } + if err := json.Unmarshal(logs.Bytes(), &record); err != nil { + t.Fatalf("expected one error log: %v", err) + } + if record.Level != "ERROR" || !strings.Contains(record.Error, wantError) { + t.Fatal("injected failure was not observable at ERROR level") + } + for _, secret := range []string{"synthetic-credential", "synthetic-signature", "synthetic-session-token"} { + if strings.Contains(logs.String(), secret) { + t.Errorf("error log exposed synthetic signed-URL field %q", secret) + } + } + if record.CacheKey != key.String() { + t.Error("error log did not identify the opaque cache object key") + } + if recorder.Header().Get(handler.CacheResultHeader) != wantCacheResult { + t.Fatal("request did not exercise the expected cache path") + } + if !cacheHit && (recorder.Code != http.StatusOK || recorder.Body.String() != payload) { + t.Fatal("cache failure interrupted the successful upstream response") + } + if !cacheHit { + reader, _, err := mem.Open(ctx, key) + if reader != nil { + _ = reader.Close() + } + if !errors.Is(err, os.ErrNotExist) { + t.Fatalf("failed cache write left an entry: %v", err) + } + } + }) + } +}