fix(metrics): wire /metrics to the engine the server actually serves from (#277)

[localai-bot]

Closes #277. Row SERVE-METRICS (+ SERVE-RESPONSE-METRICS), punch-list item 7
(ROAD-V1-C8). Spec: .agents/specs/async-metrics.md,
committed alone before any implementation.

The bug

/metrics was dead on the production server. The synchronous LLMEngine folds
IterationStats into the logger 1:1 with llm_engine.py:306-332. The shipped
server does not use it — every route is served from AsyncLLM, whose output
handler folded nothing into any logger. A real deployment therefore scraped a
well-formed vllm:* catalog whose series never moved, which is worse than an
absent endpoint: a scraper reads a motionless, correctly-named catalog as
"the server is idle".

Three defects, three discriminators

1. No fold. AsyncLLM gains the attach point LLMEngine already had,
mirroring upstream's logger_ref[0] (async_llm.py:648-652) as an atomic
pointer so an attach is visible to the already-running handler thread.
RunOutputHandler builds one IterationStats per step under a non-null logger
(:664-665), threads it through process_outputs (:676-678), and folds it
plus scheduler_stats into Record() (:697-702) — deliberately outside
output_processor_mutex_, which keeps the logger's mutex a leaf lock.

2. No scheduler_stats / timestamp on the depth-2 path.
EngineCore::step_with_batch_queue stamped neither, while step() stamped
both. Upstream stamps them in the path both step functions share —
scheduler_stats in Scheduler.update_from_output (scheduler.py:1938-1951),
timestamp in EngineCoreOutputs.__post_init__ (engine/__init__.py:249-251)
— which is precisely why upstream's step_with_batch_queue stamps nothing
extra. Unstamped, the async-scheduling serving path (what LoadedEngine
resolves to whenever the runner supports it) publishes all-zero gauges and
reports TTFT as -arrival_time. The old VT_TTFT_DUMP-only timestamp stamp is
subsumed; the diagnostic reads the same value it always did.

3. Not thread-safe. PromRegistry is documented as not thread-safe, and
upstream never needs it to be — prometheus_client mutates under the GIL. Once
the output-handler thread records while an HTTP worker scrapes, one recorder
and N readers genuinely overlap, so Record / Expose / SetCacheConfigInfo
take one mutex.

server_main.cpp attaches the single logger it already builds to both
frontends. Two stale comments in api_server.{h,cpp} claiming AsyncLLM has no
live logger are corrected.

Additive and opt-in throughout: with no logger attached the handler takes the
same no-stats process_outputs call as before, asserted byte-for-byte by a
token-stream identity case.

RED first

Verbatim in the spec's Evidence section.

test_llm_engine -tc="async_llm*"
  :1083 prompt_tokens_total                          -> 0 == 2
  :1084 generation_tokens_total                      -> 0 == 8
  :404  REQUIRE series absent: vllm:request_success_total{...,"length"}
  :1092 time_to_first_token_seconds _count           -> 0 == 2
  :1093 inter_token_latency_seconds _count           -> 0 == 6
  :1094 e2e_request_latency_seconds _count           -> 0 == 2
  :1095 request_time_per_output_token_seconds _count -> 0 == 2
  :1096 iteration_tokens_total _count                -> 0 >= 1
  :1097 request_generation_tokens _count             -> 0 == 2
  :1101-1103 request_{queue,prefill,inference}_time _count -> 0 == 2
  :1109-1113 {queue,prefill,inference,decode,e2e} _sum > 0 -> 0 > 0
  :1119 time_to_first_token_seconds _sum > 0         -> 0 > 0
  [doctest] assertions: 63 | 44 passed | 19 failed |

test_async_llm -tc="*depth-2*"
  :608 CHECK( saw_running )                          -> false
  :657 prompt_tokens_total                           -> 0 == 1
  :658 generation_tokens_total                       -> 0 == 8
  :660 time_to_first_token_seconds_count             -> 0 == 1
  :662 e2e_request_latency_seconds_count             -> 0 == 1
  :666 time_to_first_token_seconds_sum > 0           -> 0 > 0
  :668 e2e_request_latency_seconds_sum > 0           -> 0 > 0
  [doctest] assertions: 9 | 2 passed | 7 failed |

The gauge assertion had to be a poll against a deliberately slowed runner:
every gauge is legitimately 0 once the batch drains, so an end-of-run scrape
could not see defect 2. And a _count-only assertion would have passed defect
3 — only the sign of the _sum distinguishes -arrival_time from a real TTFT.

GREEN

Binary	Result
test_llm_engine	15 cases / 291 assertions, 0 failed
test_async_llm	10 cases / 325 assertions, 0 failed
test_prometheus_metrics	4 cases / 81 assertions, 0 failed
ctest --test-dir build-cpu -j 6	366/366 passed, 0 failed (780.19 s)

None of the four known-flaky binaries failed in that run. From-scratch CPU build
under -Werror: 1131/1131 clean.

Two failures on the re-run, and what they actually were

One was not a failure at all. A post-rebase re-run appeared to report
test_openai_conformance failing 13 of 23 cases. The log said otherwise before
any test was re-run: the assertions cited
/home/mudler/_git/vllm.cpp-lora-w2/…/test_conformance.cpp — a different
worktree, while strings on the binary ctest actually ran has 152 references
to this worktree and zero to that one; the file was 48,261 NUL bytes out
of 60,238 (a sparse hole, i.e. two writers at independent offsets); and its
own progress lines counted 1/368 while the summary said out of 369. A
concurrent session was running ctest in vllm.cpp-lora-w2 (pid 218469,
confirmed via /proc/<pid>/cwd) and its output landed in this session's log —
while our own run was still executing. Gate logs now go to .gatelogs/ inside
the worktree, and a failing log gets validated (cited paths vs the binary, NUL
runs, self-consistent counts) before it is believed.

One was real, pre-existing, and now has its own issue. On an uncontaminated
re-run test_async_llm genuinely failed — in async_llm test_abort and test_multi_abort leave other requests healthy (:325,
Drain(engine, reused) == 3 observing 4), a case this PR does not touch. That
binary is squarely in this PR's blast radius, so it was measured rather than
dismissed: 40 concurrent copies of the single case, three rounds each,
alternating the two builds in one worktree on the same box.

Tree	r1	r2	r3	total
main @ 848d4a87	11/40	9/40	11/40	31/120 (25.8%)
main + this PR	9/40	15/40	7/40	31/120 (25.8%)

Identical rate — pre-existing on main, neither caused nor worsened here. The
underlying defect is real (AsyncLLM::abort queues the core abort
asynchronously, while the case's precondition reads only frontend state, so a
frame from a reused id's previous incarnation can reach the new collector) and
is filed as #294 rather than silently fixed in this PR. Serially on an idle
box both binaries are green: test_async_llm 10/10, test_openai_conformance
23/23.

Recipe:

cmake -S . -B build-cpu -G Ninja -DCMAKE_BUILD_TYPE=Release \
      -DVLLM_CPP_CUDA=OFF -DVLLM_CPP_VULKAN=OFF -DVLLM_CPP_METAL=OFF
cmake --build build-cpu -j 18
ctest --test-dir build-cpu -j 6 --output-on-failure

Scope

Out, and untouched: the config-gated metric families (spec-decode,
kv-connector, multimodal cache, LoRA), which are the sibling residual on the
same row; update_scheduler_stats (LoRA-only upstream); the
VLLM_V1_OUTPUT_PROC_CHUNK_SIZE chunking loop, which our synchronous
process_outputs does not have on either engine; DP/multi-engine aggregation.

Records

SERVE-METRICS and SERVE-RESPONSE-METRICS in the engine and feature matrices,
the ROAD-V1-C8 residual in roadmap_v1.md and roadmap-v1-completion.md
(punch-list item 7 closed), the coordination claim, NOW.md (net zero against
its 6000-char budget), and docs/STATUS.md, whose claim that metrics "lack live
async backing" had become false. The STATUS edit is a net deletion (-30) and
the ratchet is re-pinned byte-tight downward in the same change, which
tests/scripts/test_check_public_doc_tables.py::test_the_rebased_character_ratchet_is_byte_tight
already enforces. docs/USAGE.md and docs/FEATURES.md updated for the
serving-surface change.

No performance axis is claimed: the wiring is inert without a logger, and with
one it costs one IterationStats per step on the output-handler thread — the
same cost the synchronous engine already paid.

🤖 Generated with Claude Code

[localai-bot]

CI note: device-leakage is red on main, not on this branch

This PR inherits a failing device-leakage check. It is not caused by these
changes, and I verified that rather than asserting it: checking out only src/
and include/ at each recent main revision and running the checker against
them gives

main revision	DSR sites
abdc3a26	32	baseline
848d4a87	32
84fc736d	32
7d45913a	33	← regression enters
e17e8f8a	33
24306364	33	this PR's base

7d45913a is the landing of #213. Diffing the checker's own site list across
84fc736d..7d45913a yields exactly one new entry —
src/vllm/model_executor/models/qwen3_5.cpp: [vt_ifdef] #ifdef VT_MARLIN_NVFP4 —
a device-specific branch in the shared layer with no DSR-ALLOW and no
deliberate baseline change.

Filed as #302 rather than fixed here: only the #213 author knows whether that
#ifdef is genuinely the platform leg (→ DSR-ALLOW with a reason) or should be
asking the Platform capability table instead, and the checker explicitly forbids
raising the baseline to make it pass.

This branch adds zero DSR sites: none of the 33 are in any file it touches.

The one local test failure, also pre-existing

test_async_llm intermittently fails async_llm test_abort and test_multi_abort leave other requests healthy (:325) — a case this PR does not touch. Measured
paired, same box, 40 concurrent copies × 3 rounds, alternating builds in one
worktree: main 31/120 (25.8%) vs main + this PR 31/120 (25.8%).
Identical, so it is neither caused nor worsened here. Filed as #294. This
PR's own new cases are 8/8 under the same contention, and serially on an idle box
test_async_llm is 10/10, test_openai_conformance 23/23,
test_openai_api_server 50/50.