Skip to content

[Bug] Illegal call tracer converts DeadlockError to NondeterminismError, bypassing #467 and committing partial command batches #503

Description

@AnushkaKulkarni

Disclaimer: heavy use of AI (fable) in this description, but tldr: we were seeing the tracer converting a deadlock detection error into a nondeterminism error. this error is not rescued + re-raised like the deadlock error is so results in stuck workflows. same category of bug as #464 with the partial workflow history. I'll put up a PR for a patch that fixed this for us.

What are you really trying to do?

Same scenario as #464: fanning out ~100 activities from Workflow::Futures (with a Workflow.sleep between batches) on workers that sometimes run under heavy CPU contention. We run 1.5.0 plus a backport of the #467 fix (DeadlockError marked with Internal::WorkflowTaskFailureError and re-raised out of futures), and still got two permanently broken workflows in production (Jul 24 and Jul 26).

Describe the bug

#467 relies on the DeadlockError class surviving until Future#initialize's rescue. There is a path where it does not survive: the illegal call tracer's validator rescue.

The deadlock detector is Timeout.timeout(...) around the whole activation (thread_pool.rb), so the DeadlockError is raised asynchronously into the workflow thread and lands wherever that thread happens to be. If it lands while the thread is executing an IllegalWorkflowCallValidator block, the tracer's rescue Exception => e (both branches in IllegalCallTracer#initialize) captures it and converts it into a Workflow::NondeterminismError with the original error flattened into a string:

rescue Exception => e # rubocop:disable Lint/RescueException
  ", reason: #{e}"
end
# ...
raise Workflow::NondeterminismError,
      "Cannot access #{class_name} #{tp.callee_id} from inside a workflow#{invalid_suffix}. ..."

NondeterminismError does not include the WorkflowTaskFailureError marker, so Future#initialize stores it instead of re-raising. The activation then completes successfully with a partial command batch — exactly the corruption #464 reported and #467 was meant to prevent.

In our production occurrences the async raise landed inside Google::Protobuf::ObjectCache#try_add's Thread::Mutex#synchronize, invoked by the SDK's own ProtoUtils.convert_to_payload_array while building a ScheduleActivity command. Because OutboundImplementation#execute_activity increments @activity_counter before add_command, the dying fiber consumes an activity id whose command is never emitted. The committed history has a hole in the activity id sequence (..., 93, 94, 96, 97, ... — 95 missing), and replay on any other worker fails forever:

[TMPRL1100] Nondeterminism error: Activity id of scheduled event '96' does not match activity id of activity command '95'

Production stack trace showing the laundering path (from a workflow task failure on a later task of the same workflow):

Cannot access Thread::Mutex synchronize from inside a workflow, reason: [TMPRL1101] Potential deadlock detected: workflow didn't yield within 2.0 second(s).. If this is known to be safe, the code can be run in a Temporalio::Workflow::Unsafe.illegal_call_tracing_disabled block.
  temporalio-1.5.0-x86_64-linux/lib/temporalio/internal/worker/workflow_instance/illegal_call_tracer.rb:116
  google-protobuf-3.25.8/lib/google/protobuf/object_cache.rb:35:in 'Google::Protobuf::ObjectCache#try_add'
  temporalio-1.5.0-x86_64-linux/lib/temporalio/internal/proto_utils.rb:108:in 'Temporalio::Internal::ProtoUtils.convert_to_payload_array'
  temporalio-1.5.0-x86_64-linux/lib/temporalio/internal/worker/workflow_instance/outbound_implementation.rb:77:in 'block in OutboundImplementation#execute_activity'
  temporalio-1.5.0-x86_64-linux/lib/temporalio/internal/worker/workflow_instance/outbound_implementation.rb:155:in 'OutboundImplementation#execute_activity_once'
  ... (workflow code: Temporalio::Workflow::Future.new { Temporalio::Workflow.execute_activity(...) })
  temporalio-1.5.0-x86_64-linux/lib/temporalio/internal/worker/workflow_instance/scheduler.rb:140:in 'block in Scheduler#fiber'

The workflow then retries the workflow task indefinitely with the same [TMPRL1100] error until manually terminated.

Minimal Reproduction

The organic trigger requires the async Timeout raise to land inside a validator block under CPU contention, which is hard to do deterministically. A custom validator that raises DeadlockError exercises the identical code path deterministically (it stands in for the watchdog's raise landing mid-validator):

require 'securerandom'
require 'temporalio/client'
require 'temporalio/worker'
require 'temporalio/workflow'

class BasicActivity < Temporalio::Activity::Definition
  def execute(value) = value
end

module ValidatorProbe
  def self.probe = nil
end

# Stands in for any traced call made while the deadlock watchdog fires
# (production case: Thread::Mutex#synchronize inside protobuf's ObjectCache
# during ScheduleActivity arg serialization).
ILLEGAL_CALLS = Temporalio::Worker.default_illegal_workflow_calls.merge(
  'ValidatorProbe' => [
    Temporalio::Worker::IllegalWorkflowCallValidator.new(method_name: :probe) do |_info|
      # Simulates Timeout.timeout's async DeadlockError landing inside the validator block
      raise Temporalio::Worker::WorkflowExecutor::ThreadPool::DeadlockError,
            "[TMPRL1101] Potential deadlock detected: workflow didn't yield within 2.0 second(s)."
    end
  ]
).freeze

class SwallowedDeadlockWorkflow < Temporalio::Workflow::Definition
  def execute
    Temporalio::Workflow::Future.new do
      ValidatorProbe.probe
      Temporalio::Workflow.execute_activity(BasicActivity, 1, start_to_close_timeout: 10)
    end
    # The future is not waited yet (mirrors a fanout blocked on all_of with
    # other futures still pending), so the stored failure never surfaces.
    Temporalio::Workflow.wait_condition { false }
  end
end

client = Temporalio::Client.connect('localhost:7233', 'default')
task_queue = "tq-#{SecureRandom.uuid}"
worker = Temporalio::Worker.new(
  client:,
  task_queue:,
  workflows: [SwallowedDeadlockWorkflow],
  activities: [BasicActivity],
  illegal_workflow_calls: ILLEGAL_CALLS
)
worker.run do
  handle = client.start_workflow(SwallowedDeadlockWorkflow, id: "wf-#{SecureRandom.uuid}", task_queue:)
  sleep 5
  handle.fetch_history_events.each { |e| puts e.event_type }
  handle.terminate
end

Expected: the workflow task fails with the DeadlockError (WorkflowTaskFailed in history) and is retried — same contract as #467 when the deadlock lands outside a traced call.

Actual: the first workflow task completes. The DeadlockError was converted to NondeterminismError by the tracer and silently stored in the future — no task failure, no log, nothing. When the raise instead happens inside execute_activity arg conversion (the production case), the completed activation contains a partial command batch with a consumed-but-unscheduled activity id, and the history is permanently unreplayable.

Environment/Versions

Additional context

The fix appears small: the validator rescues should let marker-mixed exceptions propagate instead of stringifying them, mirroring what Future#initialize does:

rescue Exception => e # rubocop:disable Lint/RescueException
  raise if e.is_a?(Internal::WorkflowTaskFailureError)

  ", reason: #{e}"
end

PR incoming.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions