Bug 2071998: pkg/verify: Expose store error details, especially slow access

pkg/verify/configmap_test.go

@@ -1,9 +1,15 @@
 package verify
 
 import (
+	"bytes"
+	"context"
+	"errors"
 	"io/ioutil"
+	"net/http"
 	"path/filepath"
+	"regexp"
 	"testing"
+	"time"
 
 	"golang.org/x/crypto/openpgp"
 
@@ -14,6 +20,38 @@ type VerifierAccessor interface {
 	Verifiers() map[string]openpgp.EntityList
 }
 
+// roundTripper implements http.RoundTripper in memory.
+type roundTripper struct {
+	data     map[string]string
+	delay    time.Duration
+	requests []string
+}
+
+// RoundTrip implements http.RoundTripper.
+func (rt *roundTripper) RoundTrip(request *http.Request) (*http.Response, error) {
+	ctx := request.Context()
+	rt.requests = append(rt.requests, request.URL.String())
+
+	select {
+	case <-ctx.Done():
+		return nil, ctx.Err()
+	case <-time.After(rt.delay):
+	}
+
+	data, ok := rt.data[request.URL.String()]
+	if !ok {
+		return &http.Response{
+			StatusCode: http.StatusNotFound,
+			Body:       ioutil.NopCloser(bytes.NewReader(nil)),
+		}, nil
+	}
+
+	return &http.Response{
+		StatusCode: http.StatusOK,
+		Body:       ioutil.NopCloser(bytes.NewReader([]byte(data))),
+	}, nil
+}
+
 func Test_newFromConfigMapData(t *testing.T) {
 	redhatData, err := ioutil.ReadFile(filepath.Join("testdata", "keyrings", "redhat.txt"))
 	if err != nil {
@@ -78,3 +116,40 @@ func Test_newFromConfigMapData(t *testing.T) {
 		})
 	}
 }
+
+func Test_newFromConfigMapData_slow_sigstore(t *testing.T) {
+	redhatData, err := ioutil.ReadFile(filepath.Join("testdata", "keyrings", "redhat.txt"))
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	rt := &roundTripper{
+		delay: time.Second,
+	}
+
+	verifier, err := newFromConfigMapData("from_test", map[string]string{
+		"store-example":              "https://example.com/signatures",
+		"verifier-public-key-redhat": string(redhatData),
+	}, func() (*http.Client, error) {
+		return &http.Client{Transport: rt}, nil
+	})
+
+	if err != nil {
+		t.Fatalf("newFromConfigMapData() error = %v", err)
+	}
+
+	ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond)
+	defer cancel()
+
+	err = verifier.Verify(ctx, "sha256:123")
+	expected := regexp.MustCompile(`^unable to verify sha256:123 against keyrings: verifier-public-key-redhat$`)
+	if !expected.MatchString(err.Error()) {
+		t.Fatalf("expected %s, got %s", expected, err.Error())
+	}
+
+	wrapped := errors.Unwrap(err)
+	expected = regexp.MustCompile(`^[[][0-9TZ:-]*: Get "https://example.com/signatures/sha256=123/signature-1": context deadline exceeded, [0-9TZ:-]*: context deadline exceeded]$`)
+	if !expected.MatchString(wrapped.Error()) {
+		t.Fatalf("expected %s, got %s", expected, wrapped.Error())
+	}
+}

pkg/verify/store/configmap/configmap.go

@@ -84,8 +84,8 @@ func (s *Store) mostRecentConfigMaps() []corev1.ConfigMap {
 	return s.last
 }
 
-// Signatures returns a list of signatures that match the request
-// digest out of config maps labelled with ReleaseLabelConfigMap in the
+// Signatures fetches signatures for the provided digest
+// out of config maps labelled with ReleaseLabelConfigMap in the
 // NamespaceLabelConfigMap namespace.
 func (s *Store) Signatures(ctx context.Context, name string, digest string, fn store.Callback) error {
 	// avoid repeatedly reloading config maps
@@ -122,6 +122,12 @@ func (s *Store) Signatures(ctx context.Context, name string, digest string, fn s
 				}
 			}
 		}
+		if done, err := fn(ctx, nil, fmt.Errorf("prefix %s in config map %s: %w", prefix, cm.ObjectMeta.Name, store.ErrNotFound)); err != nil || done {
+			return err
+		}
+		if err := ctx.Err(); err != nil {
+			return err
+		}
 	}
 	return nil
 }

pkg/verify/store/memory/memory.go

@@ -4,6 +4,7 @@ package memory
 
 import (
 	"context"
+	"fmt"
 
 	"github.com/openshift/library-go/pkg/verify/store"
 )
@@ -26,7 +27,8 @@ func (s *Store) Signatures(ctx context.Context, name string, digest string, fn s
 		}
 	}
 
-	return nil
+	_, err := fn(ctx, nil, fmt.Errorf("%s %s: %w", s.String(), digest, store.ErrNotFound))
+	return err
 }
 
 // String returns a description of where this store finds

pkg/verify/store/parallel/parallel.go

@@ -35,7 +35,11 @@ func (s *Store) Signatures(ctx context.Context, name string, digest string, fn s
 			errorChannel <- wrappedStore.Signatures(ctx, name, digest, func(ctx context.Context, signature []byte, errIn error) (done bool, err error) {
 				select {
 				case <-ctx.Done():
-					return true, nil
+					select {
+					case responses <- signatureResponse{signature: signature, errIn: errIn}:
+					default:
+					}
+					return false, ctx.Err()
 				case responses <- signatureResponse{signature: signature, errIn: errIn}:
 				}
 				return false, nil
@@ -74,7 +78,13 @@ func (s *Store) Signatures(ctx context.Context, name string, digest string, fn s
 	if loopError != nil {
 		return loopError
 	}
-	return ctx.Err() // because we discard context errors from the wrapped stores
+
+	if err := ctx.Err(); err != nil {
+		return err // because we discard context errors from the wrapped stores
+	}
+
+	_, err := fn(ctx, nil, fmt.Errorf("%s: %w", s.String(), store.ErrNotFound))
+	return err
 }
 
 // String returns a description of where this store finds

pkg/verify/store/parallel/parallel_test.go

@@ -139,7 +139,9 @@ func TestStore(t *testing.T) {
 		t.Run(testCase.name, func(t *testing.T) {
 			signatures := []string{}
 			err := parallel.Signatures(ctx, "name", "sha256:123", func(ctx context.Context, signature []byte, errIn error) (done bool, err error) {
-				if errIn != nil {
+				if errors.Is(errIn, store.ErrNotFound) {
+					return false, nil
+				} else if errIn != nil {
 					return false, errIn
 				}
 				signatures = append(signatures, string(signature))

pkg/verify/store/serial/serial.go

@@ -38,7 +38,8 @@ func (s *Store) Signatures(ctx context.Context, name string, digest string, fn s
 		}
 	}
 
-	return nil
+	_, err := fn(ctx, nil, fmt.Errorf("%s: %w", s.String(), store.ErrNotFound))
+	return err
 }
 
 // String returns a description of where this store finds

pkg/verify/store/serial/serial_test.go

@@ -74,7 +74,9 @@ func TestStore(t *testing.T) {
 		t.Run(testCase.name, func(t *testing.T) {
 			signatures := []string{}
 			err := serial.Signatures(ctx, "name", "sha256:123", func(ctx context.Context, signature []byte, errIn error) (done bool, err error) {
-				if errIn != nil {
+				if errors.Is(errIn, store.ErrNotFound) {
+					return false, nil
+				} else if errIn != nil {
 					return false, errIn
 				}
 				signatures = append(signatures, string(signature))

pkg/verify/store/sigstore/sigstore.go

@@ -32,8 +32,6 @@ import (
 // an attacker was able to take ownership of the store to perform DoS on clusters).
 const maxSignatureSearch = 10
 
-var errNotFound = errors.New("no more signatures to check")
-
 // Store provides access to signatures stored in memory.
 type Store struct {
 	// URI is the base from which signature URIs are constructed.
@@ -85,7 +83,7 @@ func checkHTTPSignatures(ctx context.Context, client *http.Client, u url.URL, ma
 
 		req, err := http.NewRequest("GET", sigURL.String(), nil)
 		if err != nil {
-			_, err = fn(ctx, nil, fmt.Errorf("could not build request to check signature: %v", err))
+			_, err = fn(ctx, nil, fmt.Errorf("could not build request to check signature: %w", err))
 			return err // even if the callback ate the error, no sense in checking later indexes which will fail the same way
 		}
 		req = req.WithContext(ctx)
@@ -110,25 +108,22 @@ func checkHTTPSignatures(ctx context.Context, client *http.Client, u url.URL, ma
 			}()
 
 			if resp.StatusCode == http.StatusNotFound {
-				return nil, errNotFound
+				return nil, store.ErrNotFound
 			}
 			if resp.StatusCode < 200 || resp.StatusCode >= 300 {
-				if i == 1 {
-					klog.V(4).Infof("Could not find signature at store location %v", sigURL)
-				}
-				return nil, fmt.Errorf("unable to retrieve signature from %v: %d", sigURL, resp.StatusCode)
+				return nil, fmt.Errorf("response status %d", resp.StatusCode)
 			}
 
 			return ioutil.ReadAll(resp.Body)
 		}()
-		if err == errNotFound {
-			break
-		}
 		if err != nil {
-			klog.V(4).Info(err)
-			done, err := fn(ctx, nil, err)
-			if done || err != nil {
-				return err
+			err := fmt.Errorf("unable to retrieve signature from %s: %w", sigURL.String(), err)
+			done, err2 := fn(ctx, nil, err)
+			if done || err2 != nil {
+				return err2
+			}
+			if errors.Is(err, store.ErrNotFound) {
+				break
 			}
 			continue
 		}

pkg/verify/store/sigstore/sigstore_test.go

@@ -3,12 +3,15 @@ package sigstore
 import (
 	"bytes"
 	"context"
+	"errors"
 	"io/ioutil"
 	"net/http"
 	"net/url"
 	"reflect"
 	"regexp"
 	"testing"
+
+	"github.com/openshift/library-go/pkg/verify/store"
 )
 
 // RoundTripper implements http.RoundTripper in memory.
@@ -113,7 +116,9 @@ func TestStore(t *testing.T) {
 
 			var signatures []string
 			err := sigstore.Signatures(ctx, "name", "sha256:123", func(ctx context.Context, signature []byte, errIn error) (done bool, err error) {
-				if errIn != nil {
+				if errors.Is(errIn, store.ErrNotFound) {
+					return false, nil
+				} else if errIn != nil {
 					return false, errIn
 				}
 				signatures = append(signatures, string(signature))

pkg/verify/store/store.go

@@ -3,6 +3,7 @@ package store
 
 import (
 	"context"
+	"errors"
 )
 
 // Callback returns true if an acceptable signature has been found, or
@@ -11,13 +12,25 @@ import (
 // problem and the function can decide how to handle that error.
 type Callback func(ctx context.Context, signature []byte, errIn error) (done bool, err error)
 
+// ErrNotFound is a base error for Callback, to be used when the store
+// decides one signature-retrieval avenue is exhausted.
+var ErrNotFound = errors.New("no more signatures to check")
+
 // Store provides access to signatures by digest.
 type Store interface {
 
 	// Signatures fetches signatures for the provided digest, feeding
 	// them into the provided callback until an acceptable signature is
-	// found or an error occurs.  Not finding any acceptable signatures
-	// is not an error; it is up to the caller to handle that case.
+	// found or an error occurs.
+	//
+	// Not finding additional signatures should result in a callback
+	// call with an error wrapping ErrNotFound, to allow the caller to
+	// figure out when and why the store was unable to find a signature.
+	// When a store has several lookup mechanisms, this may result in
+	// several callback calls with different ErrNotFound.  Signatures
+	// itself should return nil in this case, because eventually running
+	// out of signatures is an expected part of any invocation where the
+	// callback calls never return done=true.
 	Signatures(ctx context.Context, name string, digest string, fn Callback) error
 
 	// String returns a description of where this store finds

pkg/verify/verify.go

@@ -189,19 +189,19 @@ func (v *releaseVerifier) Verify(ctx context.Context, releaseDigest string) erro
 	err := v.store.Signatures(ctx, "", releaseDigest, func(ctx context.Context, signature []byte, errIn error) (done bool, err error) {
 		if errIn != nil {
 			klog.V(4).Infof("error retrieving signature for %s: %v", releaseDigest, errIn)
-			errs = append(errs, errIn)
+			errs = append(errs, fmt.Errorf("%s: %w", time.Now().Format(time.RFC3339), errIn))
 			return false, nil
 		}
 		for k, keyring := range remaining {
 			content, _, err := verifySignatureWithKeyring(bytes.NewReader(signature), keyring)
 			if err != nil {
 				klog.V(4).Infof("keyring %q could not verify signature for %s: %v", k, releaseDigest, err)
-				errs = append(errs, err)
+				errs = append(errs, fmt.Errorf("%s: %w", time.Now().Format(time.RFC3339), err))
 				continue
 			}
 			if err := verifyAtomicContainerSignature(content, releaseDigest); err != nil {
 				klog.V(4).Infof("signature for %s is not valid: %v", releaseDigest, err)
-				errs = append(errs, err)
+				errs = append(errs, fmt.Errorf("%s: %w", time.Now().Format(time.RFC3339), err))
 				continue
 			}
 			delete(remaining, k)
@@ -210,9 +210,8 @@ func (v *releaseVerifier) Verify(ctx context.Context, releaseDigest string) erro
 		return len(remaining) == 0, nil
 	})
 	if err != nil {
-		klog.V(4).Infof("Failed to retrieve signatures for %s (should never happen)", releaseDigest)
-		errs = append(errs, err)
-		return err
+		klog.V(4).Infof("Failed to retrieve signatures for %s: %v", releaseDigest, err)
+		errs = append(errs, fmt.Errorf("%s: %w", time.Now().Format(time.RFC3339), err))
 	}
 
 	if len(remaining) > 0 {