diff --git a/GraphcodeKit/Sources/Domain/DialLog.swift b/GraphcodeKit/Sources/Domain/DialLog.swift index 714327a9..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,48 @@ 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 — + /// 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. + /// 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 { + "{ mkdir -p \"$HOME/.graphcode\"; " + trimFragment + + "printf '%s \(session) \(dial) \(event) %s\\n' \"$(date -u +%Y-%m-%dT%H:%M:%SZ)\" " + + "\"$\(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 6ebe8ebb..b538a79f 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,57 @@ 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 -d '\\r' | tr '\\n\\t' ' ' " + + "| 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") + + "; 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. + /// + /// 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 **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 \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 /// appears in argv, shell history, or a process listing. diff --git a/graphcode/Tests/DialLogBoundTests.swift b/graphcode/Tests/DialLogBoundTests.swift new file mode 100644 index 00000000..bb170b7a --- /dev/null +++ b/graphcode/Tests/DialLogBoundTests.swift @@ -0,0 +1,65 @@ +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. 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") + #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 78287b3a..d583364f 100644 --- a/graphcode/Tests/RemoteInstallerExecutionTests.swift +++ b/graphcode/Tests/RemoteInstallerExecutionTests.swift @@ -114,4 +114,111 @@ 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 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 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 + // 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 + // 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..9687860e 100644 --- a/graphcode/Tests/RemoteSessionResumeTests.swift +++ b/graphcode/Tests/RemoteSessionResumeTests.swift @@ -214,7 +214,25 @@ 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 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. + // 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) }) // Not a manifest entry — the manifest is the one token that base64-decodes to JSON. let files = try #require(