Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions .changeset/issue-1444-inactivity-timeout.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
---
'@link-assistant/hive-mind': patch
---

Add stream inactivity timeout to prevent mid-session hangs when Claude CLI stops producing output (Issue #1444)
170 changes: 170 additions & 0 deletions docs/case-studies/issue-1444/ANALYSIS.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,170 @@
# Case Study: `/hive` Command Stuck on Completion — Stream Inactivity Hang

## Issue Summary

**Issue URL**: https://github.com/link-assistant/hive-mind/issues/1444
**Report Date**: 2026-03-19
**Reporter**: @konard
**Severity**: High — Requires manual interrupt (CTRL+C) to terminate
**Full Log**: https://github.com/konard/log-home-hive-hive-2026-03-19T07-40-34-118Z

## Problem Description

The `/hive` command processing a queue of 11 issues from `suenot/machine-learning-for-trading` got stuck while processing issue #299 (the last issue). The user had to manually interrupt with CTRL+C. The process hung silently for ~74 seconds before the user intervened.

## Timeline Reconstruction

Based on the full log file (156,197 lines):

| Timestamp | Event | Notes |
| --------------------------------- | ---------------------------------------------- | ------------------------------------------------------------------------------ |
| `07:40:34.118Z` | Hive started, 11 issues queued | Single worker, opus model |
| `07:40:50.402Z` | Issue #299 added to queue (last) | 11th of 11 issues |
| `07:40:53.753Z` - `09:50:38.446Z` | Issues #281-#298 processed successfully | 18 "Stream closed normally" events |
| `09:50:52.582Z` | Issue #299 solve started | Last issue in queue |
| `09:51:00.648Z` | Claude CLI started for issue #299 | Session ID: `79535306-e052-4230-bcd1-4e415b907bcd` |
| `09:54:39.266Z` | Rate limit warning received | `anthropic-ratelimit-unified-7d-utilization: 0.85`, `overage-status: rejected` |
| `09:55:55.236Z` | **Last output**: tool_result for file creation | Created `262_market_making_ml/README.md` |
| **GAP** | **~74 seconds of silence — no output** | **Claude CLI waiting for API response** |
| `09:57:09.533Z` | User pressed CTRL+C | Process stuck, no activity |
| `09:57:09.534Z` | Graceful shutdown initiated | Auto-committed uncommitted changes |
| `09:57:09.749Z` | Token usage summary printed | Only 1,975 output tokens used |

**Critical Gap**: Between `09:55:55.236Z` and `09:57:09.533Z` (74 seconds), the Claude CLI process produced no output at all.

## Root Cause Analysis

### Primary Root Cause: Missing Stream Inactivity Timeout

The existing Issue #1280 fix only handles the case when the Claude CLI **emits a `result` event but the stream doesn't close** (30s timeout). In this incident, the problem is fundamentally different:

1. The Claude CLI was still actively working (mid-session, not completed)
2. The last event was a `tool_result` (file creation) — Claude was about to make another API call
3. The Anthropic API had rate limit warnings (`7d-utilization: 0.85`, `overage-status: rejected`)
4. The API call likely **hung indefinitely** or was rejected, causing the Claude CLI to produce no further output
5. Without a `result` event, the Issue #1280 timeout was **never started**
6. There is **no inactivity timeout** — the system will wait forever if no output comes

### Why the Issue #1280 Fix Didn't Help

The Issue #1280 workaround (`forceExitOnTimeout`) is triggered by:

```javascript
if (data.type === 'result') {
if (!resultEventReceived) {
resultEventReceived = true;
resultTimeoutId = setTimeout(forceExitOnTimeout, streamCloseTimeoutMs); // 30s
}
}
```

Since the Claude CLI **never emitted a `result` event** for issue #299, the timeout was never started.

### Contributing Factor: Rate Limiting

The log shows the API was near its 7-day rate limit:

```
anthropic-ratelimit-unified-7d-utilization: 0.85
anthropic-ratelimit-unified-7d-surpassed-threshold: 0.75
anthropic-ratelimit-unified-overage-status: rejected
```

This likely caused the Claude CLI to either:

- Wait for an API response that was slow to arrive
- Get rate-limited and enter an internal retry loop without producing NDJSON output
- Hang on a connection that was silently dropped

### Impact Assessment

- 10 out of 11 issues were completed successfully
- Only the last issue (#299) was affected
- The worker had been running for ~2h17m continuously
- Token usage for issue #299 was minimal (1,975 output tokens, session barely started)

## Evidence

### Key Log Entries

Last API response before hang (line 156080-156087):

```json
{
"cache_creation_input_tokens": 382,
"output_tokens": 1,
"service_tier": "standard"
}
```

Last activity (line 156100):

```
"content": "File created successfully at: /tmp/gh-issue-solver-1773913873834/262_market_making_ml/README.md"
```

CTRL+C interrupt (line 156118):

```
🛑 Received interrupt signal, shutting down gracefully...
```

### Comparison with Issue #1280

| Aspect | Issue #1280 | Issue #1444 |
| ----------------------------- | --------------------------------------- | ------------------------------------ |
| When stuck | After `result` event (session complete) | During active session (mid-work) |
| Result event received | Yes | No |
| Issue #1280 timeout triggered | Would have (fix added after) | No — never started |
| Root cause | command-stream pipe not closing | No output from Claude CLI (API hang) |
| Duration of hang | ~5 min 26 sec | ~74 sec (user interrupted early) |

## Applied Solution

### Inactivity Timeout for Claude CLI Stream

Add a configurable inactivity timeout that tracks the time since the last chunk was received from the Claude CLI stream. If no output is received within the timeout period, force-kill the process.

**Configuration**: `HIVE_MIND_STREAM_INACTIVITY_TIMEOUT_MS` (default: 300000 = 5 minutes)

This complements the existing Issue #1280 fix:

- **Issue #1280**: Timeout after `result` event (stream close wait) — 30s default
- **Issue #1444**: Timeout after inactivity (no output at all) — 5 min default

The 5-minute default is chosen because:

1. Claude CLI normally makes API calls that return within 10 minutes (600s `x-stainless-timeout`)
2. Between tool results, there can be pauses while Claude "thinks" or while API calls complete
3. 5 minutes is long enough to accommodate legitimate delays but short enough to detect hangs

### Debug Logging

Added verbose logging to track:

- Inactivity timeout reset on each chunk
- Warning when inactivity timeout is approaching (at 80% of timeout)
- Clear message when force-killing due to inactivity

## Workaround

Users experiencing this issue before the fix can:

1. Monitor the log output — if no new lines appear for several minutes, the process is likely stuck
2. Press CTRL+C to trigger graceful shutdown, which will auto-commit any uncommitted work
3. Re-run the command — it will pick up from where it left off if `--auto-restart-on-uncommitted-changes` is enabled

## Related Issues

- **Issue #1280**: Stream hang after result event (fixed with post-result timeout)
- **Issue #1431**: Process hang at exit (fixed with `drainHandles()`)
- **Issue #1437**: Stuck retry loop (fixed with `x-should-retry` detection)
- **Issue #1353**: Request timeout detection (separate retry logic)
- **command-stream#155**: Upstream issue about `stream()` not terminating

## References

1. Log file: https://github.com/konard/log-home-hive-hive-2026-03-19T07-40-34-118Z
2. Issue #1280 case study: `docs/case-studies/issue-1280/ANALYSIS.md`
3. Claude Code CLI NDJSON streaming: streams `type: "result"` on session completion
4. Anthropic API rate limits: `anthropic-ratelimit-unified-*` headers
63 changes: 13 additions & 50 deletions src/claude.lib.mjs
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ import { sanitizeObjectStrings } from './unicode-sanitization.lib.mjs';
import { displayBudgetStats } from './claude.budget-stats.lib.mjs';
import { buildClaudeResumeCommand } from './claude.command-builder.lib.mjs';
import { handleClaudeRuntimeSwitch } from './claude.runtime-switch.lib.mjs'; // see issue #1141
import { createStreamTimeoutManager } from './claude.stream-timeout.lib.mjs'; // Issue #1280 + #1444
import { CLAUDE_MODELS as availableModels } from './model-validation.lib.mjs'; // Issue #1221
export { availableModels }; // Re-export for backward compatibility
// Helper to display resume command at end of session
Expand Down Expand Up @@ -921,43 +922,17 @@ export const executeClaudeCommand = async params => {
// Issue #1183: Line buffer for NDJSON stream parsing - accumulate incomplete lines across chunks
// Long JSON messages (e.g., result with total_cost_usd) may be split across multiple stdout chunks
let stdoutLineBuffer = '';
// Issue #1280: Track result event and timeout for hung processes.
// command-stream's stream() waits for BOTH process exit AND stdout pipe close; if stdout stays open
// the stream hangs. Workaround: force-kill after result event. See command-stream/issues/155
let resultEventReceived = false;
let resultTimeoutId = null;
let forceExitTriggered = false;
const streamCloseTimeoutMs = timeouts.resultStreamCloseMs;
const forceExitOnTimeout = async () => {
if (forceExitTriggered) return;
forceExitTriggered = true;
const elapsed = `${streamCloseTimeoutMs / 1000}s`;
await log(`⚠️ Stream didn't close ${elapsed} after result event, forcing exit (Issue #1280)`, { verbose: true });
await log(` command-stream stream() is likely stuck waiting for pipe close`, { verbose: true });
try {
if (execCommand.kill) {
await log(` Sending SIGTERM to process...`, { verbose: true });
execCommand.kill('SIGTERM');
// Issue #1346: Capture timer handle so it can be cleared after use to avoid
// leaking an active event loop reference when the process exits before 2s
const sigkillTimerId = setTimeout(() => {
try {
if (!execCommand.result?.code) {
log(` Process still alive after 2s, sending SIGKILL`, { verbose: true });
execCommand.kill('SIGKILL');
}
} catch {
/* process may have exited */
}
}, 2000);
sigkillTimerId.unref();
}
} catch (e) {
await log(` Warning: Could not kill process: ${e.message}`, { verbose: true });
}
};
// Issue #1280 + #1444: Stream timeout management (result-close + inactivity)
const streamTimeouts = createStreamTimeoutManager({
streamCloseTimeoutMs: timeouts.resultStreamCloseMs,
streamInactivityMs: timeouts.streamInactivityMs,
execCommand,
log,
});
streamTimeouts.resetInactivityTimeout(); // Issue #1444
for await (const chunk of execCommand.stream()) {
if (forceExitTriggered) break;
if (streamTimeouts.forceExitTriggered) break;
streamTimeouts.resetInactivityTimeout(); // Issue #1444: reset on each chunk
if (chunk.type === 'stdout') {
const output = chunk.data.toString();
// Append to buffer and split; keep last element (may be incomplete) for next chunk
Expand Down Expand Up @@ -1002,11 +977,7 @@ export const executeClaudeCommand = async params => {
// Handle session result type from Claude CLI (emitted when session completes)
if (data.type === 'result') {
// Issue #1280: Start 30s timeout for stream close after result event
if (!resultEventReceived) {
resultEventReceived = true;
await log(`📌 Result event received, starting ${streamCloseTimeoutMs / 1000}s stream close timeout (Issue #1280)`, { verbose: true });
resultTimeoutId = setTimeout(forceExitOnTimeout, streamCloseTimeoutMs);
}
await streamTimeouts.onResultEvent();
// Issue #1354: Track when result event confirms success (prevents false positive detection)
if (data.subtype === 'success') {
resultSuccessReceived = true;
Expand Down Expand Up @@ -1160,15 +1131,7 @@ export const executeClaudeCommand = async params => {
if (!stdoutLineBuffer.includes('node:internal')) await log(stdoutLineBuffer, { stream: 'raw' });
}
}
// Issue #1280: Clear the stream close timeout since we exited the loop
if (resultTimeoutId) {
clearTimeout(resultTimeoutId);
if (forceExitTriggered) {
await log('⚠️ Stream exited via force-kill timeout (Issue #1280)', { verbose: true });
} else {
await log('✅ Stream closed normally after result event', { verbose: true });
}
}
await streamTimeouts.cleanup();
// Issue #1165: Check actual exit code from command result (stream() may not emit 'exit' chunks)
if (execCommand.result && typeof execCommand.result.code === 'number') {
const resultExitCode = execCommand.result.code;
Expand Down
98 changes: 98 additions & 0 deletions src/claude.stream-timeout.lib.mjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
/**
* Stream timeout management for Claude CLI execution.
* Handles two types of timeouts:
* - Issue #1280: Force-kill after result event if stream doesn't close
* - Issue #1444: Force-kill on stream inactivity (no output for too long)
*/

/**
* Creates a stream timeout manager for Claude CLI execution.
* @param {Object} params
* @param {number} params.streamCloseTimeoutMs - Timeout after result event (Issue #1280)
* @param {number} params.streamInactivityMs - Timeout for stream inactivity (Issue #1444)
* @param {Object} params.execCommand - The command-stream execution handle
* @param {Function} params.log - Logging function
* @returns {Object} Timeout manager with methods to control timeouts
*/
export const createStreamTimeoutManager = ({ streamCloseTimeoutMs, streamInactivityMs, execCommand, log }) => {
let resultEventReceived = false;
let resultTimeoutId = null;
let forceExitTriggered = false;
let inactivityTimeoutId = null;

const killProcess = () => {
try {
if (!execCommand.kill) return;
execCommand.kill('SIGTERM');
// Issue #1346: unref timer to avoid event loop leak
const sigkillTimerId = setTimeout(() => {
try {
if (!execCommand.result?.code) execCommand.kill('SIGKILL');
} catch {
/* process may have exited */
}
}, 2000);
sigkillTimerId.unref();
} catch {
/* process may have exited */
}
};

const forceExit = async reason => {
if (forceExitTriggered) return;
forceExitTriggered = true;
if (inactivityTimeoutId) {
clearTimeout(inactivityTimeoutId);
inactivityTimeoutId = null;
}
if (reason === 'inactivity') {
await log(`⚠️ No output for ${streamInactivityMs / 1000}s, forcing exit (Issue #1444)`, { verbose: true });
} else {
await log(`⚠️ Stream didn't close ${streamCloseTimeoutMs / 1000}s after result, forcing exit (Issue #1280)`, { verbose: true });
}
killProcess();
};

const resetInactivityTimeout = () => {
if (inactivityTimeoutId) clearTimeout(inactivityTimeoutId);
if (forceExitTriggered || resultEventReceived) return;
inactivityTimeoutId = setTimeout(() => forceExit('inactivity'), streamInactivityMs);
inactivityTimeoutId.unref();
};

const onResultEvent = async () => {
if (resultEventReceived) return;
resultEventReceived = true;
if (inactivityTimeoutId) {
clearTimeout(inactivityTimeoutId);
inactivityTimeoutId = null;
}
await log(`📌 Result event received, starting ${streamCloseTimeoutMs / 1000}s stream close timeout (Issue #1280)`, { verbose: true });
resultTimeoutId = setTimeout(() => forceExit('result_stream_close'), streamCloseTimeoutMs);
};

const cleanup = async () => {
if (inactivityTimeoutId) {
clearTimeout(inactivityTimeoutId);
inactivityTimeoutId = null;
}
if (resultTimeoutId) {
clearTimeout(resultTimeoutId);
await log(forceExitTriggered ? '⚠️ Stream exited via force-kill timeout (Issue #1280)' : '✅ Stream closed normally after result event', { verbose: true });
} else if (forceExitTriggered && !resultEventReceived) {
await log('⚠️ Stream exited via inactivity timeout (Issue #1444)', { verbose: true });
}
};

return {
get forceExitTriggered() {
return forceExitTriggered;
},
get resultEventReceived() {
return resultEventReceived;
},
resetInactivityTimeout,
onResultEvent,
cleanup,
};
};
5 changes: 5 additions & 0 deletions src/config.lib.mjs
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,11 @@ export const timeouts = {
// Issue #1280: Timeout (ms) to wait for stream close after result event before force-killing
// command-stream's stream() waits for process exit + pipe close; if stdout stays open, it hangs
resultStreamCloseMs: parseIntWithDefault('HIVE_MIND_RESULT_STREAM_CLOSE_MS', 30000),
// Issue #1444: Timeout (ms) for stream inactivity — force-kill if no output received within this period
// Handles the case where Claude CLI hangs mid-session (e.g., API rate limit, connection drop)
// without ever emitting a result event (which Issue #1280 timeout requires)
// Default: 5 minutes (300000ms) — long enough for legitimate API delays, short enough to detect hangs
streamInactivityMs: parseIntWithDefault('HIVE_MIND_STREAM_INACTIVITY_TIMEOUT_MS', 300000),
};

// Auto-continue configurations
Expand Down