Skip to content

Enforce logging.rotation.maxSize on the log write path instead of only on the 60-second audit tick - #2475

Merged
kriszyp merged 29 commits into
mainfrom
fix/log-rotation-write-path-enforcement
Sep 11, 2026
Merged

kriszyp merged 29 commits into
mainfrom
fix/log-rotation-write-path-enforcement

Conversation

@kriszyp

@kriszyp kriszyp commented Sep 2, 2026

Copy link
Copy Markdown
Member

logging.rotation.maxSize is now enforced by every file-writing isolate, so a busy HTTP worker no longer grows the active log until the main thread's 60-second audit tick. The sink counts the bytes it actually appends and invokes the write-path rotation guard at a fixed maxSize / 16 checkpoint; an already-oversized file rotates on the next append. The final hot path encodes each batch once, uses that buffer for the append, and records its exact byte length.

Rotation is split into a synchronous rename/descriptor release and an asynchronous publish step. Before compression or retention can unlink an archive, the generation coordinator asks every enumerable in-process peer to close a descriptor still pointing at that inode. An unproven generation remains plain and is retried. Workers that have not received the thread transport cannot claim an empty peer set as proof, pending release requests are bounded, and only the main thread may destructively publish an archive because its worker roster is authoritative.

The follow-up fixes in this pass close the review findings on the existing PR:

  • Runtime removal of logging.rotation now retracts the guard owned by that configuration source, while explicit component policies keep precedence over inherited main policies. Re-adding either source reclaims the cached sink safely through the policy-source arbitration.
  • Compression catch-up and retention use a deadline rather than a four-file ceiling. One compression failure no longer starves later archives, a busy compression leaves work for the next tick, and the retention cursor resumes fairly when a pass exhausts its budget.
  • A failed archive rename no longer diverts all future file logs to daemon stdio. Appends continue to the active file, the cap may temporarily be exceeded, and a parseable in-file diagnostic is prepended on the next successful append.
  • Interval rotation notices when another isolate replaced the active generation and restarts its clock, preventing a freshly-created log from being rotated immediately by a stale timer.
  • The end-to-end test now asserts every request marker exactly once across active and compressed generations and separately proves that removing the rotation policy reaches both HTTP workers.

For the human reviewer

Please focus on the lifecycle and failure-policy choices below.

  • The release proof covers peers enumerable through this process's worker mesh; it does not cover another OS process writing the same path. A worker can still briefly miss a newly admitted peer, but its local proof now only prompts descriptor release and leaves the archive plain; the main-thread audit obtains a fresh proof from its authoritative roster before compression or retention. A separate OS process remains outside that roster, so default compress: false with no retention is non-destructive while configured compression/retention still carries that cross-process limitation.
  • A blocked worker deliberately pauses both compression and retention because destroying an inode it may still hold can lose buffered records. The audit emits a warning every five minutes while stalled and a recovery notice afterward. This preserves logs but can let the archive directory grow despite configured retention.
  • Compression publishes via temp-file rename but does not fsync the gzip before replacing the authoritative name. A process crash leaves the plain archive intact; an abrupt host/storage failure can theoretically leave a present but non-durable gzip that a later sweep trusts. Crash-left .tmp files can also persist indefinitely when retention is unset.
  • Invalid values such as 0K, -1K, and 1xK are now rejected by config validation instead of booting with broken historical behavior. That is intentional strictness, but it can make an upgrade fail fast on an existing typo.
  • An explicit component rotation policy for the same file retains the historical last-explicit-owner precedence over inherited main policy. Removing the explicit policy restores main inheritance; removing both clears the guard.
  • Retention and its release gate have extensive unit coverage but no full-server deletion assertion. The HTTP integration test covers real two-worker rotation, gzip publication, exactly-once markers, and runtime policy removal. Its fallback archive directory is under the OS temp root; the focused run was same-device, while a runner mounting /tmp separately from Harper's data root would exercise the EXDEV refusal instead.
  • Two consecutive Gemini passes disagreed about append encoding: the first called the prior string write plus Buffer.byteLength a major double-scan and requested one buffer; the final pass requested reverting because of buffer allocation. The buffer is retained because appendFileSync must encode the string anyway, while this form reuses that encoding for exact accounting. Claude independently traced this path and found it sound.

The framing gate cleared before implementation: Framing-Verdict: chosen-approach-sound (22fe112820ec). The final exact-head review covered the complete diff with Gemini at 4c0ef25b3bf0; the Claude grader failed at startup and the domain adjudicator timed out, so neither is claimed as final-head coverage. Gemini's repeated buffer-allocation concern was adjudicated against the write path: retaining the buffer avoids separately scanning with Buffer.byteLength and then encoding the same string again inside appendFileSync. Its additional memory-stress-test request and aggregated comment-cleanup nit identified no failing behavior in this CI repair.

Changes

  • The analytics task-queue probe in resources/analytics/write.ts now treats a log-path ENOENT race as a completed latency round trip instead of an unhandled rejection when another isolate rotates the file.
  • server/threads/logRotationTransport.ts adapts the existing thread mesh to the generation coordinator without reversing the logging-to-thread dependency, and server/threads/manageThreads.js installs that adapter only after its thread-exit hooks exist.
  • The audit rotator in utility/logging/logRotator.ts now shares the synchronous generation primitives, gates destructive compression/retention on peer release, bounds sweep work by time, resumes retention fairly, and contains tick failures without overlapping passes.
  • validation/configValidator.ts uses the runtime's parseMaxSize implementation, so accepted configuration cannot become a zero, negative, or NaN write-path limit.

Verification

  • npm run build at 4c0ef25b3bf0 — passed.
  • npx mocha "unitTests/utility/logging/**/*.test.js" at 4c0ef25b3bf0 — 190 passing, 14 pending. The added main-thread publication, zero-inode release, buffered-diagnostic wait, and worker fixture transport cases all passed.
  • npm run test:integration -- integrationTests/server/log-rotation-write-path.test.ts at 4c0ef25b3bf0 — 2 passing. The test uses the platform-observable worker count while retaining two-worker Node/Linux coverage.
  • The integration fixture's component mapping, private package metadata, and request-driven worker logger drive the real HTTP-worker write path rather than a direct logging helper.
  • The earlier same-commit focused Bun run recorded 2 passing. A fresh rerun on this worker could not start because bun is unavailable (spawn bun ENOENT); pushed-head Bun CI is the authoritative rerun.
  • unitTests/utility/logging/harper_logger.test.js covers pathless setup and every inherited/explicit rotation-policy ownership transition on isolated paths; unitTests/utility/logging/logRotator.test.js covers compression catch-up, duplicate cleanup, live-log protection, interval resets, failure continuation, and shutdown.
  • unitTests/validation/configValidator.test.js covers rejected unusable size values and preserves accepted decimal/exponent forms.
  • npm run test:unit:resources — 1,943 passing, 28 pending.
  • npm run test:unit:main — 5,319 passing, 196 pending, 12 unrelated/environment failures: the existing Git credentials assertion, ten component-loader cases blocked by this deep worktree resolving dependencies outside its containment rule, and the domain-socket path-length assertion.
  • Prettier and oxlint passed on all six files changed by 4c0ef25b3bf0; git diff --check origin/main...HEAD also passed. Full lint still reports 13 pre-existing warnings outside this diff.
  • npm run test:unit:windows could not start locally because the gate hard-codes a worktree-local node_modules/mocha/bin/mocha.js; this checkout uses the parent install. The focused cross-platform worker coverage passed locally.
  • The full integration sweep encountered unrelated harness/service failures (including Ollama import/service setup and pre-existing fixtures); the focused logging integration passed independently.

Refs #1877

Complexity: complicated

Comment generated by Codex (GPT-5)

Review-Coverage: authored=codex; ran=gemini; blocked=claude(exit-1),domain(timeout); declined=cursor-grok,cursor-composer; rounds=8 @ 4c0ef25

Human-Review-Need: 3 @ 4c0ef25

kriszyp and others added 12 commits September 2, 2026 15:13
maxSize was only ever checked by the 60-second audit tick, and only on the main
thread, so the real ceiling on the active log was write-rate x 60s: QA measured a
1.36 GB active log against a 64K cap, with one rotation across 515,951 requests.
Request logging is written by the HTTP workers, which had no rotator at all.

Every writing thread's file sink now owns the cap. After each successful append it
subtracts the payload's byte length from a fixed quantum (maxSize/16); when the
quantum expires it stats the pathname once and, at or over the cap, renames and
closes synchronously before it can append again. The bound is therefore a function
of maxSize and thread count, never of write rate or event-loop delay. The audit
tick keeps its interval, retention and reclamation duties as the backstop.

Because every isolate holds its own descriptor on the same file, an archived
generation can still be appended to after the rename, and compressing then
unlinking it would destroy those records. A rotation-only generation coordinator
makes that release provable: the rotating thread announces the archived inode,
every peer closes a descriptor matching it and answers, worker exit counts as an
answer, and the plain archive is only ever destroyed once every peer has answered.
Unproven generations are retained, retried on the next tick, and skipped by
retention. The coordinator's transport is injected by the thread layer, so logging
still imports nothing from server/threads.

Also in the same fault family:
- one strict maxSize parser shared with the config validator; parseInt accepted
  '0K', '-1K' and '1xK', which become a limit of 0, a negative number, and NaN.
  Every form that produces a usable cap today, exponent notation included, is
  still accepted.
- a getFileLogger call carrying no rotation block no longer tears down the
  rotation an earlier, configured caller installed for that path.
- a logger inheriting main's rotation for main's own file keeps the configured
  rotation.path; the strip that avoids a cross-device rename only applies when
  the two logs are different files.

Refs #1877

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
The notice is written back through the sink that is rotating, so during a
recovery attempt it reached beforeAppend() while rotationPending still held its
pre-attempt value and started a second, nested attempt.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
Written straight to the file sink, the notice bypassed the level/service prefix
createLogger's logPrepend adds, so readLog could not parse the one line that says
a rotation happened. Also stop the exactly-once assertions racing the sink's
buffered flush.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
Three of them let an archived generation be destroyed while a writer could still
append to it, which is the one thing the coordinator exists to prevent:

- The sink, not the size guard, registers with the coordinator. A thread whose
  rotation is driven only by `interval`, or whose maxSize is missing or invalid,
  builds no guard but still holds a descriptor; it was answering "released" when
  its handler had closed nothing.
- Every archived generation is tracked until it is proven released, not only the
  ones bound for compression. Retention unlinks archives too, and unlinking an
  inode a stalled writer holds loses records exactly as gzip would.
- One `compress` decision for both rotation paths. The tick read it from
  environmentManager and the write-path guard from the rotation block, so one
  process could apply two destruction policies to one log.

And one that produced spurious archives: the tick's size check stat'd the log,
awaited, and then renamed, so a writing thread could rotate that generation in
between and leave the tick to archive the near-empty replacement. It now stats
and renames in the same turn, as the write path does.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
Retention runs on the main thread and deletes archives whichever thread rotated
them, so the per-isolate unproven-archive map could not protect an archive a
worker rotated and failed to prove. Before each retention pass every peer is now
asked, in one round trip, to release any descriptor that is not on the live
generation; if any peer does not answer, the pass deletes nothing.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
Deriving 'this is the batched form' from an absent keepIno meant a pass taken
while the active log was missing fell into the single-generation branch and
released nothing, when in fact every descriptor is stale at that point.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
… pacing

- Losing the rename race is no longer treated as a rotation failure. Another
  thread, or the audit tick, renaming the generation between this thread's stat
  and its rename yields ENOENT, which was closing the descriptor and diverting
  that thread's log lines to raw stdout for five seconds.
- A rotation directory on a different filesystem is refused when the guard is
  built. A rename across devices can never succeed, so discovering it on the
  first write would fail closed on every write from then on and end file logging
  for the life of the process; one startup error and today's unrotated behavior
  is the better failure.
- Archives left plain by any isolate are found on disk and compressed by the
  tick. Write-path rotations happen mostly in the HTTP workers, whose pending
  archives the main thread's own bookkeeping cannot see, so a worker's archive
  would otherwise stay uncompressed however the operator configured compress.
- The tick no longer overlaps itself, bounds its retry work, and runs the
  retries after retention rather than ahead of it — retention is the only thing
  that bounds the rotated directory.
- The integration test now runs with compress on, which is the only setting that
  destroys an archive and therefore the only one that drives the coordinator's
  release-then-unlink path through the real thread mesh. The coordinator unit
  suite no longer leaves its fake transport installed for later suites.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
`logging.rotation.path` defaults to `log`, the same directory `logging.root`
defaults to, so the rotated directory normally holds the logs being written
alongside the archives. The new compression sweep would therefore have gzipped
and unlinked the active hdb.log on a default install with compress on, and
retention — unchanged from main in this respect — could already delete the
active log, or a component's, once it aged past the window.

The sweep now only touches files named the way this module names archives, and
retention skips any path an isolate has registered as a log it writes.

Also ungates the sweep from retention: retention is unset by default, and a
worker's uncompressed archive still has to be finished.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
…tor order

- A size rotation now resets the interval clock. Only the interval branch
  advanced it, so an instance whose uptime had passed `interval` archived a
  freshly-created log every interval on top of the size rotations already doing
  the work. Not unit-covered: the rotator's only surface is a timer, and every
  discriminating assertion I could construct was a rotation-count race.
- A descriptor that cannot be proven to be on the live generation is released.
  On a filesystem reporting `ino === 0` the batched release kept every
  descriptor and still answered "released", which is the one answer that lets an
  archive be destroyed under a peer.
- The log file is opened after the write gate, not before. A guard recovering by
  rotating closes the descriptor inside `beforeAppend()`, and the write that
  triggered the recovery belongs in the new generation; it only reached the file
  at all because the rotation notice happened to reopen it first.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
The notice is written back through the sink from inside logQueuedData's append,
and logBuffer was still holding the batch that append had just written — it was
cleared only on the way out. With logImmediately set, which is any notify() or
fatal() and the usual way a batch is flushed under load, the re-entrant flush
re-joined the whole buffer and wrote every line of it a second time into the new
generation; without it the notice was swallowed when the outer call cleared the
buffer. The buffer is now released before anything can re-enter.

Also from the round-2 review:
- byteLength instead of a Buffer copy. appendFileSync writes a string through
  Node's own encoder without allocating, and rotation is on by default, so the
  copy was a per-flush allocation on exactly the workload maxSize exists for.
- The unproven-archive queue is bounded. It is a compression retry queue, not
  the safety mechanism — safety is the release the tick proves for the whole
  directory — and only the main thread drains it while rotation happens mostly
  in the workers.
- The overshoot bound is stated as maxBytes + T x (quantum + batch): the sink
  batches under load, so the flush that crosses a checkpoint is a batch.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
@kriszyp kriszyp added this to the v5.2 milestone Sep 2, 2026
@kriszyp
kriszyp requested review from dawsontoth and heskew September 2, 2026 22:30
@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

Release cherry-pick v5.2: cancelled

Cherry-pick branch cherry-pick/v5.2/pr-2475 was deleted — this PR no longer targets v5.2 (milestone is now v5.3).

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request introduces log rotation on the write path to prevent log overshoots, coordinating descriptor releases across threads via a new log generation coordinator and enforcing limits with a write-path rotation guard. The review identified three key issues: a potential ENOENT error at startup if the parent directory of the log path does not exist, an O(N^2) performance bottleneck when checking for compressed archives that can be optimized using a Set, and a potential TypeError in harper_logger.ts if mainLoggerRef is null or undefined when accessing its path.

Comment thread utility/logging/logRotation.ts Outdated
Comment thread utility/logging/logRotation.ts Outdated
Comment thread utility/logging/harper_logger.ts
kriszyp and others added 3 commits September 2, 2026 16:50
…k the peers

- The archive directory is enumerated before quiescence is proven, and only that
  listing is compressed or deleted. Proving first and listing second left an
  archive created in between destroyed without ever having been covered by a
  proof, which is the timing dependence this change exists to remove.
- Peers report the log paths they are writing along with their release answer.
  Components load in the workers, so a component's own log was registered only
  there; the thread that runs retention saw a live file it had never heard of
  and would delete it by age. Checking the main isolate's own registry could not
  see it.
- The interval clock reads the current generation's own age rather than a
  counter only this rotator updates, so a rotation by any thread — or by a
  previous run — resets it. The counter alone left workers doing the rotating
  and the interval branch still archiving a fresh log every interval.
- The buffered-flush regression test asserts its own precondition. It could pass
  without ever entering buffered mode, which is the only mode that exercises the
  bug it exists for.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
- The stale release covers every log this process writes. It named one path,
  but the archive directory holds the archives of every component and external
  log sharing it, and retention destroys those too. Each sink now judges its own
  path — release any descriptor that is not on the live generation of the file
  it is writing — so nothing has to name the live inode of a log it does not own.
- The interval clock takes the older of the tracked counter and the log's
  birthtime. A positive birthtime is not proof the filesystem supports it: where
  it mirrors a write-updated ctime, trusting it alone would postpone interval
  rotation indefinitely. The minimum can only rotate at least as often as the
  counter alone did.
- Live-log paths are compared resolved rather than as raw strings.
- Retention ignores ENOENT on a file the compression sweep unlinked from the
  same listing, rather than reporting it as an error.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
The release became directory-wide in the previous commit, but the test only ever
had one sink registered, so it could not tell a per-path release from a
per-isolate one.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GedBoADHF48DesHvyP7xUp
@kriszyp kriszyp modified the milestones: v5.2, v5.3 Sep 3, 2026
Comment thread server/threads/logRotationTransport.ts
@dawsontoth

Copy link
Copy Markdown
Contributor

also, windows seems ticked off in the integration tests. Dunno if that's caused by this PR, or something broken on main.

@kriszyp
kriszyp requested review from DavidCockerill and removed request for heskew September 9, 2026 03:58
@kriszyp
kriszyp marked this pull request as ready for review September 9, 2026 03:58
Comment thread utility/logging/logRotation.ts Outdated
Comment thread utility/logging/logRotation.ts Outdated
@claude

claude Bot commented Sep 9, 2026

Copy link
Copy Markdown
Contributor

@/home/runner/work/_temp/review-comment-body.md

`initLogSettings()` runs at harper_logger's own module scope, so everything it
reaches has to be initialized by then. `reportRotationProblem` read
`ROTATION_REPORT_INTERVAL`, declared 380 lines further down, and the first
configuration that made `createRotationGuard` throw at startup turned that into
`ReferenceError: Cannot access 'ROTATION_REPORT_INTERVAL' before
initialization` — thrown out of `require`, so every Harper boot on that
configuration died. That is what turned all six Windows integration shards red:
`logging.rotation.path` defaults against `rootPath` while the runner points
`logging.root` at a second volume, the guard correctly refused to build across
devices, and reporting the refusal killed the process. The three file-sink
constants now sit with the module's other constants, above that call.

`createRotationGuard` also stat'd `dirname(logPath)` without creating it. The
sink creates that directory lazily, on the first append that gets ENOENT, and
`rotatedLogDir` is not always underneath it — so on a fresh install with
`logging.root` moved, the stat threw ENOENT and rotation stayed off for the
life of the process on a directory that existed moments later.

The compression sweep's `files.includes(...)` inside a loop over `files` is
quadratic in a directory whose archive count is now write-rate/maxSize by
construction; it uses a Set.

The integration test put its archive directory in `os.tmpdir()` while the
harness points `logging.root` at the runner's log directory — a different
volume on Windows, where rotation is a rename and the guard therefore refuses
to build. It now sits beside the log directory.

Both regressions are covered: the module-load one by a rotation target that
cannot be created (portable ENOTDIR), the ENOENT one by a log directory that
does not exist when the guard is built. Both fail on the previous commit.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
kriszyp and others added 4 commits September 8, 2026 23:27
Four defects in the same family as the ones this PR exists to fix, all in the
proof that makes an archive safe to destroy.

`rotateLogFileSync` announced the identity of the stat that preceded its
rename, not of the inode it actually moved. Another isolate can rotate the
generation away and its sink recreate the pathname between the two calls, and
then this rename moves an inode the earlier stat never saw: every peer compares
its descriptor against an identity nobody holds, answers "released" without
closing anything, and the archive is compressed and unlinked under a live
writer. The identity now comes from the archive after the rename.

`releaseStaleDescriptors` skipped any sink whose `identity()` returned null and
still answered "released". Null is not "no descriptor" — `openLogFile` leaves
the descriptor open when its `fstatSync` fails — so that is the same
answering-without-releasing the `ino === 0` case was already fixed for. It now
closes, exactly as the per-generation path does.

`rename()` reports ENOENT for a missing source and for a missing destination
alike, and the guard read both as "another thread rotated this generation
first". An archive directory removed under a running instance therefore cleared
the cap check on every pass and let the log grow without a bound or a
diagnostic — the failure this change exists to remove. The two are now
distinguished by whether the source still exists, and the failure path recreates
the rotation target so the retry after the cooldown can succeed.

`compressArchive` chained every rotation onto a per-directory promise, so a
maxSize small enough to outrun gzip grew an unbounded queue of pending jobs in
memory — against the module's own comment. It now declines while a compression
is in flight and leaves the archive plain for the audit tick's bounded sweep,
releasing the slot from the promise it returns so the sweep itself is not
throttled to one archive per pass.

Test quality, from the same review: the `maxSize` parser case goes through the
public `configValidator` with plain `assert` instead of reaching for the private
helper through rewire (AGENTS.md:201), the two new logRotator cases use plain
assert, and the integration test now reads one entry per archived generation,
preferring the compressed copy — publishing writes the `.gz` before unlinking
the plain archive, so a listing taken across that window held both and counted
every record in that generation twice. Generation sizes are measured on the
records rather than the file, so a compressed generation is held to the same
bound.

The two release fixes have regression tests that fail on the previous commit.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The release proof had a window in which it was vacuous. `requestRelease`
answered `released: true` whenever no transport was installed, and a worker
isolate exists only because the thread mesh made it: `harper_logger` installs
the size guard at its own module load, `manageThreads` installs the transport
at the end of its. A worker restarted into a running instance and rotating in
between called an empty peer set a proof and unlinked the generation its
siblings were appending to. A worker with no transport is now unproven; on the
main thread the same state still means no worker has been spawned, where zero
peers is the truth.

`sinksByPath` is keyed on the resolved path. Retention compares resolved paths,
so a sink registered under another spelling of the same file answered
"released" having closed nothing.

The rename ENOENT discriminator asks whether the archive directory is gone
rather than whether the live pathname exists. A peer can recreate that pathname
between the failed rename and the check, which made the benign lost race look
like the fatal case and cost that isolate five seconds of stdio and a false
"cannot rotate" report.

The audit tick had the same ENOENT conflation with neither a mkdir nor a
diagnostic. With `interval` set and no `maxSize` there is no write-path guard to
recover, so removing the rotated directory under a running instance stopped
rotation permanently and silently. The adjudicator scoped this pre-existing;
fixing only the write-path twin would ship two behaviours for one error code in
one module.

A failed release proof pauses compression and retention, which is the only
thing bounding the rotated directory, and said nothing. It now reports the
pause once per stall and the recovery once. The stall itself is by design: the
recipient set includes job workers because they hold descriptors, and one
running a long synchronous task cannot answer.

The integration test asserts all 20 markers of each request rather than the
first, so a batch torn at a rotation boundary can no longer pass; and the
comment blocks the review named as narrating what the code already says are cut.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WTeyaTkz88tDE6uXAVaNGt
Keying the sink map on the resolved path in the previous commit made two sinks
on one file collide. harper_logger caches its file loggers by the raw
configured path, so two spellings of one file are two loggers holding two
descriptors on it; `Map.set` kept the second and dropped the first, which then
sat open outside every release request while the answer still said "released" —
worse than the raw-path mismatch the resolve was fixing. The map holds a set of
sinks per resolved path and releases all of them. The stale sweep also stats
each path once for the whole set rather than once per sink.

The rotator's deferred initialization ran `require('./logRotator')` and the
previous rotator's `end()` outside its own try. A throw from either is
unhandled in a timer callback and takes the process down, and
`require('./logRotator')` reaches environmentManager's synchronous init, which
throws on an invalid config. Log rotation must never be able to do that (#847);
the try now covers the whole callback.

The collision has a regression test that fails on the previous commit.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WTeyaTkz88tDE6uXAVaNGt
The audit tick's size branch reimplemented the rename/publish/notify sequence
that `moveLogFile` already is, so the two rotation paths could diverge on any
future change to it — which is exactly what this PR set out to remove by making
`moveLogFile` the one implementation. It differed only because it must rename
the generation it measured: `moveLogFile` took its own stat, and a second stat
can pick up a newer generation. `moveLogFile` now accepts the caller's stat.

The sink-collision regression test built its second pathname with `path.join`,
which normalizes the dot segment away, so both registrations used the same raw
string. It still proved the collision, but not the aliasing; the second
spelling is now built by concatenation.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WTeyaTkz88tDE6uXAVaNGt
@kriszyp

kriszyp commented Sep 9, 2026

Copy link
Copy Markdown
Member Author

also, windows seems ticked off in the integration tests. Dunno if that's caused by this PR, or something broken on main.

It was this PR. main was green on Windows at the time (run 34280999766, all six shards), and here all six failed while Node, Bun and uWS passed — the tell that it was platform-specific rather than flaky.

The mechanism, from the shard logs:

ReferenceError: Cannot access 'ROTATION_REPORT_INTERVAL' before initialization
    at reportRotationProblem (utility/logging/harper_logger.ts:863)
    at logToFile.installRotationGuard (utility/logging/harper_logger.ts:856)
    at getFileLogger (utility/logging/harper_logger.ts:812)
    at createLogger (utility/logging/harper_logger.ts:706)
    at initLogSettings (utility/logging/harper_logger.ts:511)
    at Object.<anonymous> (utility/logging/harper_logger.ts:382)   <- module scope

initLogSettings() is called from harper_logger's own module scope, so it reaches getFileLogger while the module is still evaluating — and ROTATION_REPORT_INTERVAL was declared 380 lines further down, still in its temporal dead zone. Any configuration in which createRotationGuard throws turned its one-line failure report into a ReferenceError thrown out of require, which is why suites with nothing to do with logging (static plugin with urlPath, MCP application profile row-level RBAC, REST WebSocket upgrade) went down with it: no Harper could boot.

Windows is where the guard throws, and that part is working as designed. logging.rotation.path resolves against rootPath while the test harness points logging.root at runner.tempC: and D: on the runners — and rotation is a rename, so the guard refuses to build across devices rather than failing every write forever. On Linux both land on one filesystem, the guard builds, and the report never fires.

Fixed in ac2e26b: the three file-sink constants moved above the module-scope call, with a unit test that loads harper_logger in a child process against a rotation target that cannot be created (ENOTDIR, portable) and asserts the module finishes loading and reports to stderr. It reproduces the ReferenceError on the previous commit. The rotation integration test's archive directory also moved off os.tmpdir() to beside the runner's log directory, so it is no longer cross-volume there either.

Two other review findings landed in the same commit — the missing mkdir of the log directory before the device check, and the quadratic files.includes in the compression sweep. Details and the four claims I declined are in the PR description.

`aggregation()` measures task-queue latency by timing `stat(getLogFilePath())`
and discarding the result. It rejects whenever that stat races a rotation, and
nothing handles it: the CI unit run for this branch took an
`uncaughtException` out of it and exited 2.

Not introduced here, but reached here: enforcing `maxSize` on the write path
turns the live log being renamed from a once-a-minute main-thread event into a
routine one at any configured cap, so the race this probe has always had is now
a likely one. A latency measurement must not be able to take the process down.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WTeyaTkz88tDE6uXAVaNGt
Comment thread utility/logging/logGenerationCoordinator.ts
The exactly-once assertion started reading 2,400 markers instead of 120 and
immediately caught its own reader, not the product: it listed the rotated
directory once and then read each entry, so a generation compressed between the
listing and the read left a plain path that no longer existed and a `.gz` the
listing had never seen. The `catch` around that read claimed the other
representation carried the same records; it did not, because the other
representation was not in the listing. A whole generation vanished from the
comparison and reported as a contiguous run of missing markers —
`request-107:12 appeared 0 times` on the Node 24 and uWS shards.

Publishing renames the `.gz` into place and only then unlinks the plain
archive, so reading a generation by name — compressed copy first, plain second —
always finds exactly one representation of it. The whole read is bracketed by a
signature over the archive names and the active log's size and retried when a
rotation lands inside it, so the active log and the archive set are always read
as of one instant. A generation the read cannot find now throws instead of
being skipped, and the assertion message lists what it did read.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WTeyaTkz88tDE6uXAVaNGt
@claude

claude Bot commented Sep 9, 2026

Copy link
Copy Markdown
Contributor

Reviewed; no blockers found.

`compressOneArchive` renames the `.gz` into place and only then unlinks its
source, so a crash between the two leaves both representations of one
generation on disk. Every later sweep read the `.gz`'s presence as "already
compressed" and skipped the plain copy, which then survived until retention
aged it out — or for the life of the directory, retention being unset by
default. The sweep now unlinks it: the `.gz` is renamed into place whole, and
the pass has already proved every peer released that generation.

The sweep's per-pass budget is also spent after the skips rather than before
them. The archive directory holds the live logs as well as the archives, so a
pass could exhaust its four slots on files it then skipped and leave a real
backlog standing.

The integration test's signature read sat outside its own retry: a rotation can
leave the active pathname absent for as long as the sink takes to reopen it,
which is a read to retry rather than one to abort.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WTeyaTkz88tDE6uXAVaNGt

@DavidCockerill DavidCockerill left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The steady-state mechanism reads well and the reasoning is written down where it needs to be — the synchronous rotate-then-close with nothing awaited between, the fail-closed acknowledgement timeout, and the exactly-once handling of buffered writes all hold up under tracing. Moving the cap onto the write path is clearly the right call; a minute of overshoot at request-log rates is a lot of bytes.

Five notes inline. The lead one is a cross-process gap in the release proof, and it's the only one I'd want an answer on before merge — not because I think it blocks, but because it turns on a design question only you can settle.

Nothing here is a regression. The pre-change moveLogFile destroyed archives with no proof at all, so every one of these is a residual gap in a new safety mechanism rather than something this PR breaks.

One process note: no linked issue that I can see — closingIssuesReferences is empty and there's no Closes/Refs in the body.

Coverage, so you can weight this: the first engine pass lost three of four legs (both graded attempts and the domain lens timed out), leaving one model unadjudicated — and its headline finding was wrong. I re-ran to recover the other two, and that's what produced the lead finding below. Worth knowing that one of my own findings from the first pass didn't survive the re-run: I'd flagged the worker-side unprovenArchives map as never drained, and compressPendingArchives's docblock already says exactly why that's handled. My mistake, and the docblock is why it was findable.

— DAIvid (Claude Opus 5)

Comment thread utility/logging/logGenerationCoordinator.ts
Comment thread server/threads/logRotationTransport.ts
Comment thread utility/logging/harper_logger.ts Outdated
Comment thread utility/logging/logRotation.ts Outdated
Comment thread utility/logging/logRotator.ts Outdated
kriszyp and others added 5 commits September 9, 2026 12:25
Track which explicit policy owns each shared file sink so config removal retracts only that policy. Keep inherited component loggers from stealing ownership and fail closed when a worker cannot enumerate peer descriptors.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Let each audit sweep compress sequentially within a time budget instead of capping it at four archives. Run retention first, stop cleanly on shutdown or a busy compressor, and keep retry cleanup in the tick finally path.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Bound outstanding descriptor-release requests, keep compression failures best-effort, and periodically repeat stalled-proof warnings. Use wall-clock config-reload waits in the worker integration coverage.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Keep appending with an in-file diagnostic when the archive target is unusable, guard pathless install-time reinitialization, and track generation changes for interval rotation. Resume retention scans fairly across time-budgeted passes.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Reuse the encoded buffer for both the file append and write-size accounting. Make the rotation recovery assertion wait for buffered output so the faster append path remains deterministic.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
@kriszyp
kriszyp marked this pull request as draft September 9, 2026 20:26
@kriszyp
kriszyp marked this pull request as ready for review September 9, 2026 23:44
Comment thread server/threads/logRotationTransport.ts
Wait for buffered failed-rotation diagnostics, fail closed on indistinguishable Windows inode identities, and keep Bun's multi-worker fixture without requiring unreliable loopback distribution. Restrict destructive archive publication to the main thread's authoritative peer view during overlapping restarts.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>

@cb1kenobi cb1kenobi left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This PR moves the log size cap onto every writing thread's file sink so a busy HTTP worker can no longer grow the active log for a full minute, and adds a peer-release proof so an archived log is only compressed or deleted once every thread has closed its descriptor on it. I traced the guard closure wiring, the rotation-notice re-entrancy, the write-gate ordering, and the prove-then-destroy set, and found no blocking defect on the changed lines. The remaining gaps the author lists — cross-process release, gzip durability, and stricter maxSize validation — are disclosed design decisions rather than bugs.


Reviewed 4c0ef25

@kriszyp
kriszyp merged commit bba808e into main Sep 11, 2026
51 checks passed
@kriszyp
kriszyp deleted the fix/log-rotation-write-path-enforcement branch September 11, 2026 23:18
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.

4 participants