Logging & troubleshooting

Every musefs crate reports through the log facade; the musefs binary installs the sink and writes it to stderr. Nothing is logged to the mount or to the store, so the log is wherever that process's stderr goes — your terminal, the journal, or the container log.

Raising log detail

The default floor is warn: enough that a failure is never silent, quiet enough to leave running. -v raises it, and repeats stack:

-v / --verbose is global — musefs -v mount … and musefs mount … -v are equivalent.

RUST_LOG wins. The -v count only supplies the default filter, so an explicit RUST_LOG in the environment takes precedence and -v then has nothing to do. That is the lever to reach for when you cannot edit the command line (a systemd unit, a container ExecStart), and it is also the only way to filter per crate:

RUST_LOG=info musefs mount /mnt/music --db library.db
RUST_LOG=warn,musefs_fuse=debug musefs mount /mnt/music --db library.db

Targets are crate names with underscores: musefs, musefs_cli, musefs_core, musefs_db, musefs_fuse, musefs_format. There is no MUSEFS_* variable for verbosity — unlike the mount and scan flags, this one is RUST_LOG or -v only.

Two kinds of output ignore the log level entirely: scan/revalidate progress and per-target summaries (suppressed with --quiet / -q, see Scanning), and a handful of CLI diagnostics printed directly to stderr — warning: mountpoint … is not empty, the --file-mode / --dir-mode write-bit warnings, and the final musefs: <error> on a hard failure.

They share stderr with the log, but they do not collide with it: the progress bar is drawn through a target the log sink suspends around every record, so a warning emitted mid-scan clears the bar, prints, and the bar is redrawn beneath it. Raising verbosity during an interactive scan is safe.

What each level buys

warn — the default

• Serve-path failures behind the mount: read(…) failed: …, lookup(…) failed: …, and read(…) rejected: EAGAIN load-shedding. These go through the warn limiter.
• Scan-time refusals: skipping <path>: <reason>, skipping <path>: no parseable audio metadata. These are capped per reason — see Scanning.
• The end-of-scan failure summaries: failed 38: unparseable=30, io=5, oversize=2, rejected=1 (these reasons, plus panicked, partition the failed count the CLI reports and the exit-2 signal keys on; empty buckets are omitted) and walk errors 12: unreadable=9, symlink=3 for entries the walk never queued. Neither fires on a healthy library.
• Degraded-but-correct fallbacks: incremental tree mutation failed …; falling back to full rebuild, poll_refresh failed, inval_inode(…) failed.
• Tag keys dropped during Vorbis synthesis (track N: dropping tag key … (not a valid field name)). Like the serve-path failures above, these go through the warn limiter.
• An in-place store schema upgrade: upgrading store schema at … from version 1 to version 3; this is irreversible …. Once per store per schema bump — it is at warn precisely so it lands in your scrollback before you ever try to run an older musefs against that store.
• scan --revalidate deprecation.
• error sits above it, reserved for a caught panic in a synthesis or scan worker, a scan aborted mid-ingest, and recovered lock poisoning.

-v (info) — "why is my mount doing this"

This is the level worth knowing about. The lines that explain a mount's behaviour are all info, so by default they are invisible:

• The pre-mount line naming the store, mountpoint, and template, then the post-mount summary once the session is actually serving:

  musefs mounted at /mnt/music: 41230 files in 3812 directories (Synthesis)
  

  An empty or wrong --db is otherwise indistinguishable from a correctly serving one — the mount succeeds either way; the counts are the tell.

• The passthrough decision. In structure-only mode on Linux 6.9+ musefs registers the backing fd with the kernel so reads bypass the daemon; when that is not available it says so once and serves reads itself:

  FUSE passthrough unavailable; serving reads through the daemon: <error>
  StructureOnly mount without CAP_SYS_ADMIN: kernel passthrough unavailable; reads will be served by the daemon
  StructureOnly mount: kernel passthrough is Linux-only; reads will be served by the daemon
  

  This is the single best explanation for "why is my structure-only mount slower than I expected".

• changelog gap; falling back to full refresh — the mount slept past more external edits than the changelog ring retains, so it rebuilt the tree wholesale instead of applying a diff. Correct, just more expensive.

• The per-extension breakdown of a scan's skip count (skipped 42: jpg=20, cue=10, …). This sits at info rather than warn because cover art and .cue/.log sidecars are the normal contents of a music library, so it fires on every healthy scan — and a warning that always fires teaches you to filter warnings, which would cost you the failure summary that matters. The skipped N total is in the CLI's per-target summary at any level; -v gates only the breakdown.

• store schema at … is now at version 3 (took 0.4s) — the completion half of the upgrade announcement above.

If a mount is behaving oddly and you only reach for one thing, reach for -v.

-vv (debug)

• Everything the warn limiter dropped, tagged (over warn budget).
• Routine tree-shape misses that never warn: lookup(…) failed: no such inode: … and friends (ENOENT / EISDIR / ENOTDIR), which a kernel path probe and a stale inode after a refresh generate constantly.
• opendir(…) over the 1024-handle cap: serving it statelessly — the degraded readdir path a parallel walk can push a mount onto. The operator-facing signal for this is the musefs_dir_handle_rejections_total counter in the metrics surface; the log line is per-occurrence.
• Scan-walk detail: duplicate backing targets, symlink handling.
• Scan skips past their per-reason cap. After the first 10 of a given reason, one line says further "<reason>" skips are logged at debug … and the rest go here; the end-of-scan summary still has the totals.

The serve-path warn limiter

Serve-path failure warns are rate-limited process-wide: 10 warns per 30 s window. Over budget, a message is downgraded to debug with (over warn budget) appended and counted; the first warn of the next window carries the tally:

read(1042) failed: backing file changed since scan: /music/a.flac (317 similar serve-path warnings suppressed in the last 30s)

Read that line carefully — the suppressed failures are not necessarily the same failure as the one printed. The count is a volume signal, not a multiplicity of that message.

The limiter exists because the failure mode it guards is per-file: a library enumeration over a corpus whose backing files have moved would otherwise emit one warn per file — hundreds of thousands of lines, tens of MB of log, for a single walk. One budget is shared across the whole serve path: the reply_errno warn arm (the failures behind lookup, getattr, open, read, readdir), the read load-shedding EAGAIN line, and the synthesis warns — dropped Vorbis tag keys, over-cap art, art-blob read failures — which are emitted per cache miss and so scale the same way. Scan-time warns are capped separately and per reason; see Scanning.

Sharing the budget does not merge the log targets: each message is still attributed to the module that raised it (musefs_fuse, musefs_core::reader, musefs_core::mapping), so per-crate RUST_LOG filtering works as described above.

To see every suppressed failure, run at -vv (or RUST_LOG=debug): nothing is discarded, only downgraded. For the rate rather than the events, the musefs_serve_warns_suppressed_total counter on the metrics surface counts every downgraded warn since start — a scrape landing between bursts sees a quiet log either way, so the counter is what distinguishes a healthy serve path from a throttled one.

Reading the logs under systemd

The user units send stderr to the journal:

journalctl --user -u musefs -f          # follow the mount
journalctl --user -u musefs-scan -e     # the last of a scan run

ExecStart in the shipped unit is a bare musefs mount driven by MUSEFS_* environment variables, so the least invasive way to raise detail is the environment rather than the command line — add RUST_LOG=info to ~/.config/musefs/musefs.conf, or set it in a drop-in (systemctl --user edit musefs):

[Service]
Environment=RUST_LOG=info

Then systemctl --user restart musefs. Adding -v works too, but it means editing ExecStart itself.

Reading the logs in a container

stderr is the container's log stream, so nothing special is needed to capture it:

docker logs -f musefs        # podman logs -f musefs

Raise detail with -e RUST_LOG=info on docker run / podman run, or by appending -v to the command after the image name. Note that the most common container failure — a missing --device /dev/fuse or --cap-add SYS_ADMIN — is not a log line at all: it is a hard error, musefs: mounting at /mnt/musefs: …, and the container exits 1. See Running in containers.

Exit codes

Exit 2 is what makes a partial ingest machine-detectable, so musefs scan … && musefs mount … stops instead of mounting an incomplete library — the per-file failures otherwise surface only on stderr. It overlaps clap's usage-error code, but a usage error fails before any work starts, so the two are never ambiguous in a pipeline that got as far as running. See Scanning for what failed counts.

When the log is not the answer

• A file that will not open or errors on read is usually a backing file that changed since its last scan — see the FAQ and run musefs revalidate.
• For steady-state behaviour (handle counts, cache hit rates, read errors, degraded-readdir rejections) the counters in .musefs-metrics/ are the surface to watch; the log reports events, not rates.