Skip to content

client-side: allow logging, with atomic and pid-tagged log lines - #3000

Draft
sylvestre wants to merge 6 commits into
mozilla:mainfrom
sylvestre:pr/client-side-logging
Draft

sylvestre wants to merge 6 commits into
mozilla:mainfrom
sylvestre:pr/client-side-logging

Conversation

@sylvestre

@sylvestre sylvestre commented Nov 7, 2026 •

Copy link
Copy Markdown
Collaborator

These are @glandium's commits from https://github.com/glandium/sccache/tree/client-side-fixes, rebased on main; authorship is his. The last commit is mine.

Client-side mode was silently turned off whenever SCCACHE_LOG was set, because concurrent CLI processes writing to one stderr produced interleaved, unattributable output. That also made client-side mode impossible to debug in CI, where the log is the only thing left after a build.

  • log lines are atomic (one write per line) and carry the pid of the process that emitted them, in a logging module shared with sccache-dist;
  • SCCACHE_ERROR_LOG is honored by every process, opened O_APPEND, and can name a per-process file (%p) or a directory;
  • client-side mode stays on when SCCACHE_LOG is set, and each invocation logs its argv at debug level.

The last commit is needed on main: the daemonize allow-list of inherited descriptors closed the log file logging::init opens before daemonizing, so the daemon's log stopped at "Create the log file" (test_rust_cargo_cmd_readonly_preemtive_block caught it). It also reads the pid for each record, since the daemon is a fork of the process that initialised logging.

The logging section that went into docs/ClientSideMode.md is dropped, main having removed that file; the same content is in docs/Architecture.md.

Two more commits of mine after review:

  • with a per-process path (%p or a directory), the daemon switches after forking to the file its own pid resolves to, instead of writing to the one named after its parent;
  • LineWriter, which split each record into one write per line, is replaced by a writer that writes the whole record in one write when it fits the atomic write size of a pipe (PIPE_BUF), and line by line only beyond it. Splitting every record is what let a concurrent writer get between the lines of a multi-line record.

glandium and others added 4 commits November 7, 2026 18:46
Several sccache processes log to the same destination concurrently: the
daemon, and every short-lived CLI process. In client-side mode the CLI
runs the whole compile pipeline, so it does most of the logging and the
interleaving becomes severe.

Interleaving between processes cannot be avoided, but unreadable output
can. Move logging setup into a shared `logging` module (used by both
`sccache` and `sccache-dist`, which had a copy of it) which:

- inserts the emitting pid into the record prefix, after the level, so
  every line can be attributed and grepped for, and
- emits each physical line with exactly one `write_all`, splitting
  multi-line records and repeating the prefix on each line. One
  `write_all` of a line is a single `write` syscall to unbuffered stderr
  or to a file, which is what keeps concurrent writers from tearing each
  other's lines.

Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
(cherry picked from commit b3bfc96)
The error log was only set up for the daemon, and by redirecting file
descriptor 2 onto it. A CLI process cannot do that: it passes the
compiler's diagnostics through its own stderr, and those have to reach
the build. So in client-side mode, where the CLI runs the compile
pipeline, the interesting log output had nowhere to go but the build's
stderr.

Make the error log the log destination for whichever process is logging,
opened with O_APPEND so that concurrent processes append after one
another rather than overwriting. Combined with one write per line, a
shared file is safe. The daemon keeps redirecting its stderr as well,
which is what captures panics and backtraces.

Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
(cherry picked from commit 62ae7eb)
A shared log file stays readable now that every line carries a pid, but
for a wide parallel build it is still N processes' output woven
together. Give people a way out: `%p` anywhere in SCCACHE_ERROR_LOG is
replaced with the pid, and a value naming an existing directory becomes
`sccache.<pid>.log` inside it. Any other value keeps the previous
shared-file behaviour.

Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
(cherry picked from commit a4aaef8)
Client-side mode was silently turned off whenever SCCACHE_LOG was set,
because N concurrent CLI processes writing to one stderr produced
interleaved, unattributable output. Log lines are now atomic and
pid-tagged, and SCCACHE_ERROR_LOG gives them a destination of their own,
so the restriction can go: only distributed compilation remains
incompatible.

Also log each invocation's argv at debug level, which is what lets a pid
in the log be matched back to what that process was compiling.

Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
(cherry picked from commit ee8ca3e)
@codecov-commenter

codecov-commenter commented Nov 7, 2026 •

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 92.53333% with 28 lines in your changes missing coverage. Please review.
✅ Project coverage is 76.42%. Comparing base (c1d7204) to head (aeda628).

Files with missing lines Patch % Lines
tests/logging.rs 88.95% 18 Missing ⚠️
src/logging.rs 95.85% 8 Missing ⚠️
src/bin/sccache-dist/main.rs 0.00% 1 Missing ⚠️
src/commands.rs 87.50% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main    #3000      +/-   ##
==========================================
- Coverage   79.20%   76.42%   -2.78%     
==========================================
  Files          75       76       +1     
  Lines       46306    46463     +157     
==========================================
- Hits        36675    35510    -1165     
- Misses       9631    10953    +1322     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Logging now writes to SCCACHE_ERROR_LOG from `logging::init`, which runs
before the daemon daemonizes. Daemonizing closes every inherited
descriptor except stdio and the ones it is told to preserve, and only the
file later used for stderr was on that list, so the daemon's log records
went to a closed descriptor and were lost from "Create the log file" on.
test_rust_cargo_cmd_readonly_preemtive_block, which reads the daemon's
log, caught it.

Preserve the logger's descriptor too. Also read the pid for each record
rather than once at startup: the daemon is a fork of the process that
initialised logging, so its lines carried its parent's pid.

With a per-process path (`%p`, or a directory), the file was also named
after that parent pid. Once daemonized, the daemon now switches to the
file its own pid resolves to, for its log records and its stderr.
LineWriter split each record env_logger hands over into one write per
line. That keeps a line from being torn when a record is longer than a
pipe writes atomically, but for every other record it is what lets a
concurrent writer get in between the lines of a multi-line record, which
one write would have kept together.

Write the whole record in one write when it fits the atomic write size
of a pipe (PIPE_BUF), and line by line only when it does not.
@sylvestre
sylvestre force-pushed the pr/client-side-logging branch from 9b4103d to aeda628 Compare November 8, 2026 11:30
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.

3 participants