# Logging and profiling

> The LOG_LEVEL grammar and its four modules, timestamps, the stderr-only rule, NO_COLOR, and the three artifacts DEBUG_PERF captures.

Canonical URL: https://www.slivingdoc.dev/docs/reference/logging/ · Version: 0.1 · Updated: 2026-09-21

Full site index: https://www.slivingdoc.dev/llms.txt

Logging is configured by the environment, so it applies to every command
and works before any flag is parsed. `serve`, `pull`, and `commit` also
take `--log-level` and `--log-timestamp`, which override the environment
once the flags resolve; the few records emitted before that point — the
command router, a configuration refusal — follow the environment.

| Variable                   | Effect                                                                        |
| -------------------------- | ----------------------------------------------------------------------------- |
| `LOG_LEVEL`                | Per-module levels. A bare level is the default.                               |
| `SLIVINGDOC_LOG_TIMESTAMP` | `false` removes the `time=` field, for hosts that stamp log lines themselves. |
| `NO_COLOR`                 | Any non-empty value disables ANSI colour: the log levels and the CLI report.  |
| `DEBUG_PERF`               | Captures CPU, heap, and execution-trace profiles across one whole command.    |

## Records

Records are structured `key=value` text on stderr. Each one carries a
timestamp (unless timestamps are off), a level, and the module that
emitted it.

> **Warning:** Stdout carries only MCP protocol messages and command
> output. Nothing ever logs to stdout — that is what keeps the stdio
> transport usable.

## `LOG_LEVEL`

`LOG_LEVEL` takes a comma-separated list. `module=level` sets one module;
a bare `level` sets the default for the rest:

```text
LOG_LEVEL="cli=warn,mcp=debug,info"
```

The modules are:

| Module     | Emits                                          |
| ---------- | ---------------------------------------------- |
| `cli`      | Command routing.                               |
| `app`      | Startup and shutdown.                          |
| `mcp`      | One record per tool call, carrying `mcpReqID`. |
| `notebook` | Best-effort checkpoint and cleanup records.    |

The levels are `debug`, `info`, `warn`, and `error`. The default is
`info`.

A malformed `LOG_LEVEL` is reported and falls back to `info`; it never
refuses startup. An invalid `--log-level` flag value, in contrast,
refuses startup like any other flag. The flag takes the same grammar as
the environment variable.

## Correlating a tool call

The `mcp` module writes one pair of records per tool call — a start
record and a completion record — and both carry the same `mcpReqID`. That
value is the `diagnosticId` an agent sees in a structured error, so a
failing call in an agent transcript points straight at the two log
records that describe it. It is also how an operator reads the full cause
of an `ENGINE_FAILED` error, which the envelope itself withholds. See
[Errors](/docs/reference/errors/).

## Timestamps

`--log-timestamp` (environment `SLIVINGDOC_LOG_TIMESTAMP`, default
`true`) set to `false` removes the `time=` field. Use it when the host
already stamps every line it captures, so the record is not stamped
twice.

## Colour

Any non-empty `NO_COLOR` disables the ANSI colour of the log levels, and
of the CLI report at the same time. The convention is the value being
non-empty, not the literal string `true`. See
[CLI](/docs/reference/cli/) for what is coloured in a report.

## Profiling with `DEBUG_PERF`

`DEBUG_PERF` captures performance profiles across one whole command —
startup, the operation, and shutdown — for finding where a slow `pull` or
`commit` spends its time.

| Value               | Effect                                                            |
| ------------------- | ----------------------------------------------------------------- |
| `1` or `true`       | Write under `slivingdoc-perf/` in the system temporary directory. |
| `0`, `false`, empty | No capture.                                                       |
| Any other value     | Use that value as the base directory.                             |

```bash
DEBUG_PERF=1 slivingdoc pull ./notes
```

Each invocation creates its own timestamped run directory under the base,
so repeated benchmark runs never overwrite each other and can be compared
with `go tool pprof -diff_base`. A run directory holds three artifacts:

| File         | Shows                                                                                                  |
| ------------ | ------------------------------------------------------------------------------------------------------ |
| `cpu.pprof`  | Where CPU time went: `go tool pprof cpu.pprof`.                                                        |
| `heap.pprof` | What the command retained at exit: `go tool pprof heap.pprof`.                                         |
| `trace.out`  | The execution timeline, including time blocked on the network and on locks: `go tool trace trace.out`. |

For an operation dominated by object-store round trips, the CPU profile
stays near-empty and `trace.out` shows the waiting. That split is the
reason both are captured.

The exact paths are reported on stderr when the capture starts and
finishes; stdout stays protocol-only. A capture that cannot start or
finish is a warning, never a refusal, and it never changes the command's
result or exit code.

## Next

- [Errors](/docs/reference/errors/) — the diagnostic ID and what each
  error means.
- [CLI](/docs/reference/cli/) — exit behaviour and the report grammar.
- [Configuration](/docs/reference/configuration/) — `--log-level` and
  `--log-timestamp` beside every other flag.