Fix: Fail black-holed dials in 10s and split response durations into ttfb

CLAUDE.md

@@ -616,9 +616,26 @@ Every event on `/v1/sessions/{id}` and `/v1/events` carries:
   open and a close saying 200. An opaque CONNECT that could not be dialed
   reports the same situation one layer down as `tunnelReason: "dial-failed"` with
   `error.kind: "dial_failed"`.
+- `ttfbMs` — on a delivered response row, the wall time from request entry into the
+  listener to the upstream's response **headers** arriving, so `durationMs` − `ttfbMs`
+  is how long the body took — for a streamed completion, the stream time. The pair
+  separates a slow-to-answer origin from one that answered and then trickled, which
+  `durationMs` alone cannot (#1251). Absent when the exchange failed before headers, on
+  request rows, and on tunnel rows (an opaque tunnel has no headers to time). All three
+  listeners set `pctx.ResponseHeadersAt` at their own headers-arrival moment — `client.Do`
+  returning (forward and reverse proxy), Envoy's response-headers callback (extproc) —
+  and every response-event builder derives the figure the same way
+  (`pipeline.DurationBetween`). The row itself is recorded when the listener is
+  finished with the body — after the read on a buffered path, after the relay on a
+  streamed or unbuffered one — so the difference really is the body's time and not a
+  remainder cut short at the headers. The one arm that breaks the pattern is extproc
+  with a body-free pipeline: the row is recorded at the headers while Envoy relays the
+  body unseen, so ttfb is left absent there rather than reported as a figure equal to
+  the whole duration. agentop's detail pane renders the split as a
+  `timing:` line.
 - `requestedHost` — present only when a plugin redirected the request (`pctx.Redirect`): the host the client asked for. `host` is where the request actually went, and usage, the cost ledger and pricing all follow `host`. agentop's detail pane shows both on a `redirected:` line.
 - `inference.requestedModel` — present only when a plugin changed the model (`pctx.SetRequestModel`): the model the client asked for. `inference.model` is the model the request was sent for, which settlement prices; agentop's detail pane shows both on a `model:` line.
-- `bytesUp`, `bytesDown` — **body** bytes, one direction per row: a request row carries `bytesUp`, the body **as forwarded** (so a `tool-prune`-style rewrite is reflected, since the count is taken after the pipeline ran), and a response row carries `bytesDown`, the body **as it came back from the destination** — not as delivered, because extproc records the row before it emits a response mutator's replacement. Headers are not counted. A tunnel close is the one row carrying both. **Zero means the listener counted nothing, not that the body was empty**, and there is no third value for "unknown": every listener buffers bodies only when a plugin asks, so an unbuffered request reports zero, and so does a response relayed straight through — both proxies copy that one after the row is appended. agentop renders a zero side blank rather than as `0B`, and that is why its BYTES column can be trusted as a size when it shows one. All three listeners count the same thing for the same response, which took some doing: extproc sums the chunks Envoy hands it, while the proxies count off the upstream body at one choke point each, so every arm — buffered, block-by-block SSE, or chunk copy — reports the same figure. `core/listener/internal/bodycount` and `core/listener/parity`'s bytes fixtures hold that line.
+- `bytesUp`, `bytesDown` — **body** bytes, one direction per row: a request row carries `bytesUp`, the body **as forwarded** (so a `tool-prune`-style rewrite is reflected, since the count is taken after the pipeline ran), and a response row carries `bytesDown`, the body **as it came back from the destination** — not as delivered, because extproc records the row before it emits a response mutator's replacement. Headers are not counted. A tunnel close is the one row carrying both. **Zero means the listener counted nothing, not that the body was empty**, and there is no third value for "unknown": every listener buffers bodies only when a plugin asks, so an unbuffered request reports zero. A response relayed straight through is counted, not zero — both proxies record the row after the copy (#1251's fix), so the bytes they relayed through their own process are on it. The one arm that still reports ↓0 is extproc with a body-free pipeline: it asked Envoy for body mode NONE, so the bytes it never saw are bytes it asked not to see — `core/listener/parity`'s `TestDivergence_InboundResponseBodyCountWhenNoPluginReadsIt` pins that disagreement with its reason. agentop renders a zero side blank rather than as `0B`, and that is why its BYTES column can be trusted as a size when it shows one. Everywhere else the three listeners count the same thing for the same response, which took some doing: extproc sums the chunks Envoy hands it, while the proxies count off the upstream body at one choke point each, so every arm — buffered, block-by-block SSE, or chunk copy — reports the same figure. `core/listener/internal/bodycount` and `core/listener/parity`'s bytes fixtures hold that line.
 - `tunnel`, `tunnelReason` — an opaque CONNECT (or transparent-redirect) tunnel records two rows sharing a `requestId`: the open (`phase: "request"`, `tunnelReason` saying why the bytes stayed opaque) and, when the tunnel ends, the close (`phase: "response"`). The close carries the CONNECT's own `statusCode` — 200, or 502 with the dial error in `error` when the destination could not be reached (`tunnelReason: "dial-failed"`) — plus `durationMs` for how long the tunnel stayed open and, in `bytesUp`/`bytesDown`, the bytes it carried each way (up = client to destination; opaque bytes have no body/header split, so these are everything that crossed). It is not the destination's status: that travels inside the client's end-to-end TLS. A bridged tunnel's open is recorded with its first decrypted request — in that request's session, directly before it, stamped with its time — and records no close, because the request carries its own response; a bridged tunnel that recorded no request gets its open and a close when it ends. Tunnel rows are kept out of `/v1/usage`: a tunnel's lifetime is not a request latency.
 - `httpMethod`, `httpPath` — the HTTP verb and path, so a request no parser recognized is still identifiable rather than showing only a host. Distinct from the `method` inside `a2a` / `mcp`, which is a protocol method name. On an opaque tunnel `httpMethod` is `CONNECT` and `httpPath` is absent — opaque bytes carry no request line. The path is query-stripped and percent-decoded, so query-borne credentials never reach the timeline, but a secret in a path *segment* (a bot token, a webhook path) does survive on this unauthenticated surface — worth knowing before exporting events off-box.
 - `subagent` — present on rows from a Claude Code subagent or agent-team teammate: the `X-Claude-Code-Agent-Id` the request carried. For a subagent that is also the `<id>` in `~/.claude/projects/<dir>/<session>/subagents/agent-<id>.meta.json`; for a teammate the join is unverified. Resolved by `Context.Subagent`, pinned with the User-Agent by `ResolveClient` so no plugin can re-file a row, and **refused rather than sanitised** when unusable (control runes, over 128 bytes), because it is a join key and a cleaned-up id joins nothing. It does not move the row: a subagent's requests stay in their parent's session, so the header must not be added to `session.id_headers`. **It names an agent, it does not classify the row:** `inference.agentRole` stays the field that says whether a row is a subagent's, and a teammate's row is `agentRole: main` with `subagent` set — Claude Code writes `cc_is_subagent=true` only for `agentType: subagent`.

cmd/agentop/tui/detail_pane.go

@@ -50,7 +50,7 @@ func (m *model) showDetail(r eventRow, resetScroll bool) {
 		if r.tunnel != nil {
 			tunnel = tunnelHeader(r.tunnel)
 		}
-		for _, h := range []string{tlsHeader(e.TLS), rewriteHeader(e), tunnel} {
+		for _, h := range []string{tlsHeader(e.TLS), rewriteHeader(e), timingHeader(e), tunnel} {
 			if h != "" {
 				lines = append(lines, strings.Split(h, "\n")...)
 				lines = append(lines, "")
@@ -75,6 +75,36 @@ func (m *model) showDetail(r eventRow, resetScroll bool) {
 	m.detailVp.SetYOffset(m.detailVp.YOffset)
 }
 
+// timingHeader decomposes a response row's duration the way #1251 asked for:
+// how long the origin took to answer (ttfb) against how long the body then
+// took. Duration alone cannot tell an 11-minute response with 217 tokens
+// apart from a fast one — the two need different fixes, and the reader
+// sorting by duration is asking exactly that question. The body's share is
+// Duration − Ttfb rather than a third measurement: the row already holds
+// both ends of the span. Response rows only, and only when ttfb exists — a
+// failed exchange has no headers to time, and a request row no duration.
+//
+//	timing:  ttfb 412ms · body 10m32s of 11m07s total
+func timingHeader(e *pipeline.SessionEvent) string {
+	if e.Phase != pipeline.SessionResponse || e.Ttfb <= 0 || e.Duration == 0 {
+		return ""
+	}
+	body := e.Duration - e.Ttfb
+	if body < 0 {
+		body = 0
+	}
+	// formatDuration renders zero blank because a zero in the DURATION column
+	// means "the listener counted nothing" — an unknown. This zero is a computed
+	// difference and means the body took under a millisecond, which the sentence
+	// wants said rather than elided: a blank would print "body  of 412ms total".
+	bodyText := formatDuration(body)
+	if body == 0 {
+		bodyText = "0ms"
+	}
+	return fmt.Sprintf("timing:      ttfb %s · body %s of %s total",
+		formatDuration(e.Ttfb), bodyText, formatDuration(e.Duration))
+}
+
 // tunnelHeader summarizes the CONNECT tunnel folded into a TLS-bridged
 // request row: the bridged origin (host:port) and any gate invocations that
 // ran on the tunnel-open before the bytes were decrypted. Lets an operator

cmd/agentop/tui/detail_pane_test.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/rossoctl/cortex/core/cost/event"
 	"github.com/rossoctl/cortex/core/pipeline"
@@ -244,6 +245,51 @@ func TestRewriteHeader_StacksTheRedirectAndTheModel(t *testing.T) {
 	}
 }
 
+// The #1251 shape: an 11-minute response whose ttfb is small says "the origin
+// answered, then the stream trickled" — the header exists to make that legible
+// without dividing two millisecond figures in one's head.
+func TestTimingHeader_SplitsDurationIntoTtfbAndBody(t *testing.T) {
+	got := timingHeader(&pipeline.SessionEvent{
+		Phase:    pipeline.SessionResponse,
+		Duration: 667 * time.Second,
+		Ttfb:     5 * time.Second,
+	})
+	want := "timing:      ttfb 5.00s · body 11m02s of 11m07s total"
+	if got != want {
+		t.Errorf("timingHeader = %q, want %q", got, want)
+	}
+}
+
+// A body that landed inside the same millisecond as the headers is a computed
+// zero, not an unknown one: the column convention renders counted-nothing
+// blank, but a blank here would leave a hole in the middle of the sentence.
+func TestTimingHeader_RendersAZeroBodyExplicitly(t *testing.T) {
+	got := timingHeader(&pipeline.SessionEvent{
+		Phase:    pipeline.SessionResponse,
+		Duration: 412 * time.Millisecond,
+		Ttfb:     412 * time.Millisecond,
+	})
+	want := "timing:      ttfb 412ms · body 0ms of 412ms total"
+	if got != want {
+		t.Errorf("timingHeader = %q, want %q", got, want)
+	}
+}
+
+// No header where the decomposition would be fiction: a request row (no
+// duration), a failed exchange (no ttfb — nothing answered), and a tunnel
+// close (no headers to time).
+func TestTimingHeader_EmptyWhereTheFiguresAreNot(t *testing.T) {
+	for _, e := range []*pipeline.SessionEvent{
+		{Phase: pipeline.SessionRequest, Duration: time.Second, Ttfb: 100 * time.Millisecond},
+		{Phase: pipeline.SessionResponse, Duration: 30 * time.Second},
+		{Phase: pipeline.SessionResponse},
+	} {
+		if got := timingHeader(e); got != "" {
+			t.Errorf("timingHeader = %q for phase %v duration %v ttfb %v, want empty", got, e.Phase, e.Duration, e.Ttfb)
+		}
+	}
+}
+
 // The JSON below the header keeps requestedModel on both phases, beside model.
 func TestFilterForDetail_KeepsRequestedModel(t *testing.T) {
 	wire := []byte(`{"inference":{"model":"glm-5.3","requestedModel":"claude-opus-5-5","completion":"hi"}}`)

cmd/agentop/tui/events_pane.go

@@ -6,6 +6,7 @@ import (
 	"slices"
 	"sort"
 	"strings"
+	"time"
 
 	"github.com/charmbracelet/lipgloss"
 
@@ -1021,10 +1022,18 @@ func formatBytes(n int64) string {
 // Seconds hand over to minutes at 59.995s rather than 60s, because %.2f rounds
 // 59.999s up to "60.00s", a seconds figure that is already a minute.
 func durationCell(e pipeline.SessionEvent) string {
-	if e.Duration == 0 {
+	return formatDuration(e.Duration)
+}
+
+// formatDuration is durationCell's body, split out so the detail pane's timing
+// header can format ttfb and the body's share of a response at the same
+// precision the DURATION column uses — one rule for the same unit, everywhere
+// a reader sees it.
+func formatDuration(d time.Duration) string {
+	if d == 0 {
 		return ""
 	}
-	ms := e.Duration.Milliseconds()
+	ms := d.Milliseconds()
 	switch {
 	case ms < 1000:
 		return fmt.Sprintf("%dms", ms)

core/listener/extproc/server.go

@@ -456,6 +456,7 @@ func (s *Server) recordInboundResponseSession(pctx *pipeline.Context) {
 		HTTPMethod:     pctx.Method,
 		HTTPPath:       pctx.Path,
 		Duration:       pipeline.DurationSince(pctx.StartedAt),
+		Ttfb:           pipeline.DurationBetween(pctx.StartedAt, pctx.ResponseHeadersAt),
 		Client:         pctx.ClientInfo(),
 		Subagent:       pctx.Subagent(),
 		ParentSubagent: pctx.ParentSubagent(),
@@ -492,6 +493,7 @@ func (s *Server) recordOutboundResponseSession(pctx *pipeline.Context) {
 		HTTPMethod:     pctx.Method,
 		HTTPPath:       pctx.Path,
 		Duration:       pipeline.DurationSince(pctx.StartedAt),
+		Ttfb:           pipeline.DurationBetween(pctx.StartedAt, pctx.ResponseHeadersAt),
 		Client:         pctx.ClientInfo(),
 		Subagent:       pctx.Subagent(),
 		ParentSubagent: pctx.ParentSubagent(),
@@ -671,6 +673,22 @@ func (s *Server) handleResponseHeaders(ctx context.Context, headers *corev3.Head
 		p = s.InboundPipeline
 	}
 
+	// Envoy delivering response headers is this listener's headers-arrival
+	// moment — the same point in the exchange where the proxy listeners set
+	// theirs — so ttfb means one thing on a row from any listener (#1251).
+	// Set it, though, only when the row is NOT recorded right here while the
+	// body is still coming: with !p.NeedsBody() the body phase below is never
+	// requested, Envoy relays the body without us, and the row lands at
+	// headers time — so ttfb ≈ duration and duration−ttfb would read as
+	// "body 0ms" for a body this listener never saw, the exact misreading
+	// #1251's split exists to prevent. Absent is the contract's "not
+	// measured", so leave the timestamp zero on that arm. endOfStream means
+	// no body is coming at all, and p.NeedsBody() means the body phase
+	// records later — in both, headers arrival is a real, reportable figure.
+	if p.NeedsBody() || endOfStream {
+		pctx.ResponseHeadersAt = time.Now()
+	}
+
 	// Defer to the body phase — but only when there IS one.
 	//
 	// AND !endOfStream IS THE FIX, not a refinement. NeedsBody() alone is unconditionally true for