Skip to content

feat(log): --log-file, and a logger that survives being used - #78

Merged
glennmichael123 merged 1 commit into
mainfrom
feat/log-file
Aug 27, 2026
Merged

feat(log): --log-file, and a logger that survives being used#78
glennmichael123 merged 1 commit into
mainfrom
feat/log-file

Conversation

@chrisbbreuer

Copy link
Copy Markdown
Contributor

Closes #70.

src/log.zig was 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 through std.log and logging.zig, neither of which it has ever seen.

What lands in the file, and how

source mechanism in the file?
std.log.* (~200 sites, 50 files) pub const std_optionscraftLogFn in the exe root yes — across module boundaries
logging.zig scoped loggers its existing .target = .callback hook yes — zero call sites touched
log.zig direct callers already direct yes
std.debug.print none — goes through std.Options.debug_io no, and --help says so

The log_level = .debug already declared in minimal.zig 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. Without it --log-level debug would be a flag that could not do anything.

Wiring it up is what made its defects reachable

Seven, all on the --log-file path, none previously reachable because nothing configured the module:

  1. Messages over 2048 bytes were dropped whole, not truncated — bufPrint(...) catch return. The longest records are usually the ones worth reading, and nothing said anything was missing.
  2. The file was written from offset zero every run. CreateFileOptions has no append flag in this Zig and writeStreamingAll starts at position 0, so each launch overwrote the previous one and left anything longer stranded past the end. Now seeded from stat().size and advanced with writePositionalAll.
  3. init kept the caller's slices for output_file and filter_pattern, and minimal.zig frees the command-line strings during startup — a use-after-free that had simply never been reachable.
  4. A reentrancy hang. compat_mutex falls back to a non-recursive spinlock that never yields (std.Thread.Mutex doesn't exist in this Zig), and log holds it across the write. A std.log call from inside log would 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.
  5. The timestamp had no date. --log-file exists to leave a trail read afterwards; a time alone can't say which day. Now ISO-8601 UTC — and the comment claiming localtime_r (which isn't in std.c here, and whose result the code discarded via a dead _ = t;) no longer claims it.
  6. Bytes over 0x7f went into JSON verbatim, so one bad byte from a filename or truncated frame made the line unparseable.
  7. std.c.clock_gettime doesn't compile for Windows here. The file only ever built because nothing instantiated log().

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

$ craft --html-file p.html --headless --log-file f.log
$ cat f.log
[2026-08-27T12:02:08Z] WARN refused to open a new window for a URL the page
cannot send to the browser: craft-probe://payload

That record originates from a std.log.warn in macos.zig — a different module from the root — which is what proves the cross-module routing works. Also confirmed by running the binary:

behaviour result
two runs append 2 records (the old code left 1)
--log-json parses as JSON
--log-quiet in file: 1, on stderr: 0
--log-level error the warn is filtered out

An 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.warn and finding it still absent is what caught it.

Verified

zig build · zig build test · zig build test-js · x86_64-windows cross-build · zig fmt --check · tsc --noEmit · 511 bun tests · pickier 38 warnings, unchanged from main.

@github-actions

github-actions Bot commented Aug 27, 2026

Copy link
Copy Markdown

✅ Binary load time

rounds:    25 interleaved
base:      p50 16.7ms   p95 17.7ms   (15.3–20.0ms)
head:      p50 16.7ms   p95 18.1ms   (15.4–21.1ms)
delta:     -0.1%  (fails above +20.0%)

No binary load time regression.
What this measures

craft --help: process spawn, dynamic linking and argument parsing.
It never opens a window, so it cannot see a change in window or
webview startup — real startup is benchmarks/startup.bench.ts, which
needs a display.

Both binaries are measured interleaved on this runner and compared by
p50, rather than against a number recorded on another machine. On
byte-identical binaries that method reads within ~3.5%; the old one
swung 45%.

@github-actions

github-actions Bot commented Aug 27, 2026

Copy link
Copy Markdown

⚠️ Binary Size Report

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
glennmichael123 merged commit c602b3e into main Aug 27, 2026
10 checks passed
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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Host-side structured logging is built but never wired — no --log-file

2 participants