# Logging

## Selection

`scribe`, `scribe-server`, `scribe-auth`, and `scribe-runner` accept `--log-level off|error|warn|info|debug|trace`,
`--log-filter 'warn,scribe_server=info,scribe_objects=debug'`,
`--log-format text|json`, `-v` (debug), `-vv` (trace), `-q` (errors only, no
progress). `SCRIBE_LOG` holds the same target/level filter syntax.

`scribe-gateway` and `scribe-ctl` accept `--log-level`, `--log-format`, and
`--timings`, and honor `SCRIBE_LOG`. They do not expose `--log-filter`, `-v`,
or `-q`. All but `scribe-runner` accept global `--json` for command results; see
[JSON output for automation](/docs/json-output.md). JSON result selection is independent
of logging format.

Precedence: explicit CLI selection > `SCRIBE_LOG` > configuration
(`[logging].filter`, server only) > default (`info` for `scribe-server`,
`scribe-auth`, `scribe-gateway`, and `scribe-runner`; `warn` for `scribe` and
`scribe-ctl`).
`--log-level` with `--log-filter`, or `-v` with `-q`, is an error. A malformed
filter from any source is an error even when overridden. All levels remain
selectable in release builds; nothing is compiled out.

## Sinks

- Client: stderr. Command results go to stdout only; `--json` output remains
  parseable with `-vv` enabled.
- Server: stderr by default; `--log-dir` or `[server].log_dir` selects daily
  files `scribe-server.<date>.log` with `[logging].keep_files` retained
  (default 14). Auth: the same with `--log-dir` and `--log-keep-files`,
  files `scribe-auth.<date>.log`.
- Terminal stderr uses colored levels; `NO_COLOR=1` or `TERM=dumb` disables
  them, and files and redirected streams are plain.
- Both sinks sit behind a bounded, lossy, off-thread queue (32,768 lines).
  When the sink stalls, events are dropped and counted; the count is reported
  at shutdown. Individual events are bounded by keeping peer strings short at
  the emission site. Sink write failures are counted, never propagated into
  request paths. An unwritable log directory fails startup. Diagnostic events
  are never fsynced; logs are not part of commit authority.
- Shutdown flushes the queue with a bounded wait (about 1.1 s in
  tracing-appender 0.2). Forced kill may lose the last buffered lines.

## Levels

ERROR failed operations, integrity or persistence failures. WARN recoverable
failures, retry exhaustion, degraded resources, plaintext exposure. INFO
lifecycle, `submit.committed`, `submit.rejected` (a client outcome, not a
server error), maintenance outcomes. DEBUG batching, publication, cache,
scheduling, retries. TRACE per-request timings; never raw asset bytes.

## Events and context

Stable `event` names: `server.starting`, `server.ready`, `server.draining`,
`server.stopped`, `repo.created`, `repo.opened`, `objects.published`,
`submit.committed` (emitted only after the durable commit; a lost response
does not turn it into a failure), `submit.rejected`, `lock.acquired`,
`lock.released`, `request.rejected`, `request.failed`, `conn.opened`,
`conn.closed`, `sync.done`, `sync.displaced`, `submit.accepted`,
`init.done`, `backup.done`, `restore.done`, `server.plaintext_exposed`,
`auth.listening`, `auth.stopped`, `auth.failed`, `fault.armed` (test builds
only).

Admission and identity events: `conn.refused` (warn, with `reason` `source
pending limit` or `connection limit`), `conn.evicted` (debug, the oldest
pending connection closed to admit a newcomer), and `conn.principal_limit`
(warn, one user at `max_connections_per_principal`) on storage; the auth
service logs `connection.refused` and `connection.evicted` (debug),
`login.succeeded` and `login.failed` (info), their administrator sign-in
counterparts `admin_login.succeeded` (with `expires`), `admin_login.failed` and
`admin_login.forbidden` (info, a correct password of an account that is no
auth administrator), and `login.throttled` (warn, the per-username ceiling,
shared by both sign-ins). None carries a password or key. A storage server that receives an auth answer from
behind the newest auth revision it has seen logs `auth.rollback_detected`
(error) and refuses it; a new auth incarnation after `scribe-auth restore` is
logged as `auth.incarnation_changed` (warn), and the restore itself as
`auth.restored` (warn) by `scribe-auth`. A client that cannot revoke its
previous session during a new login logs `session.revoke_failed` (warn).

Lock releases are audited under the `scribe_server::locks` target. A holder
releasing its own lock emits `lock.released` at debug level; a forced release
of another workspace's lock emits `lock.force_released` at info level. Both
carry `repo`, `path`, `generation`, `workspace` (the releasing workspace),
`principal` and `principal_id` (the authenticated caller; absent for an
in-process local service), and `forced`. `lock.force_released` adds
`holder_workspace` and `holder`, the workspace and author that held the lock.
Online verification adds `integrity.pass_completed`, `integrity.scan_failed`,
and `integrity.generation_changed`. Both the online checker and offline doctor
emit `integrity.object_failed` with the repository, object identity, check name,
and error. See [Online integrity checking](/docs/online-integrity.md) for coverage
and saved progress reports.

Fields include repository, workspace, session, operation id, request id,
change number, counts, bytes, gate wait, transaction hold time, flush counts
and time. Timestamps are UTC `YYYY-MM-DDTHH:MM:SS.mmmZ`.

JSON logs use one object per line, with control characters, quotes, and newlines
escaped inside string values. Passwords, private keys, credential file
contents, asset file contents, and raw frames are never logged.

## Measuring logging overhead

Developers can measure logging overhead with:

```sh
cargo bench --locked -p scribe-log --bench logging
```

Results depend on the machine, output format, sink, and event volume. Use the
performance harness with phase timings disabled for regression comparisons;
enable timings when investigating where an operation spends time.

## Opt-in phase timings

All six executables accept the global `--timings` flag, before or after a
subcommand. For `scribe`, `scribe-server`, and `scribe-auth` its help text is:

```text
      --timings
          Report nested phase timings to the diagnostic sink (text or --log-format json)
```

`scribe-runner` describes it as reporting nested phase timings to the
diagnostic sink; `scribe-gateway` and `scribe-ctl` report their phase timings
to stderr.

Examples:

```sh
scribe --timings submit --message "Update assets"
scribe sync --timings --log-format json
scribe-server serve --config server.toml --timings
scribe-auth serve --data-dir auth-data --pepper-file auth.pepper --revision-file auth.revision --tls-cert server.pem --tls-key server-key.pem --timings
```

Timing records use the `scribe_timings` target and the existing diagnostic
sink: stderr by default, or the service's configured log directory. They
never go to stdout; `--json` command output remains independently parseable.
`--log-format json` produces JSON lines with `span` and the parent `spans`.
No separate tracing flag is needed: existing `-v`, `-vv`, and `--log-filter`
control ordinary diagnostic detail. `--timings` independently enables timing
even with `--log-level off` or `-q`; verbosity alone does not enable timings.
The `scribe_timings` target is reserved and controlled by the flag.

A record is emitted when each phase closes, including early error returns.
Text output shows the nested phase path followed by `time.busy` and
`time.idle`, with automatically selected units. Busy means wall time while
the span is entered, **not CPU time**; it includes blocking I/O. Idle includes
async suspension and other time outside the entered span. Their sum is the
phase lifetime. Parent phases include their children: do not add all rows to
estimate total time. A closed phase is not proof of success; the command
result and normal error diagnostics still determine the outcome.

Instrumented boundaries include:

- `connection.resolve_and_connect`, `connection.tcp`, `connection.tls`, and
  server connection/handshake phases.
- `rpc.round_trip` (including the server wait), uploads, downloads, and
  manifest fetching. RPC context includes operation name, request and session.
- `hashing.analyze_file`, `hashing.chunk_stream`, `hashing.verify_file`, and
  object verification. Streaming hashing includes input reads and chunk sinks.
- `compression.encode` and `compression.decode`, per bounded block, with the
  original byte count. These measure codec work separately from stream I/O.
- Sync planning, workspace status, materialization and journal application.
- Storage staging/verification, durable object publication, individual file
  and directory flushes, publication-gate waits/holds, and durable metadata
  acceptance. Branch preparation/finalization also has timing spans.
- Server transfer/storage admission waits; auth connection, admission,
  execution and response phases. Connection/request context is propagated
  into blocking jobs without holding an entered span across an async wait.
- Submit selection, analysis/cache publication, upload-intent and candidate
  persistence, the remote submit, and workspace finalization. Server submit spans
  distinguish `submit_turn.wait`/`submit_turn.hold` from `publication.wait`/hold,
  acceptance preparation, envelope publication, and upload-intent cleanup.
- Buffered parallel preparation, group rebasing, `submit.group`, and
  `submit.group.wait`. A leader's durable spans can cover multiple submissions;
  waiting members retain their own request spans and operation outcomes.
- Metadata writer acquisition, staged commit, and recovery archive publication.
  Writer-acquisition spans include prerequisite archive work; they are not pure
  mutex-wait measurements.

Timing RPC request/session identities are decimal strings in JSON to preserve
all 64 bits in analysis tools. Server request and admission spans carry the same
identities as the client's `rpc.round_trip`. These are diagnostic fields only;
the wire and persisted formats are unchanged.

The development-only `scribe-perf` helper uses this same subscriber and flags.
`node tools/concurrency.js --timings` correlates client/server phases, summarizes
them in the requested reports, and cleans raw logs. See the
[concurrency profiling guide](/docs/concurrency-benchmark.md#diagnose-submit-phases).

`command.total` reports numeric `elapsed_ms` from successful logging setup
until the log guard is dropped, on success or failure. For `serve`, this is
service lifetime; use the per-request phases for latency. Argument parsing,
configuration work before logging setup, process startup and final log drain
are outside this total. Use an external harness for complete process timing.

Without `--timings`, timing callsites are filtered out: no timing-span clock
reads, allocations, field evaluation, or formatting. There remains a small
runtime enabled check; existing operational metrics are unchanged. Enabled
timings add measurement and logging overhead, especially for many compression
blocks. They use the existing bounded lossy queue, so diagnostic loss cannot
stall durable operations; inspect the shutdown drop count before treating a
trace as complete. No function arguments, credentials, asset contents, or
raw frames are recorded by the timing instrumentation.

The logging benchmark also compares an uninstrumented function with a
disabled timing span. Use `node tools/scenario.js --profile ci` with timings disabled for regression
comparisons, and opt-in timings to investigate where time is spent.

### Compiling timing instrumentation out

The native Cargo feature `timings` is enabled by default. To remove all
`--timings` instrumentation from all six executables and their dependencies:

```sh
cargo build --release --locked --no-default-features \
  -p scribe-cli -p scribe-server-cli -p scribe-auth-cli -p scribe-gateway -p scribe-ctl -p scribe-runner
```

A single executable can be built the same way, for example:

```sh
cargo build --release --locked -p scribe-cli --no-default-features
```

These builds reject `--timings` with:

```text
--timings is unavailable: this binary was built without the timings Cargo feature
```

Scope attributes, guards, async instrumentation wrappers, context propagation,
and the command-total timer are removed by conditional compilation. There is
no runtime timing-scope enabled check in this mode. Ordinary logging and
existing operational metrics remain available.

Normal builds retain timings. To enable it explicitly while disabling other
default features, use `--no-default-features --features timings`. Cargo
features are additive across a shared dependency graph: keep `timings`
disabled for every selected package when building without instrumentation;
`--all-features` enables it. Internal dependencies disable their own defaults
and forward `timings` explicitly so individual client and service builds work
consistently.

## Developer reference: command styling

Executables can use `scribe_log::terminal::{Color, stdout, stderr}` for a
consistent palette: `Heading` (cyan), `Success` (green), `Warning` (yellow),
`Error` (red), and `Muted` (dim). For example:

```rust
use std::io::Write;
use scribe_log::terminal::{self, Color};
writeln!(terminal::stdout(), "{}", Color::Success.paint("Ready"))?;
```

Write painted labels through these adaptive streams, which detect stdout and
stderr independently and remove styling for redirected output, nonempty
`NO_COLOR`, or `TERM=dumb`. Keep JSON and other machine-readable formats
unstyled. Pad table cells before applying color so escape sequences do not
affect column alignment. Always include a meaningful text label; color should
never be the only signal.