fix(telemetry): hook span error tracking + TTL cleanup safety + call_id back-compat

Three #4321 review threads from wenshao (#4321 codex P3-equivalent +
two structural concerns):

1. **[Critical] Hook spans reported success on swallowed hook failures.**
   firePreToolUseHook / firePostToolUseHook /
   firePostToolUseFailureHook (and the safelyFire wrapper in
   coreToolScheduler) all catch transport / dispatch errors internally
   and return safe defaults. Before this fix, withHookSpan's `toEndMeta`
   ran on the safe default and recorded `success: true` — a crashing
   hook was indistinguishable from one that allowed execution.
   Add a `hookError?: string` field to the three result types, populate
   it in each catch, and have all 6 toEndMeta callbacks return
   `{ success: false, error: hookError }` when present.
   Existing "graceful error" tests updated to expect the new field.

2. **[Suggestion] ensureCleanupInterval not kicked from new helpers.**
   The 30-min TTL cleanup safety net for leaked spans only starts when
   `startInteractionSpan` is first called. Sub-agent or side-query code
   paths that call `startToolBlockedOnUserSpan` / `startHookSpan`
   without an interaction span first never trigger cleanup. Both
   helpers now call the (idempotent) `ensureCleanupInterval()` early.

3. **[Suggestion] `call_id` → `'tool.call_id'` rename is breaking for
   downstream consumers.** Phase 1's `startToolSpan(name, { tool_name,
   call_id })` shipped non-namespaced attribute keys. My Phase 2 #4321
   review-fix dropped both. Dual-emit `call_id` (legacy alias) +
   `'tool.call_id'` for one release cycle so existing dashboards /
   alerts don't silently return zero. Comment notes the legacy key is
   removed in the next release.

🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code)
This commit is contained in:
doudouOUC 2026-05-20 00:01:13 +08:00
parent f9ff554950
commit eafe68820e
4 changed files with 98 additions and 46 deletions

View file

@ -197,10 +197,11 @@ async function safelyFirePostToolUseFailureHook(
permissionMode,
);
} catch (error) {
const message = error instanceof Error ? error.message : String(error);
debugLogger.warn(
`PostToolUseFailure hook failed for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
`PostToolUseFailure hook failed for ${toolName}: ${message}`,
);
return {};
return { hookError: message };
}
}
@ -1412,9 +1413,13 @@ export class CoreToolScheduler {
// success path in executeSingleToolCall — must call
// finalizeToolSpan(callId, ...) to avoid leaking spans.
// `tool.name` is set automatically by startToolSpan from the first
// arg; only namespaced extras go in attrs.
// arg; only namespaced extras go in attrs. `call_id` (non-namespaced)
// is dual-emitted for one release as a backwards-compat shim for
// pre-Phase-2 dashboards/alerts that grep the old key — drop after
// operators migrate (#4321 review).
const toolSpan = startToolSpan(canonicalName, {
'tool.call_id': reqInfo.callId,
call_id: reqInfo.callId,
});
this.toolSpans.set(reqInfo.callId, toolSpan);
@ -2143,6 +2148,7 @@ export class CoreToolScheduler {
if (!toolSpan) {
toolSpan = startToolSpan(toolName, {
'tool.call_id': callId,
call_id: callId, // legacy alias — see _schedule for context
});
this.toolSpans.set(callId, toolSpan);
}
@ -2208,14 +2214,17 @@ export class CoreToolScheduler {
toolUseId,
permissionMode,
),
(r) => ({
success: true,
shouldProceed: r.shouldProceed,
// Propagate the actual blockType ('denied' / 'ask' / 'stop')
// instead of collapsing every block to 'denied'.
blockType: r.shouldProceed ? undefined : r.blockType,
hasAdditionalContext: !!r.additionalContext,
}),
(r) =>
r.hookError
? { success: false, error: r.hookError }
: {
success: true,
shouldProceed: r.shouldProceed,
// Propagate the actual blockType ('denied' / 'ask' / 'stop')
// instead of collapsing every block to 'denied'.
blockType: r.shouldProceed ? undefined : r.blockType,
hasAdditionalContext: !!r.additionalContext,
},
);
if (!preHookResult.shouldProceed) {
// Hook blocked the execution
@ -2352,10 +2361,13 @@ export class CoreToolScheduler {
true,
this.config.getApprovalMode(),
),
(r) => ({
success: true,
hasAdditionalContext: !!r.additionalContext,
}),
(r) =>
r.hookError
? { success: false, error: r.hookError }
: {
success: true,
hasAdditionalContext: !!r.additionalContext,
},
);
// Append additional context from hook if provided
@ -2397,12 +2409,15 @@ export class CoreToolScheduler {
toolUseId,
permissionMode,
),
(r) => ({
success: true,
shouldStop: r.shouldStop,
hasAdditionalContext: !!r.additionalContext,
blockType: r.shouldStop ? 'stop' : undefined,
}),
(r) =>
r.hookError
? { success: false, error: r.hookError }
: {
success: true,
shouldStop: r.shouldStop,
hasAdditionalContext: !!r.additionalContext,
blockType: r.shouldStop ? 'stop' : undefined,
},
);
// Append additional context from hook if provided
@ -2579,10 +2594,13 @@ export class CoreToolScheduler {
false,
this.config.getApprovalMode(),
),
(r) => ({
success: true,
hasAdditionalContext: !!r.additionalContext,
}),
(r) =>
r.hookError
? { success: false, error: r.hookError }
: {
success: true,
hasAdditionalContext: !!r.additionalContext,
},
);
// Append additional context from hook if provided
@ -2651,10 +2669,13 @@ export class CoreToolScheduler {
true,
this.config.getApprovalMode(),
),
(r) => ({
success: true,
hasAdditionalContext: !!r.additionalContext,
}),
(r) =>
r.hookError
? { success: false, error: r.hookError }
: {
success: true,
hasAdditionalContext: !!r.additionalContext,
},
);
// Append additional context from hook if provided
@ -2692,10 +2713,13 @@ export class CoreToolScheduler {
false,
this.config.getApprovalMode(),
),
(r) => ({
success: true,
hasAdditionalContext: !!r.additionalContext,
}),
(r) =>
r.hookError
? { success: false, error: r.hookError }
: {
success: true,
hasAdditionalContext: !!r.additionalContext,
},
);
// Append additional context from hook if provided

View file

@ -215,7 +215,13 @@ describe('toolHookTriggers', () => {
'auto',
);
expect(result).toEqual({ shouldProceed: true });
// #4321 review: hookError surfaces the swallowed transport error so
// observers (telemetry spans, debug logs) can distinguish a failed
// hook from a successful "allow" decision.
expect(result).toEqual({
shouldProceed: true,
hookError: 'Network error',
});
});
});
@ -338,7 +344,9 @@ describe('toolHookTriggers', () => {
'auto',
);
expect(result).toEqual({ shouldStop: false });
// #4321 review: hookError now surfaced to caller (see PreToolUse parallel test).
expect(result.shouldStop).toBe(false);
expect(result.hookError).toBeDefined();
});
});
@ -429,7 +437,9 @@ describe('toolHookTriggers', () => {
'error message',
);
expect(result).toEqual({});
// #4321 review: hookError now surfaced to caller.
expect(result.hookError).toBeDefined();
expect(result.additionalContext).toBeUndefined();
});
});

View file

@ -43,6 +43,14 @@ export interface PreToolUseHookResult {
blockType?: 'denied' | 'ask' | 'stop';
/** Additional context to add */
additionalContext?: string;
/**
* Set when the hook helper caught and absorbed a transport / dispatch
* error. The tool execution still proceeds (existing non-blocking
* contract), but observers (telemetry spans, debug logs) can detect
* that the hook itself failed instead of treating the safe-default
* response as a successful "allow" decision (#4321 review).
*/
hookError?: string;
}
/**
@ -55,6 +63,8 @@ export interface PostToolUseHookResult {
stopReason?: string;
/** Additional context to append to tool response */
additionalContext?: string;
/** See PreToolUseHookResult.hookError. */
hookError?: string;
}
/**
@ -63,6 +73,8 @@ export interface PostToolUseHookResult {
export interface PostToolUseFailureHookResult {
/** Additional context about the failure */
additionalContext?: string;
/** See PreToolUseHookResult.hookError. */
hookError?: string;
}
/**
@ -155,10 +167,9 @@ export async function firePreToolUseHook(
};
} catch (error) {
// Hook errors should not block tool execution
debugLogger.warn(
`PreToolUse hook error for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
);
return { shouldProceed: true };
const message = error instanceof Error ? error.message : String(error);
debugLogger.warn(`PreToolUse hook error for ${toolName}: ${message}`);
return { shouldProceed: true, hookError: message };
}
}
@ -232,10 +243,9 @@ export async function firePostToolUseHook(
};
} catch (error) {
// Hook errors should not affect tool result
debugLogger.warn(
`PostToolUse hook error for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
);
return { shouldStop: false };
const message = error instanceof Error ? error.message : String(error);
debugLogger.warn(`PostToolUse hook error for ${toolName}: ${message}`);
return { shouldStop: false, hookError: message };
}
}
@ -301,10 +311,11 @@ export async function firePostToolUseFailureHook(
};
} catch (error) {
// Hook errors should not affect error handling
const message = error instanceof Error ? error.message : String(error);
debugLogger.warn(
`PostToolUseFailure hook error for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
`PostToolUseFailure hook error for ${toolName}: ${message}`,
);
return {};
return { hookError: message };
}
}

View file

@ -558,6 +558,10 @@ export function startToolBlockedOnUserSpan(
if (!isTelemetrySdkInitialized()) {
return NOOP_SPAN;
}
// Idempotent — kick off the 30-min TTL cleanup in case this span is
// started in a code path where no interaction span has been created
// yet (sub-agent tool calls, side queries, future patterns).
ensureCleanupInterval();
const parentSpanId = getSpanId(toolSpan);
const parentSpanCtx = activeSpans.get(parentSpanId)?.deref();
@ -667,6 +671,9 @@ export function startHookSpan(opts: StartHookSpanOptions): Span {
if (!isTelemetrySdkInitialized()) {
return NOOP_SPAN;
}
// Same defensive cleanup-interval kick as startToolBlockedOnUserSpan —
// hook spans may run before any interaction span has been created.
ensureCleanupInterval();
// Hooks fire from inside `runInToolSpanContext` so toolContext is the
// natural parent. resolveParentContext also covers the rare case where a