Skip to content

feat: log every command to a daily file with tracing - #226

Merged
vinceblock99 merged 2 commits into
feat/atomic-sidecar-for-gitfrom
feat/tracing
Oct 1, 2026
Merged

vinceblock99 merged 2 commits into
feat/atomic-sidecar-for-gitfrom
feat/tracing

Conversation

@vinceblock99

@vinceblock99 vinceblock99 commented Sep 28, 2026 •

Copy link
Copy Markdown
Contributor

Summary

  • Every atomic command now writes info and above to ~/.atomic/logs/atomic.YYYY-MM-DD.log. The terminal output is unchanged.
  • git import logs each commit in its own span, with how long it took and the decisions the importer made for it.
  • This is the tracing base agreed at the stand-up: the git-ism fixes stack on this branch.

Why

  • Import failures are invisible. When a Git import fails or produces different files, all we have is the final error, so fixes get guessed. Agreed at the 9/28 stand-up (per the meeting notes): add the tracing crate to GitBridge with info logging for all commands. This PR applies it to every CLI command and writes it to a file, so we can read what actually happened.
  • Import speed can't be measured per commit. Normal repositories (200–300 commits) take over an hour to import. The existing phase timers miss most of each commit's time; a span per commit shows the time as it happens, per commit.
  • Nothing was kept.
    • The CLI used log + env_logger: warnings on the terminal, nothing written anywhere.
    • The importer's own progress lines (ATOMIC_TRACE_GIT_IMPORT) went to stderr only when that variable was set, with no timestamps, threads or file.
  • Bradley's git-ism PRs build on this. Per the stand-up, each git-ism fix branches off this branch once tracing is in, so its behaviour can be checked in the log.

What changed

Logging backend (atomic-cli/src/logging/)

  • tracing-subscriber replaces env_logger. Only the initialisation changed: the ~435 existing log:: calls reach it unchanged through tracing-log.
  • Terminal unchanged:
    • Warnings by default. -v shows atomic=debug,atomic_core=info. RUST_LOG wins.
    • Lines keep env_logger's [time LEVEL target] message shape.
    • The new file-only lines stay off the terminal even with -v.
    • So do h2/hyper/hyper_util, which log through tracing natively; nothing collected their events before.
    • A RUST_LOG with no usable directive shows errors, as env_logger did.
  • New log file: every command writes info and above to ~/.atomic/logs/atomic.YYYY-MM-DD.log (under ATOMIC_CONFIG_DIR when set).
    • ATOMIC_LOG sets the file's filter (off disables it). ATOMIC_LOG_DIR moves the file; it must be an absolute path, so a relative one never lands in a repository.
    • The newest 7 files are kept.
  • One write per line.
    • Each event is appended with a single O_APPEND write, so it is on disk when the call returns. Nothing is buffered to flush at exit, a panic or a signal.
    • Several processes can share the file without splitting lines; agent hooks run concurrently.
    • Why not tracing-appender's background writer: on shutdown timeout it prints to stdout (it would break --json output), it aborts startup if it cannot spawn its thread, and it drops lines silently when its queue fills. At a few lines per command the synchronous write costs nothing measurable (numbers below).
  • Line format: time pid=N LEVEL ThreadId(N) spans: target: message.
    • The pid is on every line, including threads outside the command span (tokio workers, watchers).
    • Newlines inside a message are escaped, so text from Git (tag annotations) cannot forge lines.
  • Command span: atomic{cmd=git import}, with the command's start (version, cwd), finish (outcome, exit code, error) and duration.
  • Privacy:
    • The log directory is created 0700.
    • URLs in a failed command's error lose their user:password@, query and fragment before they are logged. Remote errors name the URL, and remote URLs can carry credentials.
  • Error handling: an unusable ATOMIC_LOG_DIR gives one warning and the command runs normally. An unusable default location stays quiet (visible with -v). Panics are also logged to the file.
  • Our own retention: several processes can prune at once, so a file another process already removed is not an error, and nothing goes to stderr.

Git import

  • The existing progress lines (trace_git_import: phase timings, per-commit write/parse lines, reclassified paths) now go to the file at info, target atomic::git::import. ATOMIC_TRACE_GIT_IMPORT still prints them on the terminal.
  • Spans:
    • preflight, parse, import, write, and one commit{n, of, sha} per commit.
    • Each span logs its duration when it closes.
    • The parallel parse threads log inside the parse span.
  • The write loop's decisions are logged: self-push skip, squash insert/skip, resurrection from a binding, the write failure that stops the import, and a file-index update failure that was previously discarded.
  • Volume: about 4–5 lines, roughly 1–1.5 KB, per imported commit.

Example (3-commit import):

2026-09-28T21:52:10.482113Z pid=13208  INFO ThreadId(01) atomic{cmd=git import}:import{branch="main" commits=3}:write{commits=3}:commit{n=2 of=3 sha=1b9c1fec}: atomic::git::import: write 1b9c1fec synthesized=1 files=2 recorded=2 record=0ms assemble=0ms save=0ms apply=1ms ...
2026-09-28T21:52:10.940305Z pid=13208  INFO ThreadId(01) atomic{cmd=git import}:import{branch="main" commits=3}:write{commits=3}:commit{n=2 of=3 sha=1b9c1fec}: atomic::commands::git::parallel: close time.busy=458ms time.idle=4.50µs

The commit span's 458ms against the ~1ms of timed phases is the untimed per-commit cost #225 went after. The log now shows that gap per commit.

Not in this PR

  • Spans inside atomic-repository (verification, materialization) and redb (open, lock wait, commit). These are the next step.
  • Bridge commands beyond the command span (enable, reconcile, verify, …).
  • The other ad-hoc ATOMIC_TRACE_* / ATOMIC_DEBUG_* switches stay as they are.

Tests

  • New integration tests (atomic-cli/tests/logging_integration_test.rs, 9):
    • info reaches the daily file, and not the terminal;
    • every line carries the pid;
    • a failing command logs its error and exit code;
    • ATOMIC_LOG=off, ATOMIC_LOG_DIR, ATOMIC_CONFIG_DIR;
    • an unusable or relative log dir warns, the command still runs, and nothing lands in the working tree;
    • -v still shows the log macros' debug lines in env_logger's shape, without the file-only lines, and RUST_LOG wins over -v;
    • git import logs each commit's write line and duration inside commit{n, of, sha}.
  • New unit tests (15):
    • filter precedence, and a RUST_LOG that does not parse still shows errors;
    • the file-only targets never prefix a real module path;
    • log dir resolution; a new log dir is 0700;
    • retention keeps the newest 7 dated files and touches nothing else;
    • the terminal line shape;
    • the file line: pid, spans, and escaped newlines against forged lines;
    • URL credential redaction.
  • cargo test -p atomic-cli: 2412 pass. The 6 that fail locally fail identically on 990612c:
    • 4 clone tests hit this machine's Git default-branch setup;
    • 2 need --features adoption-test-injection. With it they pass on this branch (git_bridge_cb13d_test 21/21, graph_only_export_cb9b_test 3/3).
  • cargo fmt --check passes. cargo clippy -p atomic-cli --all-targets -D warnings reports nothing new; the local 1.95 toolchain flags existing sites (materialize.rs, record.rs, collapsible_match, git_projection_cb8a_test.rs) identically on 990612c.
  • Import time, release build, one real project, same binary with the file on and with ATOMIC_LOG=off:
Screenshot 2026-09-29 at 1 04 46 PM

Replace env_logger with tracing-subscriber. The terminal keeps
env_logger's behaviour; every command also appends info and above to
~/.atomic/logs/atomic.YYYY-MM-DD.log, one line per event with the pid
and spans. git import logs each commit in a commit{n, of, sha} span
with its duration, and the write loop's decisions.
Add spans to bridge reconcile, switch, import_head, export, verify and
pre-push, with the reconcile observation and direction and each switch
step. Copy the evidence Git's hooks journal, every consented bridge
event, and the CLI's status messages into the log file. None of these
change what the commands do or print.
@vinceblock99
vinceblock99 marked this pull request as ready for review September 29, 2026 18:47
@vinceblock99
vinceblock99 merged commit 82a93ce into feat/atomic-sidecar-for-git Oct 1, 2026
@vinceblock99
vinceblock99 deleted the feat/tracing branch October 1, 2026 20:05
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.

1 participant