From 4ef487f73de2d69f3f4d4ae6a4a6aa0be68425c9 Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Fri, 6 Nov 2026 22:17:07 +0000 Subject: [PATCH 1/7] fix(qwen): report token usage from Qwen's own chat log 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. --- agents/entire-agent-qwen/AGENT.md | 28 ++ agents/entire-agent-qwen/README.md | 21 +- .../cmd/entire-agent-qwen/main.go | 2 + .../internal/protocol/protocol.go | 22 + .../internal/protocol/types.go | 8 + .../entire-agent-qwen/internal/qwen/agent.go | 1 + .../entire-agent-qwen/internal/qwen/hooks.go | 6 + .../entire-agent-qwen/internal/qwen/tokens.go | 388 ++++++++++++++++ .../internal/qwen/tokens_test.go | 415 ++++++++++++++++++ .../internal/qwen/transcript.go | 35 +- .../entire-agent-qwen/internal/qwen/types.go | 20 + 11 files changed, 938 insertions(+), 8 deletions(-) create mode 100644 agents/entire-agent-qwen/internal/qwen/tokens.go create mode 100644 agents/entire-agent-qwen/internal/qwen/tokens_test.go diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index 7005a043a..3f8536851 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -39,6 +39,7 @@ Session filename portability: Windows reserved device basenames (case-insensitiv | `extract-prompts` | `UserPromptSubmit` | Reads sidecar prompt records | | `extract-summary` | `Stop`/failure | Reads final assistant/error message | | `compact-transcript` | Sidecar JSONL | Emits base64 Entire Transcript Format JSONL | +| `calculate-tokens` | Native chat-log usage | Sums the `AssistantUsage` sidecar records after `--offset`; see Token Usage | ## Sidecar Record Shape @@ -63,12 +64,39 @@ The projection is derived data — `readSidecarRecords` ignores `type` and | `PreToolUse` | `assistant` | `tool_use` (`type`/`id`/`name`/`input`, the only fields `stripAssistantContent` keeps) | | `PostToolUse` / `PostToolUseFailure` | `user` | `tool_result` with snake_case `tool_use_id`, so cli inlines the output into the preceding `tool_use` | | `Stop` / `StopFailure` | `assistant` | text block with the final message or error details | +| `AssistantUsage` (adapter-written, see Token Usage) | not projected | dropped from the compact transcript | | everything else | not projected | dropped from the compact transcript | `message` is stored as raw JSON so a record round-trips whichever shape it carries. Typed as a string, a projected line would fail to unmarshal and take the whole sidecar read with it. +## Token Usage + +Read from Qwen Code 0.26.9 source (`QwenLM/qwen-code` 11c83aa) and checked +with a live run of the 0.26.9 npm package against a local OpenAI-compatible +mock that streams usage: `ChatRecordingService.recordAssistantTurn` stores the +provider's usage, normalized to Gemini field names (`promptTokenCount`, +`candidatesTokenCount`, `cachedContentTokenCount`, `thoughtsTokenCount`, +`totalTokenCount`), as `usageMetadata` on each assistant record of the native +chat log. The OpenAI-compatible pipeline requests it with +`stream_options.include_usage`; the Anthropic and Responses generators convert +their usage to the same shape. + +| Step | Behavior | +|---|---| +| Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | +| Resume | The next copy starts after the furthest copied line while that line still holds the same record, and rereads the log otherwise (Qwen can rewrite it, e.g. when prompts are deleted); `native_uuid` keeps a call from being copied twice | +| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first record, such as the history of a resumed session whose sidecar was removed from the temp directory | +| Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | + +Qwen fires `Stop` without waiting for its write queue, so the last API call of +a turn can land after the `Stop` hook (seen once in six live runs, at +`PreToolUse`). It is copied at the next hook and counted with that turn or +checkpoint. Calls outside the session's chat log (subagents, the auto-memory +extractor and other background helpers) are not counted, and Qwen keeps no +separate cache-write count. + ## Lifecycle Mapping | Qwen Hook | Entire Hook Verb | Entire Event | diff --git a/agents/entire-agent-qwen/README.md b/agents/entire-agent-qwen/README.md index 38c5b5059..e01a63813 100644 --- a/agents/entire-agent-qwen/README.md +++ b/agents/entire-agent-qwen/README.md @@ -10,7 +10,26 @@ External agent binary that teaches the Entire CLI how to work with Qwen Code. | transcript_analyzer | Yes, via Entire sidecar JSONL | | compact_transcript | Yes, emits Entire compact transcript JSONL | | transcript_preparer | No | -| token_calculator | No | +| token_calculator | Yes, from the per-call usage Qwen Code writes to its own chat log, copied into the sidecar at hooks | + +## Token Usage + +Qwen Code's hook payloads carry no token counts, but its chat log +(`~/.qwen/projects//chats/.jsonl`, the hooks' +`transcript_path`) stores the provider's `usageMetadata` on every assistant +record. At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and +`SessionEnd` the adapter copies the usage of each new assistant record into the +sidecar as an `AssistantUsage` line, and `calculate-tokens` sums those lines +after `--offset`. The sidecar stays the only transcript, so a stored checkpoint +still reports its tokens on a machine without the chat log. + +Qwen writes its log through a queue and fires `Stop` without waiting for it, +so a turn's last API call can reach the log after the `Stop` hook. It is then +copied at the next hook and counted with the next turn or checkpoint; totals +are unaffected. Calls Qwen does not record in the session's chat log, such as +subagents and background helpers like its auto-memory extractor, are not +counted. Cache writes are not reported separately: for Anthropic models Qwen +folds them into the prompt count, so they appear as input tokens. ## Installation diff --git a/agents/entire-agent-qwen/cmd/entire-agent-qwen/main.go b/agents/entire-agent-qwen/cmd/entire-agent-qwen/main.go index b9a7da99e..d00b88876 100644 --- a/agents/entire-agent-qwen/cmd/entire-agent-qwen/main.go +++ b/agents/entire-agent-qwen/cmd/entire-agent-qwen/main.go @@ -60,6 +60,8 @@ func main() { err = protocol.HandleExtractPrompts(os.Args[2:], os.Stdout, agent) case "extract-summary": err = protocol.HandleExtractSummary(os.Args[2:], os.Stdout, agent) + case "calculate-tokens": + err = protocol.HandleCalculateTokens(os.Args[2:], os.Stdin, os.Stdout, agent) default: fatalf("unknown subcommand: %s", os.Args[1]) } diff --git a/agents/entire-agent-qwen/internal/protocol/protocol.go b/agents/entire-agent-qwen/internal/protocol/protocol.go index 948e04688..9265c7202 100644 --- a/agents/entire-agent-qwen/internal/protocol/protocol.go +++ b/agents/entire-agent-qwen/internal/protocol/protocol.go @@ -60,6 +60,10 @@ type transcriptAnalyzer interface { ExtractSummary(sessionRef string) (string, bool, error) } +type tokenCalculator interface { + CalculateTokens(data []byte, offset int) (TokenUsageResponse, error) +} + func WriteJSON(w io.Writer, v any) error { enc := json.NewEncoder(w) enc.SetEscapeHTML(false) @@ -321,6 +325,24 @@ func HandleExtractSummary(args []string, stdout io.Writer, analyzer transcriptAn return WriteJSON(stdout, ExtractSummaryResponse{Summary: summary, HasSummary: hasSummary}) } +func HandleCalculateTokens(args []string, stdin io.Reader, stdout io.Writer, calculator tokenCalculator) error { + fs := flag.NewFlagSet("calculate-tokens", flag.ContinueOnError) + fs.SetOutput(io.Discard) + offset := fs.Int("offset", 0, "offset") + if err := fs.Parse(args); err != nil { + return err + } + data, err := io.ReadAll(stdin) + if err != nil { + return err + } + usage, err := calculator.CalculateTokens(data, *offset) + if err != nil { + return err + } + return WriteJSON(stdout, usage) +} + func DefaultSessionDir(repoPath string) string { return filepath.Join(repoPath, ".entire", "tmp") } diff --git a/agents/entire-agent-qwen/internal/protocol/types.go b/agents/entire-agent-qwen/internal/protocol/types.go index f3e5aff2e..65554a882 100644 --- a/agents/entire-agent-qwen/internal/protocol/types.go +++ b/agents/entire-agent-qwen/internal/protocol/types.go @@ -77,6 +77,14 @@ type ExtractSummaryResponse struct { HasSummary bool `json:"has_summary"` } +type TokenUsageResponse struct { + InputTokens int `json:"input_tokens"` + CacheCreationTokens int `json:"cache_creation_tokens"` + CacheReadTokens int `json:"cache_read_tokens"` + OutputTokens int `json:"output_tokens"` + APICallCount int `json:"api_call_count"` +} + type CompactTranscriptResponse struct { Transcript string `json:"transcript"` Assets []CompactTranscriptAssetJSON `json:"assets,omitempty"` diff --git a/agents/entire-agent-qwen/internal/qwen/agent.go b/agents/entire-agent-qwen/internal/qwen/agent.go index a7623b37b..cf97098c3 100644 --- a/agents/entire-agent-qwen/internal/qwen/agent.go +++ b/agents/entire-agent-qwen/internal/qwen/agent.go @@ -47,6 +47,7 @@ func (a *Agent) Info() protocol.InfoResponse { Capabilities: protocol.DeclaredCapabilities{ Hooks: true, TranscriptAnalyzer: true, + TokenCalculator: true, CompactTranscript: true, UsesTerminal: true, }, diff --git a/agents/entire-agent-qwen/internal/qwen/hooks.go b/agents/entire-agent-qwen/internal/qwen/hooks.go index 8bf5607ae..a0399e9b1 100644 --- a/agents/entire-agent-qwen/internal/qwen/hooks.go +++ b/agents/entire-agent-qwen/internal/qwen/hooks.go @@ -21,6 +21,12 @@ func (a *Agent) ParseHook(hookName string, input []byte) (*protocol.EventJSON, e raw.HookEventName = qwenEventName(hookName, raw.HookEventName) normalizeRawHook(&raw, hookName) + if syncsUsage(hookName) { + // Copy token usage from Qwen's own chat log first, so it precedes + // this hook's record; see tokens.go. Best effort: the hook itself + // must not fail because the native log could not be read. + _ = a.syncNativeUsage(raw) + } if err := a.appendSidecar(raw); err != nil { return nil, err } diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go new file mode 100644 index 000000000..7de4c4a48 --- /dev/null +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -0,0 +1,388 @@ +package qwen + +import ( + "bufio" + "bytes" + "encoding/json" + "errors" + "io" + "os" + "strings" + "time" + + "github.com/entireio/external-agents/agents/entire-agent-qwen/internal/protocol" +) + +// Token usage. +// +// Qwen's hook payloads carry no token counts, but its own chat log does: each +// assistant record in ~/.qwen/projects//chats/.jsonl, the +// file the hooks name as transcript_path, carries the provider's usageMetadata +// for that API call (ChatRecordingService.recordAssistantTurn). +// +// The sidecar stays the session transcript. It is what Entire stores in a +// checkpoint and hands back to calculate-tokens later, possibly on a machine +// where the native log does not exist, so calculate-tokens cannot read the +// native log itself. Instead, at the hooks usageSyncHooks lists, the adapter +// copies the usage of each assistant record the native log gained since the +// last copy into the sidecar as an AssistantUsage record, and calculate-tokens +// sums the AssistantUsage records after --offset. They carry no "type", so +// Entire's compact transcript drops them. +// +// Qwen queues its log writes and fires Stop without waiting for the queue, so +// a turn's last API call can reach the log after the Stop hook has read it. +// That call is copied at the next sync and counted with the turn and the +// checkpoint in which it was copied: totals stay right, but one turn's share +// can move to the next. + +const eventAssistantUsage = "AssistantUsage" + +// nativeTypeAssistant is the type of the chat-log records that carry usage. +const nativeTypeAssistant = "assistant" + +// maxNativeLine bounds one line read while syncing usage. A native record can +// embed a whole tool result or written file, and a sidecar record a whole tool +// input or response, so a line can be very long; a longer one is skipped +// rather than failing the sync. +const maxNativeLine = 64 * 1024 * 1024 + +// usageMetadataKey prefilters native lines: only a line containing it can +// carry usage, so the rest are never decoded. +var usageMetadataKey = []byte(`"usageMetadata"`) + +// nativeUUIDKey prefilters sidecar lines the same way for AssistantUsage +// records. +var nativeUUIDKey = []byte(`"native_uuid"`) + +// syncsUsage reports whether a hook copies new native usage into the sidecar: +// PreToolUse, so a commit a tool makes mid-turn sees the API calls before it, +// and every hook that ends a turn, a subagent or the session. +func syncsUsage(hookName string) bool { + switch hookName { + case HookNamePreToolUse, HookNameStop, HookNameStopFailure, HookNameSubagentStop, HookNameSessionEnd: + return true + default: + return false + } +} + +// nativeChatRecord is the part of a Qwen chat-log record a usage sync reads. +type nativeChatRecord struct { + UUID string `json:"uuid"` + Type string `json:"type"` + Timestamp string `json:"timestamp"` + Model string `json:"model"` + UsageMetadata *qwenUsageMetadata `json:"usageMetadata"` + // IsSidechain marks a subagent's record. Qwen writes those to their own + // files under subagents/, so one in the session log is not this session's. + IsSidechain bool `json:"isSidechain"` + // ForkedFrom marks a record /branch copied from the parent session: its + // API call was made, and counted, there. + ForkedFrom *struct{} `json:"forkedFrom"` +} + +// usageSyncState is what the sidecar already records about native usage. +type usageSyncState struct { + // copied holds the native UUID of every AssistantUsage record, so a call + // is copied once even when the native log is rewritten or two hooks sync + // at the same time. + copied map[string]struct{} + // anchor is the AssistantUsage record copied from the furthest line of + // the native log in use: the sync resumes after that line when it still + // holds the same record. + anchor *sidecarRecord + // floor is the time of the sidecar's first record. A native record older + // than it predates the part of the session Entire saw, such as the + // history of a resumed session whose sidecar was cleaned out of the temp + // directory, and is not copied. + floor time.Time +} + +// syncNativeUsage copies into the sidecar the usage of assistant records the +// native log gained since the last sync. It is best effort for the hook that +// calls it: an unreadable native log costs the usage of this sync, never the +// hook. +func (a *Agent) syncNativeUsage(raw qwenHookInputRaw) error { + nativePath := strings.TrimSpace(raw.TranscriptPath) + if nativePath == "" { + return nil + } + sidecarPath := a.sidecarPath(raw.SessionID) + state, err := readUsageSyncState(sidecarPath, nativePath, raw.Timestamp) + if err != nil { + return err + } + records, err := scanNativeUsage(nativePath, raw.SessionID, state) + if err != nil || len(records) == 0 { + return err + } + return appendSidecarRecords(sidecarPath, records) +} + +// readUsageSyncState reads the copied UUIDs, the anchor for nativePath and +// the floor from the sidecar. Only lines that can be AssistantUsage records +// are decoded, so the cost of a hook stays small as the sidecar grows. An +// empty or missing sidecar takes its floor from the hook now running. +func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyncState, error) { + state := usageSyncState{copied: map[string]struct{}{}} + f, err := os.Open(sidecarPath) + if errors.Is(err, os.ErrNotExist) { + state.floor = parseTimestamp(hookTimestamp) + return state, nil + } + if err != nil { + return state, err + } + defer func() { _ = f.Close() }() + + reader := bufio.NewReaderSize(f, 64*1024) + first := true + for { + line, _, complete, err := readLine(reader, maxNativeLine) + if err != nil { + return state, err + } + if !complete { + break + } + if first && len(bytes.TrimSpace(line)) > 0 { + first = false + var head struct { + TS string `json:"ts"` + } + if json.Unmarshal(line, &head) == nil { + state.floor = parseTimestamp(head.TS) + } + } + if !bytes.Contains(line, nativeUUIDKey) { + continue + } + var record sidecarRecord + if json.Unmarshal(line, &record) != nil || !isUsageRecord(record) || record.NativeUUID == "" { + continue + } + state.copied[record.NativeUUID] = struct{}{} + if record.NativeTranscriptPath == nativePath && (state.anchor == nil || record.NativeOffset > state.anchor.NativeOffset) { + anchor := record + state.anchor = &anchor + } + } + if first { + state.floor = parseTimestamp(hookTimestamp) + } + return state, nil +} + +// scanNativeUsage returns an AssistantUsage record for each assistant record +// in the native log that carries usage and has not been copied. It resumes +// after the anchor when that line still holds the anchored record and reads +// the whole log otherwise (Qwen can rewrite it, e.g. when prompts are +// deleted), relying on the copied UUIDs to skip what is already recorded. A +// trailing line without its newline is still being written and is left for +// the next sync. +func scanNativeUsage(nativePath, sessionID string, state usageSyncState) ([]sidecarRecord, error) { + f, err := os.Open(nativePath) + if errors.Is(err, os.ErrNotExist) { + return nil, nil + } + if err != nil { + return nil, err + } + defer func() { _ = f.Close() }() + info, err := f.Stat() + if err != nil { + return nil, err + } + if !info.Mode().IsRegular() { + return nil, nil + } + + offset := resumeOffset(f, state.anchor) + if _, err := f.Seek(offset, io.SeekStart); err != nil { + return nil, err + } + reader := bufio.NewReaderSize(f, 64*1024) + var records []sidecarRecord + for { + line, n, complete, err := readLine(reader, maxNativeLine) + if err != nil { + return nil, err + } + if !complete { + return records, nil + } + lineStart := offset + offset += n + native, ok := nativeUsage(line, state) + if !ok { + continue + } + state.copied[native.UUID] = struct{}{} + records = append(records, sidecarRecord{ + V: 1, + Agent: AgentName, + Event: eventAssistantUsage, + SessionID: sessionID, + TS: native.Timestamp, + NativeTranscriptPath: nativePath, + Model: native.Model, + NativeUUID: native.UUID, + NativeOffset: lineStart, + Usage: native.UsageMetadata, + }) + } +} + +// nativeUsage decodes a native line that is an assistant record of this +// session with usage not yet copied. +func nativeUsage(line []byte, state usageSyncState) (nativeChatRecord, bool) { + if !bytes.Contains(line, usageMetadataKey) { + return nativeChatRecord{}, false + } + var record nativeChatRecord + if json.Unmarshal(line, &record) != nil { + return nativeChatRecord{}, false + } + if record.Type != nativeTypeAssistant || record.UsageMetadata == nil || record.UUID == "" || + record.IsSidechain || record.ForkedFrom != nil { + return nativeChatRecord{}, false + } + if _, copied := state.copied[record.UUID]; copied { + return nativeChatRecord{}, false + } + if at := parseTimestamp(record.Timestamp); !state.floor.IsZero() && !at.IsZero() && at.Before(state.floor) { + return nativeChatRecord{}, false + } + return record, true +} + +// resumeOffset returns the offset just past the anchor's line when that line +// still holds the anchored record, and 0 (read the whole log) otherwise. +func resumeOffset(f *os.File, anchor *sidecarRecord) int64 { + if anchor == nil || anchor.NativeUUID == "" || anchor.NativeOffset < 0 { + return 0 + } + if _, err := f.Seek(anchor.NativeOffset, io.SeekStart); err != nil { + return 0 + } + line, n, complete, err := readLine(bufio.NewReader(f), maxNativeLine) + if err != nil || !complete { + return 0 + } + var head struct { + UUID string `json:"uuid"` + } + if json.Unmarshal(line, &head) != nil || head.UUID != anchor.NativeUUID { + return 0 + } + return anchor.NativeOffset + n +} + +// readLine reads one newline-terminated line and reports how many bytes it +// consumed. complete is false at end of input, including after a trailing +// line with no newline, which is not consumed as a line. A line longer than +// limit is consumed and returned as nil. +func readLine(r *bufio.Reader, limit int) ([]byte, int64, bool, error) { + var ( + line []byte + n int64 + oversized bool + ) + for { + chunk, err := r.ReadSlice('\n') + n += int64(len(chunk)) + if !oversized { + if len(line)+len(chunk) > limit { + oversized, line = true, nil + } else { + line = append(line, chunk...) + } + } + switch { + case err == nil: + return line, n, true, nil + case errors.Is(err, bufio.ErrBufferFull): + continue + case errors.Is(err, io.EOF): + return nil, n, false, nil + default: + return nil, n, false, err + } + } +} + +func parseTimestamp(value string) time.Time { + at, err := time.Parse(time.RFC3339Nano, strings.TrimSpace(value)) + if err != nil { + return time.Time{} + } + return at +} + +func isUsageRecord(record sidecarRecord) bool { + return record.Event == eventAssistantUsage && record.Usage != nil +} + +// CalculateTokens sums the AssistantUsage records at or after offset, a +// sidecar line index like every other offset this adapter reports. A native +// call recorded twice, by two hooks syncing at once or once before offset and +// again after it, is counted once. +func (a *Agent) CalculateTokens(data []byte, offset int) (protocol.TokenUsageResponse, error) { + records, err := decodeSidecarRecords(bytes.NewReader(data)) + if err != nil { + return protocol.TokenUsageResponse{}, err + } + offset = min(max(offset, 0), len(records)) + counted := map[string]struct{}{} + for _, record := range records[:offset] { + if isUsageRecord(record) && record.NativeUUID != "" { + counted[record.NativeUUID] = struct{}{} + } + } + var usage protocol.TokenUsageResponse + for _, record := range records[offset:] { + if !isUsageRecord(record) { + continue + } + if record.NativeUUID != "" { + if _, dup := counted[record.NativeUUID]; dup { + continue + } + counted[record.NativeUUID] = struct{}{} + } + record.Usage.addTo(&usage) + } + return usage, nil +} + +// addTo adds one API call to total. Qwen's promptTokenCount is the whole +// prompt with cachedContentTokenCount included, as with Gemini and OpenAI, +// while Entire's InputTokens is fresh input only, so the cached share moves to +// CacheReadTokens. Qwen records no cache writes separately: for Anthropic +// they are folded into promptTokenCount (buildAnthropicUsageMetadata) and so +// count as input here. +func (u *qwenUsageMetadata) addTo(total *protocol.TokenUsageResponse) { + prompt := max(u.PromptTokenCount, 0) + cached := min(max(u.CachedContentTokenCount, 0), prompt) + total.InputTokens += prompt - cached + total.CacheReadTokens += cached + total.OutputTokens += u.outputTokens() + total.APICallCount++ +} + +// outputTokens counts reasoning once. OpenAI-compatible and Anthropic +// providers include it in candidatesTokenCount, while Gemini reports it only +// in thoughtsTokenCount. As in Qwen's own outputTokenCount +// (packages/core/src/telemetry/gen-ai-usage.ts), a total that lies between +// the two readings decides; without one, the OpenAI-style reading Qwen's +// default providers use applies. +func (u *qwenUsageMetadata) outputTokens() int { + output := max(u.CandidatesTokenCount, 0) + thoughts := max(u.ThoughtsTokenCount, 0) + if u.TotalTokenCount > 0 { + if derived := u.TotalTokenCount - max(u.PromptTokenCount, 0); derived >= output && derived <= output+thoughts { + return derived + } + } + return output +} diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go new file mode 100644 index 000000000..ec36e31b3 --- /dev/null +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -0,0 +1,415 @@ +package qwen + +import ( + "bufio" + "bytes" + "encoding/json" + "fmt" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/entireio/external-agents/agents/entire-agent-qwen/internal/protocol" +) + +// qwenSession drives hooks for one session against a native chat log the test +// writes, the way Qwen Code writes both. +type qwenSession struct { + t *testing.T + agent *Agent + id string + nativePath string +} + +func newQwenSession(t *testing.T) *qwenSession { + t.Helper() + t.Setenv("ENTIRE_REPO_ROOT", t.TempDir()) + t.Setenv("TMPDIR", t.TempDir()) + id := "6f1c2d3e-0000-4000-8000-000000000075" + native := filepath.Join(t.TempDir(), ".qwen", "projects", "-repo", "chats", id+".jsonl") + if err := os.MkdirAll(filepath.Dir(native), 0o700); err != nil { + t.Fatal(err) + } + return &qwenSession{t: t, agent: New(), id: id, nativePath: native} +} + +// hook runs one hook with the fields every Qwen hook payload carries. +func (s *qwenSession) hook(name, timestamp string, extra map[string]any) { + s.t.Helper() + payload := map[string]any{ + "session_id": s.id, + "transcript_path": s.nativePath, + "cwd": "/repo", + "timestamp": timestamp, + } + for key, value := range extra { + payload[key] = value + } + data, err := json.Marshal(payload) + if err != nil { + s.t.Fatal(err) + } + if _, err := s.agent.ParseHook(name, data); err != nil { + s.t.Fatalf("ParseHook(%s): %v", name, err) + } +} + +// writeNative appends raw text to the native log; a line without its newline +// is a record Qwen is still writing. +func (s *qwenSession) writeNative(text string) { + s.t.Helper() + f, err := os.OpenFile(s.nativePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) + if err != nil { + s.t.Fatal(err) + } + defer func() { _ = f.Close() }() + if _, err := f.WriteString(text); err != nil { + s.t.Fatal(err) + } +} + +func (s *qwenSession) sidecar() []byte { + s.t.Helper() + data, err := os.ReadFile(s.agent.sidecarPath(s.id)) + if err != nil { + s.t.Fatal(err) + } + return data +} + +// position is what Entire stores as a turn's start: get-transcript-position. +func (s *qwenSession) position() int { + s.t.Helper() + pos, err := s.agent.GetTranscriptPosition(s.agent.sidecarPath(s.id)) + if err != nil { + s.t.Fatal(err) + } + return pos +} + +func (s *qwenSession) tokens(offset int) protocol.TokenUsageResponse { + s.t.Helper() + usage, err := s.agent.CalculateTokens(s.sidecar(), offset) + if err != nil { + s.t.Fatal(err) + } + return usage +} + +// nativeLine renders a Qwen chat-log record as ChatRecordingService writes it. +func nativeLine(uuid, recordType, timestamp, usage string) string { + record := fmt.Sprintf(`{"uuid":%q,"parentUuid":null,"sessionId":"6f1c2d3e-0000-4000-8000-000000000075",`+ + `"timestamp":%q,"type":%q,"cwd":"/repo","version":"0.26.9","gitBranch":"main"`, uuid, timestamp, recordType) + switch recordType { + case "assistant": + record += `,"provenance":"assistant_output","model":"qwen3-coder-plus","message":{"role":"model","parts":[{"text":"done"}]}` + if usage != "" { + record += `,"usageMetadata":` + usage + } + record += `,"contextWindowSize":1000000` + case "user": + record += `,"provenance":"real_user","message":{"role":"user","parts":[{"text":"go"}]}` + default: + record += `,"provenance":"tool_result","message":{"role":"user","parts":[{"functionResponse":{"name":"write_file","response":{"output":"ok"}}}]}` + } + return record + "}\n" +} + +// openAIUsage is what Qwen records from an OpenAI-compatible provider: +// prompt_tokens includes the cached share and completion_tokens the reasoning. +func openAIUsage(prompt, completion, cached, reasoning int) string { + return fmt.Sprintf(`{"promptTokenCount":%d,"candidatesTokenCount":%d,"thoughtsTokenCount":%d,"totalTokenCount":%d,"cachedContentTokenCount":%d}`, + prompt, completion, reasoning, prompt+completion, cached) +} + +func wantUsage(t *testing.T, got protocol.TokenUsageResponse, want protocol.TokenUsageResponse) { + t.Helper() + if got != want { + t.Fatalf("usage = %+v, want %+v", got, want) + } +} + +// The regression in #75: a Qwen session reported no token usage at all. Each +// assistant record's usage is copied at the hooks and summed per turn from the +// turn's start position. +func TestTurnTokenUsageComesFromNativeChatLog(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00.000Z", map[string]any{"source": "startup"}) + + turnStart := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01.000Z", map[string]any{"prompt": "create hello.txt"}) + s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.100Z", "")) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:03.000Z", openAIUsage(1200, 80, 1000, 20))) + s.hook(HookNamePreToolUse, "2026-11-06T10:00:03.100Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1", "tool_input": map[string]any{"file_path": "hello.txt"}}) + s.hook(HookNamePostToolUse, "2026-11-06T10:00:03.200Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1", "tool_input": map[string]any{"file_path": "hello.txt"}, "tool_response": "ok"}) + s.writeNative(nativeLine("t-1", "tool_result", "2026-11-06T10:00:03.300Z", "")) + s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:05.000Z", openAIUsage(1400, 30, 1200, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:05.100Z", map[string]any{"last_assistant_message": "Created hello.txt"}) + + wantUsage(t, s.tokens(turnStart), protocol.TokenUsageResponse{ + InputTokens: (1200 - 1000) + (1400 - 1200), + CacheReadTokens: 1000 + 1200, + OutputTokens: 80 + 30, + APICallCount: 2, + }) + + // The copies are sidecar lines Entire's compactor drops (no top-level + // type), so the compact transcript and the summary are unchanged. + var copies int + for _, line := range decodeLines(t, s.sidecar()) { + var event string + _ = json.Unmarshal(line["event"], &event) + if event != eventAssistantUsage { + continue + } + copies++ + if kind := compactKind(line); kind != "" { + t.Fatalf("AssistantUsage line has compact kind %q; Entire would render it", kind) + } + } + if copies != 2 { + t.Fatalf("sidecar holds %d AssistantUsage records, want 2", copies) + } + summary, ok, err := s.agent.ExtractSummary(s.agent.sidecarPath(s.id)) + if err != nil || !ok || summary != "Created hello.txt" { + t.Fatalf("summary = %q, %v, %v", summary, ok, err) + } + if _, err := compactTranscriptBytes(s.sidecar()); err != nil { + t.Fatalf("compact transcript: %v", err) + } +} + +// Qwen fires Stop without waiting for its write queue, so the turn's last API +// call can land after the Stop hook. It is copied at the next sync and counted +// with the next turn; the session total is unaffected. +func TestUsageWrittenAfterStopIsCountedWithNextTurn(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + + turn1 := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "one"}) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:03Z", map[string]any{"last_assistant_message": "one done"}) + // The final record of turn 1 reaches the log only now, and the hook it + // missed is not run again. + s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:03.5Z", openAIUsage(200, 20, 0, 0))) + wantUsage(t, s.tokens(turn1), protocol.TokenUsageResponse{InputTokens: 100, OutputTokens: 10, APICallCount: 1}) + + turn2 := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:01:00Z", map[string]any{"prompt": "two"}) + s.writeNative(nativeLine("a-3", "assistant", "2026-11-06T10:01:02Z", openAIUsage(300, 30, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:01:03Z", map[string]any{"last_assistant_message": "two done"}) + + wantUsage(t, s.tokens(turn2), protocol.TokenUsageResponse{InputTokens: 500, OutputTokens: 50, APICallCount: 2}) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 600, OutputTokens: 60, APICallCount: 3}) +} + +// A record Qwen is still writing has no newline yet. It must not be copied +// half-read or skipped: the next sync copies it whole. +func TestPartialNativeLineIsCopiedOnceComplete(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + line := nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + s.writeNative(line[:len(line)/2]) + s.hook(HookNameStop, "2026-11-06T10:00:03Z", nil) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{}) + + s.writeNative(line[len(line)/2:]) + s.hook(HookNameSessionEnd, "2026-11-06T10:00:04Z", map[string]any{"reason": "exit"}) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 100, OutputTokens: 10, APICallCount: 1}) +} + +// Qwen can rewrite its log in place, e.g. when prompts are deleted, so the +// remembered line may no longer hold the remembered record. The sync then +// rereads the log and copies only what it has not copied before. +func TestRewrittenNativeLogIsNotCountedTwice(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01Z", "")) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:03Z", openAIUsage(200, 20, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:04Z", nil) + + // Rewrite without the first prompt group, then append a new call. + rewritten := nativeLine("a-2", "assistant", "2026-11-06T10:00:03Z", openAIUsage(200, 20, 0, 0)) + + nativeLine("a-3", "assistant", "2026-11-06T10:00:05Z", openAIUsage(300, 30, 0, 0)) + if err := os.WriteFile(s.nativePath, []byte(rewritten), 0o600); err != nil { + t.Fatal(err) + } + s.hook(HookNameStop, "2026-11-06T10:00:06Z", nil) + + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 600, OutputTokens: 60, APICallCount: 3}) +} + +// A sync resumes after the last copied line instead of rereading the log, as +// long as that line still holds the record copied from it. +func TestResumeOffsetChecksTheAnchoredRecord(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + first := nativeLine("u-1", "user", "2026-11-06T10:00:01Z", "") + anchored := nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + s.writeNative(first + anchored) + s.hook(HookNameStop, "2026-11-06T10:00:03Z", nil) + + state, err := readUsageSyncState(s.agent.sidecarPath(s.id), s.nativePath, "") + if err != nil { + t.Fatal(err) + } + if state.anchor == nil || state.anchor.NativeUUID != "a-1" || state.anchor.NativeOffset != int64(len(first)) { + t.Fatalf("anchor = %+v, want a-1 at offset %d", state.anchor, len(first)) + } + f, err := os.Open(s.nativePath) + if err != nil { + t.Fatal(err) + } + defer func() { _ = f.Close() }() + if got, want := resumeOffset(f, state.anchor), int64(len(first)+len(anchored)); got != want { + t.Fatalf("resumeOffset = %d, want %d", got, want) + } + moved := *state.anchor + moved.NativeUUID = "a-other" + if got := resumeOffset(f, &moved); got != 0 { + t.Fatalf("resumeOffset for a line holding another record = %d, want 0", got) + } +} + +// A resumed session whose sidecar was cleaned out of the temp directory must +// not count the whole earlier history into its first turn. +func TestNativeHistoryBeforeTheSidecarIsNotCopied(t *testing.T) { + s := newQwenSession(t) + s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:00Z", openAIUsage(5000, 500, 0, 0))) + s.writeNative(nativeLine("old-2", "assistant", "2026-11-01T09:05:00Z", openAIUsage(6000, 600, 0, 0))) + + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", map[string]any{"source": "resume"}) + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "continue"}) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:03Z", nil) + + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 100, OutputTokens: 10, APICallCount: 1}) +} + +// Records /branch copied from a parent session, and subagent records, were +// counted where their API calls were made. +func TestForkedAndSidechainRecordsAreNotCopied(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + forked := strings.TrimSuffix(nativeLine("f-1", "assistant", "2026-11-06T10:00:01Z", openAIUsage(900, 90, 0, 0)), "}\n") + + `,"forkedFrom":{"sessionId":"parent","messageUuid":"f-1"}}` + "\n" + sidechain := strings.TrimSuffix(nativeLine("s-1", "assistant", "2026-11-06T10:00:01Z", openAIUsage(800, 80, 0, 0)), "}\n") + + `,"isSidechain":true,"agentId":"explore-7f3c"}` + "\n" + s.writeNative(forked + sidechain + nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:03Z", nil) + + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 100, OutputTokens: 10, APICallCount: 1}) +} + +// Two hooks syncing at once can both copy the same call. It is counted once, +// also when the first copy lies before the offset and the second after it. +func TestDuplicateCopiesAreCountedOnce(t *testing.T) { + record := func(uuid string, prompt int) string { + data, err := json.Marshal(sidecarRecord{ + V: 1, Agent: AgentName, Event: eventAssistantUsage, SessionID: "s", NativeUUID: uuid, + Usage: &qwenUsageMetadata{PromptTokenCount: prompt, CandidatesTokenCount: 1, TotalTokenCount: prompt + 1}, + }) + if err != nil { + t.Fatal(err) + } + return string(data) + "\n" + } + sidecar := []byte(record("a-1", 100) + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","prompt":"next"}` + "\n" + + record("a-1", 100) + record("a-2", 200) + record("a-2", 200)) + + usage, err := New().CalculateTokens(sidecar, 0) + if err != nil { + t.Fatal(err) + } + wantUsage(t, usage, protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 2, APICallCount: 2}) + usage, err = New().CalculateTokens(sidecar, 1) + if err != nil { + t.Fatal(err) + } + wantUsage(t, usage, protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 1, APICallCount: 1}) +} + +// Qwen normalizes every provider to Gemini's usageMetadata names, but the +// providers disagree on whether reasoning is inside the output count. +func TestUsageMetadataMapping(t *testing.T) { + t.Parallel() + for _, tc := range []struct { + name string + usage qwenUsageMetadata + want protocol.TokenUsageResponse + }{ + { + name: "openai compatible: completion includes reasoning", + usage: qwenUsageMetadata{PromptTokenCount: 1000, CandidatesTokenCount: 300, ThoughtsTokenCount: 200, CachedContentTokenCount: 600, TotalTokenCount: 1300}, + want: protocol.TokenUsageResponse{InputTokens: 400, CacheReadTokens: 600, OutputTokens: 300, APICallCount: 1}, + }, + { + name: "gemini: thoughts reported apart", + usage: qwenUsageMetadata{PromptTokenCount: 1000, CandidatesTokenCount: 100, ThoughtsTokenCount: 200, CachedContentTokenCount: 0, TotalTokenCount: 1300}, + want: protocol.TokenUsageResponse{InputTokens: 1000, OutputTokens: 300, APICallCount: 1}, + }, + { + name: "no total: openai reading", + usage: qwenUsageMetadata{PromptTokenCount: 50, CandidatesTokenCount: 5, ThoughtsTokenCount: 3}, + want: protocol.TokenUsageResponse{InputTokens: 50, OutputTokens: 5, APICallCount: 1}, + }, + { + name: "cache larger than prompt is clamped", + usage: qwenUsageMetadata{PromptTokenCount: 10, CandidatesTokenCount: 1, CachedContentTokenCount: 50, TotalTokenCount: 11}, + want: protocol.TokenUsageResponse{CacheReadTokens: 10, OutputTokens: 1, APICallCount: 1}, + }, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + var got protocol.TokenUsageResponse + tc.usage.addTo(&got) + wantUsage(t, got, tc.want) + }) + } +} + +// The protocol compliance suite sends "{}" with --offset 0, and a sidecar +// without usage (written before this change) must report zeros, not fail. +func TestCalculateTokensWithoutUsage(t *testing.T) { + t.Parallel() + for _, input := range [][]byte{nil, []byte(`{}`), []byte("not json\n\n"), []byte(`{"v":1,"agent":"qwen","event":"Stop","last_assistant_message":"done"}` + "\n")} { + usage, err := New().CalculateTokens(input, 0) + if err != nil { + t.Fatalf("CalculateTokens(%q): %v", input, err) + } + wantUsage(t, usage, protocol.TokenUsageResponse{}) + } + if !New().Info().Capabilities.TokenCalculator { + t.Fatal("token_calculator is not declared, so Entire never calls calculate-tokens") + } +} + +// A line longer than the read limit is skipped without losing the lines +// around it or the byte offsets after it. +func TestReadLineSkipsOversizedLines(t *testing.T) { + t.Parallel() + input := "short\n" + strings.Repeat("x", 100) + "\n" + "tail\n" + "partial" + reader := bufio.NewReaderSize(strings.NewReader(input), 16) + var lines []string + var consumed int64 + for { + line, n, complete, err := readLine(reader, 32) + if err != nil { + t.Fatal(err) + } + if !complete { + break + } + consumed += n + lines = append(lines, string(bytes.TrimSuffix(line, []byte("\n")))) + } + if got := strings.Join(lines, "|"); got != "short||tail" { + t.Fatalf("lines = %q", got) + } + if want := int64(len(input) - len("partial")); consumed != want { + t.Fatalf("consumed %d bytes, want %d", consumed, want) + } +} diff --git a/agents/entire-agent-qwen/internal/qwen/transcript.go b/agents/entire-agent-qwen/internal/qwen/transcript.go index ba2031e81..858ba45f2 100644 --- a/agents/entire-agent-qwen/internal/qwen/transcript.go +++ b/agents/entire-agent-qwen/internal/qwen/transcript.go @@ -7,6 +7,7 @@ import ( "encoding/json" "errors" "fmt" + "io" "os" "path/filepath" "regexp" @@ -239,8 +240,25 @@ func (a *Agent) appendSidecar(raw qwenHookInputRaw) error { record.Message = encoded } } - data, err := json.Marshal(record) - if err != nil { + if err := appendSidecarRecords(path, []sidecarRecord{record}); err != nil { + return err + } + return a.writeSessionMarker(raw, path) +} + +// appendSidecarRecords appends records to the sidecar in one write, one line +// each. +func appendSidecarRecords(path string, records []sidecarRecord) error { + var buf bytes.Buffer + for _, record := range records { + data, err := json.Marshal(record) + if err != nil { + return err + } + buf.Write(data) + buf.WriteByte('\n') + } + if err := os.MkdirAll(filepath.Dir(path), 0o700); err != nil { return err } f, err := os.OpenFile(path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) @@ -248,10 +266,8 @@ func (a *Agent) appendSidecar(raw qwenHookInputRaw) error { return err } defer func() { _ = f.Close() }() - if _, err := f.Write(append(data, '\n')); err != nil { - return err - } - return a.writeSessionMarker(raw, path) + _, err = f.Write(buf.Bytes()) + return err } func (a *Agent) sessionIDAndRef(input *protocol.HookInputJSON) (string, string) { @@ -355,9 +371,14 @@ func readSidecarRecords(path string) ([]sidecarRecord, error) { return nil, err } defer func() { _ = f.Close() }() + return decodeSidecarRecords(f) +} +// decodeSidecarRecords is readSidecarRecords over any reader, for callers +// handed the sidecar's bytes rather than its path (calculate-tokens). +func decodeSidecarRecords(r io.Reader) ([]sidecarRecord, error) { var records []sidecarRecord - scanner := bufio.NewScanner(f) + scanner := bufio.NewScanner(r) scanner.Buffer(make([]byte, 64*1024), maxSidecarLine) for scanner.Scan() { line := strings.TrimSpace(scanner.Text()) diff --git a/agents/entire-agent-qwen/internal/qwen/types.go b/agents/entire-agent-qwen/internal/qwen/types.go index 5c7d7c967..04b0a6724 100644 --- a/agents/entire-agent-qwen/internal/qwen/types.go +++ b/agents/entire-agent-qwen/internal/qwen/types.go @@ -158,4 +158,24 @@ type sidecarRecord struct { LastAssistantMessage string `json:"last_assistant_message,omitempty"` CustomInstructions string `json:"custom_instructions,omitempty"` CompactSummary string `json:"compact_summary,omitempty"` + // NativeUUID, NativeOffset and Usage are set only on AssistantUsage + // records, each a copy of one assistant record's usageMetadata from + // Qwen's own chat log (see tokens.go). NativeOffset is the byte offset at + // which that record's line starts in NativeTranscriptPath. + NativeUUID string `json:"native_uuid,omitempty"` + NativeOffset int64 `json:"native_offset,omitempty"` + Usage *qwenUsageMetadata `json:"usage,omitempty"` +} + +// qwenUsageMetadata is the usageMetadata Qwen Code stores on each assistant +// record of its chat log: the provider's token counts, normalized by Qwen to +// the Gemini field names whichever provider answered (see +// ChatRecordingService.recordAssistantTurn in packages/core). Only the counts +// calculate-tokens reads are kept. +type qwenUsageMetadata struct { + PromptTokenCount int `json:"promptTokenCount,omitempty"` + CandidatesTokenCount int `json:"candidatesTokenCount,omitempty"` + CachedContentTokenCount int `json:"cachedContentTokenCount,omitempty"` + ThoughtsTokenCount int `json:"thoughtsTokenCount,omitempty"` + TotalTokenCount int `json:"totalTokenCount,omitempty"` } From 31f62d4de4873817f9b3e73bdf576d299f320055 Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Fri, 6 Nov 2026 22:31:08 +0000 Subject: [PATCH 2/7] fix(qwen): wait for a turn's final usage at Stop, start old sidecars 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. --- agents/entire-agent-qwen/AGENT.md | 20 +- agents/entire-agent-qwen/README.md | 13 +- .../entire-agent-qwen/internal/qwen/hooks.go | 2 +- .../entire-agent-qwen/internal/qwen/tokens.go | 181 +++++++++++------- .../internal/qwen/tokens_test.go | 99 +++++++++- .../internal/qwen/transcript.go | 2 +- .../entire-agent-qwen/internal/qwen/types.go | 6 + 7 files changed, 234 insertions(+), 89 deletions(-) diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index 3f8536851..5d1547c7b 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -58,6 +58,10 @@ always runs the generic compactor over the raw transcript. The projection is derived data — `readSidecarRecords` ignores `type` and `message` — so a sidecar written before it existed still reads. +Records carry `v: 2` since the adapter started copying token usage; `v: 1` +records come from an older adapter. The two differ only in that the token +usage copy starts at the first `v: 2` record (see Token Usage). + | event | projected as | content | |---|---|---| | `UserPromptSubmit` | `user` | text block with the prompt | @@ -86,16 +90,18 @@ their usage to the same shape. | Step | Behavior | |---|---| | Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | +| Wait | At `Stop`, while the log ends with a `user` or `tool_result` record (ignoring `system` records) or a line still being written, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight | | Resume | The next copy starts after the furthest copied line while that line still holds the same record, and rereads the log otherwise (Qwen can rewrite it, e.g. when prompts are deleted); `native_uuid` keeps a call from being copied twice | -| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first record, such as the history of a resumed session whose sidecar was removed from the temp directory | +| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started | | Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | -Qwen fires `Stop` without waiting for its write queue, so the last API call of -a turn can land after the `Stop` hook (seen once in six live runs, at -`PreToolUse`). It is copied at the next hook and counted with that turn or -checkpoint. Calls outside the session's chat log (subagents, the auto-memory -extractor and other background helpers) are not counted, and Qwen keeps no -separate cache-write count. +Qwen writes its log through a queue that no hook waits for, so an API call can +land after the hook that follows it (seen once in six live runs, at +`PreToolUse`; that call was copied at `Stop`). `Stop` waits for the turn's +final call as above; a call that lands later still is copied at the next hook +and counted with that turn or checkpoint. Calls outside the session's chat log +(subagents, the auto-memory extractor and other background helpers) are not +counted, and Qwen keeps no separate cache-write count. ## Lifecycle Mapping diff --git a/agents/entire-agent-qwen/README.md b/agents/entire-agent-qwen/README.md index e01a63813..00ec366a0 100644 --- a/agents/entire-agent-qwen/README.md +++ b/agents/entire-agent-qwen/README.md @@ -24,11 +24,14 @@ after `--offset`. The sidecar stays the only transcript, so a stored checkpoint still reports its tokens on a machine without the chat log. Qwen writes its log through a queue and fires `Stop` without waiting for it, -so a turn's last API call can reach the log after the `Stop` hook. It is then -copied at the next hook and counted with the next turn or checkpoint; totals -are unaffected. Calls Qwen does not record in the session's chat log, such as -subagents and background helpers like its auto-memory extractor, are not -counted. Cache writes are not reported separately: for Anthropic models Qwen +so a turn's last API call can still be on its way when the `Stop` hook reads +the log. While the log ends with a prompt or tool result the model has not +answered yet, `Stop` waits up to a second for that call. One that arrives later +still is copied at the next hook and counted with the next turn or checkpoint; +totals are unaffected. A session that an older adapter started is counted from +the first hook after the upgrade. Calls Qwen does not record in the session's +chat log, such as subagents and background helpers like its auto-memory +extractor, are not counted. Cache writes are not reported separately: for Anthropic models Qwen folds them into the prompt count, so they appear as input tokens. ## Installation diff --git a/agents/entire-agent-qwen/internal/qwen/hooks.go b/agents/entire-agent-qwen/internal/qwen/hooks.go index a0399e9b1..2e8072143 100644 --- a/agents/entire-agent-qwen/internal/qwen/hooks.go +++ b/agents/entire-agent-qwen/internal/qwen/hooks.go @@ -25,7 +25,7 @@ func (a *Agent) ParseHook(hookName string, input []byte) (*protocol.EventJSON, e // Copy token usage from Qwen's own chat log first, so it precedes // this hook's record; see tokens.go. Best effort: the hook itself // must not fail because the native log could not be read. - _ = a.syncNativeUsage(raw) + _ = a.syncNativeUsage(hookName, raw) } if err := a.appendSidecar(raw); err != nil { return nil, err diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go index 7de4c4a48..2d91a7779 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -30,15 +30,32 @@ import ( // Entire's compact transcript drops them. // // Qwen queues its log writes and fires Stop without waiting for the queue, so -// a turn's last API call can reach the log after the Stop hook has read it. -// That call is copied at the next sync and counted with the turn and the -// checkpoint in which it was copied: totals stay right, but one turn's share -// can move to the next. +// a turn's last API call can still be on its way when the Stop hook reads the +// log. Stop therefore waits, up to finalRecordWait, while the log ends with a +// record the model has yet to answer. A call that arrives later still is +// copied at the next sync and counted with the turn and the checkpoint in +// which it was copied: totals stay right, but one turn's share can move to the +// next. const eventAssistantUsage = "AssistantUsage" -// nativeTypeAssistant is the type of the chat-log records that carry usage. -const nativeTypeAssistant = "assistant" +// Types of chat-log records. Assistant records carry usage; a user or +// tool_result record is answered by one; system records (telemetry, titles, +// compression) come and go around them. +const ( + nativeTypeAssistant = "assistant" + nativeTypeUser = "user" + nativeTypeToolResult = "tool_result" + nativeTypeSystem = "system" +) + +// finalRecordWait bounds how long Stop waits for the turn's final assistant +// record to reach the log, polling every finalRecordPoll. Qwen queues that +// record before it fires Stop, so the wait ends once that queued write lands. +const ( + finalRecordWait = time.Second + finalRecordPoll = 25 * time.Millisecond +) // maxNativeLine bounds one line read while syncing usage. A native record can // embed a whole tool result or written file, and a sidecar record a whole tool @@ -47,7 +64,8 @@ const nativeTypeAssistant = "assistant" const maxNativeLine = 64 * 1024 * 1024 // usageMetadataKey prefilters native lines: only a line containing it can -// carry usage, so the rest are never decoded. +// carry usage, so unless a Stop is waiting for the final record the rest are +// never decoded. var usageMetadataKey = []byte(`"usageMetadata"`) // nativeUUIDKey prefilters sidecar lines the same way for AssistantUsage @@ -91,18 +109,22 @@ type usageSyncState struct { // the native log in use: the sync resumes after that line when it still // holds the same record. anchor *sidecarRecord - // floor is the time of the sidecar's first record. A native record older - // than it predates the part of the session Entire saw, such as the - // history of a resumed session whose sidecar was cleaned out of the temp - // directory, and is not copied. + // floor is the time of the sidecar's first record written by an adapter + // that copies usage (sidecarVersion or later). A native record older than + // it predates the part of the session whose usage the sidecar records and + // is not copied: the history of a resumed session whose sidecar was + // cleaned out of the temp directory, or of a session whose sidecar an + // older adapter started, which would otherwise all land in the first turn + // after the upgrade. floor time.Time } // syncNativeUsage copies into the sidecar the usage of assistant records the -// native log gained since the last sync. It is best effort for the hook that +// native log gained since the last sync. At Stop it first gives the turn's +// final record finalRecordWait to arrive. It is best effort for the hook that // calls it: an unreadable native log costs the usage of this sync, never the // hook. -func (a *Agent) syncNativeUsage(raw qwenHookInputRaw) error { +func (a *Agent) syncNativeUsage(hookName string, raw qwenHookInputRaw) error { nativePath := strings.TrimSpace(raw.TranscriptPath) if nativePath == "" { return nil @@ -112,11 +134,16 @@ func (a *Agent) syncNativeUsage(raw qwenHookInputRaw) error { if err != nil { return err } - records, err := scanNativeUsage(nativePath, raw.SessionID, state) - if err != nil || len(records) == 0 { + scan := &nativeScan{path: nativePath, sessionID: raw.SessionID, state: state, offset: -1, waits: hookName == HookNameStop} + pending, err := scan.next() + for waited := time.Duration(0); err == nil && pending && waited < finalRecordWait; waited += finalRecordPoll { + time.Sleep(finalRecordPoll) + pending, err = scan.next() + } + if len(scan.records) == 0 { return err } - return appendSidecarRecords(sidecarPath, records) + return errors.Join(err, appendSidecarRecords(sidecarPath, scan.records)) } // readUsageSyncState reads the copied UUIDs, the anchor for nativePath and @@ -136,7 +163,7 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn defer func() { _ = f.Close() }() reader := bufio.NewReaderSize(f, 64*1024) - first := true + floorFound := false for { line, _, complete, err := readLine(reader, maxNativeLine) if err != nil { @@ -145,12 +172,13 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn if !complete { break } - if first && len(bytes.TrimSpace(line)) > 0 { - first = false + if !floorFound { var head struct { + V int `json:"v"` TS string `json:"ts"` } - if json.Unmarshal(line, &head) == nil { + if json.Unmarshal(line, &head) == nil && head.V >= sidecarVersion { + floorFound = true state.floor = parseTimestamp(head.TS) } } @@ -167,64 +195,94 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn state.anchor = &anchor } } - if first { + if !floorFound { state.floor = parseTimestamp(hookTimestamp) } return state, nil } -// scanNativeUsage returns an AssistantUsage record for each assistant record -// in the native log that carries usage and has not been copied. It resumes -// after the anchor when that line still holds the anchored record and reads -// the whole log otherwise (Qwen can rewrite it, e.g. when prompts are -// deleted), relying on the copied UUIDs to skip what is already recorded. A -// trailing line without its newline is still being written and is left for -// the next sync. -func scanNativeUsage(nativePath, sessionID string, state usageSyncState) ([]sidecarRecord, error) { - f, err := os.Open(nativePath) +// nativeScan reads the native log forward from where its last read stopped, +// collecting an AssistantUsage record for each assistant record that carries +// usage and has not been copied. Its first read resumes after the anchor when +// that line still holds the anchored record and reads the whole log otherwise +// (Qwen can rewrite it, e.g. when prompts are deleted), relying on the copied +// UUIDs to skip what is already recorded. +type nativeScan struct { + path string + sessionID string + state usageSyncState + // offset is where the next read starts, just past the last complete + // line; -1 until the first read places it. + offset int64 + // waits is set when the caller waits for the turn's final record: every + // line is then decoded so that last is known. + waits bool + // last is the type of the last record read other than a system record. + last string + records []sidecarRecord +} + +// next reads what the native log gained since the last read. When the scan +// waits, it reports whether the turn's final record may still be on its way: +// the log ends with a line still being written, which is left for a later +// read, or with a user or tool_result record the model has yet to answer. +func (s *nativeScan) next() (bool, error) { + f, err := os.Open(s.path) if errors.Is(err, os.ErrNotExist) { - return nil, nil + return false, nil } if err != nil { - return nil, err + return false, err } defer func() { _ = f.Close() }() info, err := f.Stat() if err != nil { - return nil, err + return false, err } if !info.Mode().IsRegular() { - return nil, nil + return false, nil } - - offset := resumeOffset(f, state.anchor) - if _, err := f.Seek(offset, io.SeekStart); err != nil { - return nil, err + if s.offset < 0 { + s.offset = resumeOffset(f, s.state.anchor) + if s.offset > 0 { + s.last = nativeTypeAssistant + } + } + if _, err := f.Seek(s.offset, io.SeekStart); err != nil { + return false, err } reader := bufio.NewReaderSize(f, 64*1024) - var records []sidecarRecord for { line, n, complete, err := readLine(reader, maxNativeLine) if err != nil { - return nil, err + return false, err } if !complete { - return records, nil + return s.waits && (n > 0 || s.last == nativeTypeUser || s.last == nativeTypeToolResult), nil } - lineStart := offset - offset += n - native, ok := nativeUsage(line, state) - if !ok { + lineStart := s.offset + s.offset += n + if !s.waits && !bytes.Contains(line, usageMetadataKey) { continue } - state.copied[native.UUID] = struct{}{} - records = append(records, sidecarRecord{ - V: 1, + var native nativeChatRecord + if json.Unmarshal(line, &native) != nil { + continue + } + if native.Type != nativeTypeSystem { + s.last = native.Type + } + if !s.state.wants(native) { + continue + } + s.state.copied[native.UUID] = struct{}{} + s.records = append(s.records, sidecarRecord{ + V: sidecarVersion, Agent: AgentName, Event: eventAssistantUsage, - SessionID: sessionID, + SessionID: s.sessionID, TS: native.Timestamp, - NativeTranscriptPath: nativePath, + NativeTranscriptPath: s.path, Model: native.Model, NativeUUID: native.UUID, NativeOffset: lineStart, @@ -233,27 +291,18 @@ func scanNativeUsage(nativePath, sessionID string, state usageSyncState) ([]side } } -// nativeUsage decodes a native line that is an assistant record of this +// wants reports whether a native record is an assistant record of this // session with usage not yet copied. -func nativeUsage(line []byte, state usageSyncState) (nativeChatRecord, bool) { - if !bytes.Contains(line, usageMetadataKey) { - return nativeChatRecord{}, false - } - var record nativeChatRecord - if json.Unmarshal(line, &record) != nil { - return nativeChatRecord{}, false - } +func (s usageSyncState) wants(record nativeChatRecord) bool { if record.Type != nativeTypeAssistant || record.UsageMetadata == nil || record.UUID == "" || record.IsSidechain || record.ForkedFrom != nil { - return nativeChatRecord{}, false - } - if _, copied := state.copied[record.UUID]; copied { - return nativeChatRecord{}, false + return false } - if at := parseTimestamp(record.Timestamp); !state.floor.IsZero() && !at.IsZero() && at.Before(state.floor) { - return nativeChatRecord{}, false + if _, copied := s.copied[record.UUID]; copied { + return false } - return record, true + at := parseTimestamp(record.Timestamp) + return s.floor.IsZero() || at.IsZero() || !at.Before(s.floor) } // resumeOffset returns the offset just past the anchor's line when that line diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go index ec36e31b3..81a7552b9 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens_test.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -4,11 +4,13 @@ import ( "bufio" "bytes" "encoding/json" + "errors" "fmt" "os" "path/filepath" "strings" "testing" + "time" "github.com/entireio/external-agents/agents/entire-agent-qwen/internal/protocol" ) @@ -59,14 +61,30 @@ func (s *qwenSession) hook(name, timestamp string, extra map[string]any) { // is a record Qwen is still writing. func (s *qwenSession) writeNative(text string) { s.t.Helper() - f, err := os.OpenFile(s.nativePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) - if err != nil { + if err := appendFile(s.nativePath, text); err != nil { s.t.Fatal(err) } - defer func() { _ = f.Close() }() - if _, err := f.WriteString(text); err != nil { - s.t.Fatal(err) +} + +func appendFile(path, text string) error { + if err := os.MkdirAll(filepath.Dir(path), 0o700); err != nil { + return err + } + f, err := os.OpenFile(path, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) + if err != nil { + return err + } + _, err = f.WriteString(text) + return errors.Join(err, f.Close()) +} + +func mustRead(t *testing.T, path string) []byte { + t.Helper() + data, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) } + return data } func (s *qwenSession) sidecar() []byte { @@ -180,9 +198,12 @@ func TestTurnTokenUsageComesFromNativeChatLog(t *testing.T) { } } -// Qwen fires Stop without waiting for its write queue, so the turn's last API -// call can land after the Stop hook. It is copied at the next sync and counted -// with the next turn; the session total is unaffected. +// Qwen fires Stop without waiting for its write queue, so the turn's final +// record can still be on its way. While the log ends with a record the model +// has yet to answer, Stop waits for it; the next test covers that. Here the +// log already ends with an assistant record, so Stop has nothing to wait for, +// and the late call is copied at the next sync and counted with the next turn. +// The session total is unaffected. func TestUsageWrittenAfterStopIsCountedWithNextTurn(t *testing.T) { s := newQwenSession(t) s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) @@ -205,6 +226,37 @@ func TestUsageWrittenAfterStopIsCountedWithNextTurn(t *testing.T) { wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 600, OutputTokens: 60, APICallCount: 3}) } +// Qwen queues the turn's final record before it fires Stop, but the write can +// still be in flight when the hook reads the log. Stop waits for it, so the +// turn that made the call counts it. +func TestStopWaitsForTheTurnsFinalRecord(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "go"}) + s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "")) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) + s.writeNative(nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.5Z", "") + + nativeLine("sys-1", "system", "2026-11-06T10:00:02.6Z", "")) + + // The final record is half written when Stop fires, and finished while + // the hook waits. + final := nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0)) + s.writeNative(final[:len(final)/2]) + written := make(chan error, 1) + go func() { + time.Sleep(100 * time.Millisecond) + written <- appendFile(s.nativePath, final[len(final)/2:]) + }() + s.hook(HookNameStop, "2026-11-06T10:00:04.1Z", map[string]any{"last_assistant_message": "done"}) + if err := <-written; err != nil { + t.Fatal(err) + } + + wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) +} + // A record Qwen is still writing has no newline yet. It must not be copied // half-read or skipped: the next sync copies it whole. func TestPartialNativeLineIsCopiedOnceComplete(t *testing.T) { @@ -212,7 +264,7 @@ func TestPartialNativeLineIsCopiedOnceComplete(t *testing.T) { s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) line := nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) s.writeNative(line[:len(line)/2]) - s.hook(HookNameStop, "2026-11-06T10:00:03Z", nil) + s.hook(HookNamePreToolUse, "2026-11-06T10:00:03Z", map[string]any{"tool_name": "read_file", "tool_use_id": "call-1"}) wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{}) s.writeNative(line[len(line)/2:]) @@ -289,6 +341,35 @@ func TestNativeHistoryBeforeTheSidecarIsNotCopied(t *testing.T) { wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 100, OutputTokens: 10, APICallCount: 1}) } +// A session whose sidecar an older adapter started has no usage copied yet. +// After the upgrade, counting starts with the first record the new adapter +// wrote, instead of the session's whole history landing in the next turn. +func TestSidecarFromAnOlderAdapterStartsAtTheUpgrade(t *testing.T) { + s := newQwenSession(t) + older := `{"v":1,"agent":"qwen","event":"SessionStart","session_id":"` + s.id + `","ts":"2026-11-01T09:00:00Z","source":"startup"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-01T09:00:01Z","prompt":"first"}` + "\n" + + `{"v":1,"agent":"qwen","event":"Stop","session_id":"` + s.id + `","ts":"2026-11-01T09:00:09Z"}` + "\n" + if err := appendFile(s.agent.sidecarPath(s.id), older); err != nil { + t.Fatal(err) + } + s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:05Z", openAIUsage(5000, 500, 0, 0))) + + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "continue"}) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:03Z", nil) + // A later reread of the whole log, after Qwen rewrites it, still leaves + // the older history out. + s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:01:02Z", openAIUsage(200, 20, 0, 0))) + if err := os.WriteFile(s.nativePath, append([]byte(nativeLine("u-0", "user", "2026-11-01T09:00:01Z", "")), mustRead(t, s.nativePath)...), 0o600); err != nil { + t.Fatal(err) + } + s.hook(HookNameStop, "2026-11-06T10:01:03Z", nil) + + wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) +} + // Records /branch copied from a parent session, and subagent records, were // counted where their API calls were made. func TestForkedAndSidechainRecordsAreNotCopied(t *testing.T) { diff --git a/agents/entire-agent-qwen/internal/qwen/transcript.go b/agents/entire-agent-qwen/internal/qwen/transcript.go index 858ba45f2..ef1647818 100644 --- a/agents/entire-agent-qwen/internal/qwen/transcript.go +++ b/agents/entire-agent-qwen/internal/qwen/transcript.go @@ -198,7 +198,7 @@ func (a *Agent) appendSidecar(raw qwenHookInputRaw) error { return err } record := sidecarRecord{ - V: 1, + V: sidecarVersion, Agent: AgentName, Event: raw.HookEventName, SessionID: raw.SessionID, diff --git a/agents/entire-agent-qwen/internal/qwen/types.go b/agents/entire-agent-qwen/internal/qwen/types.go index 04b0a6724..0ee20eb3a 100644 --- a/agents/entire-agent-qwen/internal/qwen/types.go +++ b/agents/entire-agent-qwen/internal/qwen/types.go @@ -109,6 +109,12 @@ type qwenHookInputRaw struct { } `json:"llm_request,omitempty"` } +// sidecarVersion is the v of each sidecar record this adapter writes. Version +// 2 marks a record written by an adapter that copies token usage into the +// sidecar (tokens.go); version 1 records come from an older adapter and +// differ in nothing else. +const sidecarVersion = 2 + // sidecarRecord is one line of the append-only sidecar. Alongside Qwen's own // hook fields it carries the Entire-facing projection Type and Message, which // the generic compact reader needs to keep the line and read its content — see From b64e7d8ec8940083d9b08c9911aebb1790fcf4f5 Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Fri, 6 Nov 2026 22:35:06 +0000 Subject: [PATCH 3/7] fix(qwen): read the usage anchor from the end of the sidecar 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. --- agents/entire-agent-qwen/AGENT.md | 2 +- .../entire-agent-qwen/internal/qwen/tokens.go | 132 ++++++++++++------ .../internal/qwen/tokens_test.go | 70 ++++++++++ 3 files changed, 157 insertions(+), 47 deletions(-) diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index 5d1547c7b..e8542be52 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -91,7 +91,7 @@ their usage to the same shape. |---|---| | Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | | Wait | At `Stop`, while the log ends with a `user` or `tool_result` record (ignoring `system` records) or a line still being written, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight | -| Resume | The next copy starts after the furthest copied line while that line still holds the same record, and rereads the log otherwise (Qwen can rewrite it, e.g. when prompts are deleted); `native_uuid` keeps a call from being copied twice | +| Resume | A copy finds the last `AssistantUsage` record for the log by reading the sidecar backwards from its end, and starts after that record's line while the line still holds the same record. Otherwise it rereads the log (Qwen can rewrite it, e.g. when prompts are deleted) and copies its calls again; the count keeps one copy of each | | Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started | | Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go index 2d91a7779..f32c51536 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -101,13 +101,9 @@ type nativeChatRecord struct { // usageSyncState is what the sidecar already records about native usage. type usageSyncState struct { - // copied holds the native UUID of every AssistantUsage record, so a call - // is copied once even when the native log is rewritten or two hooks sync - // at the same time. - copied map[string]struct{} - // anchor is the AssistantUsage record copied from the furthest line of - // the native log in use: the sync resumes after that line when it still - // holds the same record. + // anchor is the last AssistantUsage record copied from the native log in + // use: the sync resumes after its line when that line still holds the + // same record. anchor *sidecarRecord // floor is the time of the sidecar's first record written by an adapter // that copies usage (sidecarVersion or later). A native record older than @@ -146,15 +142,14 @@ func (a *Agent) syncNativeUsage(hookName string, raw qwenHookInputRaw) error { return errors.Join(err, appendSidecarRecords(sidecarPath, scan.records)) } -// readUsageSyncState reads the copied UUIDs, the anchor for nativePath and -// the floor from the sidecar. Only lines that can be AssistantUsage records -// are decoded, so the cost of a hook stays small as the sidecar grows. An -// empty or missing sidecar takes its floor from the hook now running. +// readUsageSyncState reads the floor from the start of the sidecar and the +// anchor for nativePath from its end, so a hook reads what was appended since +// the last copy, not the whole session. An empty or missing sidecar takes its +// floor from the hook now running. func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyncState, error) { - state := usageSyncState{copied: map[string]struct{}{}} + state := usageSyncState{floor: parseTimestamp(hookTimestamp)} f, err := os.Open(sidecarPath) if errors.Is(err, os.ErrNotExist) { - state.floor = parseTimestamp(hookTimestamp) return state, nil } if err != nil { @@ -163,7 +158,6 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn defer func() { _ = f.Close() }() reader := bufio.NewReaderSize(f, 64*1024) - floorFound := false for { line, _, complete, err := readLine(reader, maxNativeLine) if err != nil { @@ -172,41 +166,90 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn if !complete { break } - if !floorFound { - var head struct { - V int `json:"v"` - TS string `json:"ts"` - } - if json.Unmarshal(line, &head) == nil && head.V >= sidecarVersion { - floorFound = true - state.floor = parseTimestamp(head.TS) - } + var head struct { + V int `json:"v"` + TS string `json:"ts"` } - if !bytes.Contains(line, nativeUUIDKey) { - continue + if json.Unmarshal(line, &head) == nil && head.V >= sidecarVersion { + state.floor = parseTimestamp(head.TS) + break } - var record sidecarRecord - if json.Unmarshal(line, &record) != nil || !isUsageRecord(record) || record.NativeUUID == "" { - continue + } + state.anchor, err = lastUsageRecord(f, nativePath) + return state, err +} + +// lastUsageRecord returns the last AssistantUsage record in the sidecar that +// was copied from nativePath, reading the sidecar backwards from its end. A +// trailing line without its newline is still being written and is skipped. +// AssistantUsage lines are small, so a line longer than one block is skipped +// without being held in memory. +func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, error) { + info, err := f.Stat() + if err != nil { + return nil, err + } + const block = 64 * 1024 + var ( + pos = info.Size() + carry []byte // the end of a line whose start lies before pos + trailing = true // the bytes after the last newline are no line yet + long bool // the line in carry is longer than a block + ) + for pos > 0 { + n := min(int64(block), pos) + pos -= n + data := make([]byte, n, n+int64(len(carry))) + if _, err := f.ReadAt(data, pos); err != nil { + return nil, err } - state.copied[record.NativeUUID] = struct{}{} - if record.NativeTranscriptPath == nativePath && (state.anchor == nil || record.NativeOffset > state.anchor.NativeOffset) { - anchor := record - state.anchor = &anchor + data = append(data, carry...) + for { + i := bytes.LastIndexByte(data, '\n') + if i < 0 { + break + } + line := data[i+1:] + data = data[:i] + if trailing || long { + trailing, long = false, false + continue + } + if record := usageRecordFrom(line, nativePath); record != nil { + return record, nil + } + } + carry = data + if len(carry) > block { + carry, long = nil, true } } - if !floorFound { - state.floor = parseTimestamp(hookTimestamp) + if trailing || long { + return nil, nil } - return state, nil + return usageRecordFrom(carry, nativePath), nil +} + +// usageRecordFrom decodes a sidecar line that is an AssistantUsage record +// copied from nativePath, or returns nil. +func usageRecordFrom(line []byte, nativePath string) *sidecarRecord { + if !bytes.Contains(line, nativeUUIDKey) { + return nil + } + var record sidecarRecord + if json.Unmarshal(line, &record) != nil || !isUsageRecord(record) || record.NativeUUID == "" || + record.NativeTranscriptPath != nativePath { + return nil + } + return &record } // nativeScan reads the native log forward from where its last read stopped, // collecting an AssistantUsage record for each assistant record that carries -// usage and has not been copied. Its first read resumes after the anchor when -// that line still holds the anchored record and reads the whole log otherwise -// (Qwen can rewrite it, e.g. when prompts are deleted), relying on the copied -// UUIDs to skip what is already recorded. +// usage. Its first read resumes after the anchor when that line still holds +// the anchored record. Otherwise it reads the whole log (Qwen can rewrite it, +// e.g. when prompts are deleted) and copies again what an earlier sync +// copied; CalculateTokens counts each call once. type nativeScan struct { path string sessionID string @@ -275,7 +318,6 @@ func (s *nativeScan) next() (bool, error) { if !s.state.wants(native) { continue } - s.state.copied[native.UUID] = struct{}{} s.records = append(s.records, sidecarRecord{ V: sidecarVersion, Agent: AgentName, @@ -292,15 +334,12 @@ func (s *nativeScan) next() (bool, error) { } // wants reports whether a native record is an assistant record of this -// session with usage not yet copied. +// session, with usage, from no earlier than the floor. func (s usageSyncState) wants(record nativeChatRecord) bool { if record.Type != nativeTypeAssistant || record.UsageMetadata == nil || record.UUID == "" || record.IsSidechain || record.ForkedFrom != nil { return false } - if _, copied := s.copied[record.UUID]; copied { - return false - } at := parseTimestamp(record.Timestamp) return s.floor.IsZero() || at.IsZero() || !at.Before(s.floor) } @@ -374,8 +413,9 @@ func isUsageRecord(record sidecarRecord) bool { // CalculateTokens sums the AssistantUsage records at or after offset, a // sidecar line index like every other offset this adapter reports. A native -// call recorded twice, by two hooks syncing at once or once before offset and -// again after it, is counted once. +// call recorded twice (by two hooks syncing at once, or copied again after Qwen +// rewrote its log), whether both copies follow offset or one precedes it, is +// counted once. func (a *Agent) CalculateTokens(data []byte, offset int) (protocol.TokenUsageResponse, error) { records, err := decodeSidecarRecords(bytes.NewReader(data)) if err != nil { diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go index 81a7552b9..0fec157f2 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens_test.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -292,6 +292,76 @@ func TestRewrittenNativeLogIsNotCountedTwice(t *testing.T) { s.hook(HookNameStop, "2026-11-06T10:00:06Z", nil) wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 600, OutputTokens: 60, APICallCount: 3}) + + // The copy made after the rewrite anchors later syncs in the rewritten + // log, so they resume instead of rereading it. + state, err := readUsageSyncState(s.agent.sidecarPath(s.id), s.nativePath, "") + if err != nil { + t.Fatal(err) + } + f, err := os.Open(s.nativePath) + if err != nil { + t.Fatal(err) + } + defer func() { _ = f.Close() }() + if got := resumeOffset(f, state.anchor); state.anchor == nil || state.anchor.NativeUUID != "a-3" || got != int64(len(rewritten)) { + t.Fatalf("anchor = %+v, resumeOffset = %d; want a-3, %d", state.anchor, got, len(rewritten)) + } + s.writeNative(nativeLine("a-4", "assistant", "2026-11-06T10:00:07Z", openAIUsage(400, 40, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:08Z", nil) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 1000, OutputTokens: 100, APICallCount: 4}) +} + +// The anchor is read from the end of the sidecar: the last AssistantUsage +// record copied from the given log, past long lines and a line still being +// written, without reading the whole session. +func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { + t.Parallel() + usage := func(uuid, native string) string { + data, err := json.Marshal(sidecarRecord{ + V: sidecarVersion, Agent: AgentName, Event: eventAssistantUsage, NativeTranscriptPath: native, + NativeUUID: uuid, Usage: &qwenUsageMetadata{PromptTokenCount: 1}, + }) + if err != nil { + t.Fatal(err) + } + return string(data) + "\n" + } + long := `{"v":2,"agent":"qwen","event":"PostToolUse","tool_response":"` + strings.Repeat("x", 200*1024) + `"}` + "\n" + for _, tc := range []struct { + name, sidecar, want string + }{ + {"first line", usage("a-1", "/n.jsonl"), "a-1"}, + {"last of several", usage("a-1", "/n.jsonl") + usage("a-2", "/n.jsonl") + long, "a-2"}, + {"past long lines and other logs", usage("a-1", "/n.jsonl") + long + usage("b-1", "/other.jsonl") + long, "a-1"}, + {"partial trailing line", usage("a-1", "/n.jsonl") + strings.TrimSuffix(usage("a-2", "/n.jsonl"), "\n"), "a-1"}, + {"none", long + usage("b-1", "/other.jsonl"), ""}, + {"empty", "", ""}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + path := filepath.Join(t.TempDir(), "sidecar.jsonl") + if err := os.WriteFile(path, []byte(tc.sidecar), 0o600); err != nil { + t.Fatal(err) + } + f, err := os.Open(path) + if err != nil { + t.Fatal(err) + } + defer func() { _ = f.Close() }() + record, err := lastUsageRecord(f, "/n.jsonl") + if err != nil { + t.Fatal(err) + } + got := "" + if record != nil { + got = record.NativeUUID + } + if got != tc.want { + t.Fatalf("last usage record = %q, want %q", got, tc.want) + } + }) + } } // A sync resumes after the last copied line instead of rereading the log, as From 43cfd1dd6bce8012df4c9c001e62dcea72748a1c Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Fri, 6 Nov 2026 22:40:41 +0000 Subject: [PATCH 4/7] fix(qwen): keep a mid-turn upgrade's turn, reread a log replaced during 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. --- agents/entire-agent-qwen/AGENT.md | 4 +- .../entire-agent-qwen/internal/qwen/tokens.go | 28 +++++++-- .../internal/qwen/tokens_test.go | 59 +++++++++++++++++++ 3 files changed, 85 insertions(+), 6 deletions(-) diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index e8542be52..c1d621a88 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -90,9 +90,9 @@ their usage to the same shape. | Step | Behavior | |---|---| | Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | -| Wait | At `Stop`, while the log ends with a `user` or `tool_result` record (ignoring `system` records) or a line still being written, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight | +| Wait | At `Stop`, while the log ends with a `user` or `tool_result` record (ignoring `system` records) or a line still being written, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight. A log replaced (Qwen rewrites it by renaming a new file over it) or cut shorter during the wait is read again from the start | | Resume | A copy finds the last `AssistantUsage` record for the log by reading the sidecar backwards from its end, and starts after that record's line while the line still holds the same record. Otherwise it rereads the log (Qwen can rewrite it, e.g. when prompts are deleted) and copies its calls again; the count keeps one copy of each | -| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started | +| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started. Until such a sidecar has a `v: 2` record, its last prompt is the cutoff, so an upgrade in the middle of a turn still counts that turn | | Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | Qwen writes its log through a queue that no hook waits for, so an API call can diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go index f32c51536..ee617a9f9 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -39,6 +39,9 @@ import ( const eventAssistantUsage = "AssistantUsage" +// eventUserPromptSubmit is the event of the sidecar record a turn starts with. +const eventUserPromptSubmit = "UserPromptSubmit" + // Types of chat-log records. Assistant records carry usage; a user or // tool_result record is answered by one; system records (telemetry, titles, // compression) come and go around them. @@ -111,7 +114,9 @@ type usageSyncState struct { // is not copied: the history of a resumed session whose sidecar was // cleaned out of the temp directory, or of a session whose sidecar an // older adapter started, which would otherwise all land in the first turn - // after the upgrade. + // after the upgrade. Until a sidecar an older adapter started has such a + // record, the floor is its last prompt, so an upgrade in the middle of a + // turn still copies that turn's calls. floor time.Time } @@ -167,13 +172,20 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn break } var head struct { - V int `json:"v"` - TS string `json:"ts"` + V int `json:"v"` + Event string `json:"event"` + TS string `json:"ts"` + } + if json.Unmarshal(line, &head) != nil { + continue } - if json.Unmarshal(line, &head) == nil && head.V >= sidecarVersion { + if head.V >= sidecarVersion { state.floor = parseTimestamp(head.TS) break } + if at := parseTimestamp(head.TS); head.Event == eventUserPromptSubmit && !at.IsZero() { + state.floor = at + } } state.anchor, err = lastUsageRecord(f, nativePath) return state, err @@ -260,6 +272,8 @@ type nativeScan struct { // waits is set when the caller waits for the turn's final record: every // line is then decoded so that last is known. waits bool + // info is the log as the last read found it. + info os.FileInfo // last is the type of the last record read other than a system record. last string records []sidecarRecord @@ -285,6 +299,12 @@ func (s *nativeScan) next() (bool, error) { if !info.Mode().IsRegular() { return false, nil } + // A log replaced since the last read (Qwen rewrites it by renaming a new + // file over it) or cut shorter is read again from the start. + if s.info != nil && (!os.SameFile(s.info, info) || info.Size() < s.offset) { + s.offset, s.last = -1, "" + } + s.info = info if s.offset < 0 { s.offset = resumeOffset(f, s.state.anchor) if s.offset > 0 { diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go index 0fec157f2..4d74167ca 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens_test.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -257,6 +257,41 @@ func TestStopWaitsForTheTurnsFinalRecord(t *testing.T) { wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) } +// Qwen rewrites its log by renaming a new file over it, for example when +// messages are deleted. A log replaced while Stop waits is read again from the +// start, so the final record is found even when it lies before the old +// file's read position. +func TestStopRereadsALogReplacedWhileWaiting(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "go"}) + user := nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") + call := nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + result := nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.5Z", "") + s.writeNative(user + call) + s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) + s.writeNative(result) + + replaced := make(chan error, 1) + go func() { + time.Sleep(100 * time.Millisecond) + next := filepath.Join(filepath.Dir(s.nativePath), ".replacement.jsonl.tmp") + content := call + result + nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0)) + if err := os.WriteFile(next, []byte(content), 0o600); err != nil { + replaced <- err + return + } + replaced <- os.Rename(next, s.nativePath) + }() + s.hook(HookNameStop, "2026-11-06T10:00:04.1Z", nil) + if err := <-replaced; err != nil { + t.Fatal(err) + } + + wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) +} + // A record Qwen is still writing has no newline yet. It must not be copied // half-read or skipped: the next sync copies it whole. func TestPartialNativeLineIsCopiedOnceComplete(t *testing.T) { @@ -440,6 +475,30 @@ func TestSidecarFromAnOlderAdapterStartsAtTheUpgrade(t *testing.T) { wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) } +// An adapter upgraded in the middle of a turn finds the turn's prompt in the +// older adapter's records, so the calls made before its first hook are still +// copied, and the history before that prompt is not. +func TestUpgradeInTheMiddleOfATurnKeepsThatTurn(t *testing.T) { + s := newQwenSession(t) + older := `{"v":1,"agent":"qwen","event":"SessionStart","session_id":"` + s.id + `","ts":"2026-11-01T09:00:00Z"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-01T09:00:01Z","prompt":"first"}` + "\n" + + `{"v":1,"agent":"qwen","event":"Stop","session_id":"` + s.id + `","ts":"2026-11-01T09:00:09Z"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-06T10:00:01Z","prompt":"second"}` + "\n" + if err := appendFile(s.agent.sidecarPath(s.id), older); err != nil { + t.Fatal(err) + } + s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:05Z", openAIUsage(5000, 500, 0, 0))) + s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + + turn := 3 // the line of the second prompt, where Entire's turn starts + s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) + s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:04.1Z", nil) + + wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) +} + // Records /branch copied from a parent session, and subagent records, were // counted where their API calls were made. func TestForkedAndSidechainRecordsAreNotCopied(t *testing.T) { From 44c5391dcc9595328ab1a68061f53a6fae18fcca Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Fri, 6 Nov 2026 22:53:46 +0000 Subject: [PATCH 5/7] fix(qwen): wait at Stop for the answer to the turn's last prompt 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. --- agents/entire-agent-qwen/AGENT.md | 4 +- agents/entire-agent-qwen/README.md | 8 +- .../entire-agent-qwen/internal/qwen/tokens.go | 183 ++++++++++++----- .../internal/qwen/tokens_test.go | 193 ++++++++++++++---- 4 files changed, 286 insertions(+), 102 deletions(-) diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index c1d621a88..529eaf528 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -90,9 +90,9 @@ their usage to the same shape. | Step | Behavior | |---|---| | Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | -| Wait | At `Stop`, while the log ends with a `user` or `tool_result` record (ignoring `system` records) or a line still being written, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight. A log replaced (Qwen rewrites it by renaming a new file over it) or cut shorter during the wait is read again from the start | +| Wait | At `Stop`, until the log holds the answer to the turn's last prompt, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight. The answer is the log's last record other than `system` records, when that 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). A line still being written is waited for too. A log replaced (Qwen rewrites it by renaming a new file over it) or cut shorter during the wait is read again from the start | | Resume | A copy finds the last `AssistantUsage` record for the log by reading the sidecar backwards from its end, and starts after that record's line while the line still holds the same record. Otherwise it rereads the log (Qwen can rewrite it, e.g. when prompts are deleted) and copies its calls again; the count keeps one copy of each | -| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started. Until such a sidecar has a `v: 2` record, its last prompt is the cutoff, so an upgrade in the middle of a turn still counts that turn | +| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started. Until such a sidecar has a `v: 2` record, the last prompt typed in it is the cutoff (not the empty one before a tool round's next call), so an upgrade in the middle of a turn still counts that turn | | Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | Qwen writes its log through a queue that no hook waits for, so an API call can diff --git a/agents/entire-agent-qwen/README.md b/agents/entire-agent-qwen/README.md index 00ec366a0..689102bf3 100644 --- a/agents/entire-agent-qwen/README.md +++ b/agents/entire-agent-qwen/README.md @@ -25,10 +25,10 @@ still reports its tokens on a machine without the chat log. Qwen writes its log through a queue and fires `Stop` without waiting for it, so a turn's last API call can still be on its way when the `Stop` hook reads -the log. While the log ends with a prompt or tool result the model has not -answered yet, `Stop` waits up to a second for that call. One that arrives later -still is copied at the next hook and counted with the next turn or checkpoint; -totals are unaffected. A session that an older adapter started is counted from +the log. Until the log holds the model's answer to the turn's last prompt, +`Stop` waits up to a second for it. A call that arrives later still is copied +at the next hook and counted with the next turn or checkpoint; totals are +unaffected. A session that an older adapter started is counted from the first hook after the upgrade. Calls Qwen does not record in the session's chat log, such as subagents and background helpers like its auto-memory extractor, are not counted. Cache writes are not reported separately: for Anthropic models Qwen diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go index ee617a9f9..de886406f 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -31,8 +31,8 @@ import ( // // Qwen queues its log writes and fires Stop without waiting for the queue, so // a turn's last API call can still be on its way when the Stop hook reads the -// log. Stop therefore waits, up to finalRecordWait, while the log ends with a -// record the model has yet to answer. A call that arrives later still is +// log. Stop therefore waits, up to finalRecordWait, until the log holds the +// model's answer to the turn's last prompt. A call that arrives later still is // copied at the next sync and counted with the turn and the checkpoint in // which it was copied: totals stay right, but one turn's share can move to the // next. @@ -40,16 +40,16 @@ import ( const eventAssistantUsage = "AssistantUsage" // eventUserPromptSubmit is the event of the sidecar record a turn starts with. +// Qwen 0.26.9 also fires UserPromptSubmit, with an empty prompt, before the +// call that follows a tool round, so each API call of a turn follows one. const eventUserPromptSubmit = "UserPromptSubmit" -// Types of chat-log records. Assistant records carry usage; a user or -// tool_result record is answered by one; system records (telemetry, titles, +// Types of chat-log records. Assistant records carry usage; user and +// tool_result records come between them; system records (telemetry, titles, // compression) come and go around them. const ( - nativeTypeAssistant = "assistant" - nativeTypeUser = "user" - nativeTypeToolResult = "tool_result" - nativeTypeSystem = "system" + nativeTypeAssistant = "assistant" + nativeTypeSystem = "system" ) // finalRecordWait bounds how long Stop waits for the turn's final assistant @@ -72,8 +72,11 @@ const maxNativeLine = 64 * 1024 * 1024 var usageMetadataKey = []byte(`"usageMetadata"`) // nativeUUIDKey prefilters sidecar lines the same way for AssistantUsage -// records. -var nativeUUIDKey = []byte(`"native_uuid"`) +// records, and promptEventKey for UserPromptSubmit records. +var ( + nativeUUIDKey = []byte(`"native_uuid"`) + promptEventKey = []byte(`"` + eventUserPromptSubmit + `"`) +) // syncsUsage reports whether a hook copies new native usage into the sidecar: // PreToolUse, so a commit a tool makes mid-turn sees the API calls before it, @@ -100,6 +103,28 @@ type nativeChatRecord struct { // ForkedFrom marks a record /branch copied from the parent session: its // API call was made, and counted, there. ForkedFrom *struct{} `json:"forkedFrom"` + // Message is kept raw: only a Stop waiting for the turn's answer reads + // it, and a shape it does not expect must not cost the record its usage. + Message json.RawMessage `json:"message"` +} + +// callsTools reports whether an assistant record asks for a tool call, after +// which Qwen sends the results back and the turn goes on. +func (r nativeChatRecord) callsTools() bool { + var message struct { + Parts []struct { + FunctionCall json.RawMessage `json:"functionCall"` + } `json:"parts"` + } + if json.Unmarshal(r.Message, &message) != nil { + return false + } + for _, part := range message.Parts { + if len(part.FunctionCall) > 0 && !bytes.Equal(part.FunctionCall, []byte("null")) { + return true + } + } + return false } // usageSyncState is what the sidecar already records about native usage. @@ -115,9 +140,14 @@ type usageSyncState struct { // cleaned out of the temp directory, or of a session whose sidecar an // older adapter started, which would otherwise all land in the first turn // after the upgrade. Until a sidecar an older adapter started has such a - // record, the floor is its last prompt, so an upgrade in the middle of a - // turn still copies that turn's calls. + // record, the floor is the last prompt typed in it (not an empty one + // before a tool round's next call), so an upgrade in the middle of a turn + // still copies that turn's calls. floor time.Time + // prompt is the time of the last UserPromptSubmit record after the + // anchor, zero when there is none: the API call that answers it has not + // been copied yet. + prompt time.Time } // syncNativeUsage copies into the sidecar the usage of assistant records the @@ -147,10 +177,10 @@ func (a *Agent) syncNativeUsage(hookName string, raw qwenHookInputRaw) error { return errors.Join(err, appendSidecarRecords(sidecarPath, scan.records)) } -// readUsageSyncState reads the floor from the start of the sidecar and the -// anchor for nativePath from its end, so a hook reads what was appended since -// the last copy, not the whole session. An empty or missing sidecar takes its -// floor from the hook now running. +// readUsageSyncState reads the floor from the start of the sidecar, and the +// anchor for nativePath and the last prompt after it from its end, so a hook +// reads what was appended since the last copy, not the whole session. An empty +// or missing sidecar takes its floor from the hook now running. func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyncState, error) { state := usageSyncState{floor: parseTimestamp(hookTimestamp)} f, err := os.Open(sidecarPath) @@ -172,9 +202,10 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn break } var head struct { - V int `json:"v"` - Event string `json:"event"` - TS string `json:"ts"` + V int `json:"v"` + Event string `json:"event"` + TS string `json:"ts"` + Prompt string `json:"prompt"` } if json.Unmarshal(line, &head) != nil { continue @@ -183,23 +214,26 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn state.floor = parseTimestamp(head.TS) break } - if at := parseTimestamp(head.TS); head.Event == eventUserPromptSubmit && !at.IsZero() { + at := parseTimestamp(head.TS) + if head.Event == eventUserPromptSubmit && strings.TrimSpace(head.Prompt) != "" && !at.IsZero() { state.floor = at } } - state.anchor, err = lastUsageRecord(f, nativePath) + state.anchor, state.prompt, err = lastUsageRecord(f, nativePath) return state, err } // lastUsageRecord returns the last AssistantUsage record in the sidecar that -// was copied from nativePath, reading the sidecar backwards from its end. A -// trailing line without its newline is still being written and is skipped. -// AssistantUsage lines are small, so a line longer than one block is skipped -// without being held in memory. -func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, error) { +// was copied from nativePath, and the time of the last UserPromptSubmit record +// after it, reading the sidecar backwards from its end. A trailing line +// without its newline is still being written and is skipped. AssistantUsage +// lines are small, so a line longer than one block is skipped without being +// held in memory; a prompt that long goes unseen, which leaves the Stop wait +// to the tool-call check alone. +func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, error) { info, err := f.Stat() if err != nil { - return nil, err + return nil, time.Time{}, err } const block = 64 * 1024 var ( @@ -207,13 +241,23 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, error) { carry []byte // the end of a line whose start lies before pos trailing = true // the bytes after the last newline are no line yet long bool // the line in carry is longer than a block + prompt time.Time ) + // visit returns the record when line is the anchor, and otherwise notes + // the last prompt seen on the way to it. + visit := func(line []byte) *sidecarRecord { + record := usageRecordFrom(line, nativePath) + if record == nil && prompt.IsZero() { + prompt = promptTime(line) + } + return record + } for pos > 0 { n := min(int64(block), pos) pos -= n data := make([]byte, n, n+int64(len(carry))) if _, err := f.ReadAt(data, pos); err != nil { - return nil, err + return nil, time.Time{}, err } data = append(data, carry...) for { @@ -227,8 +271,8 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, error) { trailing, long = false, false continue } - if record := usageRecordFrom(line, nativePath); record != nil { - return record, nil + if record := visit(line); record != nil { + return record, prompt, nil } } carry = data @@ -237,9 +281,26 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, error) { } } if trailing || long { - return nil, nil + return nil, prompt, nil } - return usageRecordFrom(carry, nativePath), nil + record := visit(carry) + return record, prompt, nil +} + +// promptTime returns the time of a sidecar line that is a UserPromptSubmit +// record, or zero. +func promptTime(line []byte) time.Time { + if !bytes.Contains(line, promptEventKey) { + return time.Time{} + } + var head struct { + Event string `json:"event"` + TS string `json:"ts"` + } + if json.Unmarshal(line, &head) != nil || head.Event != eventUserPromptSubmit { + return time.Time{} + } + return parseTimestamp(head.TS) } // usageRecordFrom decodes a sidecar line that is an AssistantUsage record @@ -270,19 +331,20 @@ type nativeScan struct { // line; -1 until the first read places it. offset int64 // waits is set when the caller waits for the turn's final record: every - // line is then decoded so that last is known. + // line is then decoded so that answered is known. waits bool // info is the log as the last read found it. info os.FileInfo - // last is the type of the last record read other than a system record. - last string - records []sidecarRecord + // answered is set while the last record read other than a system record + // is the model's answer to the turn's last prompt. + answered bool + records []sidecarRecord } // next reads what the native log gained since the last read. When the scan // waits, it reports whether the turn's final record may still be on its way: // the log ends with a line still being written, which is left for a later -// read, or with a user or tool_result record the model has yet to answer. +// read, or with anything other than the answer to the turn's last prompt. func (s *nativeScan) next() (bool, error) { f, err := os.Open(s.path) if errors.Is(err, os.ErrNotExist) { @@ -302,14 +364,13 @@ func (s *nativeScan) next() (bool, error) { // A log replaced since the last read (Qwen rewrites it by renaming a new // file over it) or cut shorter is read again from the start. if s.info != nil && (!os.SameFile(s.info, info) || info.Size() < s.offset) { - s.offset, s.last = -1, "" + s.offset, s.answered = -1, false } s.info = info if s.offset < 0 { - s.offset = resumeOffset(f, s.state.anchor) - if s.offset > 0 { - s.last = nativeTypeAssistant - } + var anchored *nativeChatRecord + s.offset, anchored = resumeOffset(f, s.state.anchor) + s.answered = anchored != nil && s.state.answers(*anchored) } if _, err := f.Seek(s.offset, io.SeekStart); err != nil { return false, err @@ -321,7 +382,7 @@ func (s *nativeScan) next() (bool, error) { return false, err } if !complete { - return s.waits && (n > 0 || s.last == nativeTypeUser || s.last == nativeTypeToolResult), nil + return s.waits && (n > 0 || !s.answered), nil } lineStart := s.offset s.offset += n @@ -333,7 +394,7 @@ func (s *nativeScan) next() (bool, error) { continue } if native.Type != nativeTypeSystem { - s.last = native.Type + s.answered = s.state.answers(native) } if !s.state.wants(native) { continue @@ -364,26 +425,36 @@ func (s usageSyncState) wants(record nativeChatRecord) bool { return s.floor.IsZero() || at.IsZero() || !at.Before(s.floor) } -// resumeOffset returns the offset just past the anchor's line when that line -// still holds the anchored record, and 0 (read the whole log) otherwise. -func resumeOffset(f *os.File, anchor *sidecarRecord) int64 { +// answers reports whether a native record is the model's answer to the turn's +// last prompt: an assistant record that calls no tool, so the turn ends with +// it, from no earlier than that prompt. +func (s usageSyncState) answers(record nativeChatRecord) bool { + if record.Type != nativeTypeAssistant || record.callsTools() { + return false + } + at := parseTimestamp(record.Timestamp) + return s.prompt.IsZero() || at.IsZero() || !at.Before(s.prompt) +} + +// resumeOffset returns the offset just past the anchor's line, and the record +// on it, when that line still holds the anchored record, and 0 (read the +// whole log) otherwise. +func resumeOffset(f *os.File, anchor *sidecarRecord) (int64, *nativeChatRecord) { if anchor == nil || anchor.NativeUUID == "" || anchor.NativeOffset < 0 { - return 0 + return 0, nil } if _, err := f.Seek(anchor.NativeOffset, io.SeekStart); err != nil { - return 0 + return 0, nil } line, n, complete, err := readLine(bufio.NewReader(f), maxNativeLine) if err != nil || !complete { - return 0 - } - var head struct { - UUID string `json:"uuid"` + return 0, nil } - if json.Unmarshal(line, &head) != nil || head.UUID != anchor.NativeUUID { - return 0 + var record nativeChatRecord + if json.Unmarshal(line, &record) != nil || record.UUID != anchor.NativeUUID { + return 0, nil } - return anchor.NativeOffset + n + return anchor.NativeOffset + n, &record } // readLine reads one newline-terminated line and reports how many bytes it diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go index 4d74167ca..9bfc7c243 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens_test.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -134,6 +134,13 @@ func nativeLine(uuid, recordType, timestamp, usage string) string { return record + "}\n" } +// toolCallLine renders an assistant record whose reply asks for a tool, as +// Qwen records a call the turn goes on from. +func toolCallLine(uuid, timestamp, usage string) string { + return strings.Replace(nativeLine(uuid, "assistant", timestamp, usage), `"parts":[{"text":"done"}]`, + `"parts":[{"functionCall":{"id":"call_1","name":"write_file","args":{"file_path":"hello.txt","content":"hello"}}}]`, 1) +} + // openAIUsage is what Qwen records from an OpenAI-compatible provider: // prompt_tokens includes the cached share and completion_tokens the reasoning. func openAIUsage(prompt, completion, cached, reasoning int) string { @@ -158,7 +165,7 @@ func TestTurnTokenUsageComesFromNativeChatLog(t *testing.T) { turnStart := s.position() s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01.000Z", map[string]any{"prompt": "create hello.txt"}) s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.100Z", "")) - s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:03.000Z", openAIUsage(1200, 80, 1000, 20))) + s.writeNative(toolCallLine("a-1", "2026-11-06T10:00:03.000Z", openAIUsage(1200, 80, 1000, 20))) s.hook(HookNamePreToolUse, "2026-11-06T10:00:03.100Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1", "tool_input": map[string]any{"file_path": "hello.txt"}}) s.hook(HookNamePostToolUse, "2026-11-06T10:00:03.200Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1", "tool_input": map[string]any{"file_path": "hello.txt"}, "tool_response": "ok"}) s.writeNative(nativeLine("t-1", "tool_result", "2026-11-06T10:00:03.300Z", "")) @@ -199,11 +206,11 @@ func TestTurnTokenUsageComesFromNativeChatLog(t *testing.T) { } // Qwen fires Stop without waiting for its write queue, so the turn's final -// record can still be on its way. While the log ends with a record the model -// has yet to answer, Stop waits for it; the next test covers that. Here the -// log already ends with an assistant record, so Stop has nothing to wait for, -// and the late call is copied at the next sync and counted with the next turn. -// The session total is unaffected. +// record can still be on its way. Until the log holds the answer to the +// turn's last prompt, Stop waits for it; the next tests cover that. Here the +// log already holds an answer, so Stop has nothing to wait for, as when a +// final record lands after the wait: the late call is copied at the next sync +// and counted with the next turn. The session total is unaffected. func TestUsageWrittenAfterStopIsCountedWithNextTurn(t *testing.T) { s := newQwenSession(t) s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) @@ -235,7 +242,7 @@ func TestStopWaitsForTheTurnsFinalRecord(t *testing.T) { turn := s.position() s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "go"}) s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "")) - s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.writeNative(toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) s.writeNative(nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.5Z", "") + nativeLine("sys-1", "system", "2026-11-06T10:00:02.6Z", "")) @@ -257,6 +264,78 @@ func TestStopWaitsForTheTurnsFinalRecord(t *testing.T) { wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) } +// The log can still end with an earlier assistant record when Stop fires: the +// turn's tool call, or the answer of the turn before, when even the records +// queued before the final one are not on disk yet. That record is no answer +// to the turn's last prompt, so Stop waits for the final record. +func TestStopWaitsUntilTheTurnsLastPromptIsAnswered(t *testing.T) { + // toolRound runs a turn to its tool call, copied at PreToolUse, and leaves + // the tool result and the final record on their way. + toolRound := func(s *qwenSession, continued bool) (int, string) { + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "go"}) + s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") + + toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) + if continued { + // Qwen's empty prompt before the call that follows the tool round. + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:03Z", map[string]any{"prompt": ""}) + } + return turn, nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.9Z", "") + + nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0)) + } + for _, tc := range []struct { + name string + // before runs the turn up to its Stop and returns where the turn + // starts and the records still on their way when Stop fires. + before func(s *qwenSession) (int, string) + want protocol.TokenUsageResponse + }{ + { + name: "tool call, then the tool round's prompt", + before: func(s *qwenSession) (int, string) { return toolRound(s, true) }, + want: protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}, + }, + { + name: "tool call with no prompt after it", + before: func(s *qwenSession) (int, string) { return toolRound(s, false) }, + want: protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}, + }, + { + name: "the previous turn's answer", + before: func(s *qwenSession) (int, string) { + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "one"}) + s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") + + nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:02.1Z", nil) + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:01:00Z", map[string]any{"prompt": "two"}) + return turn, nativeLine("u-2", "user", "2026-11-06T10:01:00.1Z", "") + + nativeLine("a-2", "assistant", "2026-11-06T10:01:02Z", openAIUsage(200, 20, 0, 0)) + }, + want: protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 20, APICallCount: 1}, + }, + } { + t.Run(tc.name, func(t *testing.T) { + s := newQwenSession(t) + s.hook(HookNameSessionStart, "2026-11-06T10:00:00Z", nil) + turn, late := tc.before(s) + written := make(chan error, 1) + go func() { + time.Sleep(100 * time.Millisecond) + written <- appendFile(s.nativePath, late) + }() + s.hook(HookNameStop, "2026-11-06T10:02:00Z", nil) + if err := <-written; err != nil { + t.Fatal(err) + } + + wantUsage(t, s.tokens(turn), tc.want) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) + }) + } +} + // Qwen rewrites its log by renaming a new file over it, for example when // messages are deleted. A log replaced while Stop waits is read again from the // start, so the final record is found even when it lies before the old @@ -267,7 +346,7 @@ func TestStopRereadsALogReplacedWhileWaiting(t *testing.T) { turn := s.position() s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "go"}) user := nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") - call := nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + call := toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) result := nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.5Z", "") s.writeNative(user + call) s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) @@ -339,7 +418,7 @@ func TestRewrittenNativeLogIsNotCountedTwice(t *testing.T) { t.Fatal(err) } defer func() { _ = f.Close() }() - if got := resumeOffset(f, state.anchor); state.anchor == nil || state.anchor.NativeUUID != "a-3" || got != int64(len(rewritten)) { + if got, _ := resumeOffset(f, state.anchor); state.anchor == nil || state.anchor.NativeUUID != "a-3" || got != int64(len(rewritten)) { t.Fatalf("anchor = %+v, resumeOffset = %d; want a-3, %d", state.anchor, got, len(rewritten)) } s.writeNative(nativeLine("a-4", "assistant", "2026-11-06T10:00:07Z", openAIUsage(400, 40, 0, 0))) @@ -363,15 +442,22 @@ func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { return string(data) + "\n" } long := `{"v":2,"agent":"qwen","event":"PostToolUse","tool_response":"` + strings.Repeat("x", 200*1024) + `"}` + "\n" + prompt := func(ts string) string { + return `{"v":2,"agent":"qwen","event":"UserPromptSubmit","ts":"` + ts + `","prompt":"go"}` + "\n" + } + // A tool payload that mentions the event is no prompt. + mention := `{"v":2,"agent":"qwen","event":"PostToolUse","ts":"2026-11-06T11:00:00Z","tool_response":{"event":"UserPromptSubmit"}}` + "\n" for _, tc := range []struct { - name, sidecar, want string + name, sidecar, want, wantPrompt string }{ - {"first line", usage("a-1", "/n.jsonl"), "a-1"}, - {"last of several", usage("a-1", "/n.jsonl") + usage("a-2", "/n.jsonl") + long, "a-2"}, - {"past long lines and other logs", usage("a-1", "/n.jsonl") + long + usage("b-1", "/other.jsonl") + long, "a-1"}, - {"partial trailing line", usage("a-1", "/n.jsonl") + strings.TrimSuffix(usage("a-2", "/n.jsonl"), "\n"), "a-1"}, - {"none", long + usage("b-1", "/other.jsonl"), ""}, - {"empty", "", ""}, + {"first line", usage("a-1", "/n.jsonl"), "a-1", ""}, + {"last of several", usage("a-1", "/n.jsonl") + usage("a-2", "/n.jsonl") + long, "a-2", ""}, + {"past long lines and other logs", usage("a-1", "/n.jsonl") + long + usage("b-1", "/other.jsonl") + long, "a-1", ""}, + {"partial trailing line", usage("a-1", "/n.jsonl") + strings.TrimSuffix(usage("a-2", "/n.jsonl"), "\n"), "a-1", ""}, + {"last prompt after the anchor", usage("a-1", "/n.jsonl") + prompt("2026-11-06T10:00:01Z") + long + prompt("2026-11-06T10:00:02Z") + mention, "a-1", "2026-11-06T10:00:02Z"}, + {"prompt before the anchor", prompt("2026-11-06T10:00:01Z") + usage("a-1", "/n.jsonl") + mention, "a-1", ""}, + {"none", prompt("2026-11-06T10:00:01Z") + long + usage("b-1", "/other.jsonl"), "", "2026-11-06T10:00:01Z"}, + {"empty", "", "", ""}, } { t.Run(tc.name, func(t *testing.T) { t.Parallel() @@ -384,7 +470,7 @@ func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { t.Fatal(err) } defer func() { _ = f.Close() }() - record, err := lastUsageRecord(f, "/n.jsonl") + record, prompt, err := lastUsageRecord(f, "/n.jsonl") if err != nil { t.Fatal(err) } @@ -392,8 +478,8 @@ func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { if record != nil { got = record.NativeUUID } - if got != tc.want { - t.Fatalf("last usage record = %q, want %q", got, tc.want) + if want := parseTimestamp(tc.wantPrompt); got != tc.want || !prompt.Equal(want) { + t.Fatalf("last usage record = %q, prompt %v; want %q, %v", got, prompt, tc.want, want) } }) } @@ -421,13 +507,13 @@ func TestResumeOffsetChecksTheAnchoredRecord(t *testing.T) { t.Fatal(err) } defer func() { _ = f.Close() }() - if got, want := resumeOffset(f, state.anchor), int64(len(first)+len(anchored)); got != want { - t.Fatalf("resumeOffset = %d, want %d", got, want) + if got, record := resumeOffset(f, state.anchor); got != int64(len(first)+len(anchored)) || record == nil || record.UUID != "a-1" { + t.Fatalf("resumeOffset = %d, %+v; want %d, a-1", got, record, len(first)+len(anchored)) } moved := *state.anchor moved.NativeUUID = "a-other" - if got := resumeOffset(f, &moved); got != 0 { - t.Fatalf("resumeOffset for a line holding another record = %d, want 0", got) + if got, record := resumeOffset(f, &moved); got != 0 || record != nil { + t.Fatalf("resumeOffset for a line holding another record = %d, %+v; want 0, nil", got, record) } } @@ -477,26 +563,53 @@ func TestSidecarFromAnOlderAdapterStartsAtTheUpgrade(t *testing.T) { // An adapter upgraded in the middle of a turn finds the turn's prompt in the // older adapter's records, so the calls made before its first hook are still -// copied, and the history before that prompt is not. +// copied, and the history before that prompt is not. The empty prompt Qwen +// fires before the call that follows a tool round is no turn's start. func TestUpgradeInTheMiddleOfATurnKeepsThatTurn(t *testing.T) { - s := newQwenSession(t) - older := `{"v":1,"agent":"qwen","event":"SessionStart","session_id":"` + s.id + `","ts":"2026-11-01T09:00:00Z"}` + "\n" + - `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-01T09:00:01Z","prompt":"first"}` + "\n" + - `{"v":1,"agent":"qwen","event":"Stop","session_id":"` + s.id + `","ts":"2026-11-01T09:00:09Z"}` + "\n" + - `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-06T10:00:01Z","prompt":"second"}` + "\n" - if err := appendFile(s.agent.sidecarPath(s.id), older); err != nil { - t.Fatal(err) - } - s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:05Z", openAIUsage(5000, 500, 0, 0))) - s.writeNative(nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + for _, tc := range []struct { + name string + // tool is what the older adapter recorded of the tool round; hooks + // runs what the upgraded adapter sees of it. + tool string + hooks func(s *qwenSession) + }{ + { + name: "before the tool call", + hooks: func(s *qwenSession) { + s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) + }, + }, + { + name: "after the tool round", + tool: `{"v":1,"agent":"qwen","event":"PreToolUse","ts":"2026-11-06T10:00:02.1Z","tool_name":"write_file"}` + "\n" + + `{"v":1,"agent":"qwen","event":"PostToolUse","ts":"2026-11-06T10:00:02.8Z","tool_name":"write_file"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","ts":"2026-11-06T10:00:03Z"}` + "\n", + hooks: func(*qwenSession) {}, + }, + } { + t.Run(tc.name, func(t *testing.T) { + s := newQwenSession(t) + older := `{"v":1,"agent":"qwen","event":"SessionStart","session_id":"` + s.id + `","ts":"2026-11-01T09:00:00Z"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-01T09:00:01Z","prompt":"first"}` + "\n" + + `{"v":1,"agent":"qwen","event":"Stop","session_id":"` + s.id + `","ts":"2026-11-01T09:00:09Z"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-06T10:00:01Z","prompt":"second"}` + "\n" + + tc.tool + if err := appendFile(s.agent.sidecarPath(s.id), older); err != nil { + t.Fatal(err) + } + s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:05Z", openAIUsage(5000, 500, 0, 0))) + s.writeNative(toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) - turn := 3 // the line of the second prompt, where Entire's turn starts - s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) - s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0))) - s.hook(HookNameStop, "2026-11-06T10:00:04.1Z", nil) + turn := 3 // the line of the second prompt, where Entire's turn starts + tc.hooks(s) + s.writeNative(nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.5Z", "")) + s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:04.1Z", nil) - wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) - wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) + wantUsage(t, s.tokens(turn), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}) + }) + } } // Records /branch copied from a parent session, and subagent records, were From b2d7ef4e46f2779a005de346fb4a2b661fee52a3 Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Fri, 6 Nov 2026 23:00:55 +0000 Subject: [PATCH 6/7] fix(qwen): count from an open turn's prompt after an upgrade, read long 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. --- agents/entire-agent-qwen/AGENT.md | 5 +- agents/entire-agent-qwen/README.md | 3 +- .../entire-agent-qwen/internal/qwen/hooks.go | 5 +- .../entire-agent-qwen/internal/qwen/tokens.go | 110 ++++++++++++++---- .../internal/qwen/tokens_test.go | 103 +++++++++++++--- 5 files changed, 186 insertions(+), 40 deletions(-) diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index 529eaf528..ca9ee1aef 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -60,7 +60,8 @@ The projection is derived data — `readSidecarRecords` ignores `type` and Records carry `v: 2` since the adapter started copying token usage; `v: 1` records come from an older adapter. The two differ only in that the token -usage copy starts at the first `v: 2` record (see Token Usage). +usage copy starts at the first `v: 2` record, or at the prompt of the turn it +lands in (see Token Usage). | event | projected as | content | |---|---|---| @@ -92,7 +93,7 @@ their usage to the same shape. | Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | | Wait | At `Stop`, until the log holds the answer to the turn's last prompt, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight. The answer is the log's last record other than `system` records, when that 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). A line still being written is waited for too. A log replaced (Qwen rewrites it by renaming a new file over it) or cut shorter during the wait is read again from the start | | Resume | A copy finds the last `AssistantUsage` record for the log by reading the sidecar backwards from its end, and starts after that record's line while the line still holds the same record. Otherwise it rereads the log (Qwen can rewrite it, e.g. when prompts are deleted) and copies its calls again; the count keeps one copy of each | -| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started. Until such a sidecar has a `v: 2` record, the last prompt typed in it is the cutoff (not the empty one before a tool round's next call), so an upgrade in the middle of a turn still counts that turn | +| Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started. 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 | | Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | Qwen writes its log through a queue that no hook waits for, so an API call can diff --git a/agents/entire-agent-qwen/README.md b/agents/entire-agent-qwen/README.md index 689102bf3..c595d63de 100644 --- a/agents/entire-agent-qwen/README.md +++ b/agents/entire-agent-qwen/README.md @@ -29,7 +29,8 @@ the log. Until the log holds the model's answer to the turn's last prompt, `Stop` waits up to a second for it. A call that arrives later still is copied at the next hook and counted with the next turn or checkpoint; totals are unaffected. A session that an older adapter started is counted from -the first hook after the upgrade. Calls Qwen does not record in the session's +the first hook after the upgrade, or from the prompt of a turn still under way +then. Calls Qwen does not record in the session's chat log, such as subagents and background helpers like its auto-memory extractor, are not counted. Cache writes are not reported separately: for Anthropic models Qwen folds them into the prompt count, so they appear as input tokens. diff --git a/agents/entire-agent-qwen/internal/qwen/hooks.go b/agents/entire-agent-qwen/internal/qwen/hooks.go index 2e8072143..620b24d77 100644 --- a/agents/entire-agent-qwen/internal/qwen/hooks.go +++ b/agents/entire-agent-qwen/internal/qwen/hooks.go @@ -195,7 +195,10 @@ func normalizeRawHook(raw *qwenHookInputRaw, hookName string) { raw.SessionID = stubSessionID } if strings.TrimSpace(raw.Timestamp) == "" { - raw.Timestamp = time.Now().UTC().Format(time.RFC3339) + // Sub-second, like Qwen's own timestamps: the Stop wait tells a + // turn's answer from the previous turn's by comparing record times + // with the prompt's (tokens.go). + raw.Timestamp = time.Now().UTC().Format(time.RFC3339Nano) } if strings.TrimSpace(raw.Prompt) == "" { raw.Prompt = raw.UserPrompt diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go index de886406f..48e7c6e5a 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -44,6 +44,14 @@ const eventAssistantUsage = "AssistantUsage" // call that follows a tool round, so each API call of a turn follows one. const eventUserPromptSubmit = "UserPromptSubmit" +// Events of the sidecar records that end a turn or start or end a session. +const ( + eventStop = "Stop" + eventStopFailure = "StopFailure" + eventSessionStart = "SessionStart" + eventSessionEnd = "SessionEnd" +) + // Types of chat-log records. Assistant records carry usage; user and // tool_result records come between them; system records (telemetry, titles, // compression) come and go around them. @@ -60,6 +68,10 @@ const ( finalRecordPoll = 25 * time.Millisecond ) +// promptHead is how much of a sidecar line too long to hold is read for its +// event and ts, which the sidecar writes ahead of the prompt. +const promptHead = 4 * 1024 + // maxNativeLine bounds one line read while syncing usage. A native record can // embed a whole tool result or written file, and a sidecar record a whole tool // input or response, so a line can be very long; a longer one is skipped @@ -139,10 +151,11 @@ type usageSyncState struct { // is not copied: the history of a resumed session whose sidecar was // cleaned out of the temp directory, or of a session whose sidecar an // older adapter started, which would otherwise all land in the first turn - // after the upgrade. Until a sidecar an older adapter started has such a - // record, the floor is the last prompt typed in it (not an empty one - // before a tool round's next call), so an upgrade in the middle of a turn - // still copies that turn's calls. + // after the upgrade. A turn an older adapter's records leave open (a + // typed prompt, not the empty one before a tool round's next call, with + // no end of turn or session after it) moves the floor back to its prompt, + // so an upgrade in the middle of a turn still copies that turn's calls, + // whichever hook the upgraded adapter runs first. floor time.Time // prompt is the time of the last UserPromptSubmit record after the // anchor, zero when there is none: the API call that answers it has not @@ -193,6 +206,7 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn defer func() { _ = f.Close() }() reader := bufio.NewReaderSize(f, 64*1024) + var open time.Time // the prompt of the turn older records leave open for { line, _, complete, err := readLine(reader, maxNativeLine) if err != nil { @@ -210,15 +224,28 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn if json.Unmarshal(line, &head) != nil { continue } + typed := head.Event == eventUserPromptSubmit && strings.TrimSpace(head.Prompt) != "" if head.V >= sidecarVersion { + // A session or turn the upgraded adapter starts closes the turn + // older records left open. + if typed || head.Event == eventSessionStart { + open = time.Time{} + } state.floor = parseTimestamp(head.TS) break } - at := parseTimestamp(head.TS) - if head.Event == eventUserPromptSubmit && strings.TrimSpace(head.Prompt) != "" && !at.IsZero() { - state.floor = at + switch head.Event { + case eventUserPromptSubmit: + if at := parseTimestamp(head.TS); typed && !at.IsZero() { + open = at + } + case eventStop, eventStopFailure, eventSessionStart, eventSessionEnd: + open = time.Time{} } } + if !open.IsZero() { + state.floor = open + } state.anchor, state.prompt, err = lastUsageRecord(f, nativePath) return state, err } @@ -227,9 +254,8 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn // was copied from nativePath, and the time of the last UserPromptSubmit record // after it, reading the sidecar backwards from its end. A trailing line // without its newline is still being written and is skipped. AssistantUsage -// lines are small, so a line longer than one block is skipped without being -// held in memory; a prompt that long goes unseen, which leaves the Stop wait -// to the tool-call check alone. +// lines are small, so a line longer than one block is never held in memory: +// only its first promptHead bytes are read, in case it is a long prompt. func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, error) { info, err := f.Stat() if err != nil { @@ -267,12 +293,18 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, } line := data[i+1:] data = data[:i] - if trailing || long { + switch { + case trailing: trailing, long = false, false - continue - } - if record := visit(line); record != nil { - return record, prompt, nil + case long: + long = false + if prompt.IsZero() { + prompt = longPromptTime(f, pos+int64(i)+1) + } + default: + if record := visit(line); record != nil { + return record, prompt, nil + } } } carry = data @@ -280,27 +312,61 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, carry, long = nil, true } } - if trailing || long { + switch { + case trailing: + return nil, prompt, nil + case long: + if prompt.IsZero() { + prompt = longPromptTime(f, 0) + } return nil, prompt, nil } record := visit(carry) return record, prompt, nil } +// longPromptTime is promptTime for the sidecar line that starts at start and +// is too long to hold, read from its first promptHead bytes. +func longPromptTime(f *os.File, start int64) time.Time { + head := make([]byte, promptHead) + n, err := f.ReadAt(head, start) + if err != nil && !errors.Is(err, io.EOF) { + return time.Time{} + } + return promptTime(head[:n]) +} + // promptTime returns the time of a sidecar line that is a UserPromptSubmit -// record, or zero. +// record, or zero. The line may be cut off anywhere after its event and ts. func promptTime(line []byte) time.Time { if !bytes.Contains(line, promptEventKey) { return time.Time{} } - var head struct { - Event string `json:"event"` - TS string `json:"ts"` + decoder := json.NewDecoder(bytes.NewReader(line)) + if token, err := decoder.Token(); err != nil || token != json.Delim('{') { + return time.Time{} + } + var event, ts string + for (event == "" || ts == "") && decoder.More() { + key, err := decoder.Token() + if err != nil { + break + } + var value json.RawMessage + if decoder.Decode(&value) != nil { + break + } + switch key { + case "event": + _ = json.Unmarshal(value, &event) + case "ts": + _ = json.Unmarshal(value, &ts) + } } - if json.Unmarshal(line, &head) != nil || head.Event != eventUserPromptSubmit { + if event != eventUserPromptSubmit { return time.Time{} } - return parseTimestamp(head.TS) + return parseTimestamp(ts) } // usageRecordFrom decodes a sidecar line that is an AssistantUsage record diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go index 9bfc7c243..e2bf7e267 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens_test.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -284,6 +284,18 @@ func TestStopWaitsUntilTheTurnsLastPromptIsAnswered(t *testing.T) { return turn, nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.9Z", "") + nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0)) } + // nextTurn runs a whole turn, then the next one to its prompt, and leaves + // that prompt's records on their way. + nextTurn := func(s *qwenSession, prompt string) (int, string) { + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "one"}) + s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") + + nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + s.hook(HookNameStop, "2026-11-06T10:00:02.1Z", nil) + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:01:00Z", map[string]any{"prompt": prompt}) + return turn, nativeLine("u-2", "user", "2026-11-06T10:01:00.1Z", "") + + nativeLine("a-2", "assistant", "2026-11-06T10:01:02Z", openAIUsage(200, 20, 0, 0)) + } for _, tc := range []struct { name string // before runs the turn up to its Stop and returns where the turn @@ -302,18 +314,16 @@ func TestStopWaitsUntilTheTurnsLastPromptIsAnswered(t *testing.T) { want: protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}, }, { - name: "the previous turn's answer", - before: func(s *qwenSession) (int, string) { - s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "one"}) - s.writeNative(nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") + - nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) - s.hook(HookNameStop, "2026-11-06T10:00:02.1Z", nil) - turn := s.position() - s.hook(HookNameUserPromptSubmit, "2026-11-06T10:01:00Z", map[string]any{"prompt": "two"}) - return turn, nativeLine("u-2", "user", "2026-11-06T10:01:00.1Z", "") + - nativeLine("a-2", "assistant", "2026-11-06T10:01:02Z", openAIUsage(200, 20, 0, 0)) - }, - want: protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 20, APICallCount: 1}, + name: "the previous turn's answer", + before: func(s *qwenSession) (int, string) { return nextTurn(s, "two") }, + want: protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 20, APICallCount: 1}, + }, + { + // The prompt's sidecar line is longer than the block the anchor + // is read backwards in. + name: "the previous turn's answer, after a long prompt", + before: func(s *qwenSession) (int, string) { return nextTurn(s, strings.Repeat("two ", 50*1024)) }, + want: protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 20, APICallCount: 1}, }, } { t.Run(tc.name, func(t *testing.T) { @@ -336,6 +346,20 @@ func TestStopWaitsUntilTheTurnsLastPromptIsAnswered(t *testing.T) { } } +// A hook payload without a timestamp gets the time the hook ran, as finely as +// Qwen's own timestamps. Rounded down to the second, a prompt's time could +// pass for earlier than the previous turn's answer in the same second, and +// Stop would take that answer for the turn's. +func TestHookWithoutTimestampKeepsSubsecondTime(t *testing.T) { + t.Parallel() + before := time.Now() + var raw qwenHookInputRaw + normalizeRawHook(&raw, HookNameUserPromptSubmit) + if at := parseTimestamp(raw.Timestamp); at.Before(before) { + t.Fatalf("timestamp %q is before the hook ran (%s)", raw.Timestamp, before.UTC().Format(time.RFC3339Nano)) + } +} + // Qwen rewrites its log by renaming a new file over it, for example when // messages are deleted. A log replaced while Stop waits is read again from the // start, so the final record is found even when it lies before the old @@ -445,6 +469,16 @@ func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { prompt := func(ts string) string { return `{"v":2,"agent":"qwen","event":"UserPromptSubmit","ts":"` + ts + `","prompt":"go"}` + "\n" } + longPrompt := func(ts string) string { + data, err := json.Marshal(sidecarRecord{ + V: sidecarVersion, Agent: AgentName, Type: "user", Timestamp: ts, Event: eventUserPromptSubmit, + SessionID: "s", TS: ts, CWD: "/repo", Prompt: strings.Repeat("p", 200*1024), + }) + if err != nil { + t.Fatal(err) + } + return string(data) + "\n" + } // A tool payload that mentions the event is no prompt. mention := `{"v":2,"agent":"qwen","event":"PostToolUse","ts":"2026-11-06T11:00:00Z","tool_response":{"event":"UserPromptSubmit"}}` + "\n" for _, tc := range []struct { @@ -457,6 +491,8 @@ func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { {"last prompt after the anchor", usage("a-1", "/n.jsonl") + prompt("2026-11-06T10:00:01Z") + long + prompt("2026-11-06T10:00:02Z") + mention, "a-1", "2026-11-06T10:00:02Z"}, {"prompt before the anchor", prompt("2026-11-06T10:00:01Z") + usage("a-1", "/n.jsonl") + mention, "a-1", ""}, {"none", prompt("2026-11-06T10:00:01Z") + long + usage("b-1", "/other.jsonl"), "", "2026-11-06T10:00:01Z"}, + {"a prompt longer than a block", usage("a-1", "/n.jsonl") + longPrompt("2026-11-06T10:00:03Z") + long, "a-1", "2026-11-06T10:00:03Z"}, + {"a long prompt on the first line", longPrompt("2026-11-06T10:00:01Z") + usage("b-1", "/other.jsonl"), "", "2026-11-06T10:00:01Z"}, {"empty", "", "", ""}, } { t.Run(tc.name, func(t *testing.T) { @@ -569,9 +605,11 @@ func TestUpgradeInTheMiddleOfATurnKeepsThatTurn(t *testing.T) { for _, tc := range []struct { name string // tool is what the older adapter recorded of the tool round; hooks - // runs what the upgraded adapter sees of it. + // runs what the upgraded adapter sees of it, before the tool call + // reaches the log when late is set. tool string hooks func(s *qwenSession) + late bool }{ { name: "before the tool call", @@ -579,6 +617,19 @@ func TestUpgradeInTheMiddleOfATurnKeepsThatTurn(t *testing.T) { s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) }, }, + { + name: "before the tool call reached the log", + hooks: func(s *qwenSession) { + s.hook(HookNamePreToolUse, "2026-11-06T10:00:02.1Z", map[string]any{"tool_name": "write_file", "tool_use_id": "call-1"}) + }, + late: true, + }, + { + name: "with a hook that copies nothing first", + hooks: func(s *qwenSession) { + s.hook(HookNameNotification, "2026-11-06T10:00:02.2Z", map[string]any{"message": "Qwen needs your permission", "notification_type": "permission_prompt"}) + }, + }, { name: "after the tool round", tool: `{"v":1,"agent":"qwen","event":"PreToolUse","ts":"2026-11-06T10:00:02.1Z","tool_name":"write_file"}` + "\n" + @@ -598,10 +649,16 @@ func TestUpgradeInTheMiddleOfATurnKeepsThatTurn(t *testing.T) { t.Fatal(err) } s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:05Z", openAIUsage(5000, 500, 0, 0))) - s.writeNative(toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0))) + call := toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + if !tc.late { + s.writeNative(call) + } turn := 3 // the line of the second prompt, where Entire's turn starts tc.hooks(s) + if tc.late { + s.writeNative(call) + } s.writeNative(nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.5Z", "")) s.writeNative(nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0))) s.hook(HookNameStop, "2026-11-06T10:00:04.1Z", nil) @@ -612,6 +669,24 @@ func TestUpgradeInTheMiddleOfATurnKeepsThatTurn(t *testing.T) { } } +// A turn the older adapter saw end was counted, without usage, where it +// ended. When the upgraded adapter's first hook copies usage, that turn's calls +// stay out, so a later checkpoint does not take them. +func TestUpgradeAfterAFinishedTurnLeavesItOut(t *testing.T) { + s := newQwenSession(t) + older := `{"v":1,"agent":"qwen","event":"SessionStart","session_id":"` + s.id + `","ts":"2026-11-01T09:00:00Z"}` + "\n" + + `{"v":1,"agent":"qwen","event":"UserPromptSubmit","session_id":"` + s.id + `","ts":"2026-11-01T09:00:01Z","prompt":"first"}` + "\n" + + `{"v":1,"agent":"qwen","event":"Stop","session_id":"` + s.id + `","ts":"2026-11-01T09:00:09Z"}` + "\n" + if err := appendFile(s.agent.sidecarPath(s.id), older); err != nil { + t.Fatal(err) + } + s.writeNative(nativeLine("old-1", "assistant", "2026-11-01T09:00:05Z", openAIUsage(5000, 500, 0, 0))) + + s.hook(HookNameSessionEnd, "2026-11-06T10:00:00Z", map[string]any{"reason": "exit"}) + + wantUsage(t, s.tokens(0), protocol.TokenUsageResponse{}) +} + // Records /branch copied from a parent session, and subagent records, were // counted where their API calls were made. func TestForkedAndSidechainRecordsAreNotCopied(t *testing.T) { From 3de67be92b41a48a7292f289c5bfe254a2614c1c Mon Sep 17 00:00:00 2001 From: Beehtrix Date: Sat, 7 Nov 2026 01:04:30 +0000 Subject: [PATCH 7/7] fix(qwen): wait at Stop for a log not created yet, compare with the last 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. --- agents/entire-agent-qwen/AGENT.md | 2 +- .../entire-agent-qwen/internal/qwen/tokens.go | 53 +++++++++++-------- .../internal/qwen/tokens_test.go | 34 +++++++++++- 3 files changed, 65 insertions(+), 24 deletions(-) diff --git a/agents/entire-agent-qwen/AGENT.md b/agents/entire-agent-qwen/AGENT.md index ca9ee1aef..b2cd11444 100644 --- a/agents/entire-agent-qwen/AGENT.md +++ b/agents/entire-agent-qwen/AGENT.md @@ -91,7 +91,7 @@ their usage to the same shape. | Step | Behavior | |---|---| | Copy | At `PreToolUse`, `Stop`, `StopFailure`, `SubagentStop` and `SessionEnd`, each native `assistant` record with `usageMetadata` not yet copied becomes an `AssistantUsage` sidecar record holding its usage, `uuid` (`native_uuid`) and the byte offset of its line (`native_offset`) | -| Wait | At `Stop`, until the log holds the answer to the turn's last prompt, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight. The answer is the log's last record other than `system` records, when that 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). A line still being written is waited for too. A log replaced (Qwen rewrites it by renaming a new file over it) or cut shorter during the wait is read again from the start | +| Wait | At `Stop`, until the log holds the answer to the turn's last prompt, the copy polls for up to 1 s: Qwen queues the turn's final assistant record before it fires `Stop`, but the write can still be in flight. The answer is the log's last record other than `system` records, when that is 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 has not created yet. A log replaced (Qwen rewrites it by renaming a new file over it) or cut shorter during the wait is read again from the start | | Resume | A copy finds the last `AssistantUsage` record for the log by reading the sidecar backwards from its end, and starts after that record's line while the line still holds the same record. Otherwise it rereads the log (Qwen can rewrite it, e.g. when prompts are deleted) and copies its calls again; the count keeps one copy of each | | Skip | Lines still being written (no newline yet), records `/branch` copied from a parent session (`forkedFrom`), subagent records (`isSidechain`), and records older than the sidecar's first `v: 2` record: the history of a resumed session whose sidecar was removed from the temp directory, or of a session an older adapter started. 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 | | Count | `calculate-tokens --offset ` sums `AssistantUsage` records from that sidecar line, counting each `native_uuid` once. Input is `promptTokenCount` minus `cachedContentTokenCount`, cache reads are `cachedContentTokenCount`, and output counts reasoning once, decided by `totalTokenCount` as in Qwen's own `outputTokenCount` | diff --git a/agents/entire-agent-qwen/internal/qwen/tokens.go b/agents/entire-agent-qwen/internal/qwen/tokens.go index 48e7c6e5a..3e5289e29 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens.go @@ -157,9 +157,10 @@ type usageSyncState struct { // so an upgrade in the middle of a turn still copies that turn's calls, // whichever hook the upgraded adapter runs first. floor time.Time - // prompt is the time of the last UserPromptSubmit record after the - // anchor, zero when there is none: the API call that answers it has not - // been copied yet. + // prompt is the time of the sidecar's last UserPromptSubmit record, zero + // when there is none. The answer to it is no older. A copy can come after + // the prompt and still be older, when a log rewrite moved the anchored + // line and a sync in the middle of the turn copied the log again. prompt time.Time } @@ -191,7 +192,7 @@ func (a *Agent) syncNativeUsage(hookName string, raw qwenHookInputRaw) error { } // readUsageSyncState reads the floor from the start of the sidecar, and the -// anchor for nativePath and the last prompt after it from its end, so a hook +// anchor for nativePath and the last prompt from its end, so a hook // reads what was appended since the last copy, not the whole session. An empty // or missing sidecar takes its floor from the hook now running. func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyncState, error) { @@ -251,11 +252,12 @@ func readUsageSyncState(sidecarPath, nativePath, hookTimestamp string) (usageSyn } // lastUsageRecord returns the last AssistantUsage record in the sidecar that -// was copied from nativePath, and the time of the last UserPromptSubmit record -// after it, reading the sidecar backwards from its end. A trailing line -// without its newline is still being written and is skipped. AssistantUsage -// lines are small, so a line longer than one block is never held in memory: -// only its first promptHead bytes are read, in case it is a long prompt. +// was copied from nativePath, and the time of the last UserPromptSubmit record, +// reading the sidecar backwards from its end until it has found both. A +// trailing line without its newline is still being written and is skipped. +// AssistantUsage lines are small, so a line longer than one block is never +// held in memory: only its first promptHead bytes are read, in case it is a +// long prompt. func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, error) { info, err := f.Stat() if err != nil { @@ -267,16 +269,20 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, carry []byte // the end of a line whose start lies before pos trailing = true // the bytes after the last newline are no line yet long bool // the line in carry is longer than a block + record *sidecarRecord prompt time.Time ) - // visit returns the record when line is the anchor, and otherwise notes - // the last prompt seen on the way to it. - visit := func(line []byte) *sidecarRecord { - record := usageRecordFrom(line, nativePath) - if record == nil && prompt.IsZero() { + found := func() bool { return record != nil && !prompt.IsZero() } + // visit notes line when it is the anchor or the last prompt. + visit := func(line []byte) { + if record == nil { + if record = usageRecordFrom(line, nativePath); record != nil { + return + } + } + if prompt.IsZero() { prompt = promptTime(line) } - return record } for pos > 0 { n := min(int64(block), pos) @@ -302,9 +308,10 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, prompt = longPromptTime(f, pos+int64(i)+1) } default: - if record := visit(line); record != nil { - return record, prompt, nil - } + visit(line) + } + if found() { + return record, prompt, nil } } carry = data @@ -314,14 +321,13 @@ func lastUsageRecord(f *os.File, nativePath string) (*sidecarRecord, time.Time, } switch { case trailing: - return nil, prompt, nil case long: if prompt.IsZero() { prompt = longPromptTime(f, 0) } - return nil, prompt, nil + default: + visit(carry) } - record := visit(carry) return record, prompt, nil } @@ -414,7 +420,10 @@ type nativeScan struct { func (s *nativeScan) next() (bool, error) { f, err := os.Open(s.path) if errors.Is(err, os.ErrNotExist) { - return false, nil + // Qwen creates the log with the first record it writes, through the + // same queue, so it can still be missing when Stop fires. With chat + // recording off, hooks name no log and no sync runs. + return s.waits, nil } if err != nil { return false, err diff --git a/agents/entire-agent-qwen/internal/qwen/tokens_test.go b/agents/entire-agent-qwen/internal/qwen/tokens_test.go index e2bf7e267..41268a66d 100644 --- a/agents/entire-agent-qwen/internal/qwen/tokens_test.go +++ b/agents/entire-agent-qwen/internal/qwen/tokens_test.go @@ -325,6 +325,36 @@ func TestStopWaitsUntilTheTurnsLastPromptIsAnswered(t *testing.T) { before: func(s *qwenSession) (int, string) { return nextTurn(s, strings.Repeat("two ", 50*1024)) }, want: protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 20, APICallCount: 1}, }, + { + // A rewrite moved the anchored line, so a sync in the middle of + // the turn copies the log again: the previous turn's answer is + // now the last copy, after the turn's prompt. + name: "the previous turn's answer, copied again after a rewrite", + before: func(s *qwenSession) (int, string) { + turn, late := nextTurn(s, "two") + rewritten := nativeLine("a-1", "assistant", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + if err := os.WriteFile(s.nativePath, []byte(rewritten), 0o600); err != nil { + s.t.Fatal(err) + } + s.hook(HookNameSubagentStop, "2026-11-06T10:01:00.5Z", map[string]any{"agent_id": "agent-1", "agent_type": "general-purpose"}) + return turn, late + }, + want: protocol.TokenUsageResponse{InputTokens: 200, OutputTokens: 20, APICallCount: 1}, + }, + { + // Qwen creates the log with its first record, through the same + // queue, so the log itself can still be missing at Stop. + name: "no log yet", + before: func(s *qwenSession) (int, string) { + turn := s.position() + s.hook(HookNameUserPromptSubmit, "2026-11-06T10:00:01Z", map[string]any{"prompt": "go"}) + return turn, nativeLine("u-1", "user", "2026-11-06T10:00:01.1Z", "") + + toolCallLine("a-1", "2026-11-06T10:00:02Z", openAIUsage(100, 10, 0, 0)) + + nativeLine("t-1", "tool_result", "2026-11-06T10:00:02.9Z", "") + + nativeLine("a-2", "assistant", "2026-11-06T10:00:04Z", openAIUsage(200, 20, 0, 0)) + }, + want: protocol.TokenUsageResponse{InputTokens: 300, OutputTokens: 30, APICallCount: 2}, + }, } { t.Run(tc.name, func(t *testing.T) { s := newQwenSession(t) @@ -489,7 +519,9 @@ func TestLastUsageRecordReadsTheSidecarBackwards(t *testing.T) { {"past long lines and other logs", usage("a-1", "/n.jsonl") + long + usage("b-1", "/other.jsonl") + long, "a-1", ""}, {"partial trailing line", usage("a-1", "/n.jsonl") + strings.TrimSuffix(usage("a-2", "/n.jsonl"), "\n"), "a-1", ""}, {"last prompt after the anchor", usage("a-1", "/n.jsonl") + prompt("2026-11-06T10:00:01Z") + long + prompt("2026-11-06T10:00:02Z") + mention, "a-1", "2026-11-06T10:00:02Z"}, - {"prompt before the anchor", prompt("2026-11-06T10:00:01Z") + usage("a-1", "/n.jsonl") + mention, "a-1", ""}, + {"prompt before the anchor", prompt("2026-11-06T10:00:01Z") + usage("a-1", "/n.jsonl") + mention, "a-1", "2026-11-06T10:00:01Z"}, + {"prompt before the anchor, past long lines", longPrompt("2026-11-06T10:00:01Z") + long + usage("b-1", "/other.jsonl") + usage("a-1", "/n.jsonl"), "a-1", "2026-11-06T10:00:01Z"}, + {"no prompt", usage("a-1", "/n.jsonl") + long + mention, "a-1", ""}, {"none", prompt("2026-11-06T10:00:01Z") + long + usage("b-1", "/other.jsonl"), "", "2026-11-06T10:00:01Z"}, {"a prompt longer than a block", usage("a-1", "/n.jsonl") + longPrompt("2026-11-06T10:00:03Z") + long, "a-1", "2026-11-06T10:00:03Z"}, {"a long prompt on the first line", longPrompt("2026-11-06T10:00:01Z") + usage("b-1", "/other.jsonl"), "", "2026-11-06T10:00:01Z"},