Add visibility into nonce redemption failure causes

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
 	}