fix: sort latest key by sequence correctly (#21425)

Fixes an issue where we will not correctly return the latest key by sequence number if the fetch returns them in a order where the latest key is not last. The db query uses `ORDER BY sequence DESC` it is likely we have been operating incorrectly.

Adds a second key to one of the test cases which fails without this fix.

Also includes some debug logging statements I found helpful while chasing key rotation issues.

coderd/cryptokeys/cache.go

@@ -126,7 +126,7 @@ func NewEncryptionCache(ctx context.Context, logger slog.Logger, fetcher Fetcher
 func newCache(ctx context.Context, logger slog.Logger, fetcher Fetcher, feature codersdk.CryptoKeyFeature, opts ...func(*cache)) *cache {
 	cache := &cache{
 		clock:   quartz.NewReal(),
-		logger:  logger,
+		logger:  logger.With(slog.F("feature", feature)),
 		fetcher: fetcher,
 		feature: feature,
 	}
@@ -134,6 +134,7 @@ func newCache(ctx context.Context, logger slog.Logger, fetcher Fetcher, feature
 	for _, opt := range opts {
 		opt(cache)
 	}
+	cache.logger.Debug(ctx, "created new key cache")
 
 	cache.cond = sync.NewCond(&cache.mu)
 	//nolint:gocritic // We need to be able to read the keys in order to cache them.
@@ -229,6 +230,7 @@ func idSecret(k codersdk.CryptoKey) (string, []byte, error) {
 }
 
 func (c *cache) cryptoKey(ctx context.Context, sequence int32) (string, []byte, error) {
+	c.logger.Debug(ctx, "request for key", slog.F("sequence", sequence))
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
@@ -343,11 +345,13 @@ func (c *cache) refresh() {
 // cryptoKeys queries the control plane for the crypto keys.
 // Outside of initialization, this should only be called by fetch.
 func (c *cache) cryptoKeys(ctx context.Context) (map[int32]codersdk.CryptoKey, error) {
+	c.logger.Debug(ctx, "fetching crypto keys")
 	keys, err := c.fetcher.Fetch(ctx, c.feature)
 	if err != nil {
 		return nil, xerrors.Errorf("fetch: %w", err)
 	}
 	cache := toKeyMap(keys, c.clock.Now())
+	c.logger.Debug(ctx, "crypto key fetch complete")
 	return cache, nil
 }
 
@@ -358,6 +362,7 @@ func toKeyMap(keys []codersdk.CryptoKey, now time.Time) map[int32]codersdk.Crypt
 		m[key.Sequence] = key
 		if key.Sequence > latest.Sequence && key.CanSign(now) {
 			m[latestSequence] = key
+			latest = key
 		}
 	}
 	return m

coderd/cryptokeys/cache_test.go

@@ -42,9 +42,15 @@ func TestCryptoKeyCache(t *testing.T) {
 				Sequence: 2,
 				StartsAt: now,
 			}
+			olderKey := codersdk.CryptoKey{
+				Feature:  codersdk.CryptoKeyFeatureTailnetResume,
+				Secret:   generateKey(t, 64),
+				Sequence: 1,
+				StartsAt: now,
+			}
 
 			ff := &fakeFetcher{
-				keys: []codersdk.CryptoKey{expected},
+				keys: []codersdk.CryptoKey{expected, olderKey},
 			}
 
 			cache, err := cryptokeys.NewSigningCache(ctx, logger, ff, codersdk.CryptoKeyFeatureTailnetResume, cryptokeys.WithCacheClock(clock))

coderd/cryptokeys/rotate.go

@@ -80,14 +80,15 @@ func StartRotator(ctx context.Context, logger slog.Logger, db database.Store, op
 // start begins the process of rotating keys.
 // Canceling the context will stop the rotation process.
 func (k *rotator) start(ctx context.Context) {
-	k.clock.TickerFunc(ctx, defaultRotationInterval, func() error {
+	w := k.clock.TickerFunc(ctx, defaultRotationInterval, func() error {
 		err := k.rotateKeys(ctx)
 		if err != nil {
 			k.logger.Error(ctx, "failed to rotate keys", slog.Error(err))
 		}
 		return nil
 	})
-	k.logger.Debug(ctx, "ctx canceled, stopping key rotation")
+	err := w.Wait()
+	k.logger.Debug(ctx, "stopping key rotation", slog.Error(err))
 }
 
 // rotateKeys checks for any keys needing rotation or deletion and
@@ -194,7 +195,7 @@ func (k *rotator) insertNewKey(ctx context.Context, tx database.Store, feature d
 		return database.CryptoKey{}, xerrors.Errorf("inserting new key: %w", err)
 	}
 
-	k.logger.Debug(ctx, "inserted new key for feature", slog.F("feature", feature))
+	k.logger.Debug(ctx, "inserted new key for feature", slog.F("feature", feature), slog.F("sequence", newKey.Sequence))
 	return newKey, nil
 }