bug: drain_reader_threads post-kill timeout not enforced; leaked thread blocks capacity slot indefinitely

[vybe]

Summary

drain_reader_threads in subprocess_pgroup.py has two related bugs: (1) the 30-second post-kill grace timeout is not enforced — observed taking 62 minutes instead of 30 seconds before the force-close path fires; (2) when a thread is leaked after force-close, the execution capacity slot is not released, so the agent's execution slot remains blocked until the thread dies on its own. Together these caused a single stuck reader thread to hold an agent's capacity slot for 4 hours 5 minutes, blocking all subsequent scheduled executions.

Component

Agent Runtime / subprocess_pgroup.py

Priority

P1

Error

WARNING  [Subprocess] Reader thread(s) still busy after process exit (stuck_count=1)
         — killing process group, then waiting 30s for natural drain
         
  [62 MINUTES PASS — no log output]

ERROR    [Subprocess] Reader thread(s) still stuck after 30s post-kill grace
         — force-closing pipes (stuck_count=1)

ERROR    [Subprocess] 1 reader thread(s) leaked after force-close; continuing anyway
         → execution slot NOT released

  [1 HOUR 55 MINUTES PASS — leaked thread alive, slot still occupied]

ERROR    [Headless Task] Error reading stdout: I/O operation on closed file.
ERROR    [Headless Task] Execution completed without a result message
         (0 tool calls / 22 turns). Likely cause: child subprocess inherited stdout.
INFO     [ProcessRegistry] Unregistered execution → slot finally freed
         → 6 backed-up executions burst-fire simultaneously

Location

• File: docker/base-image/agent_server/utils/subprocess_pgroup.py
• Function: drain_reader_threads
• Lines: the t.join(timeout=post_kill_grace) call and the if leaked: branch

Root Cause

Bug 1: t.join(timeout=post_kill_grace) doesn't time out

The relevant code:

def drain_reader_threads(process, *threads, grace=5, post_kill_grace=30, pgid=None):
    ...
    terminate_process_group(process, graceful_timeout=1, pgid=pgid)
    _kill_orphan_pipe_writers(process.stdout.fileno(), pgid)
    for t in stuck:
        t.join(timeout=post_kill_grace)  # ← should time out in 30s
    still_stuck = [t for t in stuck if t.is_alive()]
    ...

t.join(timeout=30) is called from an async context where the event loop is handling concurrent executions. Under load, the join blocks far longer than post_kill_grace — observed: 62 minutes instead of 30 seconds. Possible causes:

• If called from a coroutine running in the event loop thread, threading.Thread.join() blocks the event loop for the full duration (the 30s "timeout" only applies to the C-level sem_timedwait, but if the event loop is driving the thread, it may not fire correctly)
• _kill_orphan_pipe_writers itself may block on /proc reads for a hanging process, delaying the subsequent t.join call

Bug 2: Leaked thread holds the capacity slot

When drain_reader_threads returns with leaked threads, the caller marks the execution as failed/completed but does NOT release the capacity slot. The leaked thread keeps the slot occupied until the thread's own I/O operation on closed file error causes it to exit:

if leaked:
    logger.error("... %s reader thread(s) leaked ... continuing anyway", len(leaked))
    # ← nothing here releases the slot
    # ← caller does not release slot either
    # ← leaked thread holds slot for 1h55m in this incident

The capacity slot is only released inside the reader thread itself, or in the finally block of whatever coroutine is awaiting it. If the thread is leaked, that code path doesn't run until the thread finally dies.

Reproduction Steps

1. Deploy an agent that uses a Node.js MCP server (e.g. via npx) in stdio mode
2. Run a schedule that makes multiple large MCP tool calls (responses >100KB)
3. Let the execution run to completion — Claude exits but the node MCP server's process inherits the stdout pipe write end
4. Observe drain_reader_threads WARNING in logs
5. Observe that the ERROR does not appear within 30-60 seconds — it appears 30-90 minutes later
6. Observe that after the ERROR and "leaked" message, the execution slot remains occupied in the DB/ProcessRegistry even though the claude process has exited

Suggested Fix

Fix 1: Enforce the post-kill timeout from a thread, not the event loop

import concurrent.futures

async def drain_reader_threads_async(process, *threads, grace=5, post_kill_grace=30, pgid=None):
    ...
    terminate_process_group(process, graceful_timeout=1, pgid=pgid)
    _kill_orphan_pipe_writers(process.stdout.fileno(), pgid)
    
    # Run blocking joins in a thread pool so the event loop timeout actually fires
    loop = asyncio.get_event_loop()
    with concurrent.futures.ThreadPoolExecutor() as pool:
        join_futures = [
            loop.run_in_executor(pool, lambda t=t: t.join(timeout=post_kill_grace))
            for t in stuck
        ]
        await asyncio.wait_for(
            asyncio.gather(*join_futures, return_exceptions=True),
            timeout=post_kill_grace + 2  # hard ceiling
        )
    still_stuck = [t for t in stuck if t.is_alive()]

Fix 2: Release the capacity slot when a thread is leaked

if leaked:
    logger.error("... %s reader thread(s) leaked ...", len(leaked))
    # Signal to the caller that the slot must be released immediately
    return LeakedThreads(leaked)  # or raise, or set a flag

# In the caller:
result = await drain_reader_threads(...)
if isinstance(result, LeakedThreads):
    # Release capacity slot now, don't wait for thread to die
    process_registry.unregister(execution_id)
    execution.mark_failed("Reader thread leaked after force-close")

Fix 3 (complementary): Log timestamps at each drain phase

Add sub-second timestamps to each phase of drain so the delay is visible in logs:

logger.warning("... waiting %ss ...", post_kill_grace)
t0 = time.monotonic()
t.join(timeout=post_kill_grace)
elapsed = time.monotonic() - t0
if t.is_alive():
    logger.error("... still stuck after %.1fs (expected %ss) ...", elapsed, post_kill_grace)

Environment

• Trinity version: affected version includes the _kill_orphan_pipe_writers fix (deployed 2026-05-03)
• Docker base image: trinity-agent-base:latest
• OS: Linux (Docker container)

Impact

Period	Effect
Warning → force-close	62 min blocked instead of 30s (drain loop non-functional)
Force-close → slot free	1h55m capacity slot occupied by leaked thread
Total slot blockage	4h05m from execution start
Cascade	6 executions burst-fired when slot freed; 4 additional stuck threads within 30 min
Workaround	Container restart to clear all stuck threads

Related

• docker/base-image/agent_server/utils/subprocess_pgroup.py
• The _kill_orphan_pipe_writers fix (already deployed) correctly kills orphan node MCP processes in most cases but does not help when the reader thread is stuck processing buffered pipe data (no live orphan to kill)
• Root trigger: Node.js MCP servers started via npx in stdio mode inherit the claude stdout pipe; switching to HTTP transport (type: "http") eliminates the pipe inheritance entirely

[vybe]

/claim

[github-actions]

Claimed by @vybe. Label status-in-progress added.

Next steps:

1. Create branch: feature/649-<short-slug>
2. Implement the feature
3. Open a PR with Fixes #649

[vybe]

Shipped in v0.6.0 (released via #998).