From be540a6afc348b6b783c174fd05119683822448d Mon Sep 17 00:00:00 2001 From: scgopi Date: Sun, 20 Sep 2026 14:45:22 -0700 Subject: [PATCH 1/3] Let a failed remote delivery leave a trace on the host MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Delivery ends in `|| true` on purpose: a session without its briefing is still a session, and a launch must never be blocked by one. But it also ended in `>/dev/null 2>&1`, and that is a different decision wearing the same clothes. When #395's SyntaxError made every delivery a no-op, the reason was written to /dev/null on five days' worth of dials, so neither machine held a word about why every remote host was empty. Failure stays non-fatal. Its stderr now reaches the host's own dial log as `delivery install failed `, beside the launch decisions it belongs next to. The reason is flattened to one line, bounded, and taken from the *tail* — a python traceback ends with the line that names the fault, and keeping the head threw exactly that away: measured, `NotADirectoryError` fell outside the first 400 bytes of the very failure this was written to explain. A succeeding delivery still writes nothing. The sweep dials every host every minute, and a line per healthy tick would bury the one that isn't. `aFailedDeliveryLeavesNoStampBehind` asserted `!script.contains("printf")` as a proxy for "the shell must not write the stamp". It now asserts the rule itself: every printf in the fragment targets dials.log. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: scgopi --- GraphcodeKit/Sources/Domain/DialLog.swift | 22 +++++++++++ .../Sources/Sessions/RemoteGraphAccess.swift | 34 ++++++++++++++--- .../Tests/RemoteInstallerExecutionTests.swift | 38 +++++++++++++++++++ .../Tests/RemoteSessionResumeTests.swift | 7 +++- 4 files changed, 95 insertions(+), 6 deletions(-) diff --git a/GraphcodeKit/Sources/Domain/DialLog.swift b/GraphcodeKit/Sources/Domain/DialLog.swift index 714327a9..651f6cae 100644 --- a/GraphcodeKit/Sources/Domain/DialLog.swift +++ b/GraphcodeKit/Sources/Domain/DialLog.swift @@ -34,6 +34,28 @@ public enum DialLog { + ">> \(log); } 2>/dev/null || true" } + /// `fragment`, with the contents of a shell variable appended as a trailing detail — + /// for the one caller that has something to say beyond which branch it took: a failed + /// delivery, whose whole problem was leaving no trace of *why*. + /// + /// The value rides as a `printf` **argument** rather than inside the format, unlike + /// `session`, `dial` and `event`. Those are literals this codebase controls; this one + /// is an error message from a remote python, and a `%s` or a stray backslash in it + /// would otherwise reformat the line it is being written to. Callers are responsible + /// for flattening newlines out of the variable first — the log is one line per entry, + /// and every reader of it splits on them. + public static func fragment( + session: String, dial: String, event: String, detailVariable: String + ) -> String { + let log = logExpression + return "{ mkdir -p \"$HOME/.graphcode\"; " + + "gc_dl=$(wc -c < \(log) 2>/dev/null || echo 0); " + + "[ \"${gc_dl:-0}\" -gt \(maxBytes) ] " + + "&& { tail -n \(keptLines) \(log) > \(log).tmp && mv \(log).tmp \(log); }; " + + "printf '%s \(session) \(dial) \(event) %s\\n' \"$(date -u +%Y-%m-%dT%H:%M:%SZ)\" " + + "\"$\(detailVariable)\" >> \(log); } 2>/dev/null || true" + } + /// The same line from Swift, for the launches the daemon decides locally rather than /// in a remote shell. Best-effort by the same rule: failure to log must never fail a /// launch. diff --git a/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift b/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift index 6ebe8ebb..6abf1727 100644 --- a/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift +++ b/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift @@ -103,9 +103,17 @@ public enum RemoteGraphAccess { /// host, or `nil` when there's nothing to send. One `python3 -c` with a base64 JSON /// manifest rather than heredocs or scp: a single argument survives every quoting /// layer between here and the remote shell, needs no extra ssh round-trip, and - /// content can't collide with a delimiter. Neutered with `|| true` because delivery - /// must never block the launch it precedes — a session without its briefing is the - /// old behaviour, which works. + /// content can't collide with a delimiter. Neutered because delivery must never block + /// the launch it precedes — a session without its briefing is the old behaviour, which + /// works. + /// + /// **Neutered is not silent.** It used to be: the fragment ended `>/dev/null 2>&1 + /// || true`, and when `f6b8af41` left the embedded python with an unbalanced `exec(`, + /// every delivery raised `SyntaxError` and threw the evidence away. Remote hosts got + /// nothing at all for five days and no machine on either end held a word about it. + /// Failure is still non-fatal here, but its stderr now reaches the host's own dial log + /// as `delivery install failed `, which is the difference between a five-day + /// mystery and a one-line answer. /// /// `receipt` is a path and content written **after** every manifest entry has landed, /// as proof that the whole delivery succeeded. @@ -165,10 +173,26 @@ public enum RemoteGraphAccess { + "len(sys.argv)>2 and open(os.path.expanduser(sys.argv[2]),'w').write(sys.argv[3])" var argv = ["python3", "-c", program, json.base64EncodedString()] if let receipt { argv += [receipt.path, receipt.content] } - return argv.map(RemoteProjectLocation.shellQuoted).joined(separator: " ") - + " >/dev/null 2>&1" + (neutered ? " || true" : "") + let install = argv.map(RemoteProjectLocation.shellQuoted).joined(separator: " ") + // stderr into a variable, stdout to `/dev/null` — `2>&1 >/dev/null` in that order, + // so the substitution keeps the diagnosis and drops the noise. + return "gc_di_err=$(\(install) 2>&1 >/dev/null); gc_di_rc=$?; " + + "if [ \"$gc_di_rc\" -ne 0 ]; then " + + "gc_di_err=$(printf '%s' \"$gc_di_err\" | tr '\\n\\t' ' ' | tail -c \(errorDetailBytes)); " + + DialLog.fragment( + session: "delivery", dial: "install", event: "failed", detailVariable: "gc_di_err") + + "; fi; " + + (neutered ? "true" : "[ \"$gc_di_rc\" -eq 0 ]") } + /// How much of a failed delivery's stderr reaches the dial log — the **last** bytes, + /// not the first. A python traceback opens with frames and interpreter paths and ends + /// with the line that names the fault, so keeping the head throws away the answer: + /// measured, `NotADirectoryError` fell outside the first 400 bytes of the very failure + /// this was written to explain. A bound at all because the log is a diagnosis, not a + /// transcript, and it shares a budget with every dial on the host. + static let errorDetailBytes = 400 + /// Installs bridge state through the SSH command's stdin. Only the byte count and /// SHA-256 digest appear in the remote command; the capability-bearing JSON never /// appears in argv, shell history, or a process listing. diff --git a/graphcode/Tests/RemoteInstallerExecutionTests.swift b/graphcode/Tests/RemoteInstallerExecutionTests.swift index 78287b3a..5de3b794 100644 --- a/graphcode/Tests/RemoteInstallerExecutionTests.swift +++ b/graphcode/Tests/RemoteInstallerExecutionTests.swift @@ -114,4 +114,42 @@ struct RemoteInstallerExecutionTests { RemoteGraphAccess.installerScript(files: [doomed: "goal"], neutered: false)) #expect(try run(reporting, home: home) != 0) } + + @Test(.enabled(if: hasPython3)) + func aFailedDeliveryLeavesItsReasonInTheHostsDialLog() throws { + // Silence is what cost five days: the installer raised SyntaxError into /dev/null, + // so neither machine held a word about why every remote host was empty. Non-fatal + // is right; traceless is not. + let home = try scratchHome() + defer { try? FileManager.default.removeItem(at: home) } + let blocker = home.appendingPathComponent("blocker") + try "x".write(to: blocker, atomically: true, encoding: .utf8) + let script = try #require( + RemoteGraphAccess.installerScript(files: ["~/blocker/nested/PROMPT.md": "goal"])) + + #expect(try run(script, home: home) == 0) + + let log = home.appendingPathComponent(".graphcode/dials.log") + let entry = try #require(try? String(contentsOf: log, encoding: .utf8)) + #expect(entry.contains("delivery install failed")) + // The python's own words, not just that something went wrong. + #expect(entry.contains("NotADirectoryError") || entry.contains("Errno 20")) + // One line per entry, or every reader that splits on newlines mis-parses the log. + #expect(entry.split(separator: "\n").count == 1) + } + + @Test(.enabled(if: hasPython3)) + func aSucceedingDeliveryWritesNoDialLogNoise() throws { + // The sweep dials every host every minute. A line per healthy delivery would bury + // the one that matters under the ones that don't. + let home = try scratchHome() + defer { try? FileManager.default.removeItem(at: home) } + let script = try #require( + RemoteGraphAccess.installerScript(files: [RemoteGraphAccess.cliInstallPath: "shim"])) + + #expect(try run(script, home: home) == 0) + #expect( + !FileManager.default.fileExists( + atPath: home.appendingPathComponent(".graphcode/dials.log").path)) + } } diff --git a/graphcode/Tests/RemoteSessionResumeTests.swift b/graphcode/Tests/RemoteSessionResumeTests.swift index f4bc638d..b300227a 100644 --- a/graphcode/Tests/RemoteSessionResumeTests.swift +++ b/graphcode/Tests/RemoteSessionResumeTests.swift @@ -214,7 +214,12 @@ struct RemoteSessionResumeTests { ZmxSessionLauncher.remoteDeliveryScript( forNode: nil, at: location, settings: GraphcodeSettings())) - #expect(!script.contains("printf")) + // `printf` does appear in the fragment now — a failed delivery reports its reason to + // the host's dial log — so assert the rule this line has always stood for rather than + // its old proxy: no shell write in here targets the stamp. + #expect( + script.components(separatedBy: "printf").dropFirst() + .allSatisfy { $0.contains("dials.log") }) // Not a manifest entry — the manifest is the one token that base64-decodes to JSON. let files = try #require( From 80a088a9f19a0a8c72aa1fd93460f6677ba5ee06 Mon Sep 17 00:00:00 2001 From: scgopi Date: Sun, 20 Sep 2026 15:18:47 -0700 Subject: [PATCH 2/3] Make the failure log safe to write and safe to read MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Five findings from an adversarial review of the previous commit, four of them reproduced end to end. `tail -c` cuts bytes, so the detail landed mid-character on any host with a non-ASCII path, and one orphan continuation byte makes grep and sed fail on the *whole* file under a UTF-8 locale — a change written to make one failure legible would have hidden every dial on the host. The cut now passes through `iconv -c`, and a test writes a failure whose path runs through the boundary and greps the log afterwards. The 400-byte detail also broke DialLog's own bound. The trim keeps the last `keptLines` lines, which stands in for a byte budget only while a line stays under `maxBytes / keptLines` = 209 bytes; at 445 the trim can never get back under `maxBytes`, so every later append by every loop on that host re-reads and rewrites a 2.2 MB file forever. The size is now derived from that budget rather than chosen, and `DialLogBoundTests` locks the arithmetic so raising `keptLines` breaks there first. The trim's scratch file was a fixed `dials.log.tmp` — a race every loop on a host shares, measured at 40 concurrent fragments turning a 5000-line log into 34. Rare enough to survive before; this commit made it fire on every append, so the name is now per-process. A non-zero exit with empty stderr logged no reason at all. An OOM-killed installer is the realistic case, and the exit code is the one datum always available, so it falls back to `rc=`. Last, the test I changed in the previous commit was a loose proxy that accepted what the old line forbade: the text after a rogue write picks up `dials.log` from the next fragment. It now asserts the rule directly — no redirect names the stamp, and every append targets the dial log. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: scgopi --- GraphcodeKit/Sources/Domain/DialLog.swift | 45 ++++++++++---- .../Sources/Sessions/RemoteGraphAccess.swift | 24 +++++-- graphcode/Tests/DialLogBoundTests.swift | 62 +++++++++++++++++++ .../Tests/RemoteInstallerExecutionTests.swift | 44 +++++++++++++ .../Tests/RemoteSessionResumeTests.swift | 16 +++-- 5 files changed, 170 insertions(+), 21 deletions(-) create mode 100644 graphcode/Tests/DialLogBoundTests.swift diff --git a/GraphcodeKit/Sources/Domain/DialLog.swift b/GraphcodeKit/Sources/Domain/DialLog.swift index 651f6cae..f105f884 100644 --- a/GraphcodeKit/Sources/Domain/DialLog.swift +++ b/GraphcodeKit/Sources/Domain/DialLog.swift @@ -12,8 +12,14 @@ import Foundation /// decisions, but they die with the scrollback. /// /// Bounded before every append: past `maxBytes` the file is trimmed to its last -/// `keptLines` lines (~5000 lines is roughly 400 KB of these), so a reconnect loop -/// that waits all night cannot eat a disk. +/// `keptLines` lines, so a reconnect loop that waits all night cannot eat a disk. +/// +/// That bound is a *line-count* trim standing in for a byte budget, which only holds +/// while a line stays under `maxBytes / keptLines` — 209 bytes. A longer one breaks it +/// permanently: the trim keeps 5000 lines, 5000 long lines are still over `maxBytes`, +/// so every later append by every loop on the host re-reads and rewrites the whole file +/// and never gets under. Anything writing a variable-length field here must size it +/// against that budget rather than pick a number. public enum DialLog { public static let maxBytes = 1_048_576 public static let keptLines = 5000 @@ -25,13 +31,27 @@ public enum DialLog { /// format, which is fine for the values this codebase passes (session names are /// `graphcode-`, the rest are literals here) and would not be for user text. public static func fragment(session: String, dial: String, event: String) -> String { + "{ mkdir -p \"$HOME/.graphcode\"; " + trimFragment + + "printf '%s \(session) \(dial) \(event)\\n' \"$(date -u +%Y-%m-%dT%H:%M:%SZ)\" " + + ">> \(logExpression); } 2>/dev/null || true" + } + + /// The bound, as both fragments run it: trim to the last `keptLines` when the file has + /// grown past `maxBytes`. + /// + /// The scratch file is per-process (`$$`). It used to be a fixed `dials.log.tmp`, which + /// is a race every loop on a host shares: two dials trimming at once both redirect into + /// the same name and both `mv` it, and the second `mv` publishes a file the first was + /// still writing — measured at 40 concurrent fragments, a 5000-line log came out with + /// 34 lines, which is the launch history gone. It was survivable only because trimming + /// was rare; a per-process name makes each writer's file its own and the `mv` that + /// publishes it atomic. + private static var trimFragment: String { let log = logExpression - return "{ mkdir -p \"$HOME/.graphcode\"; " - + "gc_dl=$(wc -c < \(log) 2>/dev/null || echo 0); " + return "gc_dl=$(wc -c < \(log) 2>/dev/null || echo 0); " + "[ \"${gc_dl:-0}\" -gt \(maxBytes) ] " - + "&& { tail -n \(keptLines) \(log) > \(log).tmp && mv \(log).tmp \(log); }; " - + "printf '%s \(session) \(dial) \(event)\\n' \"$(date -u +%Y-%m-%dT%H:%M:%SZ)\" " - + ">> \(log); } 2>/dev/null || true" + + "&& { tail -n \(keptLines) \(log) > \(log).$$.tmp " + + "&& mv \(log).$$.tmp \(log); }; " } /// `fragment`, with the contents of a shell variable appended as a trailing detail — @@ -44,16 +64,15 @@ public enum DialLog { /// would otherwise reformat the line it is being written to. Callers are responsible /// for flattening newlines out of the variable first — the log is one line per entry, /// and every reader of it splits on them. + /// Callers are also responsible for keeping the value inside the per-line budget the + /// trim depends on — see `RemoteGraphAccess.errorDetailBytes`, which derives its size + /// from `maxBytes / keptLines` for exactly that reason. public static func fragment( session: String, dial: String, event: String, detailVariable: String ) -> String { - let log = logExpression - return "{ mkdir -p \"$HOME/.graphcode\"; " - + "gc_dl=$(wc -c < \(log) 2>/dev/null || echo 0); " - + "[ \"${gc_dl:-0}\" -gt \(maxBytes) ] " - + "&& { tail -n \(keptLines) \(log) > \(log).tmp && mv \(log).tmp \(log); }; " + "{ mkdir -p \"$HOME/.graphcode\"; " + trimFragment + "printf '%s \(session) \(dial) \(event) %s\\n' \"$(date -u +%Y-%m-%dT%H:%M:%SZ)\" " - + "\"$\(detailVariable)\" >> \(log); } 2>/dev/null || true" + + "\"$\(detailVariable)\" >> \(logExpression); } 2>/dev/null || true" } /// The same line from Swift, for the launches the daemon decides locally rather than diff --git a/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift b/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift index 6abf1727..5291f3f3 100644 --- a/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift +++ b/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift @@ -178,7 +178,9 @@ public enum RemoteGraphAccess { // so the substitution keeps the diagnosis and drops the noise. return "gc_di_err=$(\(install) 2>&1 >/dev/null); gc_di_rc=$?; " + "if [ \"$gc_di_rc\" -ne 0 ]; then " - + "gc_di_err=$(printf '%s' \"$gc_di_err\" | tr '\\n\\t' ' ' | tail -c \(errorDetailBytes)); " + + "gc_di_err=$(printf '%s' \"$gc_di_err\" | tr -d '\\r' | tr '\\n\\t' ' ' " + + "| tail -c \(errorDetailBytes) | iconv -c -f UTF-8 -t UTF-8 2>/dev/null); " + + "[ -n \"$gc_di_err\" ] || gc_di_err=\"rc=$gc_di_rc\"; " + DialLog.fragment( session: "delivery", dial: "install", event: "failed", detailVariable: "gc_di_err") + "; fi; " @@ -189,9 +191,23 @@ public enum RemoteGraphAccess { /// not the first. A python traceback opens with frames and interpreter paths and ends /// with the line that names the fault, so keeping the head throws away the answer: /// measured, `NotADirectoryError` fell outside the first 400 bytes of the very failure - /// this was written to explain. A bound at all because the log is a diagnosis, not a - /// transcript, and it shares a budget with every dial on the host. - static let errorDetailBytes = 400 + /// this was written to explain. + /// + /// The size is **derived, not chosen**, and `DialLogBoundTests` locks it: `DialLog` + /// trims by keeping its last `keptLines` lines, so a line longer than + /// `maxBytes / keptLines` breaks its own bound — the trim can never get the file back + /// under `maxBytes`, and from then on every append by every loop on the host re-reads + /// and rewrites the whole thing. At 400 bytes it did exactly that: 5000 × 445 = 2.2 MB + /// against a 1 MB cap. Deriving it means raising `keptLines` can never silently + /// reintroduce that, and what is left still carries the part that names the fault. + static let errorDetailBytes = + DialLog.maxBytes / DialLog.keptLines - dialLineOverhead + + /// The fixed part of a delivery-failure line — timestamp, the three literal fields, + /// and the spaces between them — measured rather than guessed so the budget above + /// cannot drift from the line it is budgeting for. + static let dialLineOverhead = + "2026-09-20T21:38:23Z delivery install failed ".utf8.count /// Installs bridge state through the SSH command's stdin. Only the byte count and /// SHA-256 digest appear in the remote command; the capability-bearing JSON never diff --git a/graphcode/Tests/DialLogBoundTests.swift b/graphcode/Tests/DialLogBoundTests.swift new file mode 100644 index 00000000..35264caf --- /dev/null +++ b/graphcode/Tests/DialLogBoundTests.swift @@ -0,0 +1,62 @@ +import Foundation +import Testing + +@testable import GraphcodeKit + +/// The dial log's bound, and the one property every writer to it owes. +/// +/// `DialLog` trims by keeping the last `keptLines` lines once the file passes +/// `maxBytes` — a line-count trim standing in for a byte budget. It holds only while a +/// line stays under `maxBytes / keptLines`. A longer one breaks it *permanently*: the +/// trim keeps 5000 lines, 5000 long lines are still over the cap, so every later append +/// by every loop on that host re-reads and rewrites the whole file and never gets under. +/// +/// A delivery-failure line shipped at 445 bytes against a 209-byte budget and did +/// exactly that — 2.2 MB of log that no trim could shrink. These lock the arithmetic so +/// raising `keptLines`, renaming a field, or adding a longer detail breaks here first. +@Suite +struct DialLogBoundTests { + /// What one line may cost if `keptLines` of them must fit inside `maxBytes`. + private var perLineBudget: Int { DialLog.maxBytes / DialLog.keptLines } + + @Test + func aFailureLineFitsTheBudgetItsOwnTrimDependsOn() { + let worstCase = RemoteGraphAccess.dialLineOverhead + RemoteGraphAccess.errorDetailBytes + #expect(worstCase <= perLineBudget) + #expect(DialLog.keptLines * worstCase <= DialLog.maxBytes) + // Derived rather than chosen, so the two can never drift apart. + #expect( + RemoteGraphAccess.errorDetailBytes == perLineBudget - RemoteGraphAccess.dialLineOverhead) + } + + @Test + func theOverheadMatchesTheLineItBudgetsFor() { + // The overhead constant is a measured string; if the fragment's fields change, the + // budget must move with them rather than stay a stale number. + let rendered = "2026-09-20T21:38:23Z delivery install failed " + #expect(RemoteGraphAccess.dialLineOverhead == rendered.utf8.count) + let fragment = DialLog.fragment( + session: "delivery", dial: "install", event: "failed", detailVariable: "gc_di_err") + #expect(fragment.contains("delivery install failed %s")) + } + + @Test + func whatIsLeftStillCarriesTheNameOfTheFault() { + // A budget that fits the trim is worth nothing if it cannot hold a real diagnosis. + let real = + "NotADirectoryError: [Errno 20] Not a directory: " + + "'/home/dev/blocker/nested/PROMPT.md'" + #expect(real.utf8.count <= RemoteGraphAccess.errorDetailBytes) + #expect("SyntaxError: invalid syntax".utf8.count <= RemoteGraphAccess.errorDetailBytes) + } + + @Test + func theTrimScratchFileIsPerProcess() { + // A fixed `dials.log.tmp` is a race every loop on a host shares: two dials trimming + // at once both redirect into one name and both `mv` it, publishing a half-written + // file. Measured at 40 concurrent fragments, a 5000-line log came out with 34. + let fragment = DialLog.fragment(session: "graphcode-x", dial: "ensure", event: "fresh") + #expect(fragment.contains(".$$.tmp")) + #expect(!fragment.contains("dials.log\".tmp")) + } +} diff --git a/graphcode/Tests/RemoteInstallerExecutionTests.swift b/graphcode/Tests/RemoteInstallerExecutionTests.swift index 5de3b794..9976e784 100644 --- a/graphcode/Tests/RemoteInstallerExecutionTests.swift +++ b/graphcode/Tests/RemoteInstallerExecutionTests.swift @@ -138,6 +138,50 @@ struct RemoteInstallerExecutionTests { #expect(entry.split(separator: "\n").count == 1) } + @Test(.enabled(if: hasPython3)) + func aLoggedFailureLeavesTheWholeLogValidUTF8() throws { + // The detail is cut to a byte budget, and a byte cut lands mid-character sooner or + // later. One orphan continuation byte is not a cosmetic blemish: it makes `grep` and + // `sed` fail on the *entire* file under a UTF-8 locale, so a feature written to make + // one failure legible would hide every dial on the host instead. + let home = try scratchHome() + defer { try? FileManager.default.removeItem(at: home) } + // A path whose non-ASCII characters run right through the tail boundary. + let deep = "~/" + String(repeating: "é", count: 400) + "/PROMPT.md" + let script = try #require(RemoteGraphAccess.installerScript(files: [deep: "goal"])) + // Something to lose: an ordinary dial entry written before the failure. + _ = try run( + DialLog.fragment(session: "graphcode-x", dial: "ensure", event: "fresh"), home: home) + + #expect(try run(script, home: home) == 0) + + let log = home.appendingPathComponent(".graphcode/dials.log") + let bytes = try #require(try? Data(contentsOf: log)) + #expect(String(data: bytes, encoding: .utf8) != nil, "dial log is not valid UTF-8") + // The earlier entry must still be findable by the tools anyone would reach for. + #expect(try run("grep -q 'ensure fresh' \(log.path)", home: home) == 0) + } + + @Test(.enabled(if: hasPython3)) + func aFailureWithNoStderrStillRecordsItsExitCode() throws { + // A killed installer — an OOM on a small box against a 105 KB argv — exits non-zero + // with nothing on stderr. The one datum always available must not be dropped. + let home = try scratchHome() + defer { try? FileManager.default.removeItem(at: home) } + let install = try #require( + RemoteGraphAccess.installerScript(files: [RemoteGraphAccess.cliInstallPath: "shim"])) + // Replace the python with a silent failure, keeping the reporting tail intact. + let silent = install.replacingOccurrences( + of: "gc_di_err=$(", with: "gc_di_err=$(sh -c 'exit 137' && ") + + #expect(try run(silent, home: home) == 0) + + let entry = try #require( + try? String( + contentsOf: home.appendingPathComponent(".graphcode/dials.log"), encoding: .utf8)) + #expect(entry.contains("delivery install failed rc=137")) + } + @Test(.enabled(if: hasPython3)) func aSucceedingDeliveryWritesNoDialLogNoise() throws { // The sweep dials every host every minute. A line per healthy delivery would bury diff --git a/graphcode/Tests/RemoteSessionResumeTests.swift b/graphcode/Tests/RemoteSessionResumeTests.swift index b300227a..c8f71093 100644 --- a/graphcode/Tests/RemoteSessionResumeTests.swift +++ b/graphcode/Tests/RemoteSessionResumeTests.swift @@ -215,11 +215,19 @@ struct RemoteSessionResumeTests { forNode: nil, at: location, settings: GraphcodeSettings())) // `printf` does appear in the fragment now — a failed delivery reports its reason to - // the host's dial log — so assert the rule this line has always stood for rather than - // its old proxy: no shell write in here targets the stamp. + // the host's dial log — so this asserts the rule the old `!contains("printf")` line + // stood for: no shell redirect in here names the stamp. Checking the *redirect* and + // not merely "every printf mentions dials.log" is deliberate; the loose form passes a + // rogue `printf 'stamp' > …/.shim-stamp;` because the text after it picks up + // `dials.log` from the next fragment's own trim. + for redirect in [">", ">>"] { + #expect(!script.contains("\(redirect) \(RemoteGraphAccess.shimStampPath)")) + #expect(!script.contains("\(redirect)\(RemoteGraphAccess.shimStampPath)")) + } + // And the only thing any redirect in the fragment appends to is the dial log. #expect( - script.components(separatedBy: "printf").dropFirst() - .allSatisfy { $0.contains("dials.log") }) + script.components(separatedBy: ">> ").dropFirst() + .allSatisfy { $0.hasPrefix(DialLog.logExpression) }) // Not a manifest entry — the manifest is the one token that base64-decodes to JSON. let files = try #require( From 3eaaf7275cb4a76758c920e9f3b63a6bc2e155e1 Mon Sep 17 00:00:00 2001 From: scgopi Date: Sun, 20 Sep 2026 15:31:02 -0700 Subject: [PATCH 3/3] Count the newline the trim counts, and measure the line instead MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Re-review at 80a088a9: the derived budget was still over by one byte. `wc -c` is what the trim measures the file with and it counts the terminator, so a line computed as exactly 209 bytes was 210 on disk and 5000 of them came to 1,050,000 against a 1,048,576 cap — the permanent re-trim was still reachable, just 2.4x further away. The overhead literal now carries its own `\n`, so the budget and the trim measure the same thing. The test written to lock that arithmetic left the newline out the same way and passed on the bug, which is the real lesson: it recomputed the line instead of looking at one. There is now a test that runs a failing delivery and measures the bytes the fragment actually wrote. Also from the re-review: - `iconv` is glibc's; musl and busybox images have none, and there the detail degraded to the exit code alone. Falls back to stripping high bytes, which costs a non-ASCII path its accents and keeps the log valid, which is the property worth keeping. - The stamp assertion matched only the tilde spelling, so a write using `$HOME` — this codebase's own spelling, the one `DialLog` uses — walked past it, as did two spaces or an fd. It matches any redirect at a target ending in the stamp's name now. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: scgopi --- .../Sources/Sessions/RemoteGraphAccess.swift | 25 +++++++++++++++---- graphcode/Tests/DialLogBoundTests.swift | 7 ++++-- .../Tests/RemoteInstallerExecutionTests.swift | 25 +++++++++++++++++++ .../Tests/RemoteSessionResumeTests.swift | 15 +++++++---- 4 files changed, 60 insertions(+), 12 deletions(-) diff --git a/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift b/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift index 5291f3f3..b538a79f 100644 --- a/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift +++ b/GraphcodeKit/Sources/Sessions/RemoteGraphAccess.swift @@ -179,7 +179,16 @@ public enum RemoteGraphAccess { return "gc_di_err=$(\(install) 2>&1 >/dev/null); gc_di_rc=$?; " + "if [ \"$gc_di_rc\" -ne 0 ]; then " + "gc_di_err=$(printf '%s' \"$gc_di_err\" | tr -d '\\r' | tr '\\n\\t' ' ' " - + "| tail -c \(errorDetailBytes) | iconv -c -f UTF-8 -t UTF-8 2>/dev/null); " + + "| tail -c \(errorDetailBytes)); " + // A byte-wise `tail` lands mid-character sooner or later, and one orphan + // continuation byte makes `grep` and `sed` fail on the *whole* log under a UTF-8 + // locale — every other dial on the host hidden by the line meant to explain one. + // `iconv -c` drops the partial character; where it doesn't exist (musl, busybox — + // it lives in glibc's libc-bin) the fallback strips high bytes outright, which + // costs a non-ASCII path its accents and keeps the log readable, which is the + // property that matters. + + "gc_di_err=$(printf '%s' \"$gc_di_err\" | iconv -c -f UTF-8 -t UTF-8 2>/dev/null " + + "|| printf '%s' \"$gc_di_err\" | LC_ALL=C tr -d '\\200-\\377'); " + "[ -n \"$gc_di_err\" ] || gc_di_err=\"rc=$gc_di_rc\"; " + DialLog.fragment( session: "delivery", dial: "install", event: "failed", detailVariable: "gc_di_err") @@ -203,11 +212,17 @@ public enum RemoteGraphAccess { static let errorDetailBytes = DialLog.maxBytes / DialLog.keptLines - dialLineOverhead - /// The fixed part of a delivery-failure line — timestamp, the three literal fields, - /// and the spaces between them — measured rather than guessed so the budget above - /// cannot drift from the line it is budgeting for. + /// The fixed part of a delivery-failure line **as it lands on disk** — timestamp, the + /// three literal fields, the spaces between them, and the newline that terminates it. + /// + /// The terminator is the point. `wc -c`, which is what the trim measures the file + /// with, counts it; the first version of this budget did not, so a line computed as + /// exactly 209 bytes was 210 on disk and 5000 of them came to 1,050,000 against a + /// 1,048,576 cap — the same permanent-trim bug this constant exists to prevent, + /// reintroduced by one byte. Writing the literal with its `\n` keeps the two + /// measurements the same measurement. static let dialLineOverhead = - "2026-09-20T21:38:23Z delivery install failed ".utf8.count + "2026-09-20T21:38:23Z delivery install failed \n".utf8.count /// Installs bridge state through the SSH command's stdin. Only the byte count and /// SHA-256 digest appear in the remote command; the capability-bearing JSON never diff --git a/graphcode/Tests/DialLogBoundTests.swift b/graphcode/Tests/DialLogBoundTests.swift index 35264caf..bb170b7a 100644 --- a/graphcode/Tests/DialLogBoundTests.swift +++ b/graphcode/Tests/DialLogBoundTests.swift @@ -32,8 +32,11 @@ struct DialLogBoundTests { @Test func theOverheadMatchesTheLineItBudgetsFor() { // The overhead constant is a measured string; if the fragment's fields change, the - // budget must move with them rather than stay a stale number. - let rendered = "2026-09-20T21:38:23Z delivery install failed " + // budget must move with them rather than stay a stale number. The `\n` is part of + // the measurement, not decoration — `wc -c`, which the trim measures the file with, + // counts it, and leaving it out here is precisely how a 210-byte line passed a + // 209-byte bound. + let rendered = "2026-09-20T21:38:23Z delivery install failed \n" #expect(RemoteGraphAccess.dialLineOverhead == rendered.utf8.count) let fragment = DialLog.fragment( session: "delivery", dial: "install", event: "failed", detailVariable: "gc_di_err") diff --git a/graphcode/Tests/RemoteInstallerExecutionTests.swift b/graphcode/Tests/RemoteInstallerExecutionTests.swift index 9976e784..d583364f 100644 --- a/graphcode/Tests/RemoteInstallerExecutionTests.swift +++ b/graphcode/Tests/RemoteInstallerExecutionTests.swift @@ -162,6 +162,31 @@ struct RemoteInstallerExecutionTests { #expect(try run("grep -q 'ensure fresh' \(log.path)", home: home) == 0) } + @Test(.enabled(if: hasPython3)) + func aLoggedFailureLineFitsTheTrimBudgetOnDisk() throws { + // Measured from the file, not recomputed. `DialLogBoundTests` checks the arithmetic, + // and arithmetic is exactly how this went wrong: the first budget left out the + // trailing newline, the test that was written to lock it left the newline out the + // same way, and a 210-byte line passed a 209-byte bound. Whatever the emitted + // fragment really writes has to fit, terminator and all. + let home = try scratchHome() + defer { try? FileManager.default.removeItem(at: home) } + // A deep path, so the traceback is far longer than the budget and the cut is real. + let deep = "~/blocker/" + String(repeating: "nested/", count: 40) + "PROMPT.md" + let blocker = home.appendingPathComponent("blocker") + try "x".write(to: blocker, atomically: true, encoding: .utf8) + let script = try #require(RemoteGraphAccess.installerScript(files: [deep: "goal"])) + + #expect(try run(script, home: home) == 0) + + let log = home.appendingPathComponent(".graphcode/dials.log") + let written = try #require(try? Data(contentsOf: log)) + #expect(!written.isEmpty) + #expect(written.count <= DialLog.maxBytes / DialLog.keptLines, "line is \(written.count) bytes") + // And `keptLines` of them really do fit under the cap the trim measures against. + #expect(DialLog.keptLines * written.count <= DialLog.maxBytes) + } + @Test(.enabled(if: hasPython3)) func aFailureWithNoStderrStillRecordsItsExitCode() throws { // A killed installer — an OOM on a small box against a 105 KB argv — exits non-zero diff --git a/graphcode/Tests/RemoteSessionResumeTests.swift b/graphcode/Tests/RemoteSessionResumeTests.swift index c8f71093..9687860e 100644 --- a/graphcode/Tests/RemoteSessionResumeTests.swift +++ b/graphcode/Tests/RemoteSessionResumeTests.swift @@ -220,11 +220,16 @@ struct RemoteSessionResumeTests { // not merely "every printf mentions dials.log" is deliberate; the loose form passes a // rogue `printf 'stamp' > …/.shim-stamp;` because the text after it picks up // `dials.log` from the next fragment's own trim. - for redirect in [">", ">>"] { - #expect(!script.contains("\(redirect) \(RemoteGraphAccess.shimStampPath)")) - #expect(!script.contains("\(redirect)\(RemoteGraphAccess.shimStampPath)")) - } - // And the only thing any redirect in the fragment appends to is the dial log. + // Matching the literal tilde spelling is not enough: `$HOME/.graphcode/...` is this + // codebase's own spelling for that directory (`DialLog.logExpression` uses it), so a + // future author writing the stamp the way the dial log is written would walk past a + // literal check. Nor is `"> " + path`, which two spaces or an fd defeat. This matches + // any redirect at any target ending in the stamp's name — and does not flag the real + // fragment, where `.shim-stamp` appears only as a quoted argv token. + #expect( + script.range( + of: #"[0-9]?>>?\s*[^\s;|&]*\.shim-stamp"#, options: .regularExpression) == nil) + // And the only thing any append in the fragment targets is the dial log. #expect( script.components(separatedBy: ">> ").dropFirst() .allSatisfy { $0.hasPrefix(DialLog.logExpression) })