Logging & diagnostics

Selection

Precedence: explicit CLI selection > SCRIBE_LOG > configuration ([logging].filter, server only) > default (info for the two services, warn for the client). --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 on (tested).
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). 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 output is newline-delimited with real escaping (tested with control characters, quotes, and newlines in peer strings). Tokens, private keys, file contents, and raw frames are never logged.

Measured cost

cargo bench -p scribe-log --bench logging: a disabled event costs about 0.5 ns; an enabled text event through the bounded queue about 0.6 us, JSON about 0.9 us. The ci profile runs the same submit/sync sequence at off, info, debug, and trace: no measurable difference (about 1.5 s each).

Opt-in phase timings

All three executables accept the global --timings flag, before or after a subcommand. Its help text is:

text

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

Examples:

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 --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.

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 scribe-perf 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 the three executables and their dependencies:

cargo build --release --locked --no-default-features \
  -p scribe-cli -p scribe-server-cli -p scribe-auth-cli

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

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.