diff --git a/internal/comparison/comparator.go b/internal/comparison/comparator.go index 08114a6..305b968 100644 --- a/internal/comparison/comparator.go +++ b/internal/comparison/comparator.go @@ -40,6 +40,12 @@ func (c *Comparator) MaxResponseBytes() int { return c.maxResponseBytes } +// Ignored reports whether the request matches an endpoint declared ignored, so +// callers can log its noisy health-check traffic at debug level. +func (c *Comparator) Ignored(requestMethod, requestPath string) bool { + return c.scripts.ignored(requestMethod, requestPath) +} + // Configure activates the comparator against the wire descriptors. func (c *Comparator) Configure(ctx context.Context, set *descriptorpb.FileDescriptorSet) error { configured, err := c.scripts.prepare(ctx, set) @@ -60,6 +66,7 @@ func (c *Comparator) Compare( reference Response, candidate Response, ) (result Result) { + ignored := c.scripts.ignored(requestMethod, requestPath) defer func() { attributes := []any{"event", logger.EventCorrelation, "path", requestPath, "outcome", result.Outcome()} differences := result.Differences() @@ -69,7 +76,11 @@ func (c *Comparator) Compare( if result.Reason() != "" { attributes = append(attributes, "reason", result.Reason()) } - c.log.InfoContext(ctx, "Response comparison completed", attributes...) + level := slog.LevelInfo + if ignored { + level = slog.LevelDebug + } + c.log.Log(ctx, level, "Response comparison completed", attributes...) }() if excludedRequestPath(requestPath) { return Resultf(Skipped, "gRPC namespace is excluded from response comparison") diff --git a/internal/comparison/comparator_test.go b/internal/comparison/comparator_test.go index ffa77b0..df528b5 100644 --- a/internal/comparison/comparator_test.go +++ b/internal/comparison/comparator_test.go @@ -589,6 +589,21 @@ func TestIgnoredEndpointSkipsComparison(t *testing.T) { assert.Equal(t, comparison.Skipped, result.Outcome()) } +func TestIgnoredEndpointLogsAtDebug(t *testing.T) { + var output bytes.Buffer + log := slog.New(slog.NewJSONHandler(&output, &slog.HandlerOptions{Level: slog.LevelDebug})) + config := newConfig(t, map[string]string{"status.ts": module(`spectre.ingress.ignore("http", "GET /_status");`)}) + comparator, err := comparison.New(t.Context(), config, log) + assert.NoError(t, err) + assert.NoError(t, comparator.Configure(t.Context(), descriptorSet())) + response := httpJSONResponse(http.StatusBadGateway, "text/html", `502 Bad Gateway`) + + result := comparator.Compare(t.Context(), http.MethodGet, "/_status", "", response, response) + + assert.Equal(t, comparison.Skipped, result.Outcome()) + assert.Contains(t, output.String(), `"level":"DEBUG","msg":"Response comparison completed","event":"correlation","path":"/_status","outcome":"skipped","reason":"endpoint \"GET /_status\" is ignored"`) +} + func TestRejectsHTTPJSONWithUnknownFields(t *testing.T) { comparator := newScriptsComparator(t, map[string]string{"weather.ts": forecastScript("")}) reference := httpJSONResponse(http.StatusOK, "application/json", `{"stable":"same","roles":[],"users":[],"count":"0","labels":{}}`) diff --git a/internal/comparison/scripts.go b/internal/comparison/scripts.go index d2ee256..75f9ab3 100644 --- a/internal/comparison/scripts.go +++ b/internal/comparison/scripts.go @@ -137,6 +137,13 @@ func (s *scriptSet) resolve(configured *configuredScripts, method, host, path, c return root, identity, selected, wildcards, newEmptyResult() } +// ignored reports whether the request matches an endpoint declared ignored, so its +// traffic is skipped during comparison and logged at debug level. +func (s *scriptSet) ignored(requestMethod, requestPath string) bool { + endpoint, _, matched := s.routes.Match(requestMethod, "", requestPath) + return matched && endpoint.Ignore() +} + // normalise gives each payload a fresh evaluator, so script state cannot carry // between payloads and a payload's normalised form depends only on its content. func (s *scriptSet) normalise(ctx context.Context, configured *configuredScripts, root *schema.Type, diff --git a/internal/ingress/handler.go b/internal/ingress/handler.go index c8a9707..0c687bd 100644 --- a/internal/ingress/handler.go +++ b/internal/ingress/handler.go @@ -46,6 +46,7 @@ type DescriptorLoader interface { // ResponseComparator compares paired backend responses against a shared schema. type ResponseComparator interface { MaxResponseBytes() int + Ignored(requestMethod, requestPath string) bool Configure(ctx context.Context, set *descriptorpb.FileDescriptorSet) error Compare( ctx context.Context, @@ -126,7 +127,8 @@ func New( comparator: comparator, candidates: proxy.NewCandidates(config.CandidateMaxInFlight, log), } - requestHandler := logging.New(http.HandlerFunc(handler.serveProxy), log, logger.EventIngressReceived) + requestHandler := logging.NewDemoting(http.HandlerFunc(handler.serveProxy), log, logger.EventIngressReceived, + func(request *http.Request) bool { return comparator.Ignored(request.Method, request.URL.Path) }) handler.health = health.New(requestHandler) return handler, nil } diff --git a/internal/ingress/handler_test.go b/internal/ingress/handler_test.go index 5f70d80..2ee8199 100644 --- a/internal/ingress/handler_test.go +++ b/internal/ingress/handler_test.go @@ -1143,6 +1143,7 @@ type responseComparator struct { comparison.Response, ) comparison.Result configure Option[func(set *descriptorpb.FileDescriptorSet)] + ignored Option[func(requestMethod, requestPath string) bool] } func newResponseComparator(compare func( @@ -1160,6 +1161,13 @@ func (c *responseComparator) MaxResponseBytes() int { return 1024 } +func (c *responseComparator) Ignored(requestMethod, requestPath string) bool { + if ignored, ok := c.ignored.Get(); ok { + return ignored(requestMethod, requestPath) + } + return false +} + func (c *responseComparator) Configure(ctx context.Context, set *descriptorpb.FileDescriptorSet) error { _ = ctx if configure, ok := c.configure.Get(); ok { diff --git a/internal/middleware/logging/handler.go b/internal/middleware/logging/handler.go index ee85857..9cca4e3 100644 --- a/internal/middleware/logging/handler.go +++ b/internal/middleware/logging/handler.go @@ -7,19 +7,30 @@ import ( "time" "github.com/alecthomas/errors" + . "github.com/alecthomas/types/optional" ) +// Demoter reports whether a request's log line should drop from info to debug level. +type Demoter func(request *http.Request) bool + // Handler logs each request after delegating it to the next handler. type Handler struct { next http.Handler log *slog.Logger event string + debug Option[Demoter] } // New constructs request logging middleware around the next handler. event names // the SPECTRE event each request is logged under, e.g. "ingress_received". func New(next http.Handler, log *slog.Logger, event string) *Handler { - return &Handler{next: next, log: log, event: event} + return &Handler{next: next, log: log, event: event, debug: None[Demoter]()} +} + +// NewDemoting is like New but logs a request at debug instead of info when demote +// reports true, keeping low-value traffic such as health checks quiet by default. +func NewDemoting(next http.Handler, log *slog.Logger, event string, demote Demoter) *Handler { + return &Handler{next: next, log: log, event: event, debug: Some(demote)} } // ServeHTTP logs the event, method, path, response status, and elapsed time. @@ -31,7 +42,11 @@ func (h *Handler) ServeHTTP(writer http.ResponseWriter, request *http.Request) { if status == 0 { status = http.StatusOK } - h.log.InfoContext(request.Context(), "HTTP request", + level := slog.LevelInfo + if demote, ok := h.debug.Get(); ok && demote(request) { + level = slog.LevelDebug + } + h.log.Log(request.Context(), level, "HTTP request", "event", h.event, "method", request.Method, "path", request.URL.Path, diff --git a/internal/middleware/logging/handler_test.go b/internal/middleware/logging/handler_test.go index 18558fa..ba14fef 100644 --- a/internal/middleware/logging/handler_test.go +++ b/internal/middleware/logging/handler_test.go @@ -51,6 +51,36 @@ func TestLogsRequests(t *testing.T) { } } +func TestDemotesMatchingRequests(t *testing.T) { + for _, test := range []struct { + name string + path string + level string + }{ + {name: "Ignored", path: "/_status", level: "DEBUG"}, + {name: "Compared", path: "/users", level: "INFO"}, + } { + t.Run(test.name, func(t *testing.T) { + var output bytes.Buffer + log := slog.New(slog.NewJSONHandler(&output, &slog.HandlerOptions{Level: slog.LevelDebug})) + handler := logging.NewDemoting(http.HandlerFunc(func(writer http.ResponseWriter, _ *http.Request) { + _, err := writer.Write([]byte("ok")) + assert.NoError(t, err) + }), log, "ingress_received", func(request *http.Request) bool { + return request.URL.Path == "/_status" + }) + handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, test.path, nil)) + + var record map[string]any + assert.NoError(t, json.Unmarshal(output.Bytes(), &record)) + level, _ := record["level"].(string) + assert.Equal(t, test.level, level) + assert.Equal(t, "HTTP request", record["msg"]) + assert.Equal(t, "ingress_received", record["event"]) + }) + } +} + func TestPreservesFlushing(t *testing.T) { response := httptest.NewRecorder() log := slog.New(slog.DiscardHandler)