[Bug] 1.11.2 workflow histories failing to replay on 1.11.5

[selbyk]

What are you really trying to do?

We want to update to the latest and have been running @temporalio/*@1.11.2 since 9/25/24. I tried to update to @temporalio/*@1.11.5 a few days ago and was faced with:

2024-12-10T21:41:34.484512Z  WARN temporal_sdk_core::worker::workflow: Failing workflow task run_id={{runId}} failure=Failure { failure: Some(Failure { message: "[TMPRL1100] Nondeterminism error: Child workflow id of scheduled event 'task/{{uuid}}' does not match child workflow id of command 'task/{{different_uuid}}'", source: "", stack_trace: "", encoded_attributes: None, cause: None, failure_info: Some(ApplicationFailureInfo(ApplicationFailureInfo { r#type: "", non_retryable: false, details: None, next_retry_delay: None })) }), force_cause: NonDeterministicError }
Replay failed https://cloud.temporal.io/namespaces/{{namespace}}/workflows/{{wfid}}/{{runid}}
DeterminismViolationError: Replay failed with a nondeterminism error. This means that the workflow code as written is not compatible with the history that was fed in. Details: Workflow activation completion failed: Failure { failure: Some(Failure { message: "[TMPRL1100] Nondeterminism error: Child workflow id of scheduled event 'task/{{uuid}}' does not match child workflow id of command 'task/{{different_uuid}}'", source: "", stack_trace: "", encoded_attributes: None, cause: None, failure_info: Some(ApplicationFailureInfo(ApplicationFailureInfo { r#type: "", non_retryable: false, details: None, next_retry_delay: None })) }), force_cause: NonDeterministicError }
    at evictionReasonToReplayError (/Users/selby/projects/monorepo/node_modules/.pnpm/@temporalio+worker@1.11.5_@swc+helpers@0.5.6_esbuild@0.21.5/node_modules/@temporalio/worker/lib/replay.js:34:20)
    at Worker.runReplayHistories (/Users/selby/projects/monorepo/node_modules/.pnpm/@temporalio+worker@1.11.5_@swc+helpers@0.5.6_esbuild@0.21.5/node_modules/@temporalio/worker/lib/worker.js:228:76)
    at async replayWorkflows (/Users/selby/projects/monorepo/apps/temporal-workers/workflow-tests/replay.ts:2:3826)
    at async replayWorkflowsInEnv (/Users/selby/projects/monorepo/apps/temporal-workers/workflow-tests/replay.ts:2:4907)
    at async replay (/Users/selby/projects/monorepo/apps/temporal-workers/workflow-tests/replay.ts:2:6297) 

on almost all of some of our workflow history types, including our latest histories. They seem to replay fine on @temporalio/*@1.11.3.

Describe the bug

We use uuid4() (from @temporalio/workflow) to generate a workflowId => task/uuid4(), and we use that workflowId in startChild({ workflowId }). We replay all running and up to the last 500 completed histories on each of our workflow types on every PR/deploy, and this part of our code and the replays have been stable for months.

Minimal Reproduction

Maybe we can find a minimal reproduction together. I just want to get this on your radar.

Environment/Versions

• OS and processor: M2 Mac and Linux (GH Actions)
• Temporal Version: 1.11.5

Additional context

[mjameswh]

Hey @selbyk! Would you be able to provide a bit more information regarding this error?

[selbyk]

Yeah, sorry for the delay. We were really hoping this was going to be a more widespread issue that would be resolved quickly. We're still on v1.11.2.

We have decided to make it a priority this sprint to investigate what's happening. Our core workflows are rather complex, so I will dig in and try to distill down to the root of it as best I can. I'll report back when I have something to share.

[selbyk]

@mjameswh Ok, this morning I finally had some time to get on this. We have 3 workflows that have replay discrepancies between v1.11.2 and v1.11.7. Two of them are very complex, but fortunately one of them is relatively small and straight forward.

How do we go from here? What is valuable to help with this on your end?

[selbyk]

So, we have narrowed down the cause on our small, straight forward workflow. It appears like a breaking change to the behavior of signalWithStart.

I downloaded the workflow history and used the Temporal VS Code extension to run v1.11.2 and v1.11.7 in the debugger:

export const mvpWorkflow: MVPWorkflow.Definition = async ({
	webhooks = [],
}) => {
	setHandler(webhookPayload, (incomingWebhook) => { // Breakpoint 1
		webhooks.push(incomingWebhook);
		logger.debug('mvpWorkflow incoming webhook', { // Breakpoint 2
			webhooks,
			incomingWebhook,
		});
	});

	if (webhooks.length > 0) { // Breakpoint 3
		const lastWebhook = webhooks.at(-1)!;
		webhooks = [];
		logger.debug('processing webhook', {
			lastWebhook,
			webhooks,
		});
		await processUpdateOrCreate({ data: lastWebhook });
	}

	await sleep('1m');

	if (webhooks.length > 0) {
		return await continueAsNew<typeof mvpWorkflow>({
			metadata,
			webhooks,
		});
	}
};

v1.11.2 hits breaks in this order: 1, 2, 3 (webhooks.length = 1)

v1.11.7 hits breaks in this order: 1, 3 (webhooks.length = 0), 2

And expectedly, the v1.11.7 replay fails because the processUpdateOrCreate activity is never hit.

I will look into our other two workflows as well. One of those also uses signalWithStart heavily so I expect it to be the same issue, but the other one doesn't so I'll start there.

[mjameswh]

@selbyk Thanks for the updates.

Assuming the webhookPayload signal is dispatched as part of the first workflow task (which is guaranteed to be the case when workflow is started using signalWithStart), the order should indeed be 1-2-3. This has never changed.

I can't reproduce the 1-3-2 sequence on my side. The following code gives me 1-2-3 in both 1.11.2 and 1.11.7. This is also the order I get if I put breakpoints on those three lines and replay using the Temporal VS Code extension using SDK 1.11.7.

// workflows.ts
export async function example(): Promise<void> {
  console.log('### checkpoint 1');
  setHandler(defineSignal('mySignal'), async () => {
    console.log('### checkpoint 2');
  });
  console.log('### checkpoint 3');
}

// client.ts
const handle = await client.workflow.signalWithStart(example, {
  taskQueue: 'repro',
  workflowId: 'workflow-' + nanoid(),
  signal: 'mySignal',
});

Can you try to work from this code and see if you can replicate the issue you are seeing?

[selbyk]

@mjameswh I'm not sure what you want to do with this issue, but just to follow up for anyone else who may run into it and winds up here. We ended up hopping on a call last week and, thanks to James and Thomas, traced the issue(s) back to changes in the OpenTelemetry interceptors.

We fixed our non-determinism errors by patching the interceptors:

class OTELInboundInterceptor extends OpenTelemetryInboundInterceptor {
	public handleSignal(input: SignalInput, next: Next<WorkflowInboundCallsInterceptor, 'handleSignal'>): Promise<void> {
		if (patch) {
			// Patch needed because of a change in OpenTelemetryInboundInterceptor that broke determinism
			return super.handleSignal(input, next);
		}
		return next(input);
	}
}

class OTELOutboundInterceptor extends OpenTelemetryOutboundInterceptor {
	public async scheduleLocalActivity(
		input: LocalActivityInput,
		next: Next<WorkflowOutboundCallsInterceptor, 'scheduleLocalActivity'>,
	): Promise<unknown> {
		if (patch) {
			// Patch needed because of a change in OpenTelemetryOutboundInterceptor that broke determinism
			return super.scheduleLocalActivity(input, next);
		}
		return next(input);
	}
}

Replace patch with your patch.

Thank you again for so much of your time tracking down the issue. Next time I should be able to narrow it down further before opening a ticket with better details.

[selbyk]

I see #1677 was opened to cover this, so closing this one.