Skip to content

Run hangs forever in Session.await() when a shutdown callback blocks during abort #7444

Description

@robsyme

Bug report

A pipeline that aborts on a task error can hang indefinitely instead of exiting. The head job stays alive with the main thread parked inside Session.await(), and because nothing on the abort path has a timeout, it never recovers. I observed a head job sitting like this for 2 h 38 min before it was killed manually; there is no reason it would ever have exited.

The cause is the statement order in Session.abort() (Session.groovy). The snippet below is from master; the statement order is identical in 25.10.0, where the field on the forceTermination() line is named ansiLogObserver rather than logObserver:

void abort(Throwable cause = null) {
    if( aborted ) return
    ...
    aborted = true
    error = cause
    LoggerHelper.aborted = true
    try {
        def status = dumpNetworkStatus()
        if( status ) log.debug(status)
        if( log.isTraceEnabled() ) log.trace(SysHelper.dumpThreads())
        shutdown0()                          // (1) runs shutdown callbacks + notifyFlowComplete()
        notifyError(null)
        logObserver?.forceTermination()
        executorFactory?.signalExecutors()
        processesBarrier.forceTermination()   // (2) the thing main is waiting on
        monitorsBarrier.forceTermination()
        operatorsForceTermination()
    }
    ...
}

Meanwhile the main thread is blocked in:

void await() {
    log.debug "Session await"
    processesBarrier.awaitCompletion()                  // <-- blocked here
    log.debug "Session await > all processes finished"
    ...
}

processesBarrier can only be released by forceTermination() at (2), which is sequenced after shutdown0() at (1). So any blocking call inside a shutdown callback deadlocks the whole run: the only code that can release main sits behind the call that is stuck. Barrier.awaitCompletion() uses condition.await() with no timeout, and neither shutdown0() nor the callbacks it invokes impose one either.

Expected behavior and actual behavior

Expected: an abort tears the session down and the process exits, even if a shutdown callback misbehaves. A callback that blocks should at worst produce a logged warning after some bounded wait.

Actual: the run hangs forever. No Execution complete -- Goodbye, no terminal status reported to any observer. If the run is being monitored by a tracking service, that service keeps seeing a live run indefinitely, because notifyFlowComplete() is also inside the blocked shutdown0() and never fires.

Steps to reproduce the problem

I hit this in the field rather than from a synthetic case, so I do not have a self-contained reproducer for the specific stall. The deadlock itself can be demonstrated directly by making a shutdown callback block, which is what any of the real blocking paths reduce to:

// hang.nf
workflow {
    Channel.of(1) | FAIL
}

process FAIL {
    input: val x
    script: 'exit 1'
}
// hang.config -- force an abort on the task failure
process.errorStrategy = 'terminate'

then register a blocking shutdown hook (e.g. from a plugin, or a workflow.onComplete handler that waits on something that never arrives). The run never exits.

The more useful question is which real callback blocks. In this run (one executor, no third-party plugins registering hooks) shutdown0() invokes exactly two: TaskPollingMonitor.cleanup() and WorkflowMetadata.invokeOnComplete(). shutdownCallbacks is a ConcurrentLinkedQueue drained FIFO, so they run in registration order, and WorkflowMetadata's hook is registered during session initialization (Session.init()) whereas the monitor's is registered later from Executor.init()monitor.start(). invokeOnComplete() therefore runs first, which means cleanup() most likely never ran at all in my case rather than running and returning early. (The log cannot distinguish the two: cleanup() returns at its first guard when runningQueue is empty without logging anything, and Killing running tasks has 0 occurrences either way. It is not load-bearing for the diagnosis.)

Execution stopped inside invokeOnComplete() before the user's onComplete actions ran, since the pipeline's own completion message never printed. The snippet below is the 25.10.0 text; on master the success line reads this.success = session.isSuccess() but the statement order is identical:

void invokeOnComplete() {
    this.complete = OffsetDateTime.now()
    this.duration = Duration.between( start, complete )
    this.success = !(session.aborted || session.cancelled)
    this.stats = getWorkflowStats()      // <-- suspect
    setErrorAttributes()
    onCompleteActions.each { ... }       // never reached

setErrorAttributes() is effectively non-blocking and exception-proof here (dumpStderr() / dumpStdout() both wrap everything in catch( Exception e ) { return emptyList() }, and the faulting task had no work dir). That leaves getWorkflowStats(), which is WorkflowStatsObserver.getStats()SimpleAgent.getValue():

T getValue() {
    final retrieve = new RetrieveValueClosure<T>(state)
    events.offer(retrieve)
    return retrieve.getResult()     // CountDownLatch.await() -- no timeout
}

getResult() awaits a CountDownLatch(1) that only SimpleAgent's own runner thread can count down. That runner is an unnamed daemon thread which logs nothing unless it errors, so if it has stopped polling for any reason, getValue() waits forever with no diagnostic.

Worth noting that the agent is constructed as new SimpleAgent(data).onError { err -> session.abort(err) }, so the agent thread can itself enter abort(); an abort raised on that thread would self-deadlock at exactly this call. That specific variant is not what happened in my case (no Unexpected error while polling agent event appears in the log), but it looks reachable.

I want to be clear about what is and is not established here. That the block is inside shutdown0(), and inside invokeOnComplete() before the user actions, is proven by the evidence below. The final step to SimpleAgent.getValue() is inference by elimination. I did not have a thread dump. The ordering problem in abort() is independent of which call blocks, and is the thing I think should be fixed.

Program output

Per-thread first/last log timestamps from the head job log, as offsets from process start. The full log is 978 lines and covers 2 h 38 min:

thread                        lines   first      last
main                          269     T+00.000   T+20.686    <- last line is "Session await"
Actor Thread 21               6       T+25.743   T+25.864    <- ran abort(); last line is inside abort()
Task monitor                  1       T+30.194   T+30.194    <- pollLoop broke on isAborted(), arrived at barrier
AWSBatch-executor-1..8        27      T+26.235   T+33.309    <- still submitting jobs (separate issue)
Task submitter                31      T+05m27s   T+2h35m28s  <- unconditional while(true), logs every 5 min
tower-logs-checkpoint         316     T+15.716   T+2h38m35s  <- still alive at EOF

The two threads that matter:

T+20.686  [main]            DEBUG nextflow.Session - Session await
...
T+25.750  [Actor Thread 21] DEBUG nextflow.processor.TaskProcessor - Handling unexpected condition for ...
T+25.855  [Actor Thread 21] ERROR nextflow.processor.TaskProcessor - Error executing process > '<PROCESS>'
T+25.859  [Actor Thread 21] DEBUG nextflow.Session - Session aborted -- Cause: <container resolution error>
T+25.864  [Actor Thread 21] DEBUG nextflow.Session - The following nodes are still active:
          [process] <PROC_A>   status=ACTIVE
          [process] <PROC_B>   status=ACTIVE
          [process] <PROC_C>   status=ACTIVE
<neither thread ever logs again, through to EOF at T+2h38m35s>

main's final line is Session await. Actor Thread 21's final line is the dumpNetworkStatus() output emitted inside abort(), immediately before shutdown0(). Absent from the entire log:

Session await > all processes finished     (0 occurrences)
Session await > all barriers passed        (0)
> Execution complete -- Goodbye            (0)
Killing running tasks                      (0)   <- cleanup() either no-op'd or never ran
<pipeline's own onComplete message>        (0)   <- onCompleteActions never ran
Failed to execute shutdown hook            (0)   <- so no callback threw; it blocked

That last one is worth calling out: shutdown0() wraps each hook in try { hook.run() } catch( Exception e ) { log.debug "Failed to execute shutdown hook: ..." }. The absence of that line rules out "a callback threw and the run died some other way" and leaves "a callback never returned".

The three processes still ACTIVE in the abort's own network dump are exactly the ones still registered on processesBarrier. With the task monitor gone, no task-completion event can drive them to finished, so the only remaining release is the forceTermination() that was never reached.

Environment

  • Nextflow version: 25.10.0 (build 10289)
  • Java version: OpenJDK 64-Bit Server VM 17.0.14+7-LTS (Groovy 4.0.28)
  • Operating system: Linux 6.8.0-1055-aws
  • Executor: awsbatch

Additional context

Suggested fixes, either of which would have bounded the failure instead of hanging forever:

  1. Reorder abort() so the barriers are force-terminated before shutdown0() runs. The callbacks are cleanup work; nothing in them should gate releasing the threads waiting to exit, and none of the current callbacks reads the barriers. This makes the abort path robust to any future blocking callback rather than just the current one. Two caveats. First, the process then exits with the blocked hook still stuck, so whatever that hook would have done (killing running tasks, completion notifications) can be abandoned -- a bounded, survivable failure rather than a clean shutdown. Second, it relies on the shutdownInitiated CAS guard added by Fix race condition calling workflow onComplete twice #7349: on pre-guard code, releasing the barrier lets main proceed into session.destroy()'s own shutdown0() while the abort thread is still inside its drain loop, re-exposing the double-onComplete race that Fix race condition calling workflow onComplete twice #7349 fixed.
  2. Bound SimpleAgent.getValue() with a timeout, returning the last known state (or the uncloned state) and logging a warning on expiry. Currently a stalled agent runner is undiagnosable: the runner thread is unnamed and silent.

A smaller diagnostic improvement: SimpleAgent's runner thread is started via Threads.start(this.&run) without a name, so it does not appear identifiably in a thread dump. Giving it a name would make this class of problem much easier to triage.

I could not find an existing issue for this. Related but distinct: #7349 replaced shutdownInitiated with an AtomicBoolean CAS after 25.10.0, so 25.10.0 has no re-entrancy guard on shutdown0() at all, though that is not what caused this particular hang.

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions