diff --git a/README.md b/README.md index 746d1e8..91440cc 100644 --- a/README.md +++ b/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 ``` diff --git a/go.mod b/go.mod index b94234b..5299b6a 100644 --- a/go.mod +++ b/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 diff --git a/pkg/metrics/prom.go b/pkg/metrics/prom.go index 669ffdb..3d24f08 100644 --- a/pkg/metrics/prom.go +++ b/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}, + }) ) diff --git a/pkg/provider/provider.go b/pkg/provider/provider.go index 662e2a4..4da0020 100644 --- a/pkg/provider/provider.go +++ b/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,8 +174,7 @@ 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)) @@ -170,16 +182,14 @@ func (p *Provider) Validate(ctx context.Context, r *externaldata.ProviderRequest 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", diff --git a/pkg/provider/provider_test.go b/pkg/provider/provider_test.go index 1424e74..b9ecdb3 100644 --- a/pkg/provider/provider_test.go +++ b/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 := ¬FoundBundleFetcher{} + 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") +}