Add visibility into nonce redemption failure causes (#8448)

Add metrics to the nonce server which give visibility into how many
nonces it is currently tracking, and what distribution of nonce ages it
actually sees. This should help us better understand the in-memory
behavior of the nonce server, so we can better debug issues related to
invalid nonce errors.

Also add much more detailed error messages throughout the nonce
redemption pipeline. Have the nonce server's `valid()` helper method
return individual error messages based on why the nonce was invalid.
Have the nonce service itself return those error messages to the WFE,
rather than simply returning "Valid: false". Finally, have the WFE
suppress those detailed error messages when displaying BadNonce errors
to the end-user, so they end up in our logs but not in user-facing API
responses.

Finally, due to the refactoring of the nonce service's `.valid()` helper
above, simplify some unnecessary layers of abstraction within the nonce
package. Remove the distinction between the "NonceService" (which
contained all nonce logic) and the "NonceServer" (which implemented the
gRPC interface). Make the non-gRPC methods unexported, since they're
really just helper methods. Simplify the inmem nonce service to look
exactly like the other inmem services, forwarding calls to the real gRPC
implementation rather than to the underlying NonceService.

Author: aarongable

cmd/nonce-service/main.go

@@ -93,9 +93,8 @@ func main() {
 	tlsConfig, err := c.NonceService.TLS.Load(scope)
 	cmd.FailOnError(err, "tlsConfig config")
 
-	nonceServer := nonce.NewServer(ns)
 	start, err := bgrpc.NewServer(c.NonceService.GRPC, logger).Add(
-		&noncepb.NonceService_ServiceDesc, nonceServer).Build(tlsConfig, scope, clock.New())
+		&noncepb.NonceService_ServiceDesc, ns).Build(tlsConfig, scope, clock.New())
 	cmd.FailOnError(err, "Unable to setup nonce service gRPC server")
 
 	logger.Info(fmt.Sprintf("Nonce server listening on %s with prefix %q", c.NonceService.GRPC.Address, noncePrefix))

email/exporter_test.go

@@ -27,11 +27,10 @@ type mockPardotClientImpl struct {
 // newMockPardotClientImpl returns a MockPardotClientImpl, implementing the
 // PardotClient interface. Both refer to the same instance, with the interface
 // for mock interaction and the struct for state inspection and modification.
-func newMockPardotClientImpl() (PardotClient, *mockPardotClientImpl) {
-	mockImpl := &mockPardotClientImpl{
+func newMockPardotClientImpl() *mockPardotClientImpl {
+	return &mockPardotClientImpl{
 		CreatedContacts: []string{},
 	}
-	return mockImpl, mockImpl
 }
 
 // SendContact adds an email to CreatedContacts.
@@ -55,10 +54,10 @@ func (m *mockPardotClientImpl) getCreatedContacts() []string {
 // ExporterImpl queue and cleanup() to drain and shutdown. If start() is called,
 // cleanup() must be called.
 func setup() (*ExporterImpl, *mockPardotClientImpl, func(), func()) {
-	mockClient, clientImpl := newMockPardotClientImpl()
+	mockClient := newMockPardotClientImpl()
 	exporter := NewExporterImpl(mockClient, nil, 1000000, 5, metrics.NoopRegisterer, blog.NewMock())
 	daemonCtx, cancel := context.WithCancel(context.Background())
-	return exporter, clientImpl,
+	return exporter, mockClient,
 		func() { exporter.Start(daemonCtx) },
 		func() {
 			cancel()
@@ -167,7 +166,7 @@ func TestSendContactDeduplication(t *testing.T) {
 	t.Parallel()
 
 	cache := NewHashedEmailCache(1000, metrics.NoopRegisterer)
-	mockClient, clientImpl := newMockPardotClientImpl()
+	mockClient := newMockPardotClientImpl()
 	exporter := NewExporterImpl(mockClient, cache, 1000000, 5, metrics.NoopRegisterer, blog.NewMock())
 
 	daemonCtx, cancel := context.WithCancel(context.Background())
@@ -182,7 +181,7 @@ func TestSendContactDeduplication(t *testing.T) {
 	cancel()
 	exporter.Drain()
 
-	contacts := clientImpl.getCreatedContacts()
+	contacts := mockClient.getCreatedContacts()
 	test.AssertEquals(t, 1, len(contacts))
 	test.AssertEquals(t, "[email protected]", contacts[0])
 

nonce/nonce.go

@@ -32,6 +32,7 @@ import (
 	"google.golang.org/grpc"
 	"google.golang.org/protobuf/types/known/emptypb"
 
+	berrors "github.com/letsencrypt/boulder/errors"
 	noncepb "github.com/letsencrypt/boulder/nonce/proto"
 )
 
@@ -63,6 +64,7 @@ func DerivePrefix(grpcAddr string, key []byte) string {
 
 // NonceService generates, cancels, and tracks Nonces.
 type NonceService struct {
+	noncepb.UnsafeNonceServiceServer
 	mu               sync.Mutex
 	latest           int64
 	earliest         int64
@@ -73,7 +75,9 @@ type NonceService struct {
 	prefix           string
 	nonceCreates     prometheus.Counter
 	nonceEarliest    prometheus.Gauge
+	nonceLatest      prometheus.Gauge
 	nonceRedeems     *prometheus.CounterVec
+	nonceAges        *prometheus.HistogramVec
 	nonceHeapLatency prometheus.Histogram
 }
 
@@ -143,11 +147,22 @@ func NewNonceService(stats prometheus.Registerer, maxUsed int, prefix string) (*
 		Help: "A gauge with the current earliest valid nonce value",
 	})
 	stats.MustRegister(nonceEarliest)
+	nonceLatest := prometheus.NewGauge(prometheus.GaugeOpts{
+		Name: "nonce_latest",
+		Help: "A gauge with the current latest valid nonce value",
+	})
+	stats.MustRegister(nonceLatest)
 	nonceRedeems := prometheus.NewCounterVec(prometheus.CounterOpts{
 		Name: "nonce_redeems",
 		Help: "A counter of nonce validations labelled by result",
 	}, []string{"result", "error"})
 	stats.MustRegister(nonceRedeems)
+	nonceAges := prometheus.NewHistogramVec(prometheus.HistogramOpts{
+		Name:    "nonce_ages",
+		Help:    "A histogram of nonce ages at the time they were (attempted to be) redeemed, expressed as fractions of the valid nonce window",
+		Buckets: []float64{-0.01, 0, .1, .2, .3, .4, .5, .6, .7, .8, .9, 1, 1.1, 1.2, 1.5, 2, 5},
+	}, []string{"result"})
+	stats.MustRegister(nonceAges)
 	nonceHeapLatency := prometheus.NewHistogram(prometheus.HistogramOpts{
 		Name: "nonce_heap_latency",
 		Help: "A histogram of latencies of heap pop operations",
@@ -164,7 +179,9 @@ func NewNonceService(stats prometheus.Registerer, maxUsed int, prefix string) (*
 		prefix:           prefix,
 		nonceCreates:     nonceCreates,
 		nonceEarliest:    nonceEarliest,
+		nonceLatest:      nonceLatest,
 		nonceRedeems:     nonceRedeems,
+		nonceAges:        nonceAges,
 		nonceHeapLatency: nonceHeapLatency,
 	}, nil
 }
@@ -232,40 +249,53 @@ func (ns *NonceService) decrypt(nonce string) (int64, error) {
 	return ctr.Int64(), nil
 }
 
-// Nonce provides a new Nonce.
-func (ns *NonceService) Nonce() (string, error) {
+// nonce provides a new Nonce.
+func (ns *NonceService) nonce() (string, error) {
 	ns.mu.Lock()
 	ns.latest++
 	latest := ns.latest
 	ns.mu.Unlock()
-	defer ns.nonceCreates.Inc()
+	ns.nonceCreates.Inc()
+	ns.nonceLatest.Set(float64(latest))
 	return ns.encrypt(latest)
 }
 
-// Valid determines whether the provided Nonce string is valid, returning
+// valid determines whether the provided Nonce string is valid, returning
 // true if so.
-func (ns *NonceService) Valid(nonce string) bool {
+func (ns *NonceService) valid(nonce string) error {
 	c, err := ns.decrypt(nonce)
 	if err != nil {
 		ns.nonceRedeems.WithLabelValues("invalid", "decrypt").Inc()
-		return false
+		return berrors.BadNonceError("unable to decrypt nonce: %s", err)
 	}
 
 	ns.mu.Lock()
 	defer ns.mu.Unlock()
-	if c > ns.latest {
+
+	// age represents how "far back" in the valid nonce window this nonce is.
+	// If it is very recent, then the numerator is very small and the age is close
+	// to zero. If it is old but still valid, the numerator is slightly smaller
+	// than the denominator, and the age is close to one. If it is too old, then
+	// the age is greater than one. If it is magically too new (i.e. greater than
+	// the largest nonce we've actually handed out), then the age is negative.
+	age := float64(ns.latest-c) / float64(ns.latest-ns.earliest)
+
+	if c > ns.latest { // i.e. age < 0
 		ns.nonceRedeems.WithLabelValues("invalid", "too high").Inc()
-		return false
+		ns.nonceAges.WithLabelValues("invalid").Observe(age)
+		return berrors.BadNonceError("nonce greater than highest dispensed nonce: %d > %d", c, ns.latest)
 	}
 
-	if c <= ns.earliest {
+	if c <= ns.earliest { // i.e. age >= 1
 		ns.nonceRedeems.WithLabelValues("invalid", "too low").Inc()
-		return false
+		ns.nonceAges.WithLabelValues("invalid").Observe(age)
+		return berrors.BadNonceError("nonce less than lowest eligible nonce: %d < %d", c, ns.earliest)
 	}
 
 	if ns.used[c] {
 		ns.nonceRedeems.WithLabelValues("invalid", "already used").Inc()
-		return false
+		ns.nonceAges.WithLabelValues("invalid").Observe(age)
+		return berrors.BadNonceError("nonce already marked as used: %d in [%d]used", c, len(ns.used))
 	}
 
 	ns.used[c] = true
@@ -279,7 +309,8 @@ func (ns *NonceService) Valid(nonce string) bool {
 	}
 
 	ns.nonceRedeems.WithLabelValues("valid", "").Inc()
-	return true
+	ns.nonceAges.WithLabelValues("valid").Observe(age)
+	return nil
 }
 
 // splitNonce splits a nonce into a prefix and a body.
@@ -290,27 +321,18 @@ func (ns *NonceService) splitNonce(nonce string) (string, string, error) {
 	return nonce[:PrefixLen], nonce[PrefixLen:], nil
 }
 
-// NewServer returns a new Server, wrapping a NonceService.
-func NewServer(inner *NonceService) *Server {
-	return &Server{inner: inner}
-}
-
-// Server implements the gRPC nonce service.
-type Server struct {
-	noncepb.UnsafeNonceServiceServer
-	inner *NonceService
-}
-
-var _ noncepb.NonceServiceServer = (*Server)(nil)
-
 // Redeem accepts a nonce from a gRPC client and redeems it using the inner nonce service.
-func (ns *Server) Redeem(ctx context.Context, msg *noncepb.NonceMessage) (*noncepb.ValidMessage, error) {
-	return &noncepb.ValidMessage{Valid: ns.inner.Valid(msg.Nonce)}, nil
+func (ns *NonceService) Redeem(ctx context.Context, msg *noncepb.NonceMessage) (*noncepb.ValidMessage, error) {
+	err := ns.valid(msg.Nonce)
+	if err != nil {
+		return nil, err
+	}
+	return &noncepb.ValidMessage{Valid: true}, nil
 }
 
 // Nonce generates a nonce and sends it to a gRPC client.
-func (ns *Server) Nonce(_ context.Context, _ *emptypb.Empty) (*noncepb.NonceMessage, error) {
-	nonce, err := ns.inner.Nonce()
+func (ns *NonceService) Nonce(_ context.Context, _ *emptypb.Empty) (*noncepb.NonceMessage, error) {
+	nonce, err := ns.nonce()
 	if err != nil {
 		return nil, err
 	}