feat(log): --log-file, and a logger that survives being used - #78
Merged
Conversation
✅ Binary load timeWhat this measures
Both binaries are measured interleaved on this runner and compared by |
|
| Metric | Value |
|---|---|
| Current Size | 14251KB (13.91MB) |
| Change | 20KB (.14%) increased |
Size limits
- Warning: 14.50MB
- Maximum: 16.00MB
`src/log.zig` was written complete — levels, JSON, a filter, a mutex, file output — and then never configured by anything. Issue #70 asks to put a flag in front of it. Doing only that would have produced an empty file: the module has two callers, `devmode.zig` and `hotreload.zig`, and craft's own diagnostics go through `std.log` and `logging.zig`, neither of which it has ever seen. So the flag is the small half. `pub const std_options` in the executable's root routes every `std.log` call in the program into this sink, across module boundaries, and `logging.zig`'s scoped loggers reach the same sink through the `callback` target it already had — no call site in either set is touched. The `log_level = .debug` already declared there turns out to be load-bearing: `std.log.debug` is compiled out at comptime below the threshold and most of craft's logging is debug level, so without it `--log-level debug` would be a flag that could not do anything. Wiring it up is also what made its defects reachable, and there were several: - A message longer than 2048 bytes was dropped whole, not truncated. The longest records are usually the ones worth reading, and nothing indicated anything was missing. - The file was written from offset zero on every run. `CreateFileOptions` has no append flag in this Zig and `writeStreamingAll` starts at position zero, so each launch overwrote the previous one and left anything longer stranded past the end. Now seeded from the file's size and advanced with `writePositionalAll`. - `init` kept the caller's `output_file` and `filter_pattern` slices, and `minimal.zig` frees the command-line strings during startup. Nothing had ever configured the logger, which is the only reason that was not already a use-after-free. - `compat_mutex` falls back to a non-recursive spinlock that never yields — `std.Thread.Mutex` does not exist in this Zig — and `log` holds it across the write. A `std.log` call made from inside `log` would spin against a lock the same thread holds, forever: a hang with no panic and no stack. Unreachable while nothing logged through it; reachable the moment 200-odd call sites do. Guarded, and the `Io` is captured once at init rather than taken from another spinlock while holding this one. - The timestamp had no date. `--log-file` exists to leave a trail read afterwards, and a time alone cannot say which day. Now ISO-8601 UTC, and the comment claiming `localtime_r` no longer claims it. - Bytes over 0x7f were copied into the JSON string verbatim, so one bad byte from a filename or a truncated frame made the line unparseable. - `std.c.clock_gettime` does not compile for Windows here. The file only ever built because nothing instantiated `log`. The module had tests, in `test/log_test.zig`, which reaches it across a module boundary and so could not touch the config storage or the formatter — the three places it was wrong. Twelve more now run against the source directly. Not captured, and said so in `--help` rather than left to be discovered from a log that is quieter than expected: `std.debug.print`, which craft uses in far more places than `std.log`. Those go through `std.Options.debug_io` rather than the log handler, and most already sit behind a debug-mode check.
glennmichael123
force-pushed
the
feat/log-file
branch
from
August 27, 2026 13:17
a6a92af to
c49fd70
Compare
This was referenced Aug 27, 2026
glennmichael123
added a commit
that referenced
this pull request
Aug 27, 2026
`compat_mutex` exists because `std.Thread.Mutex` and `std.Thread.Condition` were removed: the Io rework moved blocking primitives to `std.Io.Mutex` and `std.Io.Condition`, which take an `Io` because that is what knows how to wait. This file papered over that by spinning. `Mutex.lock` looped on `tryLock` with `spinLoopHint`, `Condition.wait` spun on a `u32` flag, and neither ever yielded. Measured: three threads waiting 300ms on a spun flag burn 896ms of CPU. Three cores held against whatever they are waiting to finish. Ten files and 88 lock sites are built on this, and #78 added ~200 more by routing every std.log call through a module that takes one of these locks across a write. Both real primitives are used now. The `Io` they need is handed to the module once from `io_context.init` rather than threaded through all 88 call sites, which would have been a signature change across ten files for something that is a property of the process rather than of any call. It is installed before `global_state` deliberately: `global_state` locks one of these mutexes to answer `io_context.get()`, so having the lock ask for the `Io` would recurse into the lock being taken. The spin path stays for everything that runs before startup finishes — tests, `--eval`, anything locking before `io_context.init` — but it yields now, so a waiter cannot hold a core against the holder. Mixing the two is safe in the only direction that occurs: `install` happens once and is never undone, so before it the only way to acquire is `tryLock`, which never reaches the `contended` state that unlock needs an `Io` to wake. One thing I could not demonstrate and am not claiming: the flag-based `Condition` also had a lost-wakeup race, where `broadcast` set one flag and the first waiter to observe it cleared it. A test written to catch that passed against the old code — spinning waiters poll often enough that they all see the flag first — so it is recorded as a reason and not as a fixed bug. The test is kept for the property, labelled as not being a regression test. These primitives had no tests, which is how they stayed spin-only through the Zig version change that made them so.
glennmichael123
added a commit
that referenced
this pull request
Aug 27, 2026
`compat_mutex` exists because `std.Thread.Mutex` and `std.Thread.Condition` were removed: the Io rework moved blocking primitives to `std.Io.Mutex` and `std.Io.Condition`, which take an `Io` because that is what knows how to wait. This file papered over that by spinning. `Mutex.lock` looped on `tryLock` with `spinLoopHint`, `Condition.wait` spun on a `u32` flag, and neither ever yielded. Measured: three threads waiting 300ms on a spun flag burn 896ms of CPU. Three cores held against whatever they are waiting to finish. Ten files and 88 lock sites are built on this, and #78 added ~200 more by routing every std.log call through a module that takes one of these locks across a write. Both real primitives are used now. The `Io` they need is handed to the module once from `io_context.init` rather than threaded through all 88 call sites, which would have been a signature change across ten files for something that is a property of the process rather than of any call. It is installed before `global_state` deliberately: `global_state` locks one of these mutexes to answer `io_context.get()`, so having the lock ask for the `Io` would recurse into the lock being taken. The spin path stays for everything that runs before startup finishes — tests, `--eval`, anything locking before `io_context.init` — but it yields now, so a waiter cannot hold a core against the holder. Mixing the two is safe in the only direction that occurs: `install` happens once and is never undone, so before it the only way to acquire is `tryLock`, which never reaches the `contended` state that unlock needs an `Io` to wake. One thing I could not demonstrate and am not claiming: the flag-based `Condition` also had a lost-wakeup race, where `broadcast` set one flag and the first waiter to observe it cleared it. A test written to catch that passed against the old code — spinning waiters poll often enough that they all see the flag first — so it is recorded as a reason and not as a fixed bug. The test is kept for the property, labelled as not being a regression test. These primitives had no tests, which is how they stayed spin-only through the Zig version change that made them so.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #70.
src/log.zigwas written complete — levels, JSON, a filter, a mutex, file output — and then never configured by anything. The issue asks to put a flag in front of it.Doing only that would have produced an empty file. The module has two callers (
devmode.zig,hotreload.zig); craft's actual diagnostics go throughstd.logandlogging.zig, neither of which it has ever seen.What lands in the file, and how
std.log.*(~200 sites, 50 files)pub const std_options→craftLogFnin the exe rootlogging.zigscoped loggers.target = .callbackhooklog.zigdirect callersstd.debug.printstd.Options.debug_io--helpsays soThe
log_level = .debugalready declared inminimal.zigturns out to be load-bearing:std.log.debugis compiled out at comptime below the threshold, and most of craft's logging is debug level. Without it--log-level debugwould be a flag that could not do anything.Wiring it up is what made its defects reachable
Seven, all on the
--log-filepath, none previously reachable because nothing configured the module:bufPrint(...) catch return. The longest records are usually the ones worth reading, and nothing said anything was missing.CreateFileOptionshas no append flag in this Zig andwriteStreamingAllstarts at position 0, so each launch overwrote the previous one and left anything longer stranded past the end. Now seeded fromstat().sizeand advanced withwritePositionalAll.initkept the caller's slices foroutput_fileandfilter_pattern, andminimal.zigfrees the command-line strings during startup — a use-after-free that had simply never been reachable.compat_mutexfalls back to a non-recursive spinlock that never yields (std.Thread.Mutexdoesn't exist in this Zig), andlogholds it across the write. Astd.logcall from insidelogwould spin against a lock the same thread holds, forever — no panic, no stack. Inert while nothing logged through it; live the moment 200 call sites do.--log-fileexists to leave a trail read afterwards; a time alone can't say which day. Now ISO-8601 UTC — and the comment claiminglocaltime_r(which isn't instd.chere, and whose result the code discarded via a dead_ = t;) no longer claims it.std.c.clock_gettimedoesn't compile for Windows here. The file only ever built because nothing instantiatedlog().That's the third time this session that wiring something up is what exposed it. It is the argument for the flag and the fixes landing together rather than the flag landing alone.
Tests
The module did have tests —
test/log_test.zig— which reach it across a module boundary and therefore cannot touch the config storage or the formatter, the three places it was wrong. Twelve more now run against the source directly, covering truncation, append across runs, string ownership, level filtering, JSON under hostile input, invalid UTF-8, stderr suppression, re-init, the date, and the reentrancy guard.Verified end to end, not just compiled
That record originates from a
std.log.warninmacos.zig— a different module from the root — which is what proves the cross-module routing works. Also confirmed by running the binary:--log-json--log-quiet--log-level errorAn earlier probe produced an empty file and I nearly reported success on "the flag works" — the file existed and the build was green. It was empty because the handler override hadn't actually landed. Forcing a known
std.log.warnand finding it still absent is what caught it.Verified
zig build·zig build test·zig build test-js·x86_64-windowscross-build ·zig fmt --check·tsc --noEmit· 511 bun tests · pickier 38 warnings, unchanged from main.