Skip to content

Commit 548909e

Browse files
committed
fix(gateway): accept trailing terminal response SSE events
Recognize complete public /v1/responses terminal events even when the upstream closes without the final SSE blank-line separator, while keeping nonterminal partial buffers conservative. Add metadata-only request-log diagnostics and regression coverage for trailing terminal stream settlement.
1 parent e3e188e commit 548909e

6 files changed

Lines changed: 502 additions & 16 deletions

File tree

lib/codex_pooler/accounting/request_logs.ex

Lines changed: 107 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -404,7 +404,7 @@ defmodule CodexPooler.Accounting.RequestLogs do
404404

405405
@spec maybe_put_transport_failure(map(), Attempt.t()) :: map()
406406
defp maybe_put_transport_failure(projection, %Attempt{} = attempt) do
407-
case transport_failure_projection(attempt.response_metadata) do
407+
case transport_failure_projection(attempt) do
408408
transport_failure when map_size(transport_failure) > 0 ->
409409
Map.put(projection, :transport_failure, transport_failure)
410410

@@ -413,9 +413,24 @@ defmodule CodexPooler.Accounting.RequestLogs do
413413
end
414414
end
415415

416-
@spec transport_failure_projection(term()) :: map()
417-
defp transport_failure_projection(response_metadata) do
418-
response_metadata
416+
@spec transport_failure_projection(Attempt.t()) :: map()
417+
defp transport_failure_projection(%Attempt{} = attempt) do
418+
metadata = Accounting.sanitize_metadata(attempt.response_metadata)
419+
420+
metadata
421+
|> persisted_transport_failure()
422+
|> case do
423+
transport_failure when map_size(transport_failure) > 0 ->
424+
transport_failure
425+
426+
_transport_failure ->
427+
stream_interruption_transport_failure(attempt, metadata)
428+
end
429+
|> safe_transport_failure()
430+
end
431+
432+
defp persisted_transport_failure(metadata) do
433+
metadata
419434
|> Accounting.sanitize_metadata()
420435
|> case do
421436
%{"transport_failure" => transport_failure} when is_map(transport_failure) ->
@@ -427,9 +442,96 @@ defmodule CodexPooler.Accounting.RequestLogs do
427442
_metadata ->
428443
%{}
429444
end
430-
|> safe_transport_failure()
431445
end
432446

447+
defp stream_interruption_transport_failure(
448+
%Attempt{} = attempt,
449+
%{"error_kind" => "stream_interrupted"} = metadata
450+
) do
451+
cond do
452+
attempt.network_error_code == "client_disconnected" ->
453+
%{
454+
"reason_class" => "downstream_client_disconnect",
455+
"reason" => "client_disconnected",
456+
"phase" => "send_payload",
457+
"pre_visible_output" => pre_visible_output?(metadata),
458+
"terminal_seen" => false,
459+
"text_frame_count" => stream_text_frame_count(metadata)
460+
}
461+
462+
attempt.network_error_code == "downstream_stream_error" ->
463+
%{
464+
"reason_class" => "downstream_stream_error",
465+
"reason" => "downstream_write_failed",
466+
"phase" => "send_payload",
467+
"pre_visible_output" => pre_visible_output?(metadata),
468+
"terminal_seen" => false,
469+
"text_frame_count" => stream_text_frame_count(metadata)
470+
}
471+
472+
attempt.network_error_code == "stream_idle_timeout" ->
473+
%{
474+
"reason_class" => "upstream_stream_idle_timeout",
475+
"reason" => "idle_timeout",
476+
"phase" => "receive_timeout",
477+
"pre_visible_output" => pre_visible_output?(metadata),
478+
"terminal_seen" => false,
479+
"text_frame_count" => stream_text_frame_count(metadata)
480+
}
481+
482+
present?(terminal_stream_error_code(metadata)) ->
483+
%{
484+
"reason_class" => "upstream_terminal_failure",
485+
"reason" => terminal_stream_error_code(metadata),
486+
"phase" => "receive",
487+
"pre_visible_output" => pre_visible_output?(metadata),
488+
"terminal_seen" => true,
489+
"text_frame_count" => stream_text_frame_count(metadata)
490+
}
491+
492+
attempt.network_error_code == "upstream_stream_error" ->
493+
%{
494+
"reason_class" => "upstream_stream_interrupted",
495+
"reason" => "closed_before_terminal",
496+
"phase" => "upstream_close",
497+
"pre_visible_output" => pre_visible_output?(metadata),
498+
"terminal_seen" => false,
499+
"text_frame_count" => stream_text_frame_count(metadata)
500+
}
501+
502+
true ->
503+
%{
504+
"reason_class" => "stream_interrupted",
505+
"reason" => "interrupted",
506+
"phase" => "receive",
507+
"pre_visible_output" => pre_visible_output?(metadata),
508+
"terminal_seen" => false,
509+
"text_frame_count" => stream_text_frame_count(metadata)
510+
}
511+
end
512+
end
513+
514+
defp stream_interruption_transport_failure(_attempt, _metadata), do: %{}
515+
516+
defp terminal_stream_error_code(metadata) do
517+
Map.get(metadata, "stream_error_code") || Map.get(metadata, "upstream_error_code")
518+
end
519+
520+
defp pre_visible_output?(metadata), do: stream_text_frame_count(metadata) == 0
521+
522+
defp stream_text_frame_count(metadata) do
523+
metadata
524+
|> Map.get("stream_text_frame_count")
525+
|> non_negative_integer()
526+
|> case do
527+
count when is_integer(count) -> count
528+
nil -> default_stream_text_frame_count(metadata)
529+
end
530+
end
531+
532+
defp default_stream_text_frame_count(%{"error_kind" => "stream_interrupted"}), do: 1
533+
defp default_stream_text_frame_count(_metadata), do: 0
534+
433535
@spec safe_transport_failure(map()) :: map()
434536
defp safe_transport_failure(transport_failure) when is_map(transport_failure) do
435537
%{}

lib/codex_pooler/gateway/transports/streaming/stream_protocol/public_responses.ex

Lines changed: 40 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,16 @@ defmodule CodexPooler.Gateway.Transports.Streaming.StreamProtocol.PublicResponse
1515
@spec new_state() :: state()
1616
def new_state, do: %{buffer: "", created?: false, text_delta?: false, passthrough?: false}
1717

18+
@terminal_buffer_markers [
19+
"data: [DONE]",
20+
"response.completed",
21+
"response.failed",
22+
"response.incomplete",
23+
"event: error",
24+
~s("type":"error"),
25+
~s("type": "error")
26+
]
27+
1828
@spec normalize_data(binary(), state()) :: {binary(), state()}
1929
def normalize_data(data, %{passthrough?: true} = state) when is_binary(data) do
2030
normalize_passthrough_data(data, state)
@@ -25,6 +35,9 @@ defmodule CodexPooler.Gateway.Transports.Streaming.StreamProtocol.PublicResponse
2535
{blocks, buffer} = StreamProtocol.complete_sse_blocks(buffered_data, bounded?: false)
2636

2737
cond do
38+
terminal_buffer?(buffer) ->
39+
normalize_blocks(blocks ++ [buffer], "", state)
40+
2841
blocks == [] and StreamProtocol.oversized_incomplete_sse_block?(buffer) ->
2942
record_oversized_incomplete(byte_size(buffered_data))
3043
{buffered_data, %{state | buffer: "", passthrough?: true}}
@@ -267,12 +280,37 @@ defmodule CodexPooler.Gateway.Transports.Streaming.StreamProtocol.PublicResponse
267280

268281
defp clean_string(_value), do: nil
269282

283+
@spec terminal_buffer?(binary()) :: boolean()
284+
defp terminal_buffer?(""), do: false
285+
286+
defp terminal_buffer?(buffer) when is_binary(buffer) do
287+
if terminal_buffer_candidate?(buffer) do
288+
done_marker?(buffer) or decoded_terminal_buffer?(buffer)
289+
else
290+
false
291+
end
292+
end
293+
294+
@spec terminal_buffer_candidate?(binary()) :: boolean()
295+
defp terminal_buffer_candidate?(buffer) do
296+
Enum.any?(@terminal_buffer_markers, &String.contains?(buffer, &1))
297+
end
298+
299+
@spec done_marker?(binary()) :: boolean()
300+
defp done_marker?(block), do: String.trim(block) == "data: [DONE]"
301+
302+
@spec decoded_terminal_buffer?(binary()) :: boolean()
303+
defp decoded_terminal_buffer?(buffer) do
304+
{event_type, decoded} = stream_block_event(buffer)
305+
306+
decoded != %{} and terminal_event?(event_type || decoded_string(decoded, "type"))
307+
end
308+
270309
defp stream_terminal?(blocks) do
271310
Enum.any?(blocks, fn block ->
272311
{event_type, decoded} = stream_block_event(block)
273312

274-
terminal_event?(event_type || decoded_string(decoded, "type")) or
275-
block == "data: [DONE]"
313+
terminal_event?(event_type || decoded_string(decoded, "type")) or done_marker?(block)
276314
end)
277315
end
278316

test/codex_pooler/accounting/request_logs_test.exs

Lines changed: 155 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1967,6 +1967,145 @@ defmodule CodexPooler.Accounting.RequestLogsTest do
19671967
refute inspect(log.debug) =~ "Bearer sk-example-hidden"
19681968
end
19691969

1970+
test "request log debug projection classifies interrupted HTTP SSE attempts" do
1971+
%{pool: pool, api_key: api_key} = active_api_key_fixture()
1972+
%{assignment: assignment} = upstream_assignment_fixture(pool)
1973+
1974+
request =
1975+
request_fixture(%{pool: pool, api_key: api_key}, %{
1976+
requested_model: "gpt-debug-http-sse-interrupted",
1977+
endpoint: "/backend-api/codex/responses",
1978+
transport: "http_sse",
1979+
status: "failed",
1980+
correlation_id: "debug-http-sse-interrupted",
1981+
response_status_code: 200,
1982+
request_metadata: %{
1983+
"codex_session_id" => "session-http-sse-interrupted",
1984+
"codex_session_key" => "session-key-http-sse-interrupted",
1985+
"request_body" => "raw prompt should stay hidden"
1986+
}
1987+
})
1988+
|> Ecto.Changeset.change(last_error_code: "upstream_stream_error")
1989+
|> Repo.update!()
1990+
1991+
attempt =
1992+
request
1993+
|> attempt_fixture(assignment, %{
1994+
status: "failed",
1995+
retryable: false,
1996+
upstream_status_code: 200,
1997+
usage_status: "usage_known"
1998+
})
1999+
|> Ecto.Changeset.change(%{
2000+
latency_ms: 654,
2001+
network_error_code: "upstream_stream_error",
2002+
error_message: "raw stream body must not enter debug",
2003+
response_metadata: %{
2004+
"error_kind" => "stream_interrupted",
2005+
"content_type" => "text/event-stream",
2006+
"status_code" => 200,
2007+
"raw_body" => "raw visible response body should stay hidden",
2008+
"raw_headers" => %{"authorization" => "Bearer sk-example-hidden"}
2009+
}
2010+
})
2011+
|> Repo.update!()
2012+
2013+
_turn =
2014+
debug_turn_fixture(pool, api_key, assignment, request, %{
2015+
status: "failed",
2016+
error_code: "upstream_stream_error",
2017+
final_attempt_id: attempt.id
2018+
})
2019+
2020+
assert %{items: [log], total: 1} = Accounting.list_request_logs(pool)
2021+
assert [attempt_debug] = log.debug.attempts
2022+
2023+
assert attempt_debug.transport_failure == %{
2024+
reason_class: "upstream_stream_interrupted",
2025+
reason: "closed_before_terminal",
2026+
phase: "upstream_close",
2027+
pre_visible_output: false,
2028+
terminal_seen: false,
2029+
text_frame_count: 1
2030+
}
2031+
2032+
refute inspect(log.debug) =~ "session-http-sse-interrupted"
2033+
refute inspect(log.debug) =~ "session-key-http-sse-interrupted"
2034+
refute inspect(log.debug) =~ "raw prompt should stay hidden"
2035+
refute inspect(log.debug) =~ "raw stream body"
2036+
refute inspect(log.debug) =~ "raw visible response body"
2037+
refute inspect(log.debug) =~ "Bearer sk-example-hidden"
2038+
end
2039+
2040+
test "request log debug projection classifies supported stream interruption families" do
2041+
%{pool: pool, api_key: api_key} = active_api_key_fixture()
2042+
%{assignment: assignment} = upstream_assignment_fixture(pool)
2043+
2044+
request =
2045+
request_fixture(%{pool: pool, api_key: api_key}, %{
2046+
requested_model: "gpt-debug-stream-families",
2047+
endpoint: "/backend-api/codex/responses",
2048+
transport: "http_sse",
2049+
status: "failed",
2050+
correlation_id: "debug-stream-families",
2051+
response_status_code: 200,
2052+
request_metadata: %{"codex_session_id" => "session-stream-families"}
2053+
})
2054+
|> Ecto.Changeset.change(last_error_code: "upstream_stream_error")
2055+
|> Repo.update!()
2056+
2057+
stream_family_attempt(request, assignment, 1, "client_disconnected", %{})
2058+
2059+
stream_family_attempt(request, assignment, 2, "upstream_stream_error", %{
2060+
"stream_error_code" => "server_error"
2061+
})
2062+
2063+
stream_family_attempt(request, assignment, 3, "stream_idle_timeout", %{})
2064+
stream_family_attempt(request, assignment, 4, "stream_parse_error", %{})
2065+
2066+
assert %{items: [log], total: 1} = Accounting.list_request_logs(pool)
2067+
2068+
attempts_by_number = Map.new(log.debug.attempts, &{&1.attempt_number, &1.transport_failure})
2069+
2070+
assert attempts_by_number[1] == %{
2071+
reason_class: "downstream_client_disconnect",
2072+
reason: "client_disconnected",
2073+
phase: "send_payload",
2074+
pre_visible_output: false,
2075+
terminal_seen: false,
2076+
text_frame_count: 1
2077+
}
2078+
2079+
assert attempts_by_number[2] == %{
2080+
reason_class: "upstream_terminal_failure",
2081+
reason: "server_error",
2082+
phase: "receive",
2083+
pre_visible_output: false,
2084+
terminal_seen: true,
2085+
text_frame_count: 1
2086+
}
2087+
2088+
assert attempts_by_number[3] == %{
2089+
reason_class: "upstream_stream_idle_timeout",
2090+
reason: "idle_timeout",
2091+
phase: "receive_timeout",
2092+
pre_visible_output: false,
2093+
terminal_seen: false,
2094+
text_frame_count: 1
2095+
}
2096+
2097+
assert attempts_by_number[4] == %{
2098+
reason_class: "stream_interrupted",
2099+
reason: "interrupted",
2100+
phase: "receive",
2101+
pre_visible_output: false,
2102+
terminal_seen: false,
2103+
text_frame_count: 1
2104+
}
2105+
2106+
refute inspect(log.debug) =~ "session-stream-families"
2107+
end
2108+
19702109
test "request log debug projection reports failed request with linked open turn as mismatch" do
19712110
%{pool: pool, api_key: api_key} = active_api_key_fixture()
19722111
%{assignment: assignment} = upstream_assignment_fixture(pool)
@@ -2616,6 +2755,22 @@ defmodule CodexPooler.Accounting.RequestLogsTest do
26162755
}
26172756
end
26182757

2758+
defp stream_family_attempt(request, assignment, attempt_number, network_error_code, metadata) do
2759+
request
2760+
|> attempt_fixture(assignment, %{
2761+
attempt_number: attempt_number,
2762+
status: "failed",
2763+
retryable: false,
2764+
upstream_status_code: 200,
2765+
usage_status: "usage_unknown"
2766+
})
2767+
|> Ecto.Changeset.change(%{
2768+
network_error_code: network_error_code,
2769+
response_metadata: Map.merge(%{"error_kind" => "stream_interrupted"}, metadata)
2770+
})
2771+
|> Repo.update!()
2772+
end
2773+
26192774
defp debug_turn_fixture(pool, api_key, assignment, request, attrs) do
26202775
now = ~U[2026-05-26 00:00:00.000000Z]
26212776

0 commit comments

Comments
 (0)