Structured, bounded diagnostics for daemon IPC (#289)

[scgopi]

Based on main after the #288 series. Closes #289. #290 was closed as its duplicate.

The gap

When mail inbox timed out, nothing said where the ten seconds went. graphcoded.log held bare client connected / client disconnected lines with no clock, graphcoded.err.log was empty, and the CLI printed one generic sentence. The stall in the #288 report — a daemon parked in write(2) on one deaf client — left no trace anywhere. And the log had no bound: 317 KB and growing on the machine that filed the issue (acceptance criterion 5 was already violated before any of this).

The change

DaemonLog — one key=value line per IPC event, UTC-stamped to the millisecond, never a payload, written on a serial queue off the IPC path, rotated at 2 MB into one .1 generation (so two files of that size is the documented bound). launchd points the daemon's stdout at graphcoded.log; the daemon now opens the same file itself and, when stdout is not a terminal, moves stdout and stderr onto its own descriptor — so anything still printed the old way, and the runtime's own crash output, lands in the file that rotates rather than in one that only grows.

What gets recorded, and by what:

line	fields	where
startup	pid, version, build, executable, support dir, socket	daemon start — version skew between a client and the daemon is readable off the two logs
connect / disconnect	conn (connection number), id (the connection uuid's first eight characters), fd, peer (the client's pid, via LOCAL_PEERPID / SO_PEERCRED), requests served, lifetime	connection loop
request	conn, seq, command kind (graphCommand.memoNode, never its text), bytes, decode_ms	connection loop, on receipt — a request that hangs is the one worth a line, and a line on completion would never come
handled	conn, seq, kind, handle_ms	connection loop, on completion
persist	conn/seq, nodes, ms	GraphStore.broadcast
broadcast	kind, revision, bytes, encode_ms, recipients, accepted, ms	notifyClients (snapshot and delta)
reply	kind, fd, bytes, encode_ms	ProjectRegistry unicast replies
write-stall	conn (uuid8 — fds are reused within minutes), fd, bytes (frame incl. 4-byte header), remaining, blocked_ms	the writer, once a write has waited 250 ms — a write on a client that never reads again completes never, so a line only at completion would name exactly the client that matters never
write	conn, fd, bytes (incl. header), ms, blocked_ms, errno on failure	the writer, at completion — only for a write that waited or failed
backlog-drop	fd, pending bytes, budget	the channel, replacing the stderr notice

Beside #301

#301 landed the SO_SNDTIMEO fix that lets the writer's loop run at all (macOS ignores MSG_DONTWAIT on a blocking unix socket); this PR does not carry it. What this PR adds on top: blocked time measured per stretch by the clock rather than by summing poll durations (which undercounted), and a regression test that a detached writer wedged on a deaf peer retires within a bounded time — the path that cannot shutdown, where a writer parked in send would never notice isClosing.

blocked_ms is recorded per client, separately from the broadcast's own duration — the field that names the #288 bug directly: the actor's ms now never includes a client's read, and the client that holds a write shows up by its own fd with how long it held it.

Correlation without a request id on the wire. The daemon logs each connection's peer pid and numbers its frames; DaemonRequestContext (a task-local) carries conn/seq into the store's and registry's lines so one command's phases read as one story. The CLI's timeout now says its phase, elapsed time, pid and frames sent — "timed out after 10.0s waiting for the mailbox answer (pid 4321, 2 frames sent) … graphcoded.log lines with peer=4321 are this run's; seq=2 is the frame it was waiting on" — which is exactly the daemon line to look at. No protocol change, so an older CLI or daemon on either side keeps working.

Why the peer pid, and not an id the daemon mints

The one field here that crosses a process boundary is peer= — the client's pid, read off the socket (LOCAL_PEERPID on Darwin, SO_PEERCRED on Linux). It exists for correlation without a wire change: when the CLI times out it prints its own pid, and nothing else the CLI knows ever appears in the daemon's log. An opaque per-connection id minted by the daemon would tell two connections apart in the log, but a client that never learns it cannot print it — the two records could not be joined from the outside, which is the whole ask ("make request IDs usable across CLI and daemon records"). Carrying an id on the wire would close that too, at the cost of a protocol change during the very upgrade window #298 is about. A pid records nothing about the user: it is visible to anyone on the machine with ps, it identifies a process and not a person, and it is not reused as a credential anywhere. The uid/gid that SO_PEERCRED also returns are discarded.

Privacy

Every field is a number, a case name, a descriptor, or a path the daemon already owns (its support directory, its socket). No prompt text, mail body, tool output, repository path, or raw command reaches the log; DaemonCommand.kindName logs a memoNode as graphCommand.memoNode. The test seeds a graph with a marker title and goal and asserts neither appears in any line.

The bound, honestly

The file's size is read with fstat before every write and rotation decided on that, not on a count of this log's own lines — stdout and stderr write to the same file through the mirrored descriptors, and a bound that only saw its own records was measured 25× over. Mirroring is explicit (open(mirroringStandardStreams: true), the daemon only); a test never moves the runner's output.

A smoke test that runs the binary

A helper that called itself took every CLI verb down with SIGSEGV and passed three green gates: the graphcode test scheme does not build graphcode-cli, a scheme build cannot see a runtime fault, and no test invoked the binary. scripts/cli-smoke.sh now runs the built CLI against a throwaway daemon (status, mail list, mail post, mail read, projects) and insists on exit 0; the Linux job runs it after swift build.

Verification

Gate: full Xcode suite (gate on this head in flight; previous base passed 1641 tests / 170 suites, exit 0; reported in a comment when it completes), swiftlint 0 errors, swift-format clean, graphcoded and graphcode-cli schemes build; SwiftPM swift build and .build/debug/graphcode pass locally (the Linux branch of SocketPeer compiles there).

DaemonDiagnosticsTests, one per acceptance criterion: a deaf subscriber on a 4 KB socket beside a reading one — the broadcast line records fanout and size, the deaf client's fd gets a write line with blocked_ms > 0, the reading client gets none, and no content reaches the log (1–3); the timeout message names phase, elapsed, pid and frame count (4); a DaemonLog with a 2 KB bound rolls into .1 and both files stay within it, every line stamped (5); and a command is logged by kind down through a sub-graph command.

🤖 Generated with Claude Code

https://claude.ai/code/session_01DeGL2CxuGmq16RSZpJYm2N

[scgopi]

Gate on this head (6b74d87), run in a private DerivedData so no neighbour could touch it: xcodebuild test exit 0 — 1648 tests / 172 suites / 0 failures; graphcode-cli scheme build exit 0; graphcoded scheme build exit 0; swiftlint 0 errors; swift-format clean; Linux job green on this head (it caught an earlier ucred reference — Glibc's Swift module does not export the type; a local struct of the same layout fixes it).

Two things changed since the first push, both from the review brief: the peer-pid reasoning is a code comment on SocketPeer rather than only here, and DaemonLog's taps and file now have separate locks — record never waits on write(2), so a disk stall cannot hold the GraphStore actor or a channel's writer. A sweep for \\(command) / \\(event) on any log path found none; kinds go through Mirror case labels.

[scgopi]

Independent review of #303 (ReviewPR303) — do not merge as it stands

Reviewed 6b74d87 in my own worktree. One blocker, which the green gate cannot see; privacy — the thing I was asked to attack hardest — holds up under a deliberate attempt to break it.

---

🛑 BLOCKER — sendCommand calls itself. The entire CLI segfaults.

graphcode-cli/Sources/main.swift:94

func sendCommand(_ command: DaemonCommand) throws {
  try sendCommand(command)     // ← should be client.send(command)
  framesSent += 1
}

sendCommand is defined exactly once in the file and there is no other overload in scope, so this is unbounded self-recursion. Every one of the 15 call sites the PR introduced now blows the stack.

Proven, not inferred:

(lldb) run
Process 2375 stopped, stop reason = EXC_BAD_ACCESS (code=2, address=0x16f603fe0)
  frame #0: graphcode`sendCommand(command=openProject) at main.swift:94

Against a live daemon, on 6b74d87:

command	exit
graphcode --help	0 (never dials)
graphcode projects	139 (SIGSEGV)
graphcode status <p>	139
graphcode mail list <p>	139
graphcode mail inbox <p>	139
graphcode usage <p>	139
graphcode node memo <p> <id> hi	139

Same result from the SwiftPM binary and from .derived/Build/Products/Debug/graphcode built by the graphcode-cli scheme — i.e. the binary that ships. Control: the base commit a7fd527, same daemon, same project, exits 0 and prints the graph. It is this PR.

No output, no message — the process dies before it writes anything. Every loop in this graph reads mail, posts and memos through this binary.

Why every gate missed it, including the one PerfTriage ran on the merged result. The project's own worktree-build-check skill says it outright: "The graphcode scheme does not build graphcode-cli or graphcoded. A compile error in graphcode-cli/Sources/main.swift survives a green app build and a green test run." This is worse than a compile error — it builds fine and dies at runtime, and no test invokes the binary. My gate was green too: 1648 tests / 172 suites / exit 0, swiftlint 0 errors, swift-format clean, graphcode-cli and graphcoded schemes BUILD SUCCEEDED, Linux CI green. All of that is true and none of it touches the broken line.

theTimeoutNamesItsPhaseElapsedAndCorrelationNumbers tests renderTimeout as a pure string function. It passes. The CLI can no longer reach the timeout it renders. Acceptance criterion 4 is verified by a test that cannot see the code under it is dead.

A one-word fix (client.send), but it needs a test that actually runs the binary, or the next one lands the same way.

---

🔒 Privacy — I tried to break it and could not

Not a read of the call sites; two independent attacks.

1. Every field a command can emit. Built a probe against GraphcodeKit and pushed a nonce through every string payload of all 17 GraphCommand cases, 10 DaemonCommand cases and DaemonEvent, then checked kindName:

ok  memoNode          -> memoNode
ok  mailroomPost      -> mailroomPost
ok  subGraphCommand   -> subGraphCommand.memoNode
ok  graphCommand      -> graphCommand.mailroomPost
ok  openProject       -> openProject
ok  errorOccurred     -> errorOccurred

0 leaks / 30 cases. The Mirror trick is sound here: every case with associated values yields the case label, and the String(describing:) fallback is reached only by payload-less cases, where it is just the name. This was my main suspicion going in (a bare interpolation of a Swift enum prints its payload) and it is not there.

2. Live daemon, nonce NONCEZZ9LEAKCANARY7, driven over the raw socket. A node created with the nonce in both its title and its goal summary, then: mailroom post body + topic, memo, refine, rename, message; and the failure paths — oversize-post refusal, openProject on a bad path (the error text returned to the client contains the nonce), an undecodable JSON frame carrying the nonce, a non-JSON garbage frame carrying the nonce, an orphan memo, and a mailbox search string.

$ grep -c NONCEZZ9LEAKCANARY7 graphcoded.log
0

While that node was live and being broadcast, the log says only:

event=persist conn=1 seq=7 nodes=1 ms=0.3
event=broadcast conn=1 seq=7 kind=graphChanged revision=6 bytes=676 encode_ms=0.0 recipients=1 accepted=1 ms=0.0
event=reply conn=2 seq=1 kind=errorOccurred fd=6 bytes=132 encode_ms=0.0

Counts and sizes. The error path is the one I expected to leak — errorOccurred messages do interpolate user-supplied paths — and it records kind=errorOccurred bytes=132, never the message. Criterion 3 met. I am satisfied on privacy.

One thing to state rather than hide: startup logs support= and executable=, which carry the user's home directory and username. That is the daemon's own path, not user content, and it is in the log's own filename anyway — but it is new information in a file that previously had none. Fine by #289; worth knowing.

✅ The peer pid — argument accepted, on verification not on trust

I checked the claim instead of taking it. SocketPeer is called in exactly one place (graphcoded/Sources/main.swift:208). On Darwin only LOCAL_PEERPID is requested — uid/gid are never even asked for. On Linux the ucred is a function-local; only .pid is returned and the struct dies with the call. Grepping uid|gid across the whole diff matches two lines, 258–259, the unread struct fields. They really are discarded — never logged, never retained.

And the correlation argument holds: a daemon-minted id cannot be printed by a client that never learns it, so criterion 4 is genuinely unsatisfiable without a wire change. A pid is visible to anyone with ps. I accept it. Good call putting the reasoning in the code comment.

---

⚠️ Finding 2 — the documented bound is not enforced for the bytes this PR redirects into the file

DaemonLog.write rotates on bytesWritten, a counter of its own writes. But openLocked dup2s stdout and stderr onto the same descriptor, and those bytes never touch the counter. Measured on 6b74d87, bound set to 4096:

	file	.1	rotated?
rotation driven by record	2190	4066	✅ both under bound
same bound, bytes via the dup2'd stderr	102,474	(none)	❌ never once

25× the bound, and no .1 was ever created. The PR says the redirect means output "lands in the file that rotates rather than in one that only grows" — true about where it lands, not about bounded. The traffic the redirect exists to capture is exactly the traffic that escapes the check.

Latent today (graphcoded's own prints were removed; only fail() and runtime crash output remain), but the redirect is there for future and foreign output. Fix is one line: size from lseek(descriptor, 0, SEEK_END) instead of the running counter.

Rotation itself is correct and I want to say so plainly: bound 4096 → 2190 + 4066, last record present, ids contiguous across the boundary (342…399, no gaps), 0 unstamped lines. A rotation loses no in-flight record.

⚠️ Finding 3 — theLogRollsOverAtItsBound hijacks the test runner's stdout and stderr, permanently

open sets mirrorsStandardStreams = isatty(STDOUT_FILENO) == 0. Under xcodebuild stdout is a pipe, so that test dup2s fds 1 and 2 onto a temp file which its own defer then deletes. Nothing restores them. I hit this myself before I spotted it: every print() in my own rotation probe vanished into the log file instead of my capture. The suite still passes because Swift Testing reports out-of-band, but from that test onward the process has no usable stdout/stderr — which will silently swallow another test's diagnostic output or a later crash report. Give the test a non-mirroring open, or save and restore fds 1 and 2.

⚠️ Finding 4 — write / write-stall / backlog-drop carry fd, and fds are reused

Criterion 2 asks the diagnostics to name "the exact phase and client write". They name the fd. In my own live log fd=5 was conn 1, 2, 3, 4, 5, 6 and 11 inside seven minutes. Attributing this line —

event=write fd=5 bytes=271 ms=6132.6 blocked_ms=6080.8 errno=32

— to a client means scanning back for the most recent connect fd=5, which is precisely the ambiguity conn was added to remove. conn is documented as "stable for the daemon's lifetime" and is absent from the three lines that matter most. OutboundChannel only knows the fd, so this needs an fd→conn (or fd→peer) registration.

🔍 Finding 5 — remaining exceeds bytes on the stall line

event=write-stall fd=7 bytes=271 remaining=275 blocked_ms=252.7

bytes is data.count; remaining counts down the framed buffer, which is the payload plus the 4-byte length header. The one line that says how far a stalled write got reports more remaining than there ever was. One-line fix.

🔍 Finding 6 — the request you are diagnosing is the one with no request line

event=request is emitted only after registry.handle returns. A command that hangs — the case #289 exists for — produces no request line at all. The CLI says "seq=2 is the frame it was waiting on"; if the hang is before the store is reached (decode, project open, registry routing), nothing in the log carries seq=2 and the operator's search comes back empty, reading as "the frame never arrived". Visible in my logs: persist/broadcast for seq=N always precede request seq=N. A request-begin line closes it.

📝 Note — the SO_SNDTIMEO fix is not in this PR

The body presents it as "a defect in the writer this surfaced (fixed here, two lines in OutboundChannel)". It is already on main at a7fd527 via #301 — git show a7fd527:…/OutboundChannel.swift has it at line 126. This PR adds OutboundChannelBoundedSendTests for it, which is welcome, but the body overstates its own diff to a reviewer trusting the description.

---

✅ What genuinely works — verified live, not read

The core of the PR does what it claims. Deaf subscriber on a 4 KB socket beside a reading one, 120 broadcasts:

event=broadcast conn=13 seq=121 kind=graphChanged revision=124 bytes=272 recipients=3 accepted=3 ms=0.2
event=write-stall fd=7 bytes=271 remaining=275 blocked_ms=252.7
event=write      fd=5 bytes=271 ms=6132.6 blocked_ms=6080.8 errno=32

The actor's ms=0.2 never includes a client's read; the stalled client is named by its own blocked_ms; the reading client gets no write line at all. That is the field #288 was missing, and it is here. Criteria 1, 2, 3 and 5 (for the log's own lines) are met.

What I did NOT check

• The Linux ucred layout at runtime. CI compiles it; nothing runs it. Three 4-byte fields in declaration order will match struct ucred in practice, but getsockopt's returned size is not checked against MemoryLayout, so a layout mismatch would silently yield a wrong pid rather than fail.
• Behaviour of the real app (only the daemon, the CLI and the kit).
• Log behaviour on a full disk, and openLocked failing after a rotation (descriptor stays -1 and is never retried — the log goes dark permanently).
• I did not re-run the full gate on 6b74d87; I ran it on e0ee469 (green, 1648/172) and the only delta is DaemonLog.swift lock-splitting, which I re-verified by hand.

Verdict: excellent diagnostics, and the privacy discipline is real — I attacked it properly and it held. But I would not merge until sendCommand is fixed, because the shipped CLI segfaults on every command that touches the daemon, and nothing in the gate can tell you that. Findings 2–6 are worth fixing here rather than filing; none of them individually blocks.

🤖 Generated with Claude Code

https://claude.ai/code/session_01KpDkvGcyWyyYWRrULokzi6

[scgopi]

Do not merge. Confirming the review's blocker independently — I read the source on the branch myself rather than relying on the report.

graphcode-cli/Sources/main.swift:94

func sendCommand(_ command: DaemonCommand) throws {
  try sendCommand(command)      // ← calls itself
  framesSent += 1
}

Unbounded recursion. Every CLI verb that dials the daemon crashes; only --help survives.

How three green gates missed it

Gate	Result	Why it was blind
Author's	1648/172/0, exit 0	The graphcode test scheme does not build graphcode-cli
Mine, on the merged result	1648/172/0, 0 restarts	Same
Reviewer's	1648/172, both schemes BUILD SUCCEEDED, Linux green	A build succeeds — the fault is at runtime

All three of us also built the graphcode-cli scheme successfully. That proves it compiles, which is not the same as it working, and no test in this repo ever invokes the built binary.

renderTimeout is tested as a pure string function, so #289's acceptance criterion 4 passes while the code path underneath it is dead.

The fix, and the fix for the class

One line: try client.send(command).

But the more important change is a smoke test that runs the built CLI against a throwaway daemon and asserts exit 0 on status and mail list. Without it this class recurs and nothing we currently run will catch it — that is the actual finding here, and it is worth more than the one-line correction.

The rest of the review stands

Privacy held under a serious attack — a nonce through every string payload of all 17 GraphCommand and 10 DaemonCommand cases, then a live daemon with the nonce in node title, goal, mail body, topic, memo, refine, rename, an oversize refusal, a bad-path openProject whose error text contains the nonce, and undecodable frames: 0 leaks. The peer-pid argument is accepted on verification, not on trust — uid/gid are genuinely discarded.

Still to fix alongside the recursion: the log bound is 25× over because dup2'd stdout/stderr bytes never reach bytesWritten; a test permanently hijacks the runner's stdout onto a deleted temp file; write-stall records carry only an fd, and fds are reused (fd=5 was seven different connections in seven minutes); remaining=275 vs bytes=271 misses the 4-byte header; and a hung request logs no request line at all — which is the exact case #289 exists for, so the request should be logged on receipt rather than on completion.

Also: the PR body claims SO_SNDTIMEO, which is already on main via #301 and is not in this diff.

[scgopi]

Gate on ba2dba0, private DerivedData: xcodebuild test exit 0 — 1648 tests / 172 suites / 0 failures; graphcode-cli build exit 0; graphcoded build exit 0; swiftlint 0 errors; swift-format clean. Linux job green on this head, and it now runs scripts/cli-smoke.sh — the built CLI against a throwaway daemon, exit 0 on status, mail list, mail post, mail read, projects — which is the check that would have caught the recursion the three scheme-level gates missed.

Since the last comment: the recursion fix; the log bound is decided from fstat before every write so mirrored stdout/stderr bytes count (test: 1900 external bytes, the next record rotates; a generation is bounded by the limit plus what arrived between two records, said in the doc); mirroring is opt-in and only the daemon asks; write/write-stall/backlog-drop carry conn=<uuid8> beside fd and connect logs id=; byte counts include the 4-byte header; request is logged on receipt and handled on completion; the body no longer claims #301's SO_SNDTIMEO.