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

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:

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

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.

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:

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:

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

These builds reject --timings with:

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

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.