diff --git a/internal/httpserver/handlers.go b/internal/httpserver/handlers.go index 9a9085eb5..21cb66fc3 100644 --- a/internal/httpserver/handlers.go +++ b/internal/httpserver/handlers.go @@ -25,17 +25,20 @@ import ( "strings" "time" + "github.com/notaryproject/ratify/v2/internal/logger" "github.com/notaryproject/ratify/v2/pkg/metrics" "github.com/open-policy-agent/frameworks/constraint/pkg/externaldata" - "github.com/sirupsen/logrus" "oras.land/oras-go/v2/registry" ) +var logOpt = logger.Option{ComponentType: logger.Server} + // verify handles the verification request from Gatekeeper. func (s *server) verify(ctx context.Context, w http.ResponseWriter, r *http.Request) error { start := time.Now() defer func() { metrics.ReportVerificationRequest(ctx, time.Since(start).Milliseconds()) }() defer r.Body.Close() + log := logger.GetLogger(ctx, logOpt) body, err := io.ReadAll(r.Body) if err != nil { return fmt.Errorf("failed to read request body: %w", err) @@ -46,6 +49,7 @@ func (s *server) verify(ctx context.Context, w http.ResponseWriter, r *http.Requ return fmt.Errorf("failed to unmarshal request body to provider request: %w", err) } + log.Debugf("verifying %d artifact(s)", len(providerRequest.Request.Keys)) results := make([]externaldata.Item, len(providerRequest.Request.Keys)) for idx, artifact := range providerRequest.Request.Keys { results[idx] = externaldata.Item{ @@ -54,11 +58,14 @@ func (s *server) verify(ctx context.Context, w http.ResponseWriter, r *http.Requ key := verifyKey(artifact) // Fetch the cache value first. - result, err := s.verifyCache.Get(ctx, key) - if err == nil && result != nil { - results[idx].Value = result + cached, err := s.verifyCache.Get(ctx, key) + if err == nil && cached != nil { + log.Debugf("verify cache hit for %s", artifact) + logVerificationResult(log, artifact, cached) + results[idx].Value = cached continue } + log.Debugf("verify cache miss for %s", artifact) // Cache is missed, block multiple goroutines from validating the same // artifact. @@ -73,16 +80,21 @@ func (s *server) verify(ctx context.Context, w http.ResponseWriter, r *http.Requ } renderedResult := convertResult(result) if err = s.verifyCache.Set(ctx, key, renderedResult, 0); err != nil { - logrus.Warnf("failed to set verify cache for image %s: %v", artifact, err) + log.Warnf("failed to set verify cache for image %s: %v", artifact, err) } return renderedResult, nil }) if err != nil { + log.Errorf("failed to verify %s: %v", artifact, err) results[idx].Error = err.Error() + metrics.ReportSystemError(ctx, "verify_artifact") + } else if res, ok := val.(*result); ok && res != nil { + logVerificationResult(log, artifact, res) } results[idx].Value = val } + log.Debugf("verified %d artifact(s) in %dms", len(providerRequest.Request.Keys), time.Since(start).Milliseconds()) return sendResponse(results, w, http.StatusOK, false) } @@ -100,6 +112,7 @@ func (s *server) mutate(ctx context.Context, w http.ResponseWriter, r *http.Requ if err = json.Unmarshal(body, &providerRequest); err != nil { return fmt.Errorf("failed to unmarshal request body to provider request: %w", err) } + logger.GetLogger(ctx, logOpt).Debugf("mutating %d reference(s)", len(providerRequest.Request.Keys)) results := make([]externaldata.Item, len(providerRequest.Request.Keys)) for idx, key := range providerRequest.Request.Keys { results[idx] = s.resolveReference(ctx, key) @@ -109,6 +122,7 @@ func (s *server) mutate(ctx context.Context, w http.ResponseWriter, r *http.Requ } func (s *server) resolveReference(ctx context.Context, key string) externaldata.Item { + log := logger.GetLogger(ctx, logOpt) namespace := extractNamespace(key) reference := stripNamespacePrefix(key) item := externaldata.Item{ @@ -119,6 +133,8 @@ func (s *server) resolveReference(ctx context.Context, key string) externaldata. ref, err := registry.ParseReference(reference) if err != nil { item.Error = fmt.Sprintf("failed to parse reference: %v", err) + log.Errorf("failed to parse reference %s: %v", reference, err) + metrics.ReportSystemError(ctx, "mutate_parse_reference") return item } if _, err = ref.Digest(); err == nil { @@ -131,9 +147,11 @@ func (s *server) resolveReference(ctx context.Context, key string) externaldata. cacheKey := mutateKey(key) result, err := s.mutateCache.Get(ctx, cacheKey) if err == nil && result != "" { + log.Debugf("mutate cache hit for %s", reference) item.Value = result return item } + log.Debugf("mutate cache miss for %s", reference) // Cache is missed, block multiple goroutines from resolving the same // reference. @@ -150,13 +168,16 @@ func (s *server) resolveReference(ctx context.Context, key string) externaldata. resolvedRef := ref.String() if err = s.mutateCache.Set(ctx, cacheKey, resolvedRef, 0); err != nil { - logrus.Warnf("failed to set mutate cache for image %s: %v", reference, err) + log.Warnf("failed to set mutate cache for image %s: %v", reference, err) } return resolvedRef, nil }) if err != nil { + log.Errorf("failed to resolve %s: %v", reference, err) item.Error = err.Error() + metrics.ReportSystemError(ctx, "mutate_resolve_reference") } else { + log.Debugf("resolved %s to %v", reference, val) item.Value = val } return item @@ -211,3 +232,18 @@ func stripNamespacePrefix(key string) string { } return key } + +// resultLogger is the subset of the request logger used to report results. +type resultLogger interface { + Infof(format string, args ...interface{}) +} + +// logVerificationResult logs the whole report, so the log shows which verifier +// produced which outcome and why, not just whether the artifact passed. +func logVerificationResult(log resultLogger, artifact string, res *result) { + if detail, err := json.Marshal(res); err == nil { + log.Infof("verification result for %s: succeeded=%t, report=%s", artifact, res.Succeeded, detail) + return + } + log.Infof("verification result for %s: succeeded=%t", artifact, res.Succeeded) +} diff --git a/internal/httpserver/handlers_test.go b/internal/httpserver/handlers_test.go index c57555393..4ccac9691 100644 --- a/internal/httpserver/handlers_test.go +++ b/internal/httpserver/handlers_test.go @@ -28,6 +28,8 @@ import ( "github.com/notaryproject/ratify/v2/internal/executor" "github.com/open-policy-agent/frameworks/constraint/pkg/externaldata" + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" "golang.org/x/sync/singleflight" ) @@ -400,3 +402,218 @@ func TestVerifyStripsNamespacePrefix(t *testing.T) { t.Errorf("prefixed key should be stripped before parsing; got parse error: %q", itemErr) } } + +func newHandlerTestServer() *server { + return &server{ + getExecutor: func(_ string) *executor.ScopedExecutor { return nil }, + sfGroup: &singleflight.Group{}, + verifyCache: &mockResultCache{entries: make(map[string]*result)}, + mutateCache: &mockCache{entries: make(map[string]string)}, + } +} + +// findEntry returns the first log entry at the given level whose message +// contains want. The logrus hook is global, so tests must match on their own +// message rather than assuming they are the only writer. +func findEntry(hook *test.Hook, level logrus.Level, want string) *logrus.Entry { + for _, entry := range hook.AllEntries() { + if entry.Level == level && strings.Contains(entry.Message, want) { + return entry + } + } + return nil +} + +func TestVerifyHandler(t *testing.T) { + srv := newHandlerTestServer() + body := `{"apiVersion":"externaldata.gatekeeper.sh/v1beta1","kind":"ProviderRequest","request":{"keys":["ghcr.io/org/image:v1"]}}` + req := httptest.NewRequest(http.MethodPost, "/verify", strings.NewReader(body)) + w := httptest.NewRecorder() + + srv.verifyHandler().ServeHTTP(w, req) + + if w.Code != http.StatusOK { + t.Errorf("verifyHandler() status = %d, want %d", w.Code, http.StatusOK) + } +} + +func TestVerifyHandler_LogsFailure(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + srv := newHandlerTestServer() + req := httptest.NewRequest(http.MethodPost, "/verify", strings.NewReader("not json")) + srv.verifyHandler().ServeHTTP(httptest.NewRecorder(), req) + + entry := findEntry(hook, logrus.ErrorLevel, "failed to handle the verification request") + if entry == nil { + t.Fatal("expected the verify handler to log the error it previously discarded") + } + if entry.Data["trace-id"] == nil { + t.Error("expected the logged entry to carry a trace ID") + } +} + +func TestMutateHandler(t *testing.T) { + srv := newHandlerTestServer() + body := `{"apiVersion":"externaldata.gatekeeper.sh/v1beta1","kind":"ProviderRequest","request":{"keys":["ghcr.io/org/image:v1"]}}` + req := httptest.NewRequest(http.MethodPost, "/mutate", strings.NewReader(body)) + w := httptest.NewRecorder() + + srv.mutateHandler().ServeHTTP(w, req) + + if w.Code != http.StatusOK { + t.Errorf("mutateHandler() status = %d, want %d", w.Code, http.StatusOK) + } +} + +func TestMutateHandler_LogsFailure(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + srv := newHandlerTestServer() + req := httptest.NewRequest(http.MethodPost, "/mutate", strings.NewReader("not json")) + srv.mutateHandler().ServeHTTP(httptest.NewRecorder(), req) + + entry := findEntry(hook, logrus.ErrorLevel, "failed to handle the mutation request") + if entry == nil { + t.Fatal("expected the mutate handler to log the error it previously discarded") + } + if entry.Data["trace-id"] == nil { + t.Error("expected the logged entry to carry a trace ID") + } +} + +func TestVerify_LogsFailures(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + srv := &server{ + getExecutor: func(_ string) *executor.ScopedExecutor { return nil }, + verifyCache: &mockResultCache{entries: make(map[string]*result)}, + sfGroup: new(singleflight.Group), + } + req := httptest.NewRequest(http.MethodPost, "/verify", strings.NewReader(`{"request":{"keys":["artifact1"]}}`)) + if err := srv.verify(context.Background(), httptest.NewRecorder(), req); err != nil { + t.Fatalf("verify() error = %v", err) + } + + if findEntry(hook, logrus.ErrorLevel, "artifact1") == nil { + t.Error("expected a verification failure for artifact1 to be logged at error level") + } +} + +func TestResolveReference_LogsFailures(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + srv := &server{ + getExecutor: func(_ string) *executor.ScopedExecutor { return nil }, + mutateCache: &mockCache{entries: make(map[string]string)}, + sfGroup: new(singleflight.Group), + } + if item := srv.resolveReference(context.Background(), "!invalid!"); item.Error == "" { + t.Fatal("expected an error item for an invalid reference") + } + + if findEntry(hook, logrus.ErrorLevel, "!invalid!") == nil { + t.Error("expected the invalid reference to be logged at error level") + } +} + +func TestLogVerificationResult(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + res := &result{ + Succeeded: false, + ArtifactReports: []*validationReport{ + { + Subject: "registry.example/app:v1", + Artifact: "registry.example/app@sha256:deadbeef", + Results: []*verificationResult{ + { + VerifierName: "notation-1", + ErrorReason: "signature is not produced by a trusted signer", + }, + }, + }, + }, + } + logVerificationResult(logrus.StandardLogger(), "registry.example/app:v1", res) + + entry := findEntry(hook, logrus.InfoLevel, "registry.example/app:v1") + if entry == nil { + t.Fatal("expected the verification result to be logged at info level") + } + for _, want := range []string{"notation-1", "signature is not produced by a trusted signer", `"succeeded":false`} { + if !strings.Contains(entry.Message, want) { + t.Errorf("expected the logged result to contain %q, got: %s", want, entry.Message) + } + } +} + +// A warm cache must not make the request log go quiet: the outcome is the audit +// signal, so it is reported whether or not the result was recomputed. +func TestVerify_LogsOutcomeOnCacheHit(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + artifact := "ghcr.io/org/image:v1" + srv := &server{ + getExecutor: func(_ string) *executor.ScopedExecutor { return nil }, + verifyCache: &mockResultCache{entries: map[string]*result{ + verifyKey(artifact): {Succeeded: false}, + }}, + sfGroup: new(singleflight.Group), + } + body := `{"request":{"keys":["` + artifact + `"]}}` + req := httptest.NewRequest(http.MethodPost, "/verify", strings.NewReader(body)) + if err := srv.verify(context.Background(), httptest.NewRecorder(), req); err != nil { + t.Fatalf("verify() error = %v", err) + } + + entry := findEntry(hook, logrus.InfoLevel, artifact) + if entry == nil { + t.Fatal("expected a cached verification result to still be logged at info level") + } + if !strings.Contains(entry.Message, "succeeded=false") { + t.Errorf("expected the violation to be greppable, got: %s", entry.Message) + } +} + +func TestLogVerificationResult_Violation(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + logVerificationResult(logrus.StandardLogger(), "registry.example/app:v1", &result{Succeeded: false}) + + entry := findEntry(hook, logrus.InfoLevel, "registry.example/app:v1") + if entry == nil { + t.Fatal("expected a violation to be logged at info level") + } + if !strings.Contains(entry.Message, "succeeded=false") { + t.Errorf("expected succeeded=false in the message, got: %s", entry.Message) + } +} + +func TestLogVerificationResult_UnmarshalableReport(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + defer hook.Reset() + + // validationReport is self-referential, so a malformed upstream report can + // contain a cycle that json.Marshal rejects. The outcome must still be logged. + report := &validationReport{Subject: "registry.example/app:v1"} + report.ArtifactReports = []*validationReport{report} + logVerificationResult(logrus.StandardLogger(), "registry.example/app:v1", &result{ + ArtifactReports: []*validationReport{report}, + }) + + entry := findEntry(hook, logrus.InfoLevel, "registry.example/app:v1") + if entry == nil { + t.Fatal("expected the outcome to be logged even when the report cannot be marshalled") + } + if strings.Contains(entry.Message, "report=") { + t.Errorf("expected the fallback message without a report, got: %s", entry.Message) + } +} diff --git a/internal/httpserver/server.go b/internal/httpserver/server.go index 2842e1ae6..bdf93ea72 100644 --- a/internal/httpserver/server.go +++ b/internal/httpserver/server.go @@ -33,6 +33,7 @@ import ( "github.com/notaryproject/ratify/v2/internal/executor" "github.com/notaryproject/ratify/v2/internal/httpserver/config" "github.com/notaryproject/ratify/v2/internal/httpserver/tlssecret" + "github.com/notaryproject/ratify/v2/internal/logger" "github.com/sirupsen/logrus" "golang.org/x/sync/singleflight" ) @@ -200,13 +201,19 @@ func (s *server) registerVerifyHandler() error { func (s *server) verifyHandler() http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - _ = s.verify(r.Context(), w, r) + ctx := logger.InitContext(r.Context(), r) + if err := s.verify(ctx, w, r); err != nil { + logger.GetLogger(ctx, logOpt).Errorf("failed to handle the verification request: %v", err) + } } } func (s *server) mutateHandler() http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - _ = s.mutate(r.Context(), w, r) + ctx := logger.InitContext(r.Context(), r) + if err := s.mutate(ctx, w, r); err != nil { + logger.GetLogger(ctx, logOpt).Errorf("failed to handle the mutation request: %v", err) + } } }