QwenLM#3731) (QwenLM#4432) * feat(telemetry): Phase 4b — retry visibility for qwen-code.llm_request (QwenLM#3731) Adds per-attempt retry telemetry for HTTP-status retries (429/5xx) emitted by retryWithBackoff at the 4 LLM call sites. Second slice of Phase 4 (sub-issue Architectural discovery (mid-planning) -------------------------------------- The Phase 4 design doc assumed claude-code's "one LLM span owns the retry loop" pattern. Reading the 4 retryWithBackoff call sites revealed qwen-code inverts that: retryWithBackoff sits ABOVE LoggingContentGenerator. Each attempt creates a fresh LLM span. The original "in-LCG accumulator" plan wouldn't work. Resolution: propagate retry state via AsyncLocalStorage (`retryContext`). retryWithBackoff wraps each `await fn()` in `retryContext.run(...)`, and LoggingContentGenerator reads the ALS in its synchronous prelude (before the first await) and threads the snapshot into all endLLMRequestSpan callsites — success / error / idle-timeout / abort. Matches existing patterns (promptIdContext, subagentNameContext, agent-context). Plan went through 3 review rounds (Plan-agent reviews) finding 22 issues total — all addressed before implementation. Changes ------- - New retryContext.ts (AsyncLocalStorage<RetryAttemptContext>) with attempt + requestSetupMs + retryTotalDelayMs fields. Computed in retry.ts immediately before `await fn()` so values are anchored to the attempt's actual start, not derived downstream. - retry.ts: - New `onRetry?: (info: RetryAttemptInfo) => void` option on RetryOptions. Opt-in per caller: non-LLM callers stay silent. - Monotonic `iterationCount` decoupled from `attempt` (which is clamped at `maxAttempts - 1` in persistent mode). Always reflects "this is the Nth fn() call" — no flip-flopping for mixed-error sequences. - retryContext.run wrap around fn() so LCG can read the ALS. - onRetry invocations wrapped in try/catch: telemetry exceptions never break the retry loop (logged via debugLogger). - logRetryAttempt debug log line KEPT — useful when OTel SDK isn't wired up (local CLI debugging, integration tests, early-startup errors). - ApiRetryEvent telemetry event class (types.ts) with model + promptId + attempt_number + error fields + subagent_name. JSDoc cross-references ContentRetryEvent (they cover different retry budgets — HTTP-status vs invalid-stream — and can both fire for one prompt). - logApiRetry function in loggers.ts — three-sink fan-out matching logContentRetry: QwenLogger RUM, OTel log signal (bridged via LogToSpanProcessor), recordApiRetry metric counter. - recordApiRetry metric (metrics.ts) — `qwen-code.api.retry.count` Counter tagged with {model}. Full COUNTER_DEFINITIONS entry + initialization + recording function + index.ts export. - qwen-logger.ts adds logApiRetryEvent for RUM consistency. - 4 LLM caller wiring sites (client.ts, baseLlmClient.ts x2, geminiChat.ts) opt in with onRetry callback that emits ApiRetryEvent with subagentName from subagentNameContext.getStore(). - LoggingContentGenerator: snapshotRetryMetadata() helper called in the SYNCHRONOUS prelude of generateContent / generateContentStream — only point where retryContext is guaranteed active for the streaming path (the returned AsyncGenerator is iterated AFTER retryWithBackoff resolves). Snapshot threaded as parameter to loggingStreamWrapper so every endLLMRequestSpan callsite (success / error / idle-timeout / abort) sees the same values. `attempt` defaults to 1 when no retry context is present (warmup, side-queries, direct calls) so dashboards filtering WHERE attempt=1 include those. Bundled Phase 4a bug fix (sampling_ms formula) ----------------------------------------------- Phase 4a's `sampling_ms = duration_ms - ttft_ms - (requestSetupMs ?? 0)` was silently wrong. `duration_ms` only covers `ttft + sampling` for the span (startTime is captured when startLLMRequestSpan runs, AFTER any setup phase). Subtracting setup again is double-counting. Phase 4a masked the bug because requestSetupMs was always undefined → 0. Phase 4b populates requestSetupMs with cumulative retry overhead — without this fix, sampling_ms would clamp to 0 for every retried request, wiping output-throughput data exactly when operators need it most. Fix: `sampling_ms = duration_ms - ttft_ms` (drop the setup subtraction). Phase 4a tests updated accordingly: 1 test rewritten to use inputs that actually exercise the clamp under the new formula (ttft > duration = clock skew); 1 test renamed to assert the FIX (setup is NOT subtracted). Out of scope (deferred, noted in PR description) ------------------------------------------------ - Persistent retry mode emission cap (50+ events under QWEN_CODE_UNATTENDED_RETRY). Aggregated attempt/retry_total_delay_ms remain accurate regardless. - SDK-internal retries (openai/google-genai maxRetries=3) remain invisible — operator awareness only. - Stream-iteration errors (mid-stream network drop during for-await) bypass retryWithBackoff entirely. Pre-existing behavior, not a Phase 4b regression. - shouldRetryOnContent content-retry path (retry.ts:184-193) skips onRetry. No caller uses this path today — code path is dead. Tests ----- - retry.test.ts: 9 new cases (monotonic counter, requestSetupMs growth, first-try success, onRetry callback contract, absent-callback silence, callback-throws resilience, shouldRetryOnError mid-loop giveup, parallel-call ALS isolation, nested-retry inner-frame read). - loggers.test.ts: 3 new cases (3-sink fan-out, subagent_name propagation, SDK-not-initialized path). - loggingContentGenerator.test.ts: 4 new cases (non-stream ALS propagation, non-stream default attempt=1, stream ALS propagation through wrapper closure, stream default attempt=1). - session-tracing.test.ts: 1 test rewritten + 1 renamed for the sampling_ms fix. All 580 telemetry + retry + LCG tests pass. tsc --noEmit clean. eslint clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): address Phase 4b review comments (QwenLM#4432) Fixes 6 of 9 inline review comments from wenshao + Copilot. The remaining 3 are pushback (duration_ms semantic = design intent per D5; persistent retry cap = explicitly deferred in PR description). 1. Fix JSDoc inaccuracy on `onRetry` contract (#1+#2): the comment incorrectly said "synchronous throws inside fn execute OUTSIDE the ALS frame." In fact fn() runs inside retryContext.run() so throws ARE inside the frame. What's outside the frame is the onRetry callback itself (it fires from the catch block). Rewritten per wenshao's suggestion: tells callers not to read retryContext.getStore() inside onRetry — all data comes via the RetryAttemptInfo parameter. 2. Add doc comment on content-retry delay inflation (#3): retryTotalDelayMs accumulator includes content-retry delays (shouldRetryOnContent path) which don't fire onRetry. This is intentional — the LLM span attribute reports total user-perceived backoff time — but was undocumented. 3. Add signal?.aborted guard before onRetry invocations (#6): if the abort signal fires between the catch and onRetry execution point, we now skip the callback to avoid phantom retry events that inflate the counter for retries that never actually proceeded. Applied to both persistent and normal retry paths. 4. Add persistent retry path test (status=429 + persistentMode) (#4): the highest-volume production retry path had zero Phase 4b test coverage. Now verifies onRetry fires with monotonic attempt counter and that persistent-mode exponential backoff produces increasing delayMs. 5. Add Retry-After header path test (status=429 + retry-after: 2) (#7): verifies that when the error carries a Retry-After header, onRetry.delayMs reflects the parsed header value (2000ms) instead of the exponential backoff calculation. 6. Add stream idle-timeout retry-attr propagation test (#8): verifies that the closure-captured retrySnapshot reaches the setTimeout-fired endLLMRequestSpan call with correct retry context values (attempt=4, requestSetupMs=3000, retryTotalDelayMs=2500). All 186 affected tests pass (retry 68 + LCG 48 + session-tracing 70). tsc --noEmit clean. eslint clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): R3 review fixes — idle-timeout test guard + prompt_id in RUM (QwenLM#4432) Addresses 2 of 5 R3 review comments from wenshao (2026-05-26): 1. loggingContentGenerator.test.ts:2290 — replace `if (timeoutRecord)` guard with `expect(timeoutRecord).toBeDefined()` so the idle-timeout retry-attr test fails loudly instead of passing with 0 assertions when setTimeout doesn't fire. Also rewrote the test to use fake timers from the START (so the 5-min idle timeout is created under fake clock and can be advanced via vi.advanceTimersByTimeAsync), fixing the underlying reason it wasn't firing. 2. qwen-logger.ts:963 — add `prompt_id: event.prompt_id` to logApiRetryEvent RUM properties. Without this, RUM dashboards cannot correlate api_retry events with specific prompts, unlike the analogous logApiErrorEvent which already includes prompt_id. 165 affected tests pass. Remaining 3 R3 items (#9 onRetry helper, #10 error-path test coverage, #11 caller integration assertions) deferred to follow-up PR — non-blocking refactor/test-hardening. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code)

Release Failed for v0.24.0-nightly.20260502.405d40408 on 2026-05-02 #11

Description

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions