feat: make the provider request path observable

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)
+}

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)
+	}
+}