feat: log verification and mutation request outcomes - #2873
Conversation
There was a problem hiding this comment.
Pull request overview
This PR improves observability for the Gatekeeper provider request path by introducing request-scoped logging (including trace IDs) and emitting logs/metrics for verification and mutation outcomes and failure paths.
Changes:
- Initialize a request context (trace ID) for
verify/mutatehandlers and use the request-scoped logger throughout the handler path. - Add debug/info/error logs around verification/mutation processing (cache hit/miss, resolved references, per-artifact outcomes, and failures) plus system-error metrics.
- Add unit tests that assert error paths emit
error-level logs; add metrics exporter flags/initialization wiring.
Reviewed changes
Copilot reviewed 5 out of 5 changed files in this pull request and generated 4 comments.
Show a summary per file
| File | Description |
|---|---|
| internal/httpserver/server.go | Initializes request context (trace IDs) for verify/mutate handler entrypoints. |
| internal/httpserver/handlers.go | Adds request-scoped logging and request duration/system-error metrics in verify/mutate/resolveReference. |
| internal/httpserver/handlers_test.go | Adds tests asserting failure paths emit error logs via logrus hooks. |
| cmd/ratify-gatekeeper-provider/main.go | Adds flags and wiring to optionally initialize the Prometheus metrics exporter. |
| cmd/ratify-gatekeeper-provider/main_test.go | Updates tests for new metrics flags and validates metrics-init failures don’t become the returned error. |
Suppressed comments (1)
internal/httpserver/handlers.go:82
- The per-artifact info log happens inside the singleflight closure. If singleflight returns a shared result, the waiting caller won't emit the outcome log (it will only show up under the trace ID of the goroutine that executed the closure). Capture the returned
sharedflag and log the outcome for shared callers too so each request has a consistent audit signal.
renderedResult := convertResult(result)
if renderedResult != nil {
log.Infof("verification result for %s: succeeded=%t", artifact, renderedResult.Succeeded)
}
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| func (s *server) verifyHandler() http.HandlerFunc { | ||
| return func(w http.ResponseWriter, r *http.Request) { | ||
| _ = s.verify(r.Context(), w, r) | ||
| _ = s.verify(logger.InitContext(r.Context(), r), w, r) | ||
| } | ||
| } |
| var logged bool | ||
| for _, entry := range hook.AllEntries() { | ||
| if entry.Level == logrus.ErrorLevel { | ||
| logged = true | ||
| } | ||
| } |
| func (s *server) mutateHandler() http.HandlerFunc { | ||
| return func(w http.ResponseWriter, r *http.Request) { | ||
| _ = s.mutate(r.Context(), w, r) | ||
| _ = s.mutate(logger.InitContext(r.Context(), r), w, r) | ||
| } | ||
| } |
| // Fetch the cache value first. | ||
| result, err := s.verifyCache.Get(ctx, key) | ||
| if err == nil && result != nil { | ||
| log.Debugf("verify cache hit for %s", artifact) | ||
| results[idx].Value = result | ||
| continue | ||
| } |
b8b084a to
8b17659
Compare
The metrics package (OTel + Prometheus, ported from v1) was never wired into the gatekeeper provider: the exporter was never initialized and no request duration was recorded, so the provider emitted no metrics and served no /metrics endpoint. Initialize the Prometheus exporter on startup behind a new --metrics-port flag (default 8888, 0 disables) and record verification/mutation request durations in the verify/mutate handlers. Exporter init failures are logged but non-fatal. Signed-off-by: Charles Wu <yuewu2@microsoft.com>
Attach a trace ID to each verify/mutate request context via logger.InitContext, so it propagates to all context-aware downstream logging (executor, verifiers, auth and policy providers). Switch the handler cache-warning logs to the context logger so they carry the trace ID too, and count handler/processing failures with metrics.ReportSystemError using stable low-cardinality category labels (verify_artifact, mutate_parse_reference, mutate_resolve_reference). Signed-off-by: Charles Wu <yuewu2@microsoft.com>
The v2 request path was effectively silent: a failed verification or reference resolution was returned to Gatekeeper but never logged, so operators had nothing to debug with. v1 logged the subject, the verification response, cache hits/misses and timings for every request. Log verification and resolve failures at error level, the full verification report at info level so the log shows which verifier produced which outcome and why, and request start, cache hit/miss and duration at debug level. Logs go through the request-scoped logger so they carry the trace ID. Adds regression tests asserting the failure paths are logged. Signed-off-by: Charles Wu <yuewu2@microsoft.com>
8b17659 to
2561560
Compare
Codecov Report❌ Patch coverage is
❌ Your patch check has failed because the patch coverage (77.77%) is below the target coverage (80.00%). You can increase the patch coverage or adjust the target coverage. Additional details and impacted files@@ Coverage Diff @@
## main #2873 +/- ##
==========================================
+ Coverage 76.58% 76.66% +0.08%
==========================================
Files 89 89
Lines 4095 4127 +32
==========================================
+ Hits 3136 3164 +28
- Misses 812 816 +4
Partials 147 147 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
Description
The v2 provider's request path is effectively silent. Compared to v1, an operator gets almost nothing to debug with:
pkg/+httpserver/)internal/, nearly all startup/lifecycle)Warnf, only on a cache-write failure)executor/store/cosignverifierThe worst case: a failed verification logs nothing at all. The error is placed into the Gatekeeper response (
results[idx].Error = err.Error()) but never written to the pod log, sono valid executor configured, a registry auth failure, or a signature failure leaves no trace on the server side.Change
In
internal/httpserver/handlers.go:error— verification failures (failed to verify <artifact>) and reference parse/resolve failures. This is the gap that matters most; these were previously silent.info— the per-artifact verification outcome (verification result for <artifact>: succeeded=<bool>), the key operational/audit signal (v1 logged the same).debug— request start (artifact/reference count), cache hit/miss, resolved reference, and request duration.All logging goes through the request-scoped logger (
logger.GetLogger(ctx, logOpt)), so entries carry the trace ID andcomponent-type.Example output that previously did not exist at all:
Note
Stacked on #2849 (per-request trace IDs), which is itself stacked on #2847. This branch contains those commits; review the logging commit here. Merge order: #2847 → #2849 → this. I'll rebase onto
mainas they land.This is deliberately scoped to the HTTP request path. Adding debug logging inside
internal/executor, the verifiers and the stores (also currently at zero) is a sensible follow-up.Testing
TestVerify_LogsFailuresandTestResolveReference_LogsFailuresuse a logrus test hook to assert the failure paths actually emit anerrorentry, so this can't silently regress.go build ./...,go vet, package tests andgolangci-lintpass. Nogo.modchange (logrus/hooks/testships with logrus).