Skip to content

Commit e672801

Browse files
pyricauclaude
andcommitted
Log every message an agent sends, and which way in it came
An agent's session kept the calls that reached a tool. So a refused `conclude` was a row with no answer under it, and a call to a tool that does not exist, a method this build has never heard of and a line that was not JSON were not rows at all — which is exactly the traffic somebody opens that screen to look at, since the question it gets opened for is usually why nothing happened. Now every line goes down: `tool` is null for the ones that reached no tool and `method` says what arrived instead, `output` is what went back whatever that was, and `error` is separate from `refused` because they are opposite claims — a refusal is the method working and an error is this app failing. `AgentSession.toolCalls` is the subset that got as far as a tool, which is what the eval counts and what the screen's `n call(s)` says, so a command line's handshake per call doesn't read as twice the work. And a line records whether it came in over MCP or from `--agent` at a shell. Told to `McpSession` at construction rather than worked out: past the handshake the two are the same protocol on the same socket, which is the point of them, so the door is the only place that knows. It travels as the last word of the handshake line, and a connection that says nothing is MCP. Leaving `output` null for a refusal was a deliberate call — the refusal was already in `refused`, so writing it twice looked like the same paragraph on disk twice. From outside it looked like a call the app answered and did not log. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
1 parent b74ce5b commit e672801

19 files changed

Lines changed: 964 additions & 134 deletions

File tree

docs/shark-dive-changelog.md

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -85,9 +85,13 @@ uses, without the one for a newly recognized library leak:
8585
what an agent *said* it was doing, and a step taken on an answer that said nothing reads exactly like one
8686
taken on an answer that said everything until you open both. The `▸ {}` under a row is what opens it, and
8787
what was sent names the tool the agent called as well as what it sent to it — `describe_object` beside the
88-
window's own word for it, which is the pair worth having when a step doesn't follow. `agent_log` hands an
89-
agent the same text, so one agent can work out where another went wrong. Kept in `~/.shark-dive/agents/sessions`,
90-
one file per session and the newest hundred kept, so a session outlives the window it was worked in.
88+
window's own word for it, which is the pair worth having when a step doesn't follow. **The full traffic, not
89+
only the calls that worked**: the handshake, a call naming a tool that doesn't exist and a line that wasn't
90+
JSON are rows too, a refusal and an error are under `answered:` as the agent was handed them, and each row
91+
says whether it came in over MCP or from `--agent` at a shell — because what this screen gets opened for is
92+
often why *nothing* happened. `agent_log` hands an agent the same text, so one agent can work out where
93+
another went wrong. Kept in `~/.shark-dive/agents/sessions`, one file per session and the newest hundred
94+
kept, so a session outlives the window it was worked in.
9195
See [Hand it to an agent](shark-dive.md#hand-it-to-an-agent).
9296
***The chain marks the faulty reference**: the one step going from an `Expected` object straight to a
9397
`Stuck` one reads `Holder.activity · faulty reference`, which is the leak itself rather than one of the

docs/shark-dive.md

Lines changed: 38 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -419,10 +419,13 @@ unexplained steps cannot report a root cause, however sure it is, and what it ge
419419
objects to go and read.
420420

421421
**What it did is on the *Agent logs* screen**, one row per agent that has connected to the app. Open a row
422-
and there is every call that agent made, in order and in words — what it did, which object it did it to, and
423-
the sentence it gave for doing it:
422+
and there is everything that agent sent, in order and in words — what each call did, which object it did it
423+
to, and the sentence it gave for doing it:
424424

425425
```
426+
08:23:01 Connected
427+
08:23:01 Sent the notification notifications/initialized
428+
08:23:02 Asked what the tools are
426429
08:23:04 Asked which heap dumps are open
427430
because: Seeing what there is to read before asking anything about it.
428431
08:23:11 Listed the leaks
@@ -454,14 +457,32 @@ rather than on to an answer:
454457
reference: the rules can only name one once something below it is known not to belong. […]
455458
```
456459

460+
**And so is every other line that arrived** — the three at the top of that session are the handshake. A call
461+
naming a tool that doesn't exist, a line that wasn't JSON at all, a read that failed: each is a row, and the
462+
ones nothing could answer say *Failed* rather than *Refused*, which is the opposite claim. A refusal is the
463+
method working; this is Shark Dive not working.
464+
465+
```
466+
08:24:02 Called solve_the_leak 0x12d368b8
467+
because: Trying my luck.
468+
Failed: There is no tool called "solve_the_leak". This server has open_heap_dumps, […]
469+
08:24:09 Sent something this app could not read
470+
Failed: That is not JSON: Unexpected JSON token at offset 0
471+
```
472+
473+
Which is the point of keeping them: what this screen gets opened for is often why *nothing* happened, and a
474+
screen holding only the calls that worked is the one screen that can't answer that. It shows in the shape of a
475+
session — one sent from a shell is a *Connected* per call, `--agent` being a process per call — and the
476+
`n call(s)` above the rows counts the calls rather than the lines.
477+
457478
**And every row unfolds onto the call itself** — the `▸ {}` under a row opens what the agent sent and what it
458479
read back, as the text each of them was, so a step you don't follow is one question rather than a dead end:
459480

460481
```
461482
11:37:31 Looked at 0x12d368b8
462483
because: The one App leak: a MainActivity the app watched. Reading what it is before the chain.
463484
▾ {}
464-
sent:
485+
sent over MCP:
465486
describe_object {
466487
"object": "0x12d368b8",
467488
"reason": "The one App leak: a MainActivity the app watched. Reading what it is
@@ -484,12 +505,19 @@ read back, as the text each of them was, so a step you don't follow is one quest
484505

485506
What it sent is the tool's own name and then the arguments under it, which is the call as the model wrote it:
486507
*Looked at* is this window's word for `describe_object`, and the pair is worth having side by side exactly
487-
when a step doesn't follow from the one before it.
508+
when a step doesn't follow from the one before it. And *over MCP* is which way in it came — a client holding a
509+
connection open, or `--agent` typed at this window — which is the one thing about a call that nothing else on
510+
the screen can tell you, since by the time anything answers one the two are the same protocol on the same
511+
socket.
488512

489513
Whole, never a first line of it: what you open a call for is the part the sentence left out, so an answer cut
490-
to fit would be one where the field that misled the agent is the part that got cut. A refused call shows what
491-
it sent and no answer, its answer having been the refusal already on the row. And a session recorded by an
492-
older Shark Dive says so rather than opening onto a gap.
514+
to fit would be one where the field that misled the agent is the part that got cut. And a session recorded by
515+
an older Shark Dive says so rather than opening onto a gap.
516+
517+
**Including the calls that came to nothing**, which is what this is most worth opening for. A refusal is
518+
under `answered:` as the agent was handed it, as well as in red on the row; so is an error, if a read failed
519+
or this app has a bug; so is the answer to a call naming a tool that doesn't exist. The only row with nothing
520+
under `answered:` is a notification, which is the one kind of message the protocol forbids answering.
493521

494522
The mark is under the row rather than on the verb because a row is a sentence with one link in it, and a fold
495523
over its first words made hovering light up the half that isn't the link.
@@ -500,9 +528,9 @@ one that said everything, until you open both. Select and copy either half — i
500528
whoever handed you the dump, into a diff of two runs.
501529

502530
A session is kept in `~/.shark-dive/agents/sessions`, one file per agent that connected and the newest
503-
hundred kept, a line of JSON per call, each carrying that call's `input` and `output` — so it outlives the
504-
window and can be read by something other than this app. `agent_log` hands an agent the same text, which is
505-
how one agent works out where another went wrong. **And the reads each call cost are in the run's log**, in
531+
hundred kept, a line of JSON per message, each carrying that message's `input` and `output` — so it outlives
532+
the window and can be read by something other than this app. `agent_log` hands an agent the same text, which
533+
is how one agent works out where another went wrong. **And the reads each call cost are in the run's log**, in
506534
`~/.shark-dive/logs`, where the reason it gave is followed by the work it caused:
507535

508536
```

shark/shark-dive/notes/agent-surface.md

Lines changed: 22 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -27,27 +27,33 @@ descriptions that say when to reach for a tool. Re-measure it if the count doubl
2727

2828
## And what reading somebody else's session costs
2929

30-
`agent_log` without a session id is a line per session and cheap. With one, it is now every call of that
31-
session *with what each one sent and read back*, which is the only form that answers "why did it do that
32-
next" — and the numbers are worth knowing before reaching for it. Measured on a five-call session against
33-
`leak_asynctask_o.hprof`, one `list_leaks` twice, a `describe_object`, a `chain_from_gc_root` and a refused
34-
`conclude`:
30+
`agent_log` without a session id is a line per session and cheap. With one, it is now every *message* of that
31+
session with what each one sent and read back, which is the only form that answers "why did it do that
32+
next" — and the numbers are worth knowing before reaching for it. Measured against a packaged run on
33+
`leak_asynctask_o.hprof`: four calls typed at `--agent` (two `list_leaks`, a refused `conclude`, a
34+
`solve_the_leak` that is no tool) and four messages pushed at the socket by hand (a line that is not JSON, a
35+
`resources/list`, a `tools/call` with no name, a notification):
3536

3637
| | Measured |
3738
| --- | --- |
38-
| The five answers as recorded | 7,783 + 7,783 + 11,935 + 5,364 characters, and none for the refusal |
39-
| The five calls as sent | 95 + 81 + 150 + 121 + 163 characters — a rounding error beside the answers |
40-
| The whole `agent_log session=…` answer | 39,615 characters, ≈9,900 tokens |
41-
42-
So **a session is roughly two thousand tokens a call**, and a thirty-call investigation read in full is most
43-
of a small context window. That is the tool being used for what it is for rather than a leak — it is the one
44-
call on this surface whose subject is somebody else's whole investigation — but it means the list form is
45-
what "worth reading before starting" points at, and the session form is what somebody reaches for when an
46-
investigation went wrong and the reasons on their own didn't say where.
39+
| The four tool-call rows | 8,783 + 8,775 + 1,750 + 987 characters — the answer is nearly all of each |
40+
| The four protocol rows | 37,313 characters, of which **32,976 is four `initialize` answers** |
41+
| The whole `agent_log session=…` answer | 57,693 characters, ≈14,400 tokens |
42+
43+
So **a tool call is one to two thousand tokens** and a thirty-call investigation read in full is most of a
44+
small context window. That is the tool being used for what it is for rather than a leak — it is the one call
45+
on this surface whose subject is somebody else's whole investigation.
46+
47+
**The handshakes are the surprise, and they are a command line's.** `initialize` answers with
48+
`AgentMethod.INSTRUCTIONS`, and `--agent` is a process per call, so a session of typed calls carries the
49+
method once per call: 57% of the answer above, handed to a reader that already has the same text in its own
50+
context. An MCP session pays it once. Nothing about that is a reason to record less — a session that keeps
51+
only what reached a tool cannot say why nothing did, which is the whole point of keeping the traffic — but if
52+
`agent_log` needs to be cheaper, **the handshake answers are where to look first**, and the shape to reach
53+
for is a way to ask for one message's exchange rather than a shorter version of every message's.
4754

4855
Nothing truncates it, deliberately: a session cut to fit is one where the answer that misled an agent is the
49-
part that got cut. If this needs to be cheaper the answer is a way to ask for *one call's* exchange, not a
50-
shorter version of every call's.
56+
part that got cut.
5157

5258
## What the command line costs, now that there is one
5359

shark/shark-dive/shark-dive-agent/AGENTS.md

Lines changed: 26 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -91,8 +91,24 @@ same string `toolResult` puts in `content[0].text`, formatted once and then both
9191
down, so that a session can be compared against a client's own transcript character for character. Everything
9292
else on a call is derived, and a derived field is the one thing that is no use when the question is why an
9393
investigation went wrong: a step made on an answer that said nothing reads exactly like a step made on one
94-
that said everything. **A refused call has no `output`**, its answer having been the refusal that is already
95-
in `refused` — writing it twice would put the same paragraph on disk and on the screen twice over.
94+
that said everything.
95+
96+
**`output` is what went back, whatever that was.** A refusal is in it as well as in `refused`, and an error as
97+
well as in `error`, and the two are not the same field said twice: `refused` and `error` are this app's
98+
reading — the method said no, this app could not answer — and `output` is the text the agent was handed. The
99+
first version left `output` null for a refusal on the grounds that the refusal was already written down, and
100+
what that looked like from outside was a call that got no answer at all. **Null on `output` means nothing went
101+
back**, which is a notification and nothing else.
102+
103+
**And a line goes down for every message, not only the ones that reached a tool.** The handshake, a
104+
`tools/list`, a ping, a notification, a method this build has never heard of, a `tools/call` with no name or a
105+
name nothing answers to, and a line that was not JSON: all of them. `tool` is null for the ones that reached
106+
no tool and `method` says what arrived instead, `AgentSession.toolCalls` is the subset that got as far as a
107+
tool, and **that distinction is not cosmetic** — the eval counts calls, and a run scored on lines sent would
108+
have a number that moved with the transport. `AgentSessionCall.over` is which way in a line came, told to
109+
`McpSession` at construction because a command line and an MCP client are indistinguishable from the moment
110+
the handshake is past, which is the point of them. The word travels as the last field of `AgentServer`'s
111+
handshake line, and a connection that says nothing is MCP.
96112

97113
The name is in `input` even though `tool` has it, and that is not an oversight: this field is read as one
98114
thing, and a set of arguments lifted away from what they are arguments *to* is the one form of a call nobody
@@ -114,8 +130,10 @@ answer printed twice.
114130

115131
**The verbs are here rather than in the app.** `verbOfTool` is beside the tool names, so that a screen never
116132
spells them itself and drift is one list rather than two. `AgentSessionFileTest` asserts every tool in the
117-
registry has one; a tool added without a verb reads as its own name, which is the protocol showing through on
118-
the screen that exists to not show it.
133+
registry has one — **which is what makes the fallback mean something**: a name `verbOfTool` has no verb for is
134+
a name this build has no tool for, so a row reading `Called solve_the_leak` is a typo or a tool from a newer
135+
build, and the name is left exactly as it arrived because that string is what somebody is looking for. A
136+
message that reached no tool at all reads through `verbOfMethod` instead.
119137

120138
**A verb stops where the thing it was about starts**, which is why several of them end mid-sentence: a row of
121139
that screen is prose with one link in it, and the link is the thing. So `list_leaks` is "Listed the" and
@@ -152,10 +170,10 @@ to one adapter and not the other is the mistake this shape exists to make imposs
152170
`notes/agent-surface.md`, which also has what a call costs.
153171

154172
**A process per call would otherwise be a session per call**, and a session is what somebody reads afterwards.
155-
So the handshake is `token[ sessionName]` on one line, `AgentSessionFile.continuing` appends to the newest file
156-
whose name carries that id, and a command line defaults to `cli<the shell's pid>` — an agent's calls come out
157-
of one shell the way its MCP calls come out of one connection. A client that says nothing gets a session of
158-
its own, which is what every MCP client does.
173+
So the handshake is `token[ sessionName[ over]]` on one line, `AgentSessionFile.continuing` appends to the
174+
newest file whose name carries that id, and a command line defaults to `cli<the shell's pid>` — an agent's
175+
calls come out of one shell the way its MCP calls come out of one connection. A client that says nothing gets
176+
a session of its own, which is what every MCP client does, and its lines are recorded as MCP.
159177

160178
**The name is checked at both ends**, because it becomes part of a file name: the command line refuses one
161179
that isn't letters and digits before calling anything, and `AgentServer` serves the connection anyway with a

shark/shark-dive/shark-dive-agent/src/main/java/shark/dive/agent/AgentCommandLine.kt

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -164,9 +164,11 @@ object AgentCommandLine {
164164
): Int {
165165
val toApp = PrintWriter(OutputStreamWriter(socket.getOutputStream(), Charsets.UTF_8), true)
166166
val fromApp = BufferedReader(InputStreamReader(socket.getInputStream(), Charsets.UTF_8))
167-
// The token, and then which session this call is one of: one line, because the alternative is a
168-
// handshake that has to be answered before the protocol can start. See [AgentServer].
169-
toApp.println("${run.token} $sessionName")
167+
// The token, then which session this call is one of, then that it was typed rather than sent by a
168+
// client: one line, because the alternative is a handshake that has to be answered before the protocol
169+
// can start. Saying so here is the only chance there is — from the next line on this is indistinguishable
170+
// from an MCP client, which is the point of it. See [AgentServer] and [AgentTransport].
171+
toApp.println("${run.token} $sessionName ${AgentTransport.CLI.recorded}")
170172
if (fromApp.readLine() != AgentServer.ACCEPTED) {
171173
say("Shark Dive run ${run.pid} refused the token in ${run.file}, so it is not the run that wrote it")
172174
return NOTHING_ANSWERED

shark/shark-dive/shark-dive-agent/src/main/java/shark/dive/agent/AgentJson.kt

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -91,8 +91,16 @@ internal object AgentJson {
9191
put("session", session.sessionId)
9292
put("client", session.client)
9393
put("startedAt", session.startedAt?.toString())
94-
put("calls", session.calls.size)
94+
// Which way in it was talked to, and usually one: a session with both in it is somebody typing calls at
95+
// the window a client is working in, which is worth knowing before reading it.
96+
putJsonArray("over") { session.transports.forEach { add(it.recorded) } }
97+
// The calls that reached a tool, and not every message of it: the protocol around them is in the session
98+
// form below, and counting it here would make a command line's investigation — a handshake per call —
99+
// read as twice the work it was. See [AgentSession.toolCalls].
100+
put("calls", session.toolCalls.size)
95101
put("refused", session.refusedCount)
102+
// And how many got no answer at all, which is this app failing rather than the surface saying no.
103+
put("errors", session.errorCount)
96104
// What it concluded, which is the one thing a reader is looking for — and null for a session that
97105
// concluded nothing, which is most of them.
98106
put("concluded", session.calls.mapNotNull { it.outcome }.lastOrNull())
@@ -124,17 +132,24 @@ internal object AgentJson {
124132
session.calls.forEach { call ->
125133
addJsonObject {
126134
put("at", call.at.toString())
135+
// Which way in it came, and what arrived: null on `tool` is a message that reached none, and the
136+
// method is then the whole of what it was. Not only the calls, because a session that shows the
137+
// ones that worked cannot answer why the others didn't. See [AgentSession.calls].
138+
put("over", call.over?.recorded)
139+
put("method", call.method)
127140
put("tool", call.tool)
128141
put("reason", call.reason)
129142
// What the call was about, as the agent wrote it: an address is that dump's address, and this is
130143
// read by something that can resolve it.
131144
put("about", call.subject)
132145
put("heapDumpPath", call.heapDumpPath)
133146
put("refused", call.refusal)
147+
// And why nothing could be answered at all, which is a different thing from being told no.
148+
put("error", call.error)
134149
put("outcome", call.outcome)
135150
// Last, and in that order, because they are the two long ones and they read as the call: this is
136151
// what went out, and this is what came back. Null on both for a session recorded by a build older
137-
// than they are; null on `output` alone for a call whose answer was the refusal above it.
152+
// than they are; null on `output` alone for a notification nothing was sent back for.
138153
put("input", call.input)
139154
put("output", call.output)
140155
}

0 commit comments

Comments
 (0)