[Router] Log every request at one site; derive its outcome from the final status (3/3) (#39465)

Co-authored-by: Kangyan Zhou <kangyan.zhou@radixark.ai>
Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-authored-by: Shangming Cai <csmthu@gmail.com>

experimental/sgl-router/tests/proxy/chat_routing.rs

@@ -527,6 +527,158 @@ async fn non_streaming_upstream_500_preserved() {
     assert_eq!(got, upstream_body);
 }
 
+/// A response the router FORWARDS from a worker with a non-2xx status is an
+/// `Ok(Response)` at the router layer — only transport failures become `Err`.
+/// The per-worker `worker_requests_total` outcome must therefore be derived from
+/// the client-visible HTTP status, not from `Result::Ok`/`Err`: a forwarded 5xx
+/// is counted `outcome="error"`, NOT credited as a success.
+#[tokio::test]
+async fn forwarded_5xx_records_worker_outcome_error_not_success() {
+    let worker = crate::common::mock_worker::MockWorker::start_returning_error(
+        StatusCode::INTERNAL_SERVER_ERROR,
+        serde_json::json!({"error": {"type": "server_error", "message": "boom"}}),
+    )
+    .await;
+    let ctx = build_ctx_with_worker(&worker.url);
+    let app = build_router(ctx.clone());
+
+    let req = Request::builder()
+        .method("POST")
+        .uri("/v1/chat/completions")
+        .header("content-type", "application/json")
+        .body(Body::from(
+            serde_json::to_vec(&serde_json::json!({
+                "model": "tiny",
+                "messages": [{"role": "user", "content": "hi"}],
+                "stream": false,
+            }))
+            .unwrap(),
+        ))
+        .unwrap();
+    let res = app.oneshot(req).await.unwrap();
+    assert_eq!(res.status(), StatusCode::INTERNAL_SERVER_ERROR);
+    let _ = res.into_body().collect().await.unwrap().to_bytes();
+
+    let m = ctx.metrics.render();
+    let error_line = format!(
+        r#"sgl_router_worker_requests_total{{worker_url="{}",model_id="tiny",mode="plain",outcome="error"}} 1"#,
+        worker.url,
+    );
+    assert!(
+        m.contains(&error_line),
+        "a forwarded 5xx must be counted as outcome=\"error\"; got:\n{m}",
+    );
+    let success_line = format!(
+        r#"sgl_router_worker_requests_total{{worker_url="{}",model_id="tiny",mode="plain",outcome="success"}}"#,
+        worker.url,
+    );
+    assert!(
+        !m.contains(&success_line),
+        "a forwarded 5xx must NOT be credited as a success; got:\n{m}",
+    );
+}
+
+/// Buffer-backed `tracing` writer so a test can assert on the access log.
+#[derive(Clone)]
+struct VecWriter(Arc<std::sync::Mutex<Vec<u8>>>);
+
+impl std::io::Write for VecWriter {
+    fn write(&mut self, b: &[u8]) -> std::io::Result<usize> {
+        self.0.lock().unwrap().extend_from_slice(b);
+        Ok(b.len())
+    }
+    fn flush(&mut self) -> std::io::Result<()> {
+        Ok(())
+    }
+}
+
+impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for VecWriter {
+    type Writer = VecWriter;
+    fn make_writer(&'a self) -> Self::Writer {
+        self.clone()
+    }
+}
+
+/// Install a permissive global subscriber once per test binary.
+///
+/// `tracing` caches each callsite's "interest" the first time it is hit. Under
+/// the parallel test harness a thread with no subscriber of its own evaluates
+/// the `http_request` callsite against `NoSubscriber`, which caches it as
+/// *never* interested — after which a per-test `set_default` capture on another
+/// thread records nothing, and an access-log assertion fails depending only on
+/// which test ran first. A global subscriber that is interested in everything
+/// keeps the callsite live; it discards what it receives, so per-test
+/// `set_default` buffers stay isolated to their own thread.
+fn prime_tracing_callsites() {
+    static PRIMED: std::sync::OnceLock<()> = std::sync::OnceLock::new();
+    PRIMED.get_or_init(|| {
+        let _ = tracing::subscriber::set_global_default(
+            tracing_subscriber::fmt()
+                .with_max_level(tracing::Level::TRACE)
+                .with_writer(std::io::sink)
+                .finish(),
+        );
+    });
+}
+
+/// The access-log line for a DISPATCHED request must name the worker it was
+/// dispatched to. Only the chat handler knows that, so it attaches a
+/// `RequestLogContext` to the response — including on the post-dispatch error
+/// path, which is where "which engine failed" matters most. Without the attach
+/// the line is still emitted, just anonymous, so only a log assertion catches a
+/// regression here.
+#[tokio::test]
+async fn dispatched_error_names_its_worker_in_the_access_log() {
+    prime_tracing_callsites();
+    let buf = Arc::new(std::sync::Mutex::new(Vec::<u8>::new()));
+    let subscriber = tracing_subscriber::fmt()
+        .with_ansi(false)
+        .with_writer(VecWriter(buf.clone()))
+        .finish();
+    let _guard = tracing::subscriber::set_default(subscriber);
+
+    // A worker that accepts the connection then drops it mid-body: dispatch
+    // succeeds, the request fails afterwards.
+    let worker = crate::common::mock_worker::MockWorker::start_returning_partial_body(
+        StatusCode::OK,
+        b"{\"partial\": ",
+    )
+    .await;
+    let ctx = build_ctx_with_worker(&worker.url);
+
+    let req = Request::builder()
+        .method("POST")
+        .uri("/v1/chat/completions")
+        .header("content-type", "application/json")
+        .header("x-request-id", "rid-dispatched-error")
+        .body(Body::from(
+            serde_json::to_vec(&serde_json::json!({
+                "model": "tiny",
+                "messages": [{"role": "user", "content": "hi"}],
+                "stream": false,
+            }))
+            .unwrap(),
+        ))
+        .unwrap();
+    let res = build_router(ctx.clone()).oneshot(req).await.unwrap();
+    assert_eq!(res.status(), StatusCode::BAD_GATEWAY);
+    let _ = res.into_body().collect().await.unwrap().to_bytes();
+
+    let logs = String::from_utf8(buf.lock().unwrap().clone()).unwrap();
+    let line = logs
+        .lines()
+        .find(|l| l.contains("rid-dispatched-error"))
+        .unwrap_or_else(|| panic!("no access-log line for the request; captured:\n{logs}"));
+    assert!(
+        line.contains(&format!(r#"worker="{}""#, worker.url)),
+        "a dispatched failure must name its worker: {line}",
+    );
+    assert!(
+        line.contains(r#"model="tiny""#) && line.contains(r#"outcome="error""#),
+        "a dispatched failure must carry model and outcome=error: {line}",
+    );
+}
+
 #[tokio::test]
 async fn non_streaming_upstream_4xx_body_passthrough() {
     // Regression: the worker's response bytes must reach the client

experimental/sgl-router/tests/proxy/timeout.rs

@@ -77,7 +77,7 @@ async fn non_streaming_request_times_out_when_worker_hangs() {
     let policies = Arc::new(build_policy_registry(&cfg).unwrap());
     let proxy = Arc::new(Proxy::new(Duration::from_millis(200)).unwrap());
     let ctx = Arc::new(AppContext::new(cfg, tokenizers, proxy, registry, policies));
-    let app = build_router(ctx);
+    let app = build_router(ctx.clone());
 
     let req = Request::builder()
         .method("POST")
@@ -111,6 +111,19 @@ async fn non_streaming_request_times_out_when_worker_hangs() {
     );
     let bytes = res.into_body().collect().await.unwrap().to_bytes();
     let body_str = String::from_utf8_lossy(&bytes);
+    // A hung worker is the most common hard worker failure there is, so it must
+    // land in `outcome="error"` — the series a per-worker error-ratio alert
+    // watches. Deriving the outcome from the 504 status instead would silently
+    // reclassify it as `cancelled` and blind that alert.
+    assert!(
+        ctx.metrics
+            .render()
+            .lines()
+            .any(|l| l.starts_with("sgl_router_worker_requests_total{")
+                && l.contains(r#"outcome="error""#)),
+        "an upstream timeout must be counted outcome=error, not cancelled:\n{}",
+        ctx.metrics.render(),
+    );
     assert!(
         body_str.contains("\"code\":\"upstream_timeout\""),
         "body: {body_str}"