From 85cc34e09cb3eb08a9dd892ee2d95f50ca76e3b6 Mon Sep 17 00:00:00 2001 From: Jeroen Schweitzer Date: Mon, 15 Jun 2026 09:29:41 +0200 Subject: [PATCH] feat(log): crash-survivable FileLogSink + dev/prod verbosity toggle (T-432) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit First increment of the observability epic (T-425), the productive pivot after the ConPTY freeze refused to reproduce on CI: if we can't reproduce it, make the next occurrence leave evidence. - FileLogSink (lib/kernel/src/file_log_sink.dart): synchronous, crash-survivable LogSink. Appends each record as one JSON line to a size-rotated file; fsyncs warn/error + risky-source (pty/ffi/conpty/watchdog) records immediately so the last breadcrumb is on disk before a hard death, batches the rest on a timer. Never throws. Flutter-free → unit-tested under dart test against a temp dir. - logDirectory() (paths.dart): persistent per-platform log dir (LOCALAPPDATA / ~/Library/Logs / $XDG_STATE_HOME) — durable across reboot, unlike the ephemeral socketDirectory. - resolveLogLevel() (log.dart): the requested dev/prod toggle. CLIDE_LOG dart-define → CLIDE_LOG env → app.log.level setting → warn(release)/info(debug). Lenient parse; an invalid source falls through. - Boot wiring (facade.boot + main.dart): FileLogSink leads the sink chain (so a crash records before the volatile stderr/ring sinks) and the resolved level sets Logger.minLevel. Tests: FileLogSink (JSON shape, error/stack, rotation cap, append-across-restart, timer-cancel), resolveLogLevel precedence + fall-through, logDirectory per-OS. Coverage gate 95.11%. Follow-ups under T-425: live toggle CLI/command/chip (T-433), FFI breadcrumbs (T-434), watchdog isolate (T-435), CI artifact wiring (T-436). Co-Authored-By: Claude Opus 4.8 (1M context) --- .pql/changelog/ticket_history/2026-06.sql | 37 +++++ .pql/changelog/tickets/2026-06.sql | 32 +++++ CHANGELOG.md | 9 ++ lib/kernel/kernel.dart | 1 + lib/kernel/src/facade.dart | 6 +- lib/kernel/src/file_log_sink.dart | 165 ++++++++++++++++++++++ lib/kernel/src/log.dart | 29 ++++ lib/main.dart | 16 ++- lib/src/ipc/paths.dart | 26 ++++ test/ipc/paths_test.dart | 25 ++++ test/kernel/file_log_sink_test.dart | 108 ++++++++++++++ test/kernel/src/log_test.dart | 42 ++++++ 12 files changed, 494 insertions(+), 2 deletions(-) create mode 100644 lib/kernel/src/file_log_sink.dart create mode 100644 test/kernel/file_log_sink_test.dart diff --git a/.pql/changelog/ticket_history/2026-06.sql b/.pql/changelog/ticket_history/2026-06.sql index 7bc0910a..13526dd4 100644 --- a/.pql/changelog/ticket_history/2026-06.sql +++ b/.pql/changelog/ticket_history/2026-06.sql @@ -5034,3 +5034,40 @@ All the raw syscalls and anything whose output is a syscall return or that has n windows.yml runs the real ConPTY suite (start/write/resize/kill/errors) on windows-latest but collects NO coverage (no --coverage flag). So the FFI spawn path has functional validation on Windows + the VM soak (tools/windows-verify/) but no line-coverage metric anywhere. Decide whether to (a) accept functional-only validation explicitly, or (b) collect coverage on the Windows runner and merge it so the FFI path is measured. Cross-platform lcov merge is non-trivial (the gate reads one file) — may warrant a Q-record. Audit detail: full per-fragment findings + adversarial verdicts in the workflow result for run wf_a3cacb2c-2c7.', NULL, '2026-06-14 22:38:01', '2026-06-14 22:38:01', '2026-06-14 22:38:01', NULL, 'd8cafbc05c3a83c1041c29ba25e4ed83', 2) ON CONFLICT(hash) DO NOTHING; +INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCENXW1VF7VXQX64982X171R', 'description', 'Rank-1 culprit from the Windows test-freeze analysis (2026-06-14). On Windows, each WindowsPty.start() (lib/src/pty/windows_pty.dart) pairs the child with its own conhost.exe/OpenConsole.exe. TerminateProcess + ClosePseudoConsole do NOT reliably reap that conhost — it lingers until the PARENT process exits (microsoft/terminal#4050) — and the child is not placed in a Windows Job Object, so dart:io children survive parent death (dart-lang/sdk#49234). Across repeated test runs the orphaned conhost/cmd processes accumulate at the session level and are a credible bridge to the whole-OS resource starvation that ends in a hard power-cycle (cf. anthropics/claude-code#63043: ~1088 leaked conhost.exe). + +Fix: create a Windows Job Object per WindowsPty (CreateJobObject) with JOBOBJECT_EXTENDED_LIMIT_INFORMATION.BasicLimitInformation.LimitFlags = JOB_OBJECT_LIMIT_KILL_ON_JOB_CLOSE; AssignProcessToJobObject(job, hProcess) immediately after CreateProcessW; close the job handle on teardown so the child AND its conhost die when the session (or the test process) exits. Add a tearDownAll backstop in test/pty/windows_pty_test.dart that sweeps stray cmd.exe/conhost.exe children of the test pid. + +Verify with tools/windows-verify/soak-conpty.ps1 — the orphaned ConPTY-host count must stop climbing across iterations. + +Sibling ConPTY-teardown fixes surfaced by the same analysis (fold in here or file separately): CancelIoEx/overlapped reader instead of Isolate.kill (the reader isolate blocks forever in ReadFile and Isolate.kill cannot interrupt FFI — dart-lang/sdk#46680); clamp cols/rows >= 2 before CreatePseudoConsole/ResizePseudoConsole (microsoft/terminal#19922 narrow-terminal CRLF spin); fix close()/_closeConsole() teardown order (terminate -> drain to EOF -> ClosePseudoConsole -> release); add --timeout to the dart-test pty line in ci/test.sh. + +Progress (commit 606d3df, pre-VM hardening): two sibling quick-wins landed on the branch — cols/rows clamped to >= 2 in both PTY backends (lib/src/pty/pty_size.dart; microsoft/terminal#19922) and --timeout 60s on the dart-test pty line in ci/test.sh. Also made windows_pty.dart''s pure helpers (quoteArg / composeEnvironmentBlock / resolveExecutable) public + unit-tested off-Windows. + +Still open and VM-gated (new/changed FFI, can''t validate off-Windows): the Job Object reaping (this ticket''s core), CancelIoEx/overlapped reader, and the close()/_closeConsole() teardown reorder. Do these in the Windows VM session and validate each with tools/windows-verify/soak-conpty.ps1 (orphan host count must go flat).', 'Rank-1 culprit from the Windows test-freeze analysis (2026-06-14). On Windows, each WindowsPty.start() (lib/src/pty/windows_pty.dart) pairs the child with its own conhost.exe/OpenConsole.exe. TerminateProcess + ClosePseudoConsole do NOT reliably reap that conhost — it lingers until the PARENT process exits (microsoft/terminal#4050) — and the child is not placed in a Windows Job Object, so dart:io children survive parent death (dart-lang/sdk#49234). Across repeated test runs the orphaned conhost/cmd processes accumulate at the session level and are a credible bridge to the whole-OS resource starvation that ends in a hard power-cycle (cf. anthropics/claude-code#63043: ~1088 leaked conhost.exe). + +Fix: create a Windows Job Object per WindowsPty (CreateJobObject) with JOBOBJECT_EXTENDED_LIMIT_INFORMATION.BasicLimitInformation.LimitFlags = JOB_OBJECT_LIMIT_KILL_ON_JOB_CLOSE; AssignProcessToJobObject(job, hProcess) immediately after CreateProcessW; close the job handle on teardown so the child AND its conhost die when the session (or the test process) exits. Add a tearDownAll backstop in test/pty/windows_pty_test.dart that sweeps stray cmd.exe/conhost.exe children of the test pid. + +Verify with tools/windows-verify/soak-conpty.ps1 — the orphaned ConPTY-host count must stop climbing across iterations. + +Sibling ConPTY-teardown fixes surfaced by the same analysis (fold in here or file separately): CancelIoEx/overlapped reader instead of Isolate.kill (the reader isolate blocks forever in ReadFile and Isolate.kill cannot interrupt FFI — dart-lang/sdk#46680); clamp cols/rows >= 2 before CreatePseudoConsole/ResizePseudoConsole (microsoft/terminal#19922 narrow-terminal CRLF spin); fix close()/_closeConsole() teardown order (terminate -> drain to EOF -> ClosePseudoConsole -> release); add --timeout to the dart-test pty line in ci/test.sh. + +Progress (commit 606d3df, pre-VM hardening): two sibling quick-wins landed on the branch — cols/rows clamped to >= 2 in both PTY backends (lib/src/pty/pty_size.dart; microsoft/terminal#19922) and --timeout 60s on the dart-test pty line in ci/test.sh. Also made windows_pty.dart''s pure helpers (quoteArg / composeEnvironmentBlock / resolveExecutable) public + unit-tested off-Windows. + +Still open and VM-gated (new/changed FFI, can''t validate off-Windows): the Job Object reaping (this ticket''s core), CancelIoEx/overlapped reader, and the close()/_closeConsole() teardown reorder. Do these in the Windows VM session and validate each with tools/windows-verify/soak-conpty.ps1 (orphan host count must go flat). + +## Soak results on GitHub windows-latest (Server 2022) — orphan-accumulation NOT reproduced (2026-06-14) + +Ran both halves of the windows-verify soak on GitHub-hosted Windows (no VM needed — windows-latest runs the ConPTY suite green, so the soak just wraps it): + +1. Clean-path soak (soak-conpty.ps1, 25 iters): orphans stayed at 0, dart handles flat ~152, threads flat at 7. Orderly close() reaps everything. NOT REPRODUCED. +2. Abrupt-death probe (soak-conpty-kill.ps1 + conpty_orphan_probe.dart, 15 iters x 2 PTYs): start real WindowsPty sessions on long-lived children, block WITHOUT close(), then taskkill /F the parent dart.exe (no /T). Every cycle reaped to baseline — survivors=0, cum=0. When the parent dies the OS breaks the pipes and conhost exits on its own. NOT REPRODUCED. + +**Implication:** the conhost-orphan-accumulation mechanism this ticket is premised on does NOT hold on Server 2022, under clean OR abrupt teardown. The Job Object fix may still be worthwhile as defense-in-depth, but its justification (a reproduced leak) is not confirmed. + +**Caveats / what''s still untested:** +- OS mismatch: the real crashes were on desktop Win10/11; this is headless Server 2022. terminal#4050 was a desktop report. A desktop-specific behavior may be unreproducible on CI. +- Both probes let the process DIE, so within-process accumulation (culprit #2: reader isolates blocked forever in ReadFile, threads/handles climbing within one long-lived process) is reclaimed at exit and never measured. A long-lived-process probe (one dart.exe spawning + abandoning PTYs, watching its OWN handle/thread count climb) would test that — the more likely freeze mode for a long-running app. Not yet built. + +Diagnostics live in tools/windows-verify/ and run via .github/workflows/windows-soak.yml (workflow_dispatch). The same kill-probe will validate the fix if/when it lands (survivors should stay 0 — though they already do, which is the problem).', NULL, '2026-06-15 07:11:41', '2026-06-15 07:11:41', '2026-06-15 07:11:41', NULL, 'dadb5e43a8a9b44b2c4be4b7d4528beb', 2) ON CONFLICT(hash) DO NOTHING; +INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9ER04JVFW8CN3JW1AWYA8', 'status', 'backlog', 'in_progress', NULL, '2026-06-15 07:19:13', '2026-06-15 07:19:13', '2026-06-15 07:19:13', NULL, '55a53ab84e2a10fd52fe6853bd32dc55', 2) ON CONFLICT(hash) DO NOTHING; diff --git a/.pql/changelog/tickets/2026-06.sql b/.pql/changelog/tickets/2026-06.sql index 5a0b1583..c544ef42 100644 --- a/.pql/changelog/tickets/2026-06.sql +++ b/.pql/changelog/tickets/2026-06.sql @@ -5635,3 +5635,35 @@ All the raw syscalls and anything whose output is a syscall return or that has n windows.yml runs the real ConPTY suite (start/write/resize/kill/errors) on windows-latest but collects NO coverage (no --coverage flag). So the FFI spawn path has functional validation on Windows + the VM soak (tools/windows-verify/) but no line-coverage metric anywhere. Decide whether to (a) accept functional-only validation explicitly, or (b) collect coverage on the Windows runner and merge it so the FFI path is measured. Cross-platform lcov merge is non-trivial (the gate reads one file) — may warrant a Q-record. Audit detail: full per-fragment findings + adversarial verdicts in the workflow result for run wf_a3cacb2c-2c7.', 'backlog', 'medium', NULL, NULL, NULL, '2026-06-14 22:37:27', '2026-06-14 22:38:01', NULL, '43890d3049d818cea0acd681a191bc94', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCENXW1VF7VXQX64982X171R', 'bug', NULL, 'ConPTY children leak: place each WindowsPty child in a kill-on-close Job Object', 'Rank-1 culprit from the Windows test-freeze analysis (2026-06-14). On Windows, each WindowsPty.start() (lib/src/pty/windows_pty.dart) pairs the child with its own conhost.exe/OpenConsole.exe. TerminateProcess + ClosePseudoConsole do NOT reliably reap that conhost — it lingers until the PARENT process exits (microsoft/terminal#4050) — and the child is not placed in a Windows Job Object, so dart:io children survive parent death (dart-lang/sdk#49234). Across repeated test runs the orphaned conhost/cmd processes accumulate at the session level and are a credible bridge to the whole-OS resource starvation that ends in a hard power-cycle (cf. anthropics/claude-code#63043: ~1088 leaked conhost.exe). + +Fix: create a Windows Job Object per WindowsPty (CreateJobObject) with JOBOBJECT_EXTENDED_LIMIT_INFORMATION.BasicLimitInformation.LimitFlags = JOB_OBJECT_LIMIT_KILL_ON_JOB_CLOSE; AssignProcessToJobObject(job, hProcess) immediately after CreateProcessW; close the job handle on teardown so the child AND its conhost die when the session (or the test process) exits. Add a tearDownAll backstop in test/pty/windows_pty_test.dart that sweeps stray cmd.exe/conhost.exe children of the test pid. + +Verify with tools/windows-verify/soak-conpty.ps1 — the orphaned ConPTY-host count must stop climbing across iterations. + +Sibling ConPTY-teardown fixes surfaced by the same analysis (fold in here or file separately): CancelIoEx/overlapped reader instead of Isolate.kill (the reader isolate blocks forever in ReadFile and Isolate.kill cannot interrupt FFI — dart-lang/sdk#46680); clamp cols/rows >= 2 before CreatePseudoConsole/ResizePseudoConsole (microsoft/terminal#19922 narrow-terminal CRLF spin); fix close()/_closeConsole() teardown order (terminate -> drain to EOF -> ClosePseudoConsole -> release); add --timeout to the dart-test pty line in ci/test.sh. + +Progress (commit 606d3df, pre-VM hardening): two sibling quick-wins landed on the branch — cols/rows clamped to >= 2 in both PTY backends (lib/src/pty/pty_size.dart; microsoft/terminal#19922) and --timeout 60s on the dart-test pty line in ci/test.sh. Also made windows_pty.dart''s pure helpers (quoteArg / composeEnvironmentBlock / resolveExecutable) public + unit-tested off-Windows. + +Still open and VM-gated (new/changed FFI, can''t validate off-Windows): the Job Object reaping (this ticket''s core), CancelIoEx/overlapped reader, and the close()/_closeConsole() teardown reorder. Do these in the Windows VM session and validate each with tools/windows-verify/soak-conpty.ps1 (orphan host count must go flat). + +## Soak results on GitHub windows-latest (Server 2022) — orphan-accumulation NOT reproduced (2026-06-14) + +Ran both halves of the windows-verify soak on GitHub-hosted Windows (no VM needed — windows-latest runs the ConPTY suite green, so the soak just wraps it): + +1. Clean-path soak (soak-conpty.ps1, 25 iters): orphans stayed at 0, dart handles flat ~152, threads flat at 7. Orderly close() reaps everything. NOT REPRODUCED. +2. Abrupt-death probe (soak-conpty-kill.ps1 + conpty_orphan_probe.dart, 15 iters x 2 PTYs): start real WindowsPty sessions on long-lived children, block WITHOUT close(), then taskkill /F the parent dart.exe (no /T). Every cycle reaped to baseline — survivors=0, cum=0. When the parent dies the OS breaks the pipes and conhost exits on its own. NOT REPRODUCED. + +**Implication:** the conhost-orphan-accumulation mechanism this ticket is premised on does NOT hold on Server 2022, under clean OR abrupt teardown. The Job Object fix may still be worthwhile as defense-in-depth, but its justification (a reproduced leak) is not confirmed. + +**Caveats / what''s still untested:** +- OS mismatch: the real crashes were on desktop Win10/11; this is headless Server 2022. terminal#4050 was a desktop report. A desktop-specific behavior may be unreproducible on CI. +- Both probes let the process DIE, so within-process accumulation (culprit #2: reader isolates blocked forever in ReadFile, threads/handles climbing within one long-lived process) is reclaimed at exit and never measured. A long-lived-process probe (one dart.exe spawning + abandoning PTYs, watching its OWN handle/thread count climb) would test that — the more likely freeze mode for a long-running app. Not yet built. + +Diagnostics live in tools/windows-verify/ and run via .github/workflows/windows-soak.yml (workflow_dispatch). The same kill-probe will validate the fix if/when it lands (survivors should stay 0 — though they already do, which is the problem).', 'backlog', 'high', NULL, NULL, NULL, '2026-06-14 18:14:36', '2026-06-15 07:11:41', NULL, '7103394bfdac9685026b652023a7569e', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9ER04JVFW8CN3JW1AWYA8', 'task', '06FCENXXZFBZ0HVD1VCW4ZASCC', 'FileLogSink + logDirectory + boot-time verbosity resolver (CLIDE_LOG → env → setting → release/debug default)', NULL, 'backlog', 'high', NULL, NULL, NULL, '2026-06-15 07:18:58', '2026-06-15 07:18:58', NULL, '7f08c492c5eb3f6642719f0b6990f7cd', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9F446MZFXVHH65Q6CKTPM', 'task', '06FCENXXZFBZ0HVD1VCW4ZASCC', 'Live verbosity toggle: clide log level CLI + /loglevel command + sync output-dock Level chip to kernel Logger + persist app.log.level', NULL, 'backlog', 'medium', NULL, NULL, NULL, '2026-06-15 07:19:01', '2026-06-15 07:19:01', NULL, '7801e4323815cf95bdc78fa005611cf0', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9FHC8VX50759X35VNER1R', 'task', '06FCENXXZFBZ0HVD1VCW4ZASCC', 'FFI breadcrumbs in windows_pty.dart (+native_pty): injectable log callback, before/after each risky syscall with return + GetLastError; reader/waiter isolates flushSync their own append handle', NULL, 'backlog', 'high', NULL, NULL, NULL, '2026-06-15 07:19:04', '2026-06-15 07:19:04', NULL, 'd796d50acb2751cc8732a20d3805a77f', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9FYDEXCM15FXTER032K84', 'task', '06FCENXXZFBZ0HVD1VCW4ZASCC', 'Watchdog heartbeat + resource sampler in a dedicated isolate (heartbeat ~500ms; sample ConPTY child / handle / thread / memory ~2s)', NULL, 'backlog', 'medium', NULL, NULL, NULL, '2026-06-15 07:19:08', '2026-06-15 07:19:08', NULL, 'a51aac4a65ec7589c8181655aeeb73e9', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9GAQ2G0KCVMZS67SK3324', 'task', '06FCENXXZFBZ0HVD1VCW4ZASCC', 'Wire FileLogSink into test harness + ci/test.sh (CLIDE_LOG=debug, log dir outside build tree, upload as CI artifact in always() step)', NULL, 'backlog', 'medium', NULL, NULL, NULL, '2026-06-15 07:19:11', '2026-06-15 07:19:11', NULL, '1c35b3eea276c8d7d442e8b09f2c7ad8', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); +INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FCM9ER04JVFW8CN3JW1AWYA8', 'task', '06FCENXXZFBZ0HVD1VCW4ZASCC', 'FileLogSink + logDirectory + boot-time verbosity resolver (CLIDE_LOG → env → setting → release/debug default)', NULL, 'in_progress', 'high', NULL, NULL, NULL, '2026-06-15 07:18:58', '2026-06-15 07:19:13', NULL, 'f0ac1b130b28ff2e01db483a5fa47ab7', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at > tickets.updated_at OR (excluded.updated_at = tickets.updated_at AND excluded.hash > tickets.hash); diff --git a/CHANGELOG.md b/CHANGELOG.md index 6e56f0d7..dc06408d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,15 @@ heading, and (b) bumping `pubspec.yaml` `version:` in the same commit. ## [Unreleased] +### Added + +- **Crash-survivable logging.** clide writes a durable JSON-lines log to a + persistent per-platform dir (Windows `%LOCALAPPDATA%`, macOS `~/Library/Logs`, + Linux `$XDG_STATE_HOME`), fsyncing warn/error + pty/ffi records immediately so + a freeze leaves on-disk evidence. `CLIDE_LOG` (dart-define / env) or the + `app.log.level` setting sets verbosity (warn in release, info in debug). + (T-432) + ## [2.5.0] — 2026-06-14 ### Added diff --git a/lib/kernel/kernel.dart b/lib/kernel/kernel.dart index 9046379d..36aec01b 100644 --- a/lib/kernel/kernel.dart +++ b/lib/kernel/kernel.dart @@ -17,6 +17,7 @@ export 'src/events/message_bus.dart'; export 'src/events/types.dart'; export 'src/ipc/client.dart'; export 'src/log.dart'; +export 'src/file_log_sink.dart'; export 'src/settings.dart'; export 'src/facade.dart'; export 'src/clipboard.dart'; diff --git a/lib/kernel/src/facade.dart b/lib/kernel/src/facade.dart index 40dded4a..52d59556 100644 --- a/lib/kernel/src/facade.dart +++ b/lib/kernel/src/facade.dart @@ -137,9 +137,13 @@ class KernelServices { Future Function(String path)? onProjectOpen, Future Function(String path)? onValidateProject, DaemonBus? sharedBus, + List additionalSinks = const [], + LogLevel? minLogLevel, }) async { final logRing = LogRing(); - final log = Logger(sinks: [stderrSink, logRing.add]); + // additionalSinks lead the chain so a crash-survivable sink (FileLogSink, + // T-425) records the tail before the volatile stderr/ring sinks run. + final log = Logger(minLevel: minLogLevel ?? LogLevel.info, sinks: [...additionalSinks, stderrSink, logRing.add]); final events = sharedBus ?? DaemonBus(); final messages = MessageBus(); final filterStates = FilterStateCache(messages: messages); diff --git a/lib/kernel/src/file_log_sink.dart b/lib/kernel/src/file_log_sink.dart new file mode 100644 index 00000000..31f5f01b --- /dev/null +++ b/lib/kernel/src/file_log_sink.dart @@ -0,0 +1,165 @@ +/// Crash-survivable [LogSink] (T-425). +/// +/// Every other sink in clide is volatile: [stderrSink] dies with the console, +/// the [LogRing] dies with the process. The Windows freeze that motivated this +/// (a hard power-cycle, no dumps, no logs) left no evidence for exactly that +/// reason. [FileLogSink] is the durable tail: it appends each [LogRecord] as +/// one JSON line to a size-rotated file under a persistent per-platform log +/// dir, and — crucially — fsyncs the records most likely to immediately +/// precede a crash, so the last breadcrumb is on disk before the box dies. +/// +/// Design choices that matter for a CRASH logger: +/// - Synchronous I/O only. No async buffering / no IOSink — a hard death +/// between an `await` and its flush would lose the tail, which is the one +/// thing this sink exists to keep. +/// - Tiered flush. `warn`/`error` and records from inherently-risky sources +/// (pty/ffi/conpty/watchdog) `flushSync` immediately. High-volume +/// `info`/`debug` write through to the OS (surviving a process crash) and +/// are fsynced on a low-frequency timer — enough to bound power-loss to a +/// couple of seconds without an fsync per line. +/// - Never throws. A disk-full / permission error must not take logging — or +/// the app — down; every operation swallows its own failure. +/// +/// Flutter-free (only `dart:io`/`dart:async`/`dart:convert` + [LogRecord]) so +/// it unit-tests under `dart test` against a temp dir, and so the PTY/FFI +/// layer (also Flutter-free) can route breadcrumbs through it. +library; + +import 'dart:async'; +import 'dart:convert'; +import 'dart:io'; + +import 'log.dart'; + +class FileLogSink { + FileLogSink({ + required Directory dir, + String baseName = 'clide', + int maxBytes = 5 * 1024 * 1024, + int maxFiles = 5, + Set eagerSources = const {'pty', 'ffi', 'conpty', 'watchdog'}, + LogLevel eagerLevel = LogLevel.warn, + Duration flushInterval = const Duration(seconds: 2), + bool startFlushTimer = true, + }) : _dir = dir, + _baseName = baseName, + _maxBytes = maxBytes, + _maxFiles = maxFiles < 1 ? 1 : maxFiles, + _eagerSources = eagerSources, + _eagerLevel = eagerLevel { + _open(); + if (startFlushTimer && flushInterval > Duration.zero) { + _timer = Timer.periodic(flushInterval, (_) => _flush()); + } + } + + final Directory _dir; + final String _baseName; + final int _maxBytes; + final int _maxFiles; + final Set _eagerSources; + final LogLevel _eagerLevel; + + RandomAccessFile? _raf; + int _size = 0; + bool _dirty = false; + Timer? _timer; + + String get _sep => Platform.pathSeparator; + File get _active => File('${_dir.path}$_sep$_baseName.log'); + File _archive(int i) => File('${_dir.path}$_sep$_baseName.$i.log'); + + /// The active log file's path — handy for the caller to surface (e.g. an + /// "open log folder" affordance) or to add to a CI artifact upload. + String get activePath => _active.path; + + void _open() { + try { + _dir.createSync(recursive: true); + final f = _active; + _size = f.existsSync() ? f.lengthSync() : 0; + _raf = f.openSync(mode: FileMode.append); + } catch (_) { + _raf = null; // a disk problem must never kill logging + } + } + + /// The [LogSink] entry point: `logger.addSink(fileSink.call)`. + void call(LogRecord r) { + if (_raf == null) return; + try { + final bytes = utf8.encode('${jsonEncode(_encode(r))}\n'); + // Rotate BEFORE writing when this line would push the file past the cap, + // so the newest entries always live in the active file (and a single + // oversized line still lands rather than spinning rotations on an empty + // file). + if (_size > 0 && _size + bytes.length > _maxBytes) _rotate(); + final raf = _raf; + if (raf == null) return; + raf.writeFromSync(bytes); + _size += bytes.length; + _dirty = true; + if (r.level.index >= _eagerLevel.index || _eagerSources.contains(r.source)) { + raf.flushSync(); + _dirty = false; + } + } catch (_) { + // swallow — a logging failure must never propagate to the app + } + } + + Map _encode(LogRecord r) => { + 'ts': r.timestamp.toIso8601String(), + 'lvl': r.level.name, + 'src': r.source, + 'msg': r.message, + if (r.error != null) 'err': r.error.toString(), + if (r.stackTrace != null) 'stack': r.stackTrace.toString(), + }; + + void _flush() { + if (!_dirty) return; + try { + _raf?.flushSync(); + _dirty = false; + } catch (_) {} + } + + /// Roll `.log` → `.1.log`, shifting older archives up and + /// dropping the oldest past [maxFiles]. With `maxFiles == 1` the active file + /// is simply truncated (no archives kept). + void _rotate() { + try { + _raf?.flushSync(); + _raf?.closeSync(); + } catch (_) {} + _raf = null; + try { + if (_maxFiles <= 1) { + if (_active.existsSync()) _active.deleteSync(); + } else { + final oldest = _archive(_maxFiles - 1); + if (oldest.existsSync()) oldest.deleteSync(); + for (var i = _maxFiles - 2; i >= 1; i--) { + final src = _archive(i); + if (src.existsSync()) src.renameSync(_archive(i + 1).path); + } + if (_active.existsSync()) _active.renameSync(_archive(1).path); + } + } catch (_) {} + _size = 0; + _open(); + } + + /// Flush + close. Call on orderly shutdown; a crash is covered by the eager + /// fsync above, not by this. + Future close() async { + _timer?.cancel(); + _timer = null; + try { + _raf?.flushSync(); + _raf?.closeSync(); + } catch (_) {} + _raf = null; + } +} diff --git a/lib/kernel/src/log.dart b/lib/kernel/src/log.dart index 54674ca1..19e0badb 100644 --- a/lib/kernel/src/log.dart +++ b/lib/kernel/src/log.dart @@ -62,3 +62,32 @@ void stderrSink(LogRecord r) { stderr.writeln(r); if (r.stackTrace != null) stderr.writeln(r.stackTrace); } + +/// Parse a level name (case-insensitive, trimmed) to a [LogLevel], or null if +/// it is absent/blank/unknown — so an invalid source falls through to the next +/// one in [resolveLogLevel] rather than crashing the boot. +LogLevel? parseLogLevel(String? name) { + if (name == null) return null; + final n = name.trim().toLowerCase(); + if (n.isEmpty) return null; + for (final l in LogLevel.values) { + if (l.name == n) return l; + } + return null; +} + +/// Resolve the effective [Logger.minLevel] at boot — the dev/prod verbosity +/// toggle (T-425). Highest precedence first: +/// +/// 1. `--dart-define=CLIDE_LOG=` (baked into the build) +/// 2. the `CLIDE_LOG` environment variable +/// 3. the `app.log.level` setting +/// 4. a build-mode default: `warn` in release (a shipped app stays quiet), +/// `info` in debug. +/// +/// Each named source is parsed leniently; an unknown name is skipped, not +/// fatal. The build-mode flag is passed in (rather than read here) to keep +/// this Flutter-free — `main.dart` supplies `kReleaseMode`. +LogLevel resolveLogLevel({required bool isRelease, String? dartDefine, String? envVar, String? settingValue}) { + return parseLogLevel(dartDefine) ?? parseLogLevel(envVar) ?? parseLogLevel(settingValue) ?? (isRelease ? LogLevel.warn : LogLevel.info); +} diff --git a/lib/main.dart b/lib/main.dart index 2923aae3..29976ff8 100644 --- a/lib/main.dart +++ b/lib/main.dart @@ -51,7 +51,7 @@ import 'package:clide/src/git/client.dart'; import 'package:clide/src/cli/argv_dispatch.dart'; import 'package:clide/src/ipc/envelope.dart'; import 'package:clide/src/ipc/mcp_server.dart'; -import 'package:clide/src/ipc/paths.dart' show workspaceSocketPath; +import 'package:clide/src/ipc/paths.dart' show workspaceSocketPath, logDirectory; import 'package:clide/src/ipc/server.dart'; import 'package:clide/src/panes/event_sink.dart'; import 'package:clide/src/panes/registry.dart'; @@ -89,6 +89,11 @@ Future main() async { // at the last project instead so the daemon targets the real repo from the // first request. (T-352) Directory startupWorkRoot = resolveWorkspaceRoot(Directory.current); + // Crash-survivable logging (T-425): resolve the dev/prod verbosity once and + // attach a FileLogSink as the leading sink so a freeze leaves on-disk + // breadcrumbs. Desktop-only — the sink uses dart:io. + LogLevel bootLogLevel = kReleaseMode ? LogLevel.warn : LogLevel.info; + List bootLogSinks = const []; if (!kIsWeb) { final bootSettings = SettingsStore(appDir: appDir); await bootSettings.load(); @@ -97,6 +102,13 @@ Future main() async { lastProject: bootSettings.get('app.lastProject'), isGitRepo: (d) => Directory('${d.path}/.git').existsSync(), ); + bootLogLevel = resolveLogLevel( + isRelease: kReleaseMode, + dartDefine: const String.fromEnvironment('CLIDE_LOG'), + envVar: Platform.environment['CLIDE_LOG'], + settingValue: bootSettings.get('app.log.level'), + ); + bootLogSinks = [FileLogSink(dir: Directory(logDirectory())).call]; } // Resolve toolchain + boot daemon inline — same as Linux. @@ -341,6 +353,8 @@ Future main() async { preloadNamespaces: _tier0Namespaces, autoStartDaemonClient: false, toolchain: toolchain, + minLogLevel: bootLogLevel, + additionalSinks: bootLogSinks, daemonClientFactory: kIsWeb ? null : (log, events, arrangement, panels) { diff --git a/lib/src/ipc/paths.dart b/lib/src/ipc/paths.dart index 658d5f18..6759f053 100644 --- a/lib/src/ipc/paths.dart +++ b/lib/src/ipc/paths.dart @@ -54,6 +54,32 @@ String socketDirectory() { return '$base/clide'; } +/// Persistent per-platform directory for crash-survivable logs (T-425). +/// +/// Linux: `$XDG_STATE_HOME/clide/logs` (else `$HOME/.local/state/...`) +/// macOS: `$HOME/Library/Logs/clide` +/// Windows: `%LOCALAPPDATA%\clide\logs` +/// +/// Unlike [socketDirectory] — which intentionally lives in an EPHEMERAL +/// runtime dir (`$XDG_RUNTIME_DIR`, `~/Library/Caches`) that the OS may wipe +/// on logout/reboot — this is a DURABLE location. The whole point of the +/// FileLogSink is that a freeze's last breadcrumbs survive the power-cycle, so +/// the log dir must outlive a reboot. +String logDirectory() { + if (Platform.isWindows) { + final local = Platform.environment['LOCALAPPDATA']; + final base = (local != null && local.isNotEmpty) ? local : '${Platform.environment['USERPROFILE'] ?? r'C:\'}\\AppData\\Local'; + return '$base\\clide\\logs'; + } + if (Platform.isMacOS) { + final home = Platform.environment['HOME'] ?? '/tmp'; + return '$home/Library/Logs/clide'; + } + final state = Platform.environment['XDG_STATE_HOME']; + final base = (state != null && state.isNotEmpty) ? state : '${Platform.environment['HOME'] ?? '/tmp'}/.local/state'; + return '$base/clide/logs'; +} + /// FNV-1a 64-bit hash of [s] as a 16-char lower-case hex string. /// The C client (T-126) reproduces the same algorithm byte-for-byte /// so server + client always agree on socket path. Not cryptographic diff --git a/test/ipc/paths_test.dart b/test/ipc/paths_test.dart index f55e72c2..f56c65bf 100644 --- a/test/ipc/paths_test.dart +++ b/test/ipc/paths_test.dart @@ -39,6 +39,31 @@ void main() { }); }); + group('logDirectory (T-425)', () { + test('is a persistent, non-ephemeral location distinct from the socket dir', () { + // The freeze evidence must survive a reboot, so logs must NOT live in + // the ephemeral socket/runtime dir. + expect(logDirectory(), isNot(socketDirectory())); + }); + + test('Linux: XDG_STATE_HOME/clide/logs when set, else ~/.local/state/...', () { + if (Platform.isMacOS || Platform.isWindows) return; + final state = Platform.environment['XDG_STATE_HOME']; + if (state != null && state.isNotEmpty) { + expect(logDirectory(), '$state/clide/logs'); + } else { + final home = Platform.environment['HOME'] ?? '/tmp'; + expect(logDirectory(), '$home/.local/state/clide/logs'); + } + }); + + test('macOS: ~/Library/Logs/clide (not Caches)', () { + if (!Platform.isMacOS) return; + final home = Platform.environment['HOME']!; + expect(logDirectory(), '$home/Library/Logs/clide'); + }); + }); + group('fnv1a64Hex (T-126 cross-check)', () { // Reference values from . // The C client in native/clide-cli/clide.c MUST produce the same diff --git a/test/kernel/file_log_sink_test.dart b/test/kernel/file_log_sink_test.dart new file mode 100644 index 00000000..11e99795 --- /dev/null +++ b/test/kernel/file_log_sink_test.dart @@ -0,0 +1,108 @@ +import 'dart:convert'; +import 'dart:io'; + +import 'package:clide/kernel/kernel.dart'; +import 'package:flutter_test/flutter_test.dart'; + +LogRecord _rec(LogLevel level, String src, String msg, {Object? error, StackTrace? stack}) => + LogRecord(level: level, source: src, message: msg, timestamp: DateTime.utc(2026, 6, 15, 12), error: error, stackTrace: stack); + +void main() { + late Directory dir; + + setUp(() => dir = Directory.systemTemp.createTempSync('clide-filelog-')); + tearDown(() { + if (dir.existsSync()) dir.deleteSync(recursive: true); + }); + + File active() => File('${dir.path}${Platform.pathSeparator}clide.log'); + File archive(int i) => File('${dir.path}${Platform.pathSeparator}clide.$i.log'); + + group('FileLogSink', () { + test('appends one JSON line per record with the expected shape', () async { + final sink = FileLogSink(dir: dir, startFlushTimer: false); + sink(_rec(LogLevel.info, 'boot', 'hello')); + sink(_rec(LogLevel.warn, 'pty', 'spawned', error: 'note')); + await sink.close(); + + final lines = active().readAsLinesSync(); + expect(lines, hasLength(2)); + + final a = jsonDecode(lines[0]) as Map; + expect(a['lvl'], 'info'); + expect(a['src'], 'boot'); + expect(a['msg'], 'hello'); + expect(a['ts'], '2026-06-15T12:00:00.000Z'); + expect(a.containsKey('err'), isFalse); + + final b = jsonDecode(lines[1]) as Map; + expect(b['lvl'], 'warn'); + expect(b['err'], 'note'); + }); + + test('encodes error + stack trace fields when present', () async { + final sink = FileLogSink(dir: dir, startFlushTimer: false); + final st = StackTrace.current; + sink(_rec(LogLevel.error, 'ffi', 'boom', error: 'EBADF', stack: st)); + await sink.close(); + + final rec = jsonDecode(active().readAsLinesSync().single) as Map; + expect(rec['err'], 'EBADF'); + expect(rec['stack'], st.toString()); + }); + + test('creates the log directory if it does not exist', () async { + final nested = Directory('${dir.path}${Platform.pathSeparator}a${Platform.pathSeparator}b'); + final sink = FileLogSink(dir: nested, startFlushTimer: false); + sink(_rec(LogLevel.info, 's', 'm')); + await sink.close(); + expect(File('${nested.path}${Platform.pathSeparator}clide.log').existsSync(), isTrue); + }); + + test('rotates past maxBytes and caps archives at maxFiles', () async { + // ~80-byte lines, 100-byte cap → a rotation every couple of records. + final sink = FileLogSink(dir: dir, maxBytes: 100, maxFiles: 2, startFlushTimer: false); + for (var i = 0; i < 6; i++) { + sink(_rec(LogLevel.info, 's', 'msg$i')); + } + await sink.close(); + + expect(active().existsSync(), isTrue); + expect(archive(1).existsSync(), isTrue); + // maxFiles=2 keeps active + .1 only — .2 must never appear. + expect(archive(2).existsSync(), isFalse); + // The newest record is in the active file. + expect(active().readAsStringSync(), contains('msg5')); + }); + + test('append mode preserves an existing log across sink restarts', () async { + final first = FileLogSink(dir: dir, startFlushTimer: false); + first(_rec(LogLevel.info, 's', 'before')); + await first.close(); + + final second = FileLogSink(dir: dir, startFlushTimer: false); + second(_rec(LogLevel.info, 's', 'after')); + await second.close(); + + final lines = active().readAsLinesSync(); + expect(lines, hasLength(2)); + expect((jsonDecode(lines[0]) as Map)['msg'], 'before'); + expect((jsonDecode(lines[1]) as Map)['msg'], 'after'); + }); + + test('close cancels the flush timer cleanly (no pending-timer leak)', () async { + final sink = FileLogSink(dir: dir, flushInterval: const Duration(milliseconds: 10)); + sink(_rec(LogLevel.info, 's', 'm')); + await sink.close(); + // Reaching here without the test runner flagging a pending timer is the + // assertion; also confirm a post-close write is a no-op, not a throw. + sink(_rec(LogLevel.info, 's', 'after-close')); + expect(active().readAsLinesSync(), hasLength(1)); + }); + + test('activePath points at the live file', () { + final sink = FileLogSink(dir: dir, startFlushTimer: false); + expect(sink.activePath, active().path); + }); + }); +} diff --git a/test/kernel/src/log_test.dart b/test/kernel/src/log_test.dart index db80cd89..a818bebb 100644 --- a/test/kernel/src/log_test.dart +++ b/test/kernel/src/log_test.dart @@ -75,4 +75,46 @@ void main() { expect(got, isEmpty); }); }); + + group('parseLogLevel', () { + test('parses each level name case-insensitively, trimmed', () { + for (final l in LogLevel.values) { + expect(parseLogLevel(l.name), l); + expect(parseLogLevel(l.name.toUpperCase()), l); + expect(parseLogLevel(' ${l.name} '), l); + } + }); + + test('null / blank / unknown → null', () { + expect(parseLogLevel(null), isNull); + expect(parseLogLevel(''), isNull); + expect(parseLogLevel(' '), isNull); + expect(parseLogLevel('verbose'), isNull); + }); + }); + + group('resolveLogLevel (dev/prod verbosity toggle)', () { + test('build-mode default when no source is set: warn release / info debug', () { + expect(resolveLogLevel(isRelease: true), LogLevel.warn); + expect(resolveLogLevel(isRelease: false), LogLevel.info); + }); + + test('precedence: dartDefine > env > setting > default', () { + // setting only + expect(resolveLogLevel(isRelease: true, settingValue: 'debug'), LogLevel.debug); + // env beats setting + expect(resolveLogLevel(isRelease: true, envVar: 'error', settingValue: 'debug'), LogLevel.error); + // dartDefine beats both + expect(resolveLogLevel(isRelease: false, dartDefine: 'trace', envVar: 'error', settingValue: 'debug'), LogLevel.trace); + }); + + test('an unknown/blank higher source falls through to the next', () { + // empty dart-define (the String.fromEnvironment default) is skipped + expect(resolveLogLevel(isRelease: true, dartDefine: '', envVar: 'info'), LogLevel.info); + // garbage env falls through to the setting + expect(resolveLogLevel(isRelease: true, envVar: 'loud', settingValue: 'warn'), LogLevel.warn); + // all invalid → build-mode default + expect(resolveLogLevel(isRelease: false, dartDefine: 'x', envVar: 'y', settingValue: 'z'), LogLevel.info); + }); + }); }