Add per-request image count to logs and metrics

README.md

@@ -253,11 +253,24 @@ The metrics exposed beyond the default Prometheus metrics are:
   attestations that failed to verify.
 * `aaop_attestations_request_timer`: the duration in seconds for
   the validation webhook.
+* `aaop_attestations_request_images`: a histogram of the number of
+  images (keys) included in a single provider request. Gatekeeper sends
+  all of a pod's images in one request, so this captures the pod's image
+  count. Use the `_bucket`/`_count`/`_sum` series to analyze the
+  distribution of images per request (e.g. single-image vs. multi-image
+  pods) and to see whether large multi-image requests are common.
 * `aaop_attestations_retrieved_timer`: the duration in seconds for the
    time it takes to download the attestations from the OCI registry.
 * `aaop_attestations_verification_timer`: the duration in seconds for
   the time it takes to verify the retrieved attestations.
 
+Each request is also logged with a `request_id`, `image_count`, and, for
+per-image log lines, an `image_index` (1-based position within the
+request). Because images in a request are processed sequentially and
+share the request deadline, these fields let a single failure line (such
+as a `canceled`/`timeout` fetch) be traced back to whether it was a solo
+validation or one image in a larger, multi-image request.
+
 ## Uninstall
 
 ```

go.mod

@@ -6,9 +6,11 @@ require (
 	github.com/google/go-containerregistry v0.21.9
 	github.com/google/go-containerregistry/pkg/authn/k8schain v0.0.0-20250225234217-098045d5e61f
 	github.com/google/go-containerregistry/pkg/authn/kubernetes v0.0.0-20250225234217-098045d5e61f
+	github.com/google/uuid v1.6.0
 	github.com/in-toto/attestation v1.2.0
 	github.com/open-policy-agent/frameworks/constraint v0.0.0-20250310182122-79a9477fa575
 	github.com/prometheus/client_golang v1.24.1
+	github.com/prometheus/client_model v0.6.2
 	github.com/sigstore/sigstore-go v1.3.0
 	github.com/stretchr/testify v1.12.0
 	k8s.io/apimachinery v0.36.3
@@ -87,7 +89,6 @@ require (
 	github.com/golang-jwt/jwt/v4 v4.5.2 // indirect
 	github.com/google/certificate-transparency-go v1.3.3 // indirect
 	github.com/google/gnostic-models v0.7.0 // indirect
-	github.com/google/uuid v1.6.0 // indirect
 	github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 // indirect
 	github.com/in-toto/in-toto-golang v0.11.0 // indirect
 	github.com/jedisct1/go-minisign v0.0.0-20230811132847-661be99b8267 // indirect
@@ -105,7 +106,6 @@ require (
 	github.com/opencontainers/go-digest v1.0.0 // indirect
 	github.com/opencontainers/image-spec v1.1.1 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
-	github.com/prometheus/client_model v0.6.2 // indirect
 	github.com/prometheus/common v0.70.1 // indirect
 	github.com/prometheus/procfs v0.21.1 // indirect
 	github.com/rcrowley/go-metrics v0.0.0-20201227073835-cf1acfcdf475 // indirect

pkg/metrics/prom.go

@@ -53,4 +53,11 @@ var (
 		Name: "aaop_attestations_request_timer",
 		Help: "The duration (seconds) for the entire request processing",
 	})
+
+	//nolint: revive
+	AttestationsReqImages = promauto.NewHistogram(prometheus.HistogramOpts{
+		Name:    "aaop_attestations_request_images",
+		Help:    "The number of images (keys) included in a single provider request",
+		Buckets: []float64{1, 2, 3, 5, 10, 20, 50},
+	})
 )

pkg/provider/provider.go

@@ -10,6 +10,7 @@ import (
 	"github.com/google/go-containerregistry/pkg/name"
 	"github.com/google/go-containerregistry/pkg/v1"
 	"github.com/google/go-containerregistry/pkg/v1/remote"
+	"github.com/google/uuid"
 	"github.com/open-policy-agent/frameworks/constraint/pkg/externaldata"
 	"github.com/sigstore/sigstore-go/pkg/bundle"
 	"github.com/sigstore/sigstore-go/pkg/verify"
@@ -79,26 +80,41 @@ func (p *Provider) Validate(ctx context.Context, r *externaldata.ProviderRequest
 		metrics.AttestationsReqTimer.Observe(dur.Seconds())
 	}()
 
+	// Record the number of images (keys) in this request. Gatekeeper sends
+	// every image in a pod as a single request, so this captures the pod's
+	// image count. request_id/image_count/image_index are threaded through the
+	// per-image logs below so a single failure line (e.g. a fetch timeout) can
+	// be traced back to whether it was a solo or a large multi-image request.
+	var imageCount = len(r.Request.Keys)
+	var requestID = uuid.NewString()
+	var reqLog = slog.With(
+		"request_id", requestID,
+		"image_count", imageCount)
+	metrics.AttestationsReqImages.Observe(float64(imageCount))
+	reqLog.Info("validate: received request")
+
 	// Get the keychain to be able to access the OCI registry.
 	// If the keychain configured is empty, the default keychain is used
 	// which works for public registries.
 	if kc, err = p.kc.KeyChain(ctx); err != nil {
-		slog.Error("validate: error retrieving key chain",
+		reqLog.Error("validate: error retrieving key chain",
 			"error", err)
 		return ErrorResponse(fmt.Sprintf("ERROR: KeyChain: %s", err))
 	}
 	var ro = p.bf.GetRemoteOptions(kc)
 
 	// iterate over all image references (keys)
-	for _, key := range r.Request.Keys {
+	for i, key := range r.Request.Keys {
 		var res []*verify.VerificationResult
 		var ref name.Reference
 
-		slog.Info("validate: verify signature",
-			"image", key)
+		var imgLog = reqLog.With(
+			"image", key,
+			"image_index", i+1)
+
+		imgLog.Info("validate: verify signature")
 		if ref, err = name.ParseReference(key); err != nil {
-			slog.Error("validate: error parsing reference",
-				"image", key,
+			imgLog.Error("validate: error parsing reference",
 				"error", err)
 			results = append(results, externaldata.Item{
 				Key:   key,
@@ -119,8 +135,7 @@ func (p *Provider) Validate(ctx context.Context, r *externaldata.ProviderRequest
 		if err != nil {
 			reason, step, attempts := fetcher.Classify(err)
 			metrics.AttestationsRetrieveFail.WithLabelValues(reason).Inc()
-			slog.Error("validate: error fetching bundles",
-				"image", key,
+			imgLog.Error("validate: error fetching bundles",
 				"reason", reason,
 				"step", step,
 				"attempts", attempts,
@@ -134,15 +149,13 @@ func (p *Provider) Validate(ctx context.Context, r *externaldata.ProviderRequest
 		}
 
 		metrics.AttestationsRetrieved.Add(float64(len(bundles)))
-		slog.Info("validate: fetched OCI bundles",
-			"image", key,
+		imgLog.Info("validate: fetched OCI bundles",
 			"count", len(bundles),
 			"duration_s", dur.Seconds())
 
 		if len(bundles) == 0 {
 			metrics.AttestationsMissing.Inc()
-			slog.Info("validate: no bundles",
-				"image", key)
+			imgLog.Info("validate: no bundles")
 			results = append(results, externaldata.Item{
 				Key:   key,
 				Error: "image_unsigned",
@@ -161,25 +174,22 @@ func (p *Provider) Validate(ctx context.Context, r *externaldata.ProviderRequest
 		}
 
 		if err != nil {
-			slog.Error("validate: verification error",
-				"image", key,
+			imgLog.Error("validate: verification error",
 				"image_digest", hash.Hex,
 				"error", err)
 			return ErrorResponse(fmt.Sprintf("ERROR: VerifyImageSignatures(%q): %v", key, err))
 		}
 
 		var bundleVerified = len(res) > 0
 		if bundleVerified {
-			slog.Info("validate: found valid signatures",
-				"count", len(res),
-				"image", key)
+			imgLog.Info("validate: found valid signatures",
+				"count", len(res))
 			results = append(results, externaldata.Item{
 				Key:   key,
 				Value: res,
 			})
 		} else {
-			slog.Info("validate: no valid signatures",
-				"image", key)
+			imgLog.Info("validate: no valid signatures")
 			results = append(results, externaldata.Item{
 				Key:   key,
 				Error: "invalid_signature",

pkg/provider/provider_test.go

@@ -1,8 +1,11 @@
 package provider
 
 import (
+	"bytes"
 	"context"
+	"encoding/json"
 	"errors"
+	"log/slog"
 	"net/http"
 	"strings"
 	"testing"
@@ -20,6 +23,7 @@ import (
 
 	"github.com/open-policy-agent/frameworks/constraint/pkg/externaldata"
 	"github.com/prometheus/client_golang/prometheus/testutil"
+	dto "github.com/prometheus/client_model/go"
 	"github.com/sigstore/sigstore-go/pkg/bundle"
 	"github.com/sigstore/sigstore-go/pkg/verify"
 )
@@ -286,3 +290,86 @@ func TestVerifyNotFound(t *testing.T) {
 	after := testutil.ToFloat64(metrics.AttestationsRetrieveFail.WithLabelValues("not_found"))
 	assert.InDelta(t, 1.0, after-before, 0.0001, `fail metric should be labeled reason="not_found"`)
 }
+
+// TestValidateRecordsImageCount verifies the request-images histogram records
+// one observation per request whose value is the number of images (keys).
+func TestValidateRecordsImageCount(t *testing.T) {
+	v := &mockVerifier{}
+	kc := &mockKeyChainProvider{}
+	bf := &mockBundleFetcher{}
+	provider := New(v, kc, bf)
+
+	readHist := func() (uint64, float64) {
+		m := &dto.Metric{}
+		require.NoError(t, metrics.AttestationsReqImages.Write(m))
+		return m.GetHistogram().GetSampleCount(), m.GetHistogram().GetSampleSum()
+	}
+
+	beforeCount, beforeSum := readHist()
+
+	request := &externaldata.ProviderRequest{
+		APIVersion: apiVersion,
+		Kind:       "ProviderRequest",
+		Request: externaldata.Request{
+			Keys: []string{"image1", "image2", "image3"},
+		},
+	}
+	provider.Validate(context.Background(), request)
+
+	afterCount, afterSum := readHist()
+	assert.Equal(t, uint64(1), afterCount-beforeCount, "exactly one request should be observed")
+	assert.InDelta(t, 3.0, afterSum-beforeSum, 0.0001, "sum should increase by the image count")
+}
+
+// TestValidateLogsImageContext verifies that per-image log lines carry the
+// request-scoped context (request_id, image_count, image_index) so a failed
+// image fetch can be traced back to a solo vs. multi-image request.
+func TestValidateLogsImageContext(t *testing.T) {
+	v := &mockVerifier{}
+	kc := &mockKeyChainProvider{}
+	bf := &notFoundBundleFetcher{}
+	provider := New(v, kc, bf)
+
+	var buf bytes.Buffer
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})))
+	defer slog.SetDefault(prev)
+
+	request := &externaldata.ProviderRequest{
+		APIVersion: apiVersion,
+		Kind:       "ProviderRequest",
+		Request: externaldata.Request{
+			Keys: []string{validImageName, brokenImageName},
+		},
+	}
+	provider.Validate(context.Background(), request)
+
+	var entry, fetchErr map[string]any
+	for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
+		if line == "" {
+			continue
+		}
+		var m map[string]any
+		require.NoError(t, json.Unmarshal([]byte(line), &m))
+		if m["msg"] == "validate: received request" {
+			entry = m
+		}
+		if m["msg"] == "validate: error fetching bundles" {
+			fetchErr = m
+		}
+	}
+
+	require.NotNil(t, entry, "expected a request entry log line")
+	require.NotNil(t, fetchErr, "expected a fetch error log line")
+
+	// JSON numbers decode as float64.
+	assert.InDelta(t, 2.0, entry["image_count"], 0.0001)
+	assert.NotEmpty(t, entry["request_id"])
+
+	assert.InDelta(t, 2.0, fetchErr["image_count"], 0.0001, "failure line should report the request image count")
+	// fetchErr is the last "error fetching bundles" line, i.e. the second
+	// image, so its 1-based image_index must be 2.
+	assert.InDelta(t, 2.0, fetchErr["image_index"], 0.0001, "failure line should report the 1-based image position")
+	assert.Equal(t, entry["request_id"], fetchErr["request_id"],
+		"per-image failure line should carry the request's correlation id")
+}