diff --git a/internal/handler/handler.go b/internal/handler/handler.go index 9786eeac..ecc3e680 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -2180,7 +2180,24 @@ func upstreamMetadataStatus(resp *http.Response) error { body, _ := io.ReadAll(io.LimitReader(resp.Body, upstreamNotFoundBodyLimit)) return &upstreamNotFoundError{body: body} } - return fmt.Errorf("upstream returned %d", resp.StatusCode) + return &upstreamStatusError{status: resp.StatusCode} +} + +// upstreamStatusError is a metadata response other than 200, 304 and 404. +type upstreamStatusError struct { + status int +} + +func (e *upstreamStatusError) Error() string { + return fmt.Sprintf("upstream returned %d", e.status) +} + +// refused reports whether upstream answered the request with a definite 4xx, +// such as an object store's 403 for a key that doesn't exist, rather than +// failing. 408 and 429 are failures to retry, not answers. +func (e *upstreamStatusError) refused() bool { + return e.status >= 400 && e.status < 500 && + e.status != http.StatusRequestTimeout && e.status != http.StatusTooManyRequests } // refreshMetadataBlob records that upstream answered 304 for the cached @@ -2371,7 +2388,15 @@ func (p *Proxy) writeMetadataFetchError(w http.ResponseWriter, err error) { if writeUpstreamHeld(w, err) { return } - p.Logger.Error("metadata fetch failed", "error", err) + // An upstream refusal is still a 502, since the client can't act on the + // proxy's own request being refused, but it is upstream's answer and not + // a fault here, so it is logged as a warning. + var status *upstreamStatusError + if errors.As(err, &status) && status.refused() { + p.Logger.Warn("metadata fetch refused by upstream", "error", err) + } else { + p.Logger.Error("metadata fetch failed", "error", err) + } http.Error(w, "failed to fetch from upstream", http.StatusBadGateway) } diff --git a/internal/handler/metadata_fetch_error_test.go b/internal/handler/metadata_fetch_error_test.go new file mode 100644 index 00000000..784932ee --- /dev/null +++ b/internal/handler/metadata_fetch_error_test.go @@ -0,0 +1,50 @@ +package handler + +import ( + "bytes" + "fmt" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" +) + +func TestWriteMetadataFetchErrorLogLevel(t *testing.T) { + tests := []struct { + upstream int + wantLevel string + }{ + {http.StatusForbidden, "level=WARN"}, + {http.StatusUnauthorized, "level=WARN"}, + {http.StatusGone, "level=WARN"}, + {http.StatusRequestTimeout, "level=ERROR"}, + {http.StatusTooManyRequests, "level=ERROR"}, + {http.StatusInternalServerError, "level=ERROR"}, + {http.StatusBadGateway, "level=ERROR"}, + } + + for _, tt := range tests { + t.Run(http.StatusText(tt.upstream), func(t *testing.T) { + var logs bytes.Buffer + proxy := testProxy() + proxy.Logger = slog.New(slog.NewTextHandler(&logs, nil)) + + err := upstreamMetadataStatus(&http.Response{StatusCode: tt.upstream, Body: http.NoBody}) + // Wrapped the way staleMetadata returns it when nothing is cached. + err = fmt.Errorf("upstream failed and no cached metadata: %w", err) + w := httptest.NewRecorder() + proxy.writeMetadataFetchError(w, err) + + if w.Code != http.StatusBadGateway { + t.Errorf("status = %d, want %d", w.Code, http.StatusBadGateway) + } + if !strings.Contains(logs.String(), tt.wantLevel) { + t.Errorf("log = %q, want %s", logs.String(), tt.wantLevel) + } + if want := fmt.Sprintf("upstream returned %d", tt.upstream); !strings.Contains(logs.String(), want) { + t.Errorf("log = %q, want it to name %q", logs.String(), want) + } + }) + } +}