apr run: 7 defects incl. --stream emitting empty text and --trace-output always writing an empty event list #2378

Target: run

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
timeout 300 "$APR" run /home/noah/.cache/pacha/models/d47927c5638f80ab.gguf "hi" -n 8 --no-gpu --stream > out.txt 2>&1; echo "rc=$?"; cat out.txt

Observed

rc=0
=== APR Run ===

Source: /home/noah/.cache/pacha/models/d47927c5638f80ab.gguf
{"event":"token","index":0,"token_id":40,"text":""}
{"event":"token","index":1,"token_id":2776,"text":""}
{"event":"token","index":2,"token_id":1588,"text":""}
{"event":"token","index":3,"token_id":311,"text":""}
{"event":"token","index":4,"token_id":1492,"text":""}
{"event":"token","index":5,"token_id":0,"text":""}
{"event":"token","index":6,"token_id":2585,"text":""}
{"event":"token","index":7,"token_id":646,"text":""}
{"model":"...","text":"I'm here to help! How can","tokens":[40,2776,1588,311,1492,0,2585,646],"tokens_generated":8,...,"event":"final"}

Expected / root cause

--stream Enable streaming output should deliver incremental text. The token ids are right (the final event decodes them to "I'm here to help! How can"), so the per-token decode is simply never done — a consumer that renders text as it arrives sees nothing until the final event, which defeats the purpose of the flag. Note event index 5 is token_id 0, which decodes to ! in the final string, so the ids themselves are usable — only text is unfilled.

Variations tried: Varied model and token budget: same empty text on the 1.0GB Qwen2.5-coder-1.5B GGUF at n=8 and n=4, and on /home/noah/tmp/qwen_shape_shrink.gguf. Tried --stream with --chat and with --json — the per-token text is "" in every combination while the final event always carries the full decoded string. Not a tokenizer problem: the same binary/model decodes correctly in non-stream mode and in --batch-jsonl mode ({"task_id":"a","text":"2+2 equals 4.",...}).

Target: run

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
G=/home/noah/.cache/pacha/models/d47927c5638f80ab.gguf
for lvl in none basic layer payload chrome; do
  timeout 300 "$APR" run "$G" "hi" -n 3 --no-gpu --trace --trace-level $lvl --trace-output "tr_$lvl.json" > /dev/null 2>&1
  echo -n "$lvl: "; python3 -c "import json;print('events_len=',len(json.load(open('tr_$lvl.json'))['events']))"
done
ls trace-*.json

Observed

none: events_len= 0
basic: events_len= 0
layer: events_len= 0
payload: events_len= 0
chrome: events_len= 0
trace-1786290823.json

# tr_chrome.json (the file the user asked for) contains:
{
  "version": "1.0", ... "events": []
}
# while the chrome trace actually went to ./trace-1786290823.json:
#   keys= ['traceEvents', 'displayTimeUnit', 'metadata']
# stderr said: "Chrome trace written to: trace-1786290823.json (load in chrome://tracing)"

Expected / root cause

--trace-output <FILE> Save trace output to JSON file should write the trace. Two concrete breaks: (1) the events array is empty at every documented --trace-level (none/basic/layer/payload/chrome) and with the --trace-payload shorthand, even though the terminal is full of [TRACE-CACHE] and [BRICK-PROFILE] lines that are exactly the events a consumer wants; (2) --trace-level chrome — documented as "outputs chrome://tracing JSON integrating layer trace + brick profile" — writes that JSON to an auto-named trace-<epoch>.json in the working directory and leaves the user-specified --trace-output path holding the empty-events stub, so a scripted --trace-output consumer silently gets nothing.

Variations tried: Ran all five documented --trace-level values plus the --trace-payload shorthand plus an undocumented value (banana) on the 1.5B GGUF; every run produced a --trace-output file with events: [] and identical top-level keys. Confirmed the trace machinery itself is alive: --trace-level layer does print a Layer Trace table to stderr and --trace-level chrome does produce a real chrome-format file (traceEvents array present) — just at the wrong path. Also confirmed the stub file is otherwise well-formed JSON (model/inference blocks are populated with real numbers).

Target: run

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
timeout 300 "$APR" run /home/noah/.cache/pacha/models/d47927c5638f80ab.gguf "hi" -n 3 --no-gpu --trace --trace-level layer > out.txt 2>&1; echo "rc=$?"; cat out.txt

Observed

[BRICK-PROFILE] Total: 624.47ms, 12 tokens (9 prefill + 3 decode), 19.2 tok/s
[BRICK-PROFILE]   FFN                    264.63ms ( 42.4%)  avg=859.2us  count=308
[BRICK-PROFILE]   QkvProjection          131.31ms ( 21.0%)  avg=426.3us  count=308
...
=== Layer Trace (APR-TRACE-001) ===

  Step             Time       Description
  ────────────────────────────────────────────────────────
  TOKENIZE           16.43ms  Text → Token IDs
  EMBED              16.43ms  Token IDs → Vectors
  TRANSFORMER       821.45ms  Vectors → Vectors (×N layers)
  LM_HEAD            77.31ms  Hidden → Logits
  SAMPLE             19.33ms  Logits → Token ID
  DECODE             16.43ms  Token ID → Text
  ────────────────────────────────────────────────────────
  TOTAL            2899.24ms  1.0 tok/s

Expected / root cause

A trace labelled Time in a diagnostic table should be measured. These numbers are synthesised: crates/apr-cli/src/commands/gguf_generate_result.rs:373-380 computes per_token_ms = total_ms / tokens_generated then assigns TRANSFORMER = per_token0.85, LM_HEAD = per_token0.08, SAMPLE = per_token0.02 and everything else per_token0.017 — which is why TOKENIZE, EMBED and DECODE are all exactly 16.43ms. The ratios are constant for every model and every prompt, so the table always 'proves' TRANSFORMER is 85% regardless of reality, while the real [BRICK-PROFILE] block six lines above says FFN 42.4% / Qkv 21.0% / LmHead 4.5%. The same block reports TOTAL ... 1.0 tok/s against [BRICK-PROFILE] ... 19.2 tok/s for the identical run — a 19x discrepancy with no label distinguishing wall-clock-incl-load from decode rate. CLAUDE.md directs debugging to apr trace for layer-by-layer analysis, so this is the table users will act on. At minimum it must be labelled ESTIMATED; the dimmed one-line tip is not enough.

Variations tried: Repeated at n=3, n=4 and n=8 on the 1.5B GGUF and on /home/noah/models/qwen2.5-coder-1.5b-instruct-q4k.apr: TOKENIZE == EMBED == DECODE to the hundredth of a millisecond in every run, and TRANSFORMER/LM_HEAD/SAMPLE always land on the 0.85/0.08/0.02 split, confirming they are derived rather than measured. Cross-checked against the real per-brick counters in the same runs, which vary sensibly with model and length (FFN 39-42%, Qkv 21-27%).

Target: run

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
# the corrupt file declares output_norm.weight = [768] while qwen2.embedding_length = 1536
"$APR" inspect /home/noah/tmp/qwen_shape_shrink.gguf 2>&1 | grep embedding_length
"$APR" tensors /home/noah/tmp/qwen_shape_shrink.gguf 2>&1 | grep output_norm
timeout 300 "$APR" run /home/noah/tmp/qwen_shape_shrink.gguf "What is 2+2?" -n 8 --no-gpu --json > shrink.json 2>&1; echo "rc=$?"; cat shrink.json
timeout 300 "$APR" run /home/noah/models/qwen2.5-coder-1.5b-instruct-q4_k_m.gguf "What is 2+2?" -n 8 --no-gpu --json > base.json 2>&1; echo "rc=$?"; cat base.json

Observed

│                 qwen2.embedding_length │ 1536                              │
│ output_norm.weight                │ [768]          │ F32   │ 3.0 KB   │

rc=0
{
  "model": "/home/noah/tmp/qwen_shape_shrink.gguf",
  "text": "2 + 2 equals 4.",
  "tokens": [17,488,220,17,16819,220,19,13],
  "tokens_generated": 8, ... "cached": true
}

rc=0  (uncorrupted base, same prompt)
{
  "model": "/home/noah/models/qwen2.5-coder-1.5b-instruct-q4_k_m.gguf",
  "text": "4",
  "tokens": [19],
  "tokens_generated": 1, ...
}

Expected / root cause

apr ships a tensor contract validator (the --skip-contract flag exists on every command, and apr import prints [CONTRACT] Validated 103 tensors against tensor-layout-v1.yaml). A final RMSNorm weight of 768 elements against a declared embedding_length of 1536 is a shape contract violation that should be rejected, or at minimum warned about, before inference. Instead the run exits 0 with no diagnostic and the numerics are demonstrably different from the uncorrupted model (base stops after the single token '4'; the corrupt model emits 8 different tokens). The sibling corruption in the same fixture family IS caught — but only incidentally, by a file-size bound, not by shape validation (see variations).

Variations tried: Ran all three corrupt fixtures through the same command. /home/noah/tmp/qwen_shape_corrupt.gguf (output_norm.weight declared [3072], i.e. too LARGE) -> rc=8 error: ... Data range [1117314624, 1117326912) exceeds file size 1117320768 — caught only because the read runs off the end of the file, not because 3072 != 1536. /home/noah/tmp/qwen_vocab_mismatch.gguf -> rc=8 with a proper contract error eos_token_id 151645 >= vocab_size 1000 ... (OBLIG-SPECIAL-TOKEN-WITHIN-VOCAB), proving shape/vocab obligations are enforced elsewhere. Only the shrink direction slips through. Confirmed the behavioural delta on a second prompt: 'What is the capital of France?' --chat -> corrupt gives 'Paris', base gives 'The capital of France is Paris.' Verified with -v that no warning is emitted at any verbosity.

Target: run

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
G=/home/noah/.cache/pacha/models/d47927c5638f80ab.gguf
timeout 300 "$APR" run "$G" "hi" -n 4 --backend banana > b.txt 2>&1; echo "rc=$?"; head -8 b.txt
timeout 300 "$APR" run "$G" "hi" -n 4 --no-gpu -f banana > f.txt 2>&1; echo "rc=$?"; head -3 f.txt
timeout 300 "$APR" run "$G" "hi" -n 4 --no-gpu --trace --trace-level banana > t.txt 2>&1; echo "rc=$?"; head -6 t.txt

Observed

rc=0
Backend override: banana
=== APR Run ===

Source: /home/noah/.cache/pacha/models/d47927c5638f80ab.gguf
Backend: wgpu (Vulkan)
[PMAT-333] Dequantizing 28 layers (hidden=1536, heads=12/2, intermediate=8960)

rc=0
=== APR Run ===
(plain text output, -f banana silently ignored)

rc=0
Inference tracing enabled (APR-TRACE-001)
  Trace level: banana

Expected / root cause

--backend is documented as (cuda, cpu, wgpu), --trace-level as (none, basic, layer, payload, chrome), -f as (text, json, srt, vtt). An unrecognised value should be rejected (rc != 0), not echoed back as if it took effect. The --backend case is the dangerous one: the binary already contains an elaborate guard whose whole point is that silently falling back makes throughput numbers meaningless (--backend cuda on this non-CUDA build correctly rc=5 with Refusing to silently fall back to wgpu/CPU: that path is ~20x slower ... and makes any throughput measurement taken through it meaningless), yet --backend cudaa sails straight into that same slow path while printing Backend override: cudaa.

Variations tried: Confirmed valid values do work, so the flag is wired: --backend cpu skips the wgpu dequant entirely (2.67s), --backend wgpu prints Backend: wgpu (Vulkan) + [PMAT-333] Dequantized 337 weights, 6174.9 MB F32, --backend cuda rc=5 with the guard message, no --backend == wgpu default. Confirmed the same silent-accept on apr chat --backend banana (rc=0, Backend override: banana) and on apr chat --top-p 5 (rc=0, header prints Top-P: 5, out of the [0,1] range). Contrast with commands that DO validate: apr tokenize plan --algorithm banana -> rc=5 Unknown algorithm: banana. Supported: bpe, wordpiece, unigram; apr embed --pool banana -> rc=5; apr oracle --family notafamily -> rc=4.

Target: run

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
for n in 2 4 8; do timeout 300 "$APR" run /home/noah/.cache/pacha/models/d47927c5638f80ab.gguf "hi" -n $n --no-gpu --trace > tr_$n.txt 2>&1; grep -E 'CONTRACT WARN|BRICK-PROFILE. Total' tr_$n.txt; done

Observed

[CONTRACT WARN] gpu-decode-profiling-v1 TOKEN_ACCOUNTING: LmHead.count=10 != tokens_processed=11. LmHead should fire exactly once per decoded token.
[BRICK-PROFILE] Total: 774.95ms, 11 tokens (9 prefill + 2 decode), 14.2 tok/s
[CONTRACT WARN] gpu-decode-profiling-v1 TOKEN_ACCOUNTING: LmHead.count=12 != tokens_processed=13. LmHead should fire exactly once per decoded token.
[BRICK-PROFILE] Total: 1169.10ms, 13 tokens (9 prefill + 4 decode), 11.1 tok/s
[CONTRACT WARN] gpu-decode-profiling-v1 TOKEN_ACCOUNTING: LmHead.count=16 != tokens_processed=17. LmHead should fire exactly once per decoded token.
[BRICK-PROFILE] Total: 1392.95ms, 17 tokens (9 prefill + 8 decode), 12.2 tok/s

Expected / root cause

A contract falsifier that fires on 100% of healthy runs is not a signal. Either the accounting is off by one (the same run reports Embedding count=12 against 13 tokens_processed, so the discrepancy is systemic, not GPU-specific) or the contract's expectation is wrong for the CPU/prefill path — note the contract is named gpu-decode-profiling-v1 yet fires on a --no-gpu CPU run. Whichever it is, one of the two must be corrected so the warning means something.

Variations tried: Varied token budget (n=2, 3, 4, 8), model (d47927c5638f80ab.gguf 1.0GB Q4_K, /home/noah/models/qwen2.5-coder-1.5b-instruct-q4k.apr), prompt length (9-token vs 34-token prefill) and trace level (none/basic/layer/payload/chrome). The warning fires every single time and the gap is always exactly 1: 10/11, 11/12, 12/13, 16/17, and 37/38 on the APR model with a 34-token prefill. Confirmed it is not GPU-related — every run used --no-gpu and printed Backend: CPU (SIMD-accelerated).

Target: run / chat

Repro

APR=/tmp/claude-1000/-home-noah-src-aprender/3e7b3507-59c1-4c5a-873b-c4003bfeca64/scratchpad/dogfood/cratesio/bin/apr
# (a) dense model, empty lm_head -> blamed on MoE
"$APR" tensors /home/noah/models/qwen2.5-coder-0.5b-instruct.apr 2>&1 | grep -E 'lm_head|embed_tokens'
timeout 300 "$APR" run /home/noah/models/qwen2.5-coder-0.5b-instruct.apr "What is 2+2?" -n 8 --no-gpu > a.txt 2>&1; echo "rc=$?"; cat a.txt
# (b) literal {stem} in a chat error
cp /home/noah/models/qwen2.5-coder-1.5b-instruct-q4k.apr m.apr
printf '/exit\n' | timeout 300 "$APR" chat m.apr --max-tokens 4 --no-gpu > b.txt 2>&1; echo "rc=$?"; tail -6 b.txt

Observed

│ lm_head.weight                                  │ [151936, 896] │ f32   │ 0 B      │
│ model.embed_tokens.weight                       │ [151936, 896] │ bf16  │ 259.7 MB │

rc=8
=== APR Run ===

Source: /home/noah/models/qwen2.5-coder-0.5b-instruct.apr
[PMAT-171] Loaded embedded BPE tokenizer: 151936 vocab, 151387 merges, 25 special tokens
[GH-175] OwnedQuantizedModel::from_apr: 24 layers loaded in 741.1ms
error: Inference failed: Inference failed: Invalid shape: matmul weight has EMPTY data buffer (in_dim=896, out_dim=151936, qtype=0); likely a MoE per-expert tensor was registered with len-0 data — see aprender#1789

rc=4
error: Invalid APR format: No Qwen tokenizer found. Searched:
1. Pacha cache ({stem}.tokenizer.json alongside model)
2. Model directory (tokenizer.json)
3. HuggingFace cache (~/.cache/huggingface/hub/models--Qwen--*/snapshots/*/tokenizer.json)

Expected / root cause

(a) Qwen2.5-Coder-0.5B is a dense, tied-embedding model — there are no experts. The real situation is a declared-but-empty lm_head.weight (shape [151936, 896], 0 bytes) next to a fully populated model.embed_tokens.weight, i.e. tied embeddings that were not resolved. Naming MoE sends the reader down the wrong path. (b) {stem} should be substituted with the model stem (m), so the user can see the exact filename being looked for. Both exit non-zero, which is why these are P2 rather than higher.

Variations tried: For (a), varied the model to rule out an apr-format-wide break: the other two APR fixtures run fine on the same binary — /home/noah/models/qwen2.5-coder-1.5b-instruct-q4k.apr -> rc=0 'Output: 4', and qwen2.5-coder-1.5b-instruct-q4k-v2.apr -> rc=0 'Output: 4'. Also tried the failing model with and without --stream: identical error. Worth noting apr validate on that same file returns rc=0 ✓ VALID 3/100 points despite the 0-byte lm_head. For (b), reproduced with two different model stems (m.apr and a copy named sub/m.apr); the placeholder is literal in both.

Target: run (default install, wgpu backend)

Repro

APR=<cratesio>/bin/apr
M=/home/noah/.cache/pacha/models/d47927c5638f80ab.gguf   # 1.04 GiB Q4_K
/usr/bin/time -v "$APR" run "$M" --prompt 'What is 2+2?' -n 16
/usr/bin/time -v "$APR" run "$M" --prompt 'What is 2+2?' -n 16 --no-gpu

Observed

default:   11.13 s, Maximum resident set size 13,925,232 KB (13.9 GB)
--no-gpu:   3.78 s, Maximum resident set size  3,583,340 KB (3.5 GB)

Backend: wgpu (Vulkan)
[PMAT-333] Dequantizing 28 layers (hidden=1536, heads=12/2, intermediate=8960)
[PMAT-333] Dequantized 337 weights, 6174.9 MB F32
[apr-cpu-vs-gpu-output-parity-v1] wgpu path rejected, attempting fallback: cosine vs CPU = 0.884301 (< 0.99) at step 1/3

Expected / root cause

A 1.0 GB Q4_K model must not require 13.9 GB of RAM to answer one prompt. The wgpu attempt allocates 6.17 GB of F32 BEFORE any parity check can reject it, so the cost is paid unconditionally. On a 16 GB machine the documented first command OOMs. Root cause: crates/aprender-serve/src/infer/gguf_gpu_generate.rs:370 gates the wgpu attempt only on !config.no_gpu under #[cfg(feature = "gpu")]; same shape at :437 for APR models.

Variations tried: default vs --features cuda build; with and without --no-gpu; two models (1.0 GB Q4_K gguf, 533 MB Qwen3.5 gguf). Output text is correct in every case (CPU fallback runs), so this is waste, not a wrong answer.

Exit code: 0

Target: run (wgpu Q4_K numerics)

Repro

same as ORCH-001, default invocation

Observed

[apr-cpu-vs-gpu-output-parity-v1] wgpu path rejected, attempting fallback: cosine vs CPU = 0.884301 (< 0.99) at step 1/3

Expected / root cause

Contained by the guard, so users get correct output — but the shipped default backend order puts a demonstrably broken backend first. The code comment at gguf_gpu_generate.rs:57 claims 'Proven: cosine=0.999863 on Blackwell sm_121'; on RTX 4090 / Vulkan it is 0.884. The claim is hardware-specific and the code treats it as general.

Variations tried: two models; default and cuda builds

Exit code: 0

Target: run (--features cuda build)

Repro

APR=<cratesio-cuda>/bin/apr
"$APR" run /home/noah/.cache/pacha/models/d47927c5638f80ab.gguf --prompt 'What is 2+2?' -n 24 --gpu --benchmark

Observed

[trueno#243] Manual graph construction: pos=0, has_graph=false, capture_failed=false, token_count=0
[PAR-058-ATTN] Layer 0: num_heads=12, num_kv_heads=2, head_dim=128, max_len=2048, seq_len=1
[PAR-058-ATTN] K input OK, first 16: [2.9207492, 0.07158664, -0.8929267, ...]
[trueno#243] ✓ Manual graph: 619 kernels. first_args=Some(["0x79899b9e4000", ...]), current_logits_buf=0x7988c3260000
[F2-VALIDATION] pos0 argmax flip (benign BOS near-tie) ignored; ...

Expected / root cause

No --verbose and no --trace were passed. Sources: crates/aprender-serve/src/cuda/executor/kv_scatter.rs:610-655 (debug_attention_trace, called at :534 gated only on layer_idx == 0 && new_len <= 3), the trueno#243 messages in cuda/executor/mod.rs, and infer/inference_result.rs:590. debug_attention_trace also does a compute_stream.synchronize() plus a full GPU->host copy of Q and K in the decode path. 238 unconditional eprintln! calls live under crates/aprender-serve/src/cuda/.

Variations tried: cuda build vs default build (spew is cuda-path-only); with and without --verbose (identical)

Exit code: 0