Skip to content

Commit 9b56ced

Browse files
fix(transcripts): use queue-operation entries for real background agent timing
Background Task tool_results fire at launch time (~1.5s), not actual completion. Parse queue-operation/enqueue entries which carry the real <task-notification> payload: tool_use_id, completion timestamp, duration_ms, and total_tokens. Backfill AgentSpan.CompletedAt, Duration, and TotalTokens from these notifications after the main scan. Also propagate TotalTokens through ParseAgentTasks → AgentTask (was hardcoded 0 with a comment "not available in transcript data"). Verified against session 927a3b9b: Agent A now 46s, Agent B 108s (was 1.5s).
1 parent a4c202a commit 9b56ced

3 files changed

Lines changed: 95 additions & 1 deletion

File tree

CHANGELOG.md

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,19 @@
22

33
All notable changes to claudewatch are documented here.
44

5+
## [v0.4.2] - 2026-03-01
6+
7+
### Fixed
8+
9+
- **Background agent timing**`AgentSpan.CompletedAt` and `Duration` are now accurate for
10+
background Task agents. Previously, the tool_result for a background task fires at launch
11+
time (~1.5s), not completion, causing SAW wave timings to be severely understated. The fix
12+
parses `queue-operation` / `enqueue` entries in JSONL transcripts, which carry a
13+
`<task-notification>` payload with the real completion timestamp, `<tool-use-id>`, and
14+
`<total_tokens>`. These values are backfilled onto matching spans after the scan. For the
15+
SAW observability session: Agent A now shows 46s (was 1.5s), Agent B 108s (was 1.5s).
16+
`TotalTokens` is now propagated from `AgentSpan` through `ParseAgentTasks` into `AgentTask`.
17+
518
## [v0.4.1] - 2026-03-01
619

720
### Added

internal/claude/agents.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@ func ParseAgentTasks(claudeDir string) ([]AgentTask, error) {
2525
SessionID: span.SessionID,
2626
Status: status,
2727
DurationMs: span.Duration.Milliseconds(),
28-
TotalTokens: 0, // Token counts not available in transcript data.
28+
TotalTokens: span.TotalTokens,
2929
ToolUses: 0, // Tool use counts not available in transcript data.
3030
Background: span.Background,
3131
CreatedAt: span.LaunchedAt.Format("2006-01-02T15:04:05Z"),

internal/claude/transcripts.go

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import (
55
"encoding/json"
66
"os"
77
"path/filepath"
8+
"strconv"
89
"strings"
910
"time"
1011
)
@@ -24,6 +25,7 @@ type AgentSpan struct {
2425
Success bool `json:"success"`
2526
ResultLength int `json:"result_length"`
2627
ToolUseID string `json:"tool_use_id"`
28+
TotalTokens int `json:"total_tokens"`
2729
}
2830

2931
// ParseSessionTranscripts scans all JSONL files under claudeDir/projects/
@@ -97,6 +99,9 @@ func ParseSingleTranscript(path string) ([]AgentSpan, error) {
9799
// Map agentId -> tool_use_id from progress entries.
98100
agentToToolUse := make(map[string]string)
99101

102+
// Real completion data for background agents, keyed by tool_use_id.
103+
taskNotifications := make(map[string]taskNotification)
104+
100105
var spans []AgentSpan
101106

102107
scanner := bufio.NewScanner(f)
@@ -118,6 +123,8 @@ func ParseSingleTranscript(path string) ([]AgentSpan, error) {
118123
processUserEntry(&entry, pending, &spans)
119124
case "progress":
120125
processProgressEntry(&entry, agentToToolUse)
126+
case "queue-operation":
127+
processQueueOperationEntry(&entry, taskNotifications)
121128
}
122129
}
123130

@@ -146,6 +153,24 @@ func ParseSingleTranscript(path string) ([]AgentSpan, error) {
146153
spans = append(spans, p.span)
147154
}
148155

156+
// Backfill real completion times for background agents. Background task
157+
// tool_results fire at launch time, so CompletedAt/Duration from
158+
// processUserEntry is inaccurate. queue-operation/enqueue entries carry
159+
// the real timestamp, duration_ms, and total_tokens.
160+
for i := range spans {
161+
if n, ok := taskNotifications[spans[i].ToolUseID]; ok {
162+
if !n.completedAt.IsZero() {
163+
spans[i].CompletedAt = n.completedAt
164+
if !spans[i].LaunchedAt.IsZero() {
165+
spans[i].Duration = n.completedAt.Sub(spans[i].LaunchedAt)
166+
}
167+
}
168+
if n.totalTokens > 0 {
169+
spans[i].TotalTokens = n.totalTokens
170+
}
171+
}
172+
}
173+
149174
return spans, nil
150175
}
151176

@@ -157,6 +182,8 @@ type TranscriptEntry struct {
157182
Message json.RawMessage `json:"message"`
158183
Data json.RawMessage `json:"data"`
159184
ParentToolUseID string `json:"parentToolUseID"`
185+
Operation string `json:"operation"` // queue-operation: "enqueue" | "dequeue"
186+
Content string `json:"content"` // queue-operation: raw text content
160187
}
161188

162189
// AssistantMessage represents an assistant-role message.
@@ -206,6 +233,15 @@ type pendingTask struct {
206233
span AgentSpan
207234
}
208235

236+
// taskNotification holds real completion data for background agents, extracted
237+
// from queue-operation/enqueue entries. Background task tool_results fire at
238+
// launch time (not completion), so the real CompletedAt and TotalTokens live
239+
// in these notification entries.
240+
type taskNotification struct {
241+
completedAt time.Time
242+
totalTokens int
243+
}
244+
209245
// processAssistantEntry handles assistant-type entries, extracting Task
210246
// launches and TaskStop calls.
211247
func processAssistantEntry(entry *TranscriptEntry, sessionID string, pending map[string]*pendingTask, killedAgentIDs map[string]bool) {
@@ -322,6 +358,51 @@ func processProgressEntry(entry *TranscriptEntry, agentToToolUse map[string]stri
322358
}
323359
}
324360

361+
// processQueueOperationEntry handles queue-operation entries with operation
362+
// "enqueue". These carry real completion data for background Task agents inside
363+
// a <task-notification> XML block in the Content field: tool_use_id, duration_ms,
364+
// and total_tokens. The entry's Timestamp is the true completion time.
365+
func processQueueOperationEntry(entry *TranscriptEntry, notifications map[string]taskNotification) {
366+
if entry.Operation != "enqueue" || entry.Content == "" {
367+
return
368+
}
369+
370+
toolUseID := extractXMLTag(entry.Content, "tool-use-id")
371+
if toolUseID == "" {
372+
return
373+
}
374+
375+
n := taskNotification{
376+
completedAt: ParseTimestamp(entry.Timestamp),
377+
}
378+
379+
if raw := extractXMLTag(entry.Content, "total_tokens"); raw != "" {
380+
if v, err := strconv.Atoi(raw); err == nil {
381+
n.totalTokens = v
382+
}
383+
}
384+
385+
notifications[toolUseID] = n
386+
}
387+
388+
// extractXMLTag returns the text content of the first occurrence of <tag>…</tag>
389+
// in s, or "" if not found. Uses simple string search — no XML parser needed
390+
// since the content format is controlled and well-structured.
391+
func extractXMLTag(s, tag string) string {
392+
open := "<" + tag + ">"
393+
close := "</" + tag + ">"
394+
start := strings.Index(s, open)
395+
if start == -1 {
396+
return ""
397+
}
398+
start += len(open)
399+
end := strings.Index(s[start:], close)
400+
if end == -1 {
401+
return ""
402+
}
403+
return strings.TrimSpace(s[start : start+end])
404+
}
405+
325406
// resultContentLength computes the total text length of a tool_result's content.
326407
func resultContentLength(raw json.RawMessage, text string) int {
327408
if text != "" {

0 commit comments

Comments
 (0)