fix(models): stop model loaders from printing progress to stdout
- Dominant language
- Rust
- Stars
- 467
- Forks
- 54
- Avg merge
- 4h 25m
- Merged PRs (30d)
- 310
Description
## Problem
Fourteen non-test files under `src/models/` and `src/loading/` write to stdout with `println!`: loader progress (`[Mamba2] Loading config...`, `[Mamba2] Config loaded: 24 layers`, `[Mamba2] Model loaded successfully`), one load-time notice, and a debug dump. `examples/logit_trace` writes its TSV to stdout, so a trace of any affected family starts with lines that are neither `#` metadata nor data rows, and `scripts/compare_logit_traces.py:52` splits every non-`#` line into six tab-separated fields and fails with `ValueError: not enough values to unpack (expected 6, got 1)`. Reproduced at c9774d08 on `models/mlx/mamba2-130m`. Found while tracing `nvidia-nemotron-3-nano-30b-a3b-4bit` for PR #1772, where `logit_trace` reaches `NemotronHModel::load` through `src/loading/nonstandard.rs:95`. Any other caller of `mlxcel::load_model` that parses its own stdout gets the same lines.
## Evidence
69 matches at c9774d08, all `println!`, from `grep -rnE '(^|[^A-Za-z0-9_])(println|print)!\(|stdout\(\)' src/models src/loading --include='*.rs' | grep -v 'tests\.rs:'`. None is intended output.
Loader progress:
- `src/models/nemotron_h.rs:2102, 2117, 2132, 2136, 2139` (the file's `eprintln!` at `1946, 2053, 2083` is forward-pass profiling, unrelated)
- `src/models/jamba.rs:957, 963, 979, 986, 989`
- `src/models/kimi_k3.rs:1898, 1911, 1920, 1924, 1929`
- `src/models/kimi_linear.rs:1299, 1312, 1320, 1324, 1328`
- `src/models/mamba.rs:459, 465, 471, 478, 481`
- `src/models/mamba2.rs:698, 704, 714, 721, 724`
- `src/models/nemotron_nas.rs:476, 489, 496, 499, 502`
- `src/models/qwen3_5.rs:1828, 1864, 1875, 1883, 1892, 1895`; `1883` repeats the `tracing::info!` that `requantize_block_fp8_weights` already emits at `src/models/fp8_block.rs:375`
- `src/models/qwen3_next.rs:1502, 1509, 1524, 1531, 1534`
- `src/models/recurrent_gemma.rs:731, 744, 752, 759, 763`
- `src/models/solar_open.rs:60` (`sanitize_weights`), `95` (`convert_gptq_to_mlx`), `850` (`load`)
- `src/loading/vlm_kimi_k3.rs:154, 190, 199, 210`
Not progress:
- `src/models/deepseek_v2.rs:926, 937`: the `MLXCEL_MLA_ABSORBED` fold report, printed only when that flag is set. Its doc comment (`899-907`) and `docs/mla-absorbed-decode.md:104` chose stdout because the `mlxcel` CLI installed no tracing subscriber. `init_cli_tracing` (`src/main.rs:2795`) now installs a stderr subscriber when `RUST_LOG` is set. That still rules out `tracing` for a report that must show without `RUST_LOG`, but it does not rule out stderr.
- `src/models/llama4.rs:922, 929, 958, 1157, 1168, 1388, 1403, 1410, 1415`: NaN-hunting dumps in the three `forward_debug` methods (`911, 1146, 1375`), which nothing in the repository calls.
Nothing under either directory is legitimately stdout, so the guard's allow-list starts empty. Stdout written by the CLI commands themselves (`src/commands/`, `src/execution/quant_advisor.rs`, for example `mlxcel generate`'s own `Loading model from ...` line) is command output and out of scope.
## Fix
This design is decided (maintainer decision, 2026-09-11): loader progress goes to `tracing`, not to stdout and not to unconditional stderr. Implement it as written; a deviation needs a comment on this issue first.
- Loader progress: replace each `println!(` with `tracing::info!(`, message text unchanged, and delete `qwen3_5.rs:1883`. This matches the load-time notices at `fp8_block.rs:375` and `src/loading/mod.rs:599`. Decided behavior change: the server still logs these lines at its default `info` verbosity (`src/server/logging.rs:79, 169`), `mlxcel generate` shows them on stderr only when `RUST_LOG` is set, and `logit_trace`, which installs no subscriber, shows nothing.
- `deepseek_v2.rs:926, 937`: `eprintln!`, so the report still appears whenever the flag is set. Update the doc comment at `899-907`, `docs/environment-variables.md:378` ("Prints one stdout line") and `docs/mla-absorbed-decode.md:104` to say stderr, and drop the stale subscriber sentence.
- `llama4.rs`: `eprintln!`. Deleting the `pub fn forward_debug` methods would remove public API from the published crate, which is a separate decision.
- Guard: add `tests/model_loader_stdout_guard.rs`, patterned on `tests/vlm_wrapper_capability_delegation.rs` (repo root from `CARGO_MANIFEST_DIR`) and the lstat walker `collect_rs_files` at `src/lib/mlxcel-core/src/utils.rs:1432`. Walk `src/models` and `src/loading`; skip files whose name ends in `tests.rs` (the filter at `utils.rs:1391`) and lines whose trimmed text starts with `//`; flag `println!(`, `print!(` and `stdout()` when not preceded by an ASCII alphanumeric or `_`, so `eprintln!(` passes. Inline `#[cfg(test)]` modules are not exempt and use `eprintln!`. Keep an allow-list of `(repo-relative path, reason)`, empty today, and fail on an entry whose file no longer matches so it cannot go stale. The failure message lists every `path:line: code` and names the replacement: `tracing::info!` or `tracing::warn!`, or `eprintln!` for a notice that must show without `RUST_LOG`.
## Acceptance criteria
- [ ] The Evidence grep prints nothing.
- [ ] The guard passes, and fails naming the file and line when one `println!("x");` is added to `src/models/mamba2.rs`; the PR reports that revert-to-fail run.
- [ ] `logit_trace` on `models/mlx/nvidia-nemotron-3-nano-30b-a3b-4bit` and `models/mlx/mamba2-130m` writes a file whose first line starts with `# model`, and `compare_logit_traces.py` reads it unedited (a self-comparison exits 0 with `verdict: byte-identical in effect`).
- [ ] `mlxcel generate` on `models/mlx/mamba2-130m` prints no `[Mamba2]` line by default; with `RUST_LOG=info` the same lines appear on stderr.
- [ ] With `MLXCEL_MLA_ABSORBED=1`, `mlxcel generate` on `models/mlx/deepseek-v2-lite-chat-4bit-mlx` prints the `mla: absorbed decode folded` line on stderr and not on stdout.
## Verification
`CORPUS.txt` is any plain-text file over 100 tokens.
```bash
cargo build --release --features metal,accelerate --example logit_trace --bin mlxcel
T=$(mktemp -d)
for m in nvidia-nemotron-3-nano-30b-a3b-4bit mamba2-130m; do
./target/release/examples/logit_trace models/mlx/$m CORPUS.txt 32 2 8 > "$T/$m.tsv"
head -1 "$T/$m.tsv" # "# model ..."
python3 scripts/compare_logit_traces.py "$T/$m.tsv" "$T/$m.tsv" # exit 0
done
MLXCEL_MLA_ABSORBED=1 ./target/release/mlxcel generate -m models/mlx/deepseek-v2-lite-chat-4bit-mlx \
-p Hello -n 4 --temp 0 > "$T/out.txt" 2> "$T/err.txt"
grep -c 'mla:' "$T/out.txt" # 0
grep -c 'mla: absorbed decode folded' "$T/err.txt" # 1
./target/release/mlxcel generate -m models/mlx/mamba2-130m -p Hi -n 4 --temp 0 2>&1 | grep -c '\[Mamba2\]' # 0
RUST_LOG=info ./target/release/mlxcel generate -m models/mlx/mamba2-130m -p Hi -n 4 --temp 0 2>&1 >/dev/null | grep -c '\[Mamba2\]' # 5
cargo test --profile test-fast --features metal,accelerate --test model_loader_stdout_guard
cargo test --workspace --profile test-fast --features metal,accelerate
cargo clippy --workspace --all-targets --features metal,accelerate -- -D warnings
cargo fmt --all -- --check
```
Contributor guide
Research direction
Start by reviewing the listed println! sites in src/models and src/loading, then read tests/model_loader_stdout_guard.rs requirements and the related docs entries. Run the evidence grep and the guard test before exercising examples/logit_trace, compare_logit_traces.py, and the documented mlxcel generate commands. Done means the guard passes, trace output remains parseable, and stdout/stderr behavior matches the acceptance criteria.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- rust
- Domain
- backend, cli, documentation, testing-qa
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Active
- Clarity
- Clearly specified
- Newbie friendliness
- 65/100