temporalio / temporalio/temporal-worker-controller

[Bug] "Detected rollback scenario" logged on every reconcile for a steady-state current version

Open Beginner friendly
#609 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Go
Stars
187
Forks
70
Avg merge
4d 1h
Merged PRs (30d)
31

Description

Describe the bug

A WorkerDeployment that is simply sitting on its current version logs a rollback warning on every reconcile (~10s), indefinitely. No rollback is happening and the planner produces no changes.

Within RollbackMaxVersionAge the controller logs:

Detected rollback scenario using LastCurrentTime. Warning: Auto-upgrade workflows that
upgraded from a previous version to the current version may fail during this rollback,
as they may not handle downgrades properly. Monitor workflow executions for failures.

After that window elapses it switches to logging the following on every reconcile instead, which does not stop:

Skipping rollback: the version's last current time exceeds the max rollback version age
Cause

isRollbackScenario is evaluated at the top of getVersionConfigDiff (internal/planner/planner.go:989), before the check that returns nil when the target build is already current (internal/planner/planner.go:1043-1051).

LastCurrentTime is documented as "the timestamp when this version last became current" and is populated from the server's GetLastCurrentTime(), so a version that is currently Current has it set. In steady state status.TargetVersion.BuildID == status.CurrentVersion.BuildID, that build has a non-nil LastCurrentTime, and neither guard in isRollbackScenario excludes it — so it logs and returns true. The planner then reaches the current == target branch and returns nil.

The log therefore fires once per reconcile. Reconcile requeues with RequeueAfter: 10 * time.Second (internal/controller/worker_controller.go:452).

To Reproduce

Against main @ fde47e730f6f98499107b05e543eb3bbe8d8e7a3, in internal/planner:

func TestGetVersionConfigDiff_SteadyStateLogsRollback(t *testing.T) {
	testCases := []struct {
		name         string
		currentSince time.Duration
		expectedLog  string
	}{
		{
			name:         "within rollback window",
			currentSince: 5 * time.Minute,
			expectedLog:  "Detected rollback scenario using LastCurrentTime.",
		},
		{
			name:         "beyond rollback window",
			currentSince: defaults.RollbackMaxVersionAge + 30*time.Minute,
			expectedLog:  "Skipping rollback: the version's last current time exceeds the max rollback version age",
		},
	}

	for _, tc := range testCases {
		t.Run(tc.name, func(t *testing.T) {
			var logLines []string
			logger := funcr.New(func(prefix, args string) {
				logLines = append(logLines, prefix+" "+args)
			}, funcr.Options{})

			lastCurrent := time.Now().Add(-tc.currentSince)
			version := temporaliov1alpha1.BaseWorkerDeploymentVersion{
				BuildID:      "build-a",
				Status:       temporaliov1alpha1.VersionStatusCurrent,
				HealthySince: &metav1.Time{Time: lastCurrent},
			}
			status := &temporaliov1alpha1.WorkerDeploymentStatus{
				CurrentVersion: &temporaliov1alpha1.CurrentWorkerDeploymentVersion{
					BaseWorkerDeploymentVersion: version,
				},
				TargetVersion: temporaliov1alpha1.TargetWorkerDeploymentVersion{
					BaseWorkerDeploymentVersion: version,
				},
				VersionConflictToken: []byte("token"),
			}
			state := &temporal.TemporalWorkerState{
				Versions: map[string]*temporal.VersionInfo{
					"build-a": {
						BuildID:         "build-a",
						LastCurrentTime: &lastCurrent,
						Status:          temporaliov1alpha1.VersionStatusCurrent,
					},
				},
			}
			config := &Config{
				RolloutStrategy: temporaliov1alpha1.RolloutStrategy{
					Strategy: temporaliov1alpha1.UpdateProgressive,
					Steps: []temporaliov1alpha1.RolloutStep{
						{RampPercentage: 1, PauseDuration: metav1.Duration{Duration: time.Minute}},
					},
				},
			}

			versionConfig := getVersionConfigDiff(logger, status, state, config)

			assert.Nil(t, versionConfig, "target version is already current, so nothing should change")
			require.Len(t, logLines, 1)
			assert.Contains(t, logLines[0], tc.expectedLog)
		})
	}
}

Both cases pass, i.e. getVersionConfigDiff returns nil while the message is still emitted:

--- PASS: TestGetVersionConfigDiff_SteadyStateLogsRollback (0.00s)
    --- PASS: TestGetVersionConfigDiff_SteadyStateLogsRollback/within_rollback_window (0.00s)
    --- PASS: TestGetVersionConfigDiff_SteadyStateLogsRollback/beyond_rollback_window (0.00s)
Expected behaviour

No rollback log when the target version is already the current version and nothing is being rolled back.

Actual behaviour

Observed on a cluster running v1.10.1 with three stable WorkerDeployments, all reporting Ready=True, Progressing=False, RolloutComplete, ramp percentage 0, and an unchanged current version. Names and build IDs below are redacted:

{"level":"info","msg":"Detected rollback scenario using LastCurrentTime. …","name":"worker-a","targetBuildID":"<build-a>","lastCurrentTime":<redacted>}
{"level":"info","msg":"Skipping rollback: the version's last current time exceeds the max rollback version age","name":"worker-b","targetBuildID":"<build-b>","lastCurrentTime":<redacted>,"maxVersionAge":3600}

worker-a had become current roughly 48 minutes earlier and so was inside the rollback window; worker-b had become current more than an hour earlier and had crossed into the skip branch. Median gap between repeats per deployment: 10.09s, matching the requeue interval. Over three minutes that is 40 "Detected rollback" lines and 13 "Skipping rollback" lines for deployments where nothing changed.

Impact

Log noise rather than incorrect behaviour — no traffic is moved, gates are not bypassed, and drained versions stay scaled to zero. The concern is that the message is phrased as an operational warning instructing operators to "Monitor workflow executions for failures", emitted roughly six times per minute per deployment for deployments in a healthy steady state. It makes a genuine rollback warning hard to spot and adds constant volume to log pipelines.

Suggested fix

Return false early from isRollbackScenario when the target build ID already equals the current build ID, since that is not a rollback. The "Skipping rollback" branch could also drop to V(1), as it is reachable on every reconcile for any long-lived current version.

Versions
  • Controller: reproduced on main @ fde47e73; identical code in v1.11.0 and v1.10.1 (the version running in the affected cluster)
  • Rollout strategies affected: Progressive and AllAtOnce (suppressed only under Manual)

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start in internal/planner/planner.go at getVersionConfigDiff and isRollbackScenario, then review the steady-state case described around lines 989 and 1043-1051. Run the proposed internal/planner test, checking both rollback-age cases and the existing planner tests. Done means a current target returns no diff without emitting either rollback message, while genuine rollback detection remains covered.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
backend, observability
Issue type
Bug
Difficulty
2/5
Estimated time
1-3 hours
Activity status
Active
Clarity
Clearly specified
Newbie friendliness
88/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.