Skip to content

fix(qwen): report token usage from Qwen's own chat log - #111

Open
Beehtrix wants to merge 7 commits into
entireio:mainfrom
Beehtrix:fix-qwen-token-usage-75
Open

Beehtrix wants to merge 7 commits into
entireio:mainfrom
Beehtrix:fix-qwen-token-usage-75

Conversation

@Beehtrix

@Beehtrix Beehtrix commented Nov 7, 2026 •

Copy link
Copy Markdown

Why

Fixes #75. Qwen Code sessions report no token usage in entire status, checkpoint tokens or tokens profile. The adapter declares no token_calculator, and the sidecar it uses as the transcript holds hook payloads, which carry no token counts.

Qwen's own chat log does have them. ChatRecordingService.recordAssistantTurn (Qwen Code 0.26.9, packages/core/src/services/chatRecordingService.ts) stores the provider's usage as usageMetadata on every assistant record of ~/.qwen/projects/<project>/chats/<session>.jsonl, the file every hook names as transcript_path. The OpenAI-compatible pipeline asks for it with stream_options.include_usage: true, and the Anthropic and Responses generators convert their usage to the same shape.

@Ar9av reported this and traced it to the sidecar design, and asked whether a second transcript source was wanted. This keeps the sidecar as the only transcript instead, as described below. They offered to implement it, and I've asked on the issue whether they still want to. I'm happy to hand this over or fold in their changes.

What

  • At PreToolUse, Stop, StopFailure, SubagentStop and SessionEnd, the adapter copies the usage of each assistant record it has not copied yet into the sidecar as an AssistantUsage record (usage, native_uuid, native_offset). PreToolUse is there so a commit that a tool makes mid-turn sees the calls before it.
  • At Stop, the copy first waits up to a second for the turn's final assistant record. Qwen queues that record before it fires Stop (client.ts fires Stop after recordAssistantTurn in llm-chat.ts), but the write can still be in flight. The copy polls until the log's last record (system records ignored) is the answer to the turn's last prompt: an assistant record that calls no tool and is no older than the sidecar's last UserPromptSubmit. Qwen also fires UserPromptSubmit, with an empty prompt, before the call that follows a tool round. A line still being written is waited for too, and so is a log Qwen hasn't created yet (it creates the log with its first record). So the TurnEnd checkpoint counts that call, even when the log still ends with the turn's tool call or the previous turn's answer. If Qwen replaces the log during the wait (it rewrites by renaming a new file over it) or cuts it shorter, the wait reads it again from the start.
  • Sidecar records now carry v: 2. v: 1 records come from the adapter before this change; see the floor below.
  • New calculate-tokens sums the AssistantUsage records from --offset, a sidecar line index like the adapter's other offsets. token_calculator is now declared.
  • The sidecar stays the only transcript. Entire stores it in the checkpoint and later passes those stored bytes to calculate-tokens, possibly on a machine that has no chat log, so calculate-tokens never reads the native file.
  • AssistantUsage lines have no top-level type, so Entire's compact transcript drops them; extract-summary, extract-prompts and extract-modified-files ignore them.
  • Mapping: input_tokens = promptTokenCount − cachedContentTokenCount, cache_read_tokens = cachedContentTokenCount. Output counts reasoning once: OpenAI-compatible and Anthropic providers include it in candidatesTokenCount, Gemini only in thoughtsTokenCount, so totalTokenCount decides, as in Qwen's own outputTokenCount (telemetry/gen-ai-usage.ts).

Robustness:

  • A copy finds the last AssistantUsage record for the log by reading the sidecar backwards from its end, and resumes after that record's line while the line still holds the same record (uuid check). A hook therefore reads what was appended since the last copy, not the whole session. Otherwise it rereads the log, because Qwen can rewrite it, for example when prompts are deleted, and copies its calls again. A sidecar line too long to hold, such as a long prompt, is checked from its first 4 KiB, where the sidecar writes event and ts.
  • calculate-tokens counts each native_uuid once, whether both copies come after --offset or one comes before it. That covers calls copied again after a rewrite and calls copied by two hooks at the same time. Entire passes the whole session transcript plus an offset for both turn and checkpoint usage, so a copy before a checkpoint boundary is always visible to the next checkpoint.
  • A trailing line with no newline is still being written and is left for the next copy.
  • A hook payload without a timestamp gets the hook's time to the nanosecond, so a prompt can't sort before the previous turn's answer.
  • Skipped: records /branch copied from a parent session (forkedFrom), subagent records (isSidechain), and records older than the sidecar's first v: 2 record. The last case covers two kinds of history: a resumed session whose sidecar was cleaned out of the temp directory, and a session whose sidecar the older adapter started. Without the cutoff, that history would land in the first turn after the resume or the upgrade. When the older adapter's records leave a turn open (a typed prompt, not the empty one before a tool round's next call, with no end of turn or session after it), that prompt is the cutoff instead, so an upgrade in the middle of a turn still counts that turn, whichever hook runs first after it. A turn those records saw end stays out.
  • The copy is best effort. If the chat log can't be read, the hook still succeeds.

Known limits

  • Late writes. Qwen writes its log through a queue that no hook waits for, so a call can land after the hook that follows it. I saw this once in six live runs, at PreToolUse; that call was still counted in the same turn, at Stop. Stop waits up to a second for the turn's final call. A call that lands even later is copied at the next hook and counted with that turn or checkpoint. Totals are unaffected.
  • Upgraded sessions. In a sidecar the older adapter started, the first v: 2 line comes after all the old lines, so until then each copy scans those old lines to find it.
  • Main chat only. Calls that Qwen records outside the session's assistant records aren't counted. That covers subagents, which write subagents/<session>/agent-<id>.jsonl, and background helpers such as the auto-memory extractor. In the live run below, the extractor made a third request (3011 input tokens) that is not counted. Qwen's ui_telemetry api_response records in the same log do cover it, tagged with subagent_id, so they could feed subagent_tokens in a follow-up.
  • No cache-write count. For Anthropic models, Qwen folds cache writes into promptTokenCount (buildAnthropicUsageMetadata), so they count as input here.

Tests (new tokens_test.go)

Driven through ParseHook against a native log the test writes:

  • a full turn: prompt, tool call and answer, per-turn totals from the turn's start position
  • Stop waiting for a final record that is half written when the hook fires
  • Stop waiting when the log still ends with the turn's tool call (with and without the tool round's prompt after it) or with the previous turn's answer, also after a long prompt, and when a rewrite made that answer the last copy
  • Stop waiting for a log that doesn't exist yet
  • a call written after Stop while the log already holds an answer, which is counted with the next turn and leaves the session total right
  • a partial line, copied once it is complete
  • a rewritten log, with nothing counted twice, and later syncs resuming inside the rewritten log
  • the anchor check on resume, and the backwards read: first line, past 200 KiB lines, records for another log, partial trailing line, the last prompt before or after the anchor, long prompts
  • resumed history older than the sidecar, which is not copied
  • a sidecar started by the older adapter, counted from the first hook after the upgrade, or from the turn's prompt when the upgrade lands mid-turn: before the tool call, after the tool round, before the call reaches the log, or with a hook that copies nothing first. A turn it saw end stays out
  • a log replaced by rename while Stop waits, read again from the start
  • forkedFrom and isSidechain records, which are skipped
  • duplicate copies across --offset
  • a payload without a timestamp keeps sub-second time

Also: the usage mapping for OpenAI-style, Gemini-style, no-total and clamped cache; "{}" (what the compliance suite sends) and pre-change sidecars report zeros without error; oversized lines are skipped without losing offsets.

go test ./... and go test -race ./... pass for the qwen module. gofmt -l . is clean, and golangci-lint 2.11.3 (the CI pin) reports 0 issues. On main the new tests don't compile (CalculateTokens doesn't exist), and the main binary reports token_calculator: false and unknown subcommand: calculate-tokens.

Live check

I installed @qwen-code/qwen-code@0.26.9 from npm and ran qwen -p "Create hello.txt containing hello" --yolo against a local OpenAI-compatible mock. The mock streams a usage chunk, and gives each request its own numbers. The adapter's installed hooks ran through a stand-in entire that passes each payload to parse-hook.

  • Qwen sent stream_options.include_usage: true and recorded usageMetadata on both main-chat assistant records, with the mock's exact numbers: {"promptTokenCount":1011,"candidatesTokenCount":13,"cachedContentTokenCount":100,...} and {"promptTokenCount":2011,"candidatesTokenCount":23,"cachedContentTokenCount":200,...}.
  • The sidecar got one AssistantUsage record per call, and calculate-tokens --offset 0 printed {"input_tokens":2722,"cache_creation_tokens":0,"cache_read_tokens":300,"output_tokens":36,"api_call_count":2}.
  • In 5 of the 6 hooked runs, each call was copied at the first hook after it (PreToolUse, then Stop). In the other run, the first call wasn't on disk yet at PreToolUse and was copied at Stop.
  • Eleven more runs during later revisions gave the same totals: three with the first Stop wait and v: 2, two with the backwards anchor read, three with the answer-based Stop wait, two with b2d7ef4 and one with 3de67be. Each time, the final record was already on disk when Stop fired. Replaying a run's Stop with the answer-based wait returned in 5 ms, so it doesn't wait when the answer is there. In every run I checked for it, Qwen fired UserPromptSubmit a second time, with an empty prompt, before the call after the tool round.

Not verified

  • I didn't use a real provider. The mock streams usage the way an OpenAI-compatible provider does when asked.
  • I didn't run the lifecycle e2e (QWEN_E2E=1), which needs real Qwen credentials and entire.
  • I didn't run the external-agents-tests compliance suite locally. Its token test sends {} with --offset 0, which is covered by a unit test and by running the binary.
  • Not changed here, but needed for the live run: in a headless run, Qwen 0.26.9 runs project hooks (.qwen/settings.json) only in a trusted folder, or if they were approved interactively before. Otherwise it prints "Project hooks in .qwen/settings.json were not loaded: the folder is not explicitly trusted", and no Entire hook runs. That affects the adapter as a whole, not just tokens, so it has its own issue, qwen: Qwen Code 0.26.7+ skips the adapter's hooks until the user trusts them #110.

Qwen sessions reported no token usage: the adapter declared no
token_calculator, and the sidecar it uses as the transcript holds hook
payloads, which carry no token counts.

Qwen Code writes the provider's usage on every assistant record of its
own chat log, the file the hooks name as transcript_path. At PreToolUse,
Stop, StopFailure, SubagentStop and SessionEnd, copy the usage of each
assistant record not copied yet into the sidecar as an AssistantUsage
record, and add calculate-tokens, which sums those records after
--offset. The sidecar stays the only transcript, so a stored checkpoint
still reports its tokens where the chat log does not exist.

A copy resumes after the furthest copied line while that line still
holds the same record, and rereads the log otherwise; the native record
uuid keeps a call from being copied or counted twice. Lines still being
written, /branch copies, subagent records and history older than the
sidecar are skipped. Input excludes the cached share, which is reported
as cache reads, and reasoning is counted once whichever provider
convention Qwen recorded.

Qwen fires Stop without waiting for its write queue, so a turn's last
API call can be copied, and counted, one hook late.
…at the upgrade

Qwen queues the turn's final assistant record before it fires Stop, but the
write can still be in flight when the hook reads the log. While the log ends
with a user or tool_result record, or a line still being written, the Stop
sync now polls for up to a second, so the TurnEnd checkpoint counts the call
instead of the next one. Other hooks still decode only lines that can carry
usage.

A sidecar that an older adapter started has hook records but no usage copied
yet, and its first record dates from the session start, so the first sync
after an upgrade copied the session's whole history into that turn. Records
now carry v 2, and the floor is the time of the first v 2 record.
Every syncing hook, PreToolUse included, read the whole sidecar to collect
the copied UUIDs and the anchor, so each tool call cost more as the session
grew. The anchor now comes from a backwards read that stops at the last
AssistantUsage record for the log, and the floor from the first v 2 line.

The anchor is that last record rather than the copied record with the
largest native offset. After Qwen rewrote its log shorter, the largest
offset pointed past the new content, so every later sync reread the whole
log. Without the copied set, a reread copies calls again; CalculateTokens
already counts each native_uuid once, on either side of the offset.
…ng the Stop wait

Until a sidecar an older adapter started has a v 2 record, the floor was
the running hook's time, so an upgrade between a turn's prompt and its
first syncing hook dropped the calls made before that hook. The floor is
now the older adapter's last prompt in that case.

Qwen rewrites its log by renaming a new file over it. If that happened
while Stop waited, the scan kept reading the new file at the old file's
position and could skip the final record. A scan now starts over when
the log is no longer the same file or has become shorter than its
position.
Stop waited only while the log ended with a user or tool_result record, so
it gave up when the log still ended with an earlier assistant record: the
turn's tool call, or the previous turn's answer, when even the records
queued before the final one had not reached the disk. It now waits until
the last record is an assistant record that calls no tool and is no older
than the sidecar's last UserPromptSubmit after the last copy.

Qwen also fires UserPromptSubmit, with an empty prompt, before the call
that follows a tool round. The floor for a sidecar an older adapter started
now skips those, so an upgrade after a tool round still counts the turn's
first call.
…ng prompts

The floor for a sidecar an older adapter started was the first v2 record's
time. When that record came in the middle of a turn, from a hook that copied
nothing yet (a call not on disk, or a hook that does not sync), the calls
made since the turn's prompt were left out for good. The floor is now the
prompt of the turn the older records leave open, whichever hook runs first.
A turn those records saw end stays out, so a first SessionEnd after the
upgrade no longer copies the finished turn's calls.

The backwards read skipped sidecar lines longer than a block, so a long
prompt gave the Stop wait no prompt time. Such a line is now checked from
its first 4 KiB, where event and ts are written.

A payload without a timestamp got one rounded down to the second, which
could put a prompt before the previous turn's answer in the same second.
It now keeps sub-second precision.
Copilot AI lite review requested due to automatic review settings November 7, 2026 00:41
@chatgpt-codex-connector

chatgpt-codex-connector Bot commented Nov 7, 2026 •

Copy link
Copy Markdown
Codex Review Summary: ✅ Completed

This comment shows the latest Codex review activity on this pull request.

Review Status Commit Review trigger
📝 Code Review ✅ Completed 2026-11-07T01:09:36.927668Z 3de67be New commits
ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review" or "@codex security review".

Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings.

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

@Beehtrix

Beehtrix commented Nov 7, 2026

Copy link
Copy Markdown
Author

@suhaanthayyil @ashtom tagging you since you wrote and reviewed the Qwen adapter's sidecar. This fixes #75 by copying the usage Qwen already records in its own chat log into the sidecar, so the sidecar stays the only transcript. The fork workflows are waiting for approval to run. Separately, #110 is about Qwen 0.26.7+ not running the adapter's hooks until the folder is trusted.

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: b2d7ef4e46

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".

…ast prompt

Qwen creates its chat log with the first record it writes, through the
same queue as the rest, so the log can still be missing when Stop fires.
Stop now waits for it as it waits for a record still on its way. With
chat recording off, hooks name no log and no sync runs, so this never
waits for a log that will not come.

The Stop wait took the answer to be no older than the last prompt after
the last copy. After a log rewrite moved the anchored line, a sync in
the middle of the turn copies the log again, so the previous turn's
answer can be the last copy, after the turn's prompt, and Stop took it
for the answer. The wait now compares with the sidecar's last prompt,
wherever it is, reading backwards past the anchor until it finds one.
Copilot AI lite review requested due to automatic review settings November 7, 2026 01:04

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

qwen: no token usage reported (sidecar transcript drops qwen's per-message usageMetadata)

2 participants