Update nodeenrollment to fix TLS issue; add debug (#3231)

* Add more logging to worker auth rotation and test flags

This makes it much easier to figure out when and why rotation is
happening and control it for tests/debugging.

* Update auth rotation logic

Because we were looking at validity period of client certs, which may
not have matched the actual rotation interval, it was possible (mostly
in test scenarios) for the rotation to happen multiple times on the
roots before we actually hit the worker rotation interval.

This changes how the interval is calculated by looking at the difference
between not-after values on the certs to understand the rotation
interval being used by the controller. We then use that as the starting
point for calculating a next-rotation time.

go.mod

@@ -96,7 +96,7 @@ require (
 	github.com/hashicorp/cap/ldap v0.0.0-20230123181313-9c0fb924b0d9
 	github.com/hashicorp/go-kms-wrapping/extras/kms/v2 v2.0.0-20221122211539-47c893099f13
 	github.com/hashicorp/go-version v1.3.0
-	github.com/hashicorp/nodeenrollment v0.2.1
+	github.com/hashicorp/nodeenrollment v0.2.2
 	github.com/jimlambrt/gldap v0.1.6-0.20230501161051-4e73db4906d4
 	github.com/kelseyhightower/envconfig v1.4.0
 	github.com/mikesmitty/edkey v0.0.0-20170222072505-3356ea4e686a

go.sum

@@ -760,8 +760,8 @@ github.com/hashicorp/golang-lru v0.5.4 h1:YDjusn29QI/Das2iO9M0BHnIbxPeyuCHsjMW+l
 github.com/hashicorp/golang-lru v0.5.4/go.mod h1:iADmTwqILo4mZ8BN3D2Q6+9jd8WM5uGBxy+E8yxSoD4=
 github.com/hashicorp/hcl v1.0.0 h1:0Anlzjpi4vEasTeNFn2mLJgTSwt0+6sfsiTG8qcWGx4=
 github.com/hashicorp/hcl v1.0.0/go.mod h1:E5yfLk+7swimpb2L/Alb/PJmXilQ/rhwaUYs4T20WEQ=
-github.com/hashicorp/nodeenrollment v0.2.1 h1:T0YlpXCy9icscpoA99zMIc8JqfR7FXvxJdfAWNmV+sE=
-github.com/hashicorp/nodeenrollment v0.2.1/go.mod h1:Do2FvaFHgnnMaqhdSTBX+TkQP0ep8VVQ0rOr+ZjUbJU=
+github.com/hashicorp/nodeenrollment v0.2.2 h1:bMCt4m4g5TAbSUX7CLBwtGuLlhXc8HzdzS7oHNVbwok=
+github.com/hashicorp/nodeenrollment v0.2.2/go.mod h1:Do2FvaFHgnnMaqhdSTBX+TkQP0ep8VVQ0rOr+ZjUbJU=
 github.com/hashicorp/vault/api v1.3.1 h1:pkDkcgTh47PRjY1NEFeofqR4W/HkNUi9qIakESO2aRM=
 github.com/hashicorp/vault/api v1.3.1/go.mod h1:QeJoWxMFt+MsuWcYhmwRLwKEXrjwAFFywzhptMsTIUw=
 github.com/hashicorp/vault/sdk v0.1.13/go.mod h1:B+hVj7TpuQY1Y/GPbCpffmgd+tSEwvhkWnjtSYCaS2M=

internal/daemon/worker/auth_rotation.go

@@ -28,14 +28,15 @@ func (w *Worker) startAuthRotationTicking(cancelCtx context.Context) {
 	// The default time to use when we encounter an error or some other reason
 	// we can't get a better reset time
 	const defaultResetDuration = time.Hour
-	timer := time.NewTimer(defaultResetDuration)
-	// You're not supposed to call reset on timers that haven't been stopped or
-	// expired, so we stop it here so it resets in the loop below. That way if
-	// we want to adjust time, e.g. for tests, we can set the resetDuration
-	// value from within the loop
-	timer.Stop()
 	var resetDuration time.Duration // will start at 0, so we run immediately
+	timer := time.NewTimer(defaultResetDuration)
+	lastRotation := time.Time{}.UTC()
 	for {
+		// You're not supposed to call reset on timers that haven't been stopped or
+		// expired, so we stop it here and reset it to the current resetDuration. That way if
+		// we want to adjust time, e.g. for tests, we can set the resetDuration
+		// value from within the loop
+		timer.Stop()
 		if w.TestOverrideAuthRotationPeriod != 0 {
 			resetDuration = w.TestOverrideAuthRotationPeriod
 		}
@@ -58,15 +59,18 @@ func (w *Worker) startAuthRotationTicking(cancelCtx context.Context) {
 			)
 			if err != nil {
 				if errors.Is(err, nodeenrollment.ErrNotFound) {
-					// Be silent
+					// Be silent, but check again soon
+					resetDuration = 5 * time.Second
 					continue
 				}
 				event.WriteError(cancelCtx, op, err)
+				resetDuration = 5 * time.Second
 				continue
 			}
 
 			if currentNodeCreds == nil {
 				event.WriteSysEvent(cancelCtx, op, "no error loading worker pki auth creds but nil creds, skipping rotation")
+				resetDuration = 5 * time.Second
 				continue
 			}
 
@@ -81,18 +85,29 @@ func (w *Worker) startAuthRotationTicking(cancelCtx context.Context) {
 				continue
 			}
 
-			var earliestValid, latestValid time.Time
-			// Go through the bundles and find the full range of time that we
-			// have valid certificates
-			var args []any
-			for i, bundle := range currentNodeCreds.CertificateBundles {
-				if curr := bundle.CertificateNotBefore.AsTime(); earliestValid.IsZero() || curr.Before(earliestValid) {
-					earliestValid = curr
+			var current, next *types.CertificateBundle
+			// Go through the bundles and intuit the rotation interval
+			for _, bundle := range currentNodeCreds.CertificateBundles {
+				if current == nil {
+					current = bundle
+					continue
 				}
-				if curr := bundle.CertificateNotAfter.AsTime(); latestValid.IsZero() || curr.After(latestValid) {
-					latestValid = curr
+				if current.CertificateNotAfter.AsTime().Before(bundle.CertificateNotAfter.AsTime()) {
+					next = bundle
+				} else {
+					next = current
+					current = bundle
 				}
+			}
+			rotationInterval := next.CertificateNotAfter.AsTime().Sub(current.CertificateNotAfter.AsTime())
 
+			// This is useful output, but doesn't do anything other than output information
+			str := "current"
+			var args []any
+			for i, bundle := range []*types.CertificateBundle{current, next} {
+				if i == 1 {
+					str = "next"
+				}
 				cert, err := x509.ParseCertificate(bundle.CertificateDer)
 				if err != nil {
 					event.WriteError(cancelCtx, op, fmt.Errorf("error parsing leaf certificate in current worker auth bundle: %w", err))
@@ -109,9 +124,9 @@ func (w *Worker) startAuthRotationTicking(cancelCtx context.Context) {
 					continue
 				}
 				args = append(args,
-					fmt.Sprintf("leaf_cert_%d_id", i), certKeyId,
-					fmt.Sprintf("leaf_cert_%d_not_before", i), cert.NotBefore.Format(time.RFC3339),
-					fmt.Sprintf("leaf_cert_%d_not_after", i), cert.NotAfter.Format(time.RFC3339),
+					fmt.Sprintf("leaf_cert_%s_id", str), certKeyId,
+					fmt.Sprintf("leaf_cert_%s_not_before", str), cert.NotBefore.Format(time.RFC3339),
+					fmt.Sprintf("leaf_cert_%s_not_after", str), cert.NotAfter.Format(time.RFC3339),
 				)
 				caCert, err := x509.ParseCertificate(bundle.CaCertificateDer)
 				if err != nil {
@@ -129,54 +144,42 @@ func (w *Worker) startAuthRotationTicking(cancelCtx context.Context) {
 					continue
 				}
 				args = append(args,
-					fmt.Sprintf("ca_cert_%d_id", i), caCertKeyId,
-					fmt.Sprintf("ca_cert_%d_not_before", i), caCert.NotBefore.Format(time.RFC3339),
-					fmt.Sprintf("ca_cert_%d_not_after", i), caCert.NotAfter.Format(time.RFC3339),
+					fmt.Sprintf("ca_cert_%s_id", str), caCertKeyId,
+					fmt.Sprintf("ca_cert_%s_not_before", str), caCert.NotBefore.Format(time.RFC3339),
+					fmt.Sprintf("ca_cert_%s_not_after", str), caCert.NotAfter.Format(time.RFC3339),
 				)
 			}
-			// Ensure that our time periods aren't somehow quite messed up
-			now := time.Now()
+
+			// We'll rotate the first time we get this far, which is fine --
+			// better to rotate early than late -- and then we'll rotate at
+			// halfway through the current rotation interval
+			now := time.Now().UTC()
+			nextRotation := lastRotation.Add(rotationInterval / 2)
 			event.WriteSysEvent(cancelCtx, op, "checking if worker auth should rotate", append(
 				args,
 				"now", now.Format(time.RFC3339),
-				"earliest_valid", earliestValid.Format(time.RFC3339),
-				"latest_valid", latestValid.Format(time.RFC3339),
+				"last_rotation", lastRotation.Format(time.RFC3339),
+				"intuited_rotation_interval", rotationInterval.String(),
+				"next_rotation", nextRotation.Format(time.RFC3339),
 			)...,
 			)
-			if earliestValid.After(now) || latestValid.Before(now) || earliestValid.After(latestValid) {
-				// We basically have no valid creds so we can't rotate.
-				// TODO (maybe): Have this trigger a new set of creds and request?
-				event.WriteSysEvent(cancelCtx, op, "not within worker creds validity period, unsure what to do, not rotating")
+
+			// See if we don't need to do anything
+			if !lastRotation.IsZero() && now.Before(nextRotation) {
+				resetDuration = lastRotation.Add(rotationInterval / 2).Sub(now)
 				continue
 			}
 
-			// Figure out the midpoint; if we're after it, try to rotate
-			var shouldRotate bool
-			delta := latestValid.Sub(earliestValid)
-			switch {
-			case w.TestOverrideAuthRotationPeriod != 0:
-				shouldRotate = true
-			default:
-				resetDuration = latestValid.Sub(now) / 2
-				shouldRotate = now.After(earliestValid.Add(delta / 2))
-			}
-
-			if !shouldRotate {
-				event.WriteSysEvent(cancelCtx, op, "not time to rotate yet",
-					"now", now.Format(time.RFC3339),
-					"midpoint", earliestValid.Add(delta/2).Format(time.RFC3339),
-					"next_check", now.Add(resetDuration).Format(time.RFC3339),
-				)
-				continue
-			}
-
-			if err := rotateWorkerAuth(cancelCtx, w, currentNodeCreds); err != nil {
+			newRotationInterval, err := rotateWorkerAuth(cancelCtx, w, currentNodeCreds)
+			if err != nil {
+				resetDuration = 5 * time.Second
 				event.WriteError(cancelCtx, op, err)
 				continue
 			}
-			event.WriteSysEvent(cancelCtx, op, "worker credentials rotated", "next_check", now.Add(resetDuration).Format(time.RFC3339))
-
-			// TODO (maybe): Calculate new delta and set a custom retry time on the timer?
+			lastRotation := now
+			nextRotation = lastRotation.Add(newRotationInterval / 2)
+			resetDuration = nextRotation.Sub(now)
+			event.WriteSysEvent(cancelCtx, op, "worker credentials rotated", "next_rotation", nextRotation)
 		}
 	}
 }
@@ -186,7 +189,7 @@ func (w *Worker) startAuthRotationTicking(cancelCtx context.Context) {
 // it is meant to be called from other functions that have validated these
 // inputs and is separated out purely for (a) cleanliness/readability of the
 // ticking function and (b) possible future re-use.
-func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.NodeCredentials) error {
+func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.NodeCredentials) (time.Duration, error) {
 	const op = "worker.rotateWorkerAuth"
 
 	randReaderOpt := nodeenrollment.WithRandomReader(w.conf.SecureRandomReader)
@@ -194,11 +197,11 @@ func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.No
 	// Ensure we can get some needed values prior to actually doing generation
 	client := w.controllerMultihopConn.Load()
 	if client == nil {
-		return berrors.New(ctx, berrors.Internal, op, "nil multihop client")
+		return 0, berrors.New(ctx, berrors.Internal, op, "nil multihop client")
 	}
 	multihopClient, ok := client.(multihop.MultihopServiceClient)
 	if !ok {
-		return berrors.New(ctx, berrors.Internal, op, "multihop client is not the right type")
+		return 0, berrors.New(ctx, berrors.Internal, op, "multihop client is not the right type")
 	}
 
 	// Generate a new set of credentials but don't persist them yet
@@ -210,24 +213,24 @@ func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.No
 		nodeenrollment.WithSkipStorage(true),
 	)
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	err = newNodeCreds.SetPreviousEncryptionKey(currentNodeCreds)
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	// Get a signed request from the new credentials
 	fetchReq, err := newNodeCreds.CreateFetchNodeCredentialsRequest(ctx, randReaderOpt)
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	// Encrypt the values to the server
 	encFetchReq, err := nodeenrollment.EncryptMessage(ctx, fetchReq, currentNodeCreds, randReaderOpt)
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	resp, err := multihopClient.RotateNodeCredentials(ctx, &types.RotateNodeCredentialsRequest{
@@ -235,7 +238,7 @@ func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.No
 		EncryptedFetchNodeCredentialsRequest: encFetchReq,
 	})
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	// Decrypt the response using current credentials
@@ -246,7 +249,7 @@ func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.No
 		currentNodeCreds,
 		fetchResp,
 	); err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	// Call handle on the inner response, which will be encrypted to the
@@ -259,59 +262,80 @@ func rotateWorkerAuth(ctx context.Context, w *Worker, currentNodeCreds *types.No
 		nodeenrollment.WithStorageWrapper(w.conf.WorkerAuthStorageKms),
 	)
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 
 	newKeyId, err := nodeenrollment.KeyIdFromPkix(newNodeCreds.CertificatePublicKeyPkix)
 	if err != nil {
-		return berrors.Wrap(ctx, err, op)
+		return 0, berrors.Wrap(ctx, err, op)
 	}
 	w.WorkerAuthCurrentKeyId.Store(newKeyId)
 
+	var current, next *types.CertificateBundle
+	// Go through the bundles and intuit the rotation interval
+	for _, bundle := range newNodeCreds.CertificateBundles {
+		if current == nil {
+			current = bundle
+			continue
+		}
+		if current.CertificateNotAfter.AsTime().Before(bundle.CertificateNotAfter.AsTime()) {
+			next = bundle
+		} else {
+			next = current
+			current = bundle
+		}
+	}
+	rotationInterval := next.CertificateNotAfter.AsTime().Sub(current.CertificateNotAfter.AsTime())
+
+	// This is useful output, but doesn't do anything other than output information
+	str := "current"
 	var args []any
-	for i, bundle := range newNodeCreds.GetCertificateBundles() {
+	for i, bundle := range []*types.CertificateBundle{current, next} {
+		if i == 1 {
+			str = "next"
+		}
 		cert, err := x509.ParseCertificate(bundle.CertificateDer)
 		if err != nil {
-			event.WriteError(ctx, op, fmt.Errorf("error parsing leaf certificate in new worker auth bundle: %w", err))
+			event.WriteError(ctx, op, fmt.Errorf("error parsing leaf certificate in current worker auth bundle: %w", err))
 			continue
 		}
 		certPkixBytes, err := x509.MarshalPKIXPublicKey(cert.PublicKey)
 		if err != nil {
-			event.WriteError(ctx, op, fmt.Errorf("error marshaling leaf certificate public key in new worker auth bundle: %w", err))
+			event.WriteError(ctx, op, fmt.Errorf("error marshaling leaf certificate public key in current worker auth bundle: %w", err))
 			continue
 		}
 		certKeyId, err := nodeenrollment.KeyIdFromPkix(certPkixBytes)
 		if err != nil {
-			event.WriteError(ctx, op, fmt.Errorf("error deriving pkix string from leaf certificate public key in new worker auth bundle: %w", err))
+			event.WriteError(ctx, op, fmt.Errorf("error deriving pkix string from leaf certificate public key in current worker auth bundle: %w", err))
 			continue
 		}
 		args = append(args,
-			fmt.Sprintf("leaf_cert_%d_id", i), certKeyId,
-			fmt.Sprintf("leaf_cert_%d_not_before", i), cert.NotBefore.Format(time.RFC3339),
-			fmt.Sprintf("leaf_cert_%d_not_after", i), cert.NotAfter.Format(time.RFC3339),
+			fmt.Sprintf("leaf_cert_%s_id", str), certKeyId,
+			fmt.Sprintf("leaf_cert_%s_not_before", str), cert.NotBefore.Format(time.RFC3339),
+			fmt.Sprintf("leaf_cert_%s_not_after", str), cert.NotAfter.Format(time.RFC3339),
 		)
 		caCert, err := x509.ParseCertificate(bundle.CaCertificateDer)
 		if err != nil {
-			event.WriteError(ctx, op, fmt.Errorf("error parsing CA certificate in new worker auth bundle: %w", err))
+			event.WriteError(ctx, op, fmt.Errorf("error parsing CA certificate in current worker auth bundle: %w", err))
 			continue
 		}
 		caCertPkixBytes, err := x509.MarshalPKIXPublicKey(caCert.PublicKey)
 		if err != nil {
-			event.WriteError(ctx, op, fmt.Errorf("error marshaling CA certificate public key in new worker auth bundle: %w", err))
+			event.WriteError(ctx, op, fmt.Errorf("error marshaling CA certificate public key in current worker auth bundle: %w", err))
 			continue
 		}
 		caCertKeyId, err := nodeenrollment.KeyIdFromPkix(caCertPkixBytes)
 		if err != nil {
-			event.WriteError(ctx, op, fmt.Errorf("error deriving pkix string from CA certificate public key in new worker auth bundle: %w", err))
+			event.WriteError(ctx, op, fmt.Errorf("error deriving pkix string from CA certificate public key in current worker auth bundle: %w", err))
 			continue
 		}
 		args = append(args,
-			fmt.Sprintf("ca_cert_%d_id", i), caCertKeyId,
-			fmt.Sprintf("ca_cert_%d_not_before", i), caCert.NotBefore.Format(time.RFC3339),
-			fmt.Sprintf("ca_cert_%d_not_after", i), caCert.NotAfter.Format(time.RFC3339),
+			fmt.Sprintf("ca_cert_%s_id", str), caCertKeyId,
+			fmt.Sprintf("ca_cert_%s_not_before", str), caCert.NotBefore.Format(time.RFC3339),
+			fmt.Sprintf("ca_cert_%s_not_after", str), caCert.NotAfter.Format(time.RFC3339),
 		)
 	}
 	event.WriteSysEvent(ctx, op, "rotate worker auth job finished successfully", args...)
 
-	return nil
+	return rotationInterval, nil
 }

internal/daemon/worker/testing.go

@@ -463,10 +463,12 @@ func NewTestMultihopWorkers(t testing.TB,
 	})
 	t.Cleanup(pkiWorker.Shutdown)
 
+	// Give time for it to be inserted into the database
+	time.Sleep(2 * time.Second)
+
 	// Get a server repo and worker auth repo
 	serversRepo, err := serversRepoFn()
 	require.NoError(err)
-
 	// Perform initial authentication of worker to controller
 	reqBytes, err := base58.FastBase58Decoding(pkiWorker.Worker().WorkerAuthRegistrationRequest)
 	require.NoError(err)
@@ -496,6 +498,9 @@ func NewTestMultihopWorkers(t testing.TB,
 		WorkerAuthDebuggingEnabled: enableAuthDebugging,
 	})
 
+	// Give time for it to be inserted into the database
+	time.Sleep(2 * time.Second)
+
 	// Perform initial authentication of worker to controller
 	reqBytes, err = base58.FastBase58Decoding(childPkiWorker.Worker().WorkerAuthRegistrationRequest)
 	require.NoError(err)

internal/server/job/options_test.go

@@ -10,15 +10,15 @@ import (
 func Test_GetOpts(t *testing.T) {
 	t.Parallel()
 	t.Run("WithRotationFrequency", func(t *testing.T) {
-		opts := getOpts(WithRotationFrequency(time.Minute))
 		testOpts := getDefaultOptions()
 		assert.Equal(t, testOpts.withRotationFrequency, defaultRotationFrequency)
+		opts := getOpts(WithRotationFrequency(time.Minute))
 		assert.Equal(t, time.Minute, opts.withRotationFrequency)
 	})
 	t.Run("WithCertificateLifetime", func(t *testing.T) {
-		opts := getOpts(WithCertificateLifetime(time.Minute))
 		testOpts := getDefaultOptions()
-		assert.Equal(t, testOpts.withCertificateLifetime, defaultRotationFrequency)
+		assert.Equal(t, testOpts.withCertificateLifetime, time.Duration(0))
+		opts := getOpts(WithCertificateLifetime(time.Minute))
 		assert.Equal(t, time.Minute, opts.withCertificateLifetime)
 	})
 }

internal/server/service_rotate_roots.go

@@ -34,8 +34,6 @@ func RotateRoots(ctx context.Context, workerAuthRepo *WorkerAuthRepositoryStorag
 	}
 	opt = append(opt,
 		nodeenrollment.WithState(rootCerts.GetState()),
-		nodeenrollment.WithNotAfterClockSkew(0),
-		nodeenrollment.WithNotBeforeClockSkew(0),
 	)
 
 	var current, next string