Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
19 commits
Select commit Hold shift + click to select a range
a1381f7
Render replayed tool calls in the OpenAI wire shape
vinniefalco Sep 22, 2026
83c638c
Log bounded upstream error diagnostics
vinniefalco Sep 22, 2026
850dded
Close plan: replayed tool calls
vinniefalco Sep 22, 2026
cb8d437
Carry a reply origin on model reply events
vinniefalco Sep 22, 2026
0d62bb5
Document the model reply origin
vinniefalco Sep 22, 2026
754e294
Log upstream client errors at info; move vibe plans
vinniefalco Sep 22, 2026
34191d5
Enable exact JSON float parsing workspace-wide
vinniefalco Sep 22, 2026
23d09a3
Round client timings to whole microseconds
vinniefalco Sep 22, 2026
70033a2
Pin log payload round-trip fidelity in tests
vinniefalco Sep 22, 2026
d8b19ca
Extract the shared hash-key ordering helper
vinniefalco Sep 22, 2026
201acd6
Install deterministic sorted pairs and next
vinniefalco Sep 22, 2026
1c2384a
Activate deterministic iteration in the section VM
vinniefalco Sep 22, 2026
530a7a7
Pin non-finite and canonical-order JSON serialization
vinniefalco Sep 22, 2026
d55876c
Audit ordered pair walks and sort schema required names
vinniefalco Sep 22, 2026
5237076
Add the JSON round-trip rule and sorted iteration order
vinniefalco Sep 22, 2026
d1b51a1
Correct client-error log-level assertion to info
vinniefalco Sep 22, 2026
01535c4
Close plan: replay json fidelity
vinniefalco Sep 22, 2026
1ef0739
Fix deterministic iteration resumption on mid-traversal clears
vinniefalco Sep 22, 2026
7171029
Correct stale audit and rounding-rule wording
vinniefalco Sep 22, 2026
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions AGENTS.md
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,7 @@ Multi-crate Rust workspace for the PromptForge pipeline engine, the harness that
- Long-running gateway work reports through `gateway-progress`, a private gateway family crate: a producer begins an activity with a text, replaces the text as work moves, and drops the guard when done. Consumers outside the family read only the `Progress` wire type from `gateway-api-types`.
- Unsafe code stays in its explicitly owned boundary. Every unsafe block documents its safety invariants immediately before the block.
- Comments explain a non-obvious constraint, ordering requirement, or workaround. Every platform or external-bug workaround cites its upstream issue URL in the explanatory comment.
- JSON that reaches the run log or a replay comparison round-trips exactly - `to_value`, `to_string`, `from_str` yield an identical value, object keys stay canonical (sorted), numbers must be finite, and serde_json `preserve_order` is never enabled. Exact parsing (`float_roundtrip`) carries that guarantee; a value derived and then logged is additionally rounded to its meaningful precision at the source.

## Verification

Expand Down
3 changes: 2 additions & 1 deletion Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

4 changes: 3 additions & 1 deletion Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -75,7 +75,9 @@ workspace-hack = { path = "crates/workspace-hack", version = "0.1" }
pulldown-cmark = "0.12"
serde = { version = "1", features = ["derive"] }
serde_yaml_ng = "0.10"
serde_json = "1"
# `float_roundtrip` makes `from_str` reproduce the exact `f64` that
# `to_string` printed, so a payload the run log stores reads back bit-for-bit.
serde_json = { version = "1", features = ["float_roundtrip"] }
# 0.13 rather than 0.12 so the tree links exactly one rustls crypto backend:
# aws-lc-rs, the one Tauri already selects. 0.13 has no `ring`
# option, so a bump cannot re-enable it; CI checks that `ring` stays out of
Expand Down
251 changes: 246 additions & 5 deletions crates/gateway/protocol/src/upstream.rs
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
//! unchanged. Adding an Anthropic or pack upstream later is a new implementation
//! behind this same trait, with no change to routing or the request handler.

use std::fmt::Write as _;
use std::time::Duration;

use async_trait::async_trait;
Expand Down Expand Up @@ -275,6 +276,29 @@ impl OpenAiUpstream {
let body =
crate::http_util::read_body_capped(response, crate::http_util::MAX_ERROR_BODY)
.await;
// F5: the raw body may echo prompt content or credentials, so only
// its OpenAI error envelope reaches the log, bounded and escaped.
let diagnostics = UpstreamErrorDiagnostics::from_body(&body);
let code = diagnostics.code.as_str();
let kind = diagnostics.kind.as_str();
let message = diagnostics.message.as_str();
if status.is_server_error() {
tracing::warn!(
status = status.as_u16(),
code = %code,
r#type = %kind,
error.message = %message,
"upstream returned a server error"
);
} else {
tracing::info!(
status = status.as_u16(),
code = %code,
r#type = %kind,
error.message = %message,
"upstream returned a client error"
);
}
let body: String = body.chars().take(2000).collect();
return Err(ProtocolError::UpstreamStatus {
status: status.as_u16(),
Expand Down Expand Up @@ -308,6 +332,73 @@ impl OpenAiUpstream {
}
}

/// Maximum characters retained from an upstream error field for diagnostics.
/// Applied per field on the decoded string, before control escaping can expand
/// it, so one event cannot flood the log with an oversized upstream message.
const MAX_ERROR_MESSAGE_CHARS: usize = 512;

/// The bounded, safe diagnostics extracted from a non-success upstream body.
///
/// The raw body is never retained or logged: only the OpenAI error envelope's
/// `code`, `type`, and `message` are read, and each string is control-escaped
/// and bounded. A body outside that shape (or a non-string field) yields an
/// empty value rather than a fallback that could leak the body.
#[derive(Debug, Default)]
struct UpstreamErrorDiagnostics {
code: String,
kind: String,
message: String,
}

impl UpstreamErrorDiagnostics {
fn from_body(body: &str) -> Self {
let Ok(value) = serde_json::from_str::<serde_json::Value>(body) else {
return Self::default();
};
match value.get("error") {
Some(serde_json::Value::Object(error)) => Self {
code: bounded_error_field(error.get("code")),
kind: bounded_error_field(error.get("type")),
message: bounded_error_field(error.get("message")),
},
Some(serde_json::Value::String(message)) => Self {
message: escape_control(message, MAX_ERROR_MESSAGE_CHARS),
..Self::default()
},
_ => Self::default(),
}
}
}

/// Renders a string-valued error field, control-escaped and bounded; a
/// missing or non-string field renders as the empty string.
fn bounded_error_field(value: Option<&serde_json::Value>) -> String {
value
.and_then(serde_json::Value::as_str)
.map_or_else(String::new, |text| {
escape_control(text, MAX_ERROR_MESSAGE_CHARS)
})
}

/// Escapes every control character so a crafted upstream message cannot forge
/// log lines or inject terminal control sequences, keeping at most `max_chars`
/// input characters.
fn escape_control(text: &str, max_chars: usize) -> String {
let mut escaped = String::new();
for character in text.chars().take(max_chars) {
match character {
'\n' => escaped.push_str("\\n"),
'\r' => escaped.push_str("\\r"),
'\t' => escaped.push_str("\\t"),
control if control.is_control() => {
let _ = write!(escaped, "\\u{{{:x}}}", control as u32);
}
other => escaped.push(other),
}
}
escaped
}

/// Parses an upstream SSE byte stream into validated [`ChatChunk`]s.
///
/// Each `data:` line holds one JSON chunk; blank lines, comments, and the
Expand Down Expand Up @@ -846,20 +937,26 @@ mod tests {
}
}

/// Installs a WARN-level subscriber writing to a fresh capture buffer for
/// the current thread (tokio's current-thread test runtime keeps every
/// poll on this thread, so the parser's warnings land in the buffer).
fn capture_warnings() -> (LogBuffer, tracing::subscriber::DefaultGuard) {
/// Installs a subscriber at `max_level` writing to a fresh capture buffer
/// for the current thread (tokio's current-thread test runtime keeps every
/// poll on this thread, so the events land in the buffer).
fn capture_logs(max_level: tracing::Level) -> (LogBuffer, tracing::subscriber::DefaultGuard) {
let buffer = LogBuffer::default();
let subscriber = tracing_subscriber::fmt()
.with_writer(buffer.clone())
.with_ansi(false)
.with_max_level(tracing::Level::WARN)
.with_max_level(max_level)
.finish();
let guard = tracing::subscriber::set_default(subscriber);
(buffer, guard)
}

/// Installs a WARN-level subscriber writing to a fresh capture buffer for
/// the current thread, for the parser's warning assertions.
fn capture_warnings() -> (LogBuffer, tracing::subscriber::DefaultGuard) {
capture_logs(tracing::Level::WARN)
}

#[tokio::test]
async fn stream_malformed_chunks_are_logged_and_skipped() {
// An undecodable or shape-invalid chunk is logged and skipped; the
Expand Down Expand Up @@ -1046,6 +1143,150 @@ mod tests {
let _ = handle.join();
}

#[tokio::test]
async fn server_error_logs_structured_diagnostics_without_the_raw_body() {
// F5: a 5xx logs at WARN with the structured status/code/type and the
// escaped error.message, but never the raw body's other content - an
// upstream error body can echo prompt content or credentials.
let (logs, _guard) = capture_logs(tracing::Level::DEBUG);
let body = r#"{"error":{"message":"line1\nline2","type":"server_error","code":"internal"},"echo":{"prompt":"BODY_ONLY_SENTINEL"}}"#;
let (base, handle) = serve_once("500 Internal Server Error", body);
let upstream = OpenAiUpstream::new(&base, Secret::new(String::new()));
let _ = upstream
.send(request("m"), "u")
.await
.expect_err("5xx fails");
let _ = handle.join();
let logs = logs.contents();
assert!(
logs.lines()
.any(|line| line.contains("WARN")
&& line.contains("upstream returned a server error")),
"a 5xx logs at warn: {logs}"
);
assert!(logs.contains("status=500"), "status is structured: {logs}");
assert!(logs.contains("code=internal"), "code is structured: {logs}");
assert!(
logs.contains("type=server_error"),
"type is structured: {logs}"
);
assert!(
logs.contains(r"line1\nline2"),
"the error message is control-escaped: {logs}"
);
assert!(
!logs.contains("BODY_ONLY_SENTINEL"),
"unrelated body content is never logged: {logs}"
);
}

#[tokio::test]
async fn client_error_logs_at_info_not_warn() {
// A 4xx is the caller's error, not the backend's: it logs at info so
// the warn stream stays reserved for server-side failures.
let (logs, _guard) = capture_logs(tracing::Level::INFO);
let body = r#"{"error":{"message":"unknown model","type":"invalid_request_error","code":"model_not_found"}}"#;
let (base, handle) = serve_once("400 Bad Request", body);
let upstream = OpenAiUpstream::new(&base, Secret::new(String::new()));
let _ = upstream
.send(request("m"), "u")
.await
.expect_err("4xx fails");
let _ = handle.join();
let logs = logs.contents();
assert!(
logs.lines()
.any(|line| line.contains("INFO")
&& line.contains("upstream returned a client error")),
"a 4xx logs at info: {logs}"
);
assert!(
!logs
.lines()
.any(|line| line.contains("WARN")
&& line.contains("upstream returned a client error")),
"a 4xx never logs at warn: {logs}"
);
}

#[tokio::test]
async fn non_json_error_body_is_never_logged_raw() {
// A body outside the OpenAI error shape yields no diagnostic fields;
// the raw body must not be logged as a fallback.
let (logs, _guard) = capture_logs(tracing::Level::DEBUG);
let (base, handle) = serve_once("502 Bad Gateway", "RAW_BODY_SECRET");
let upstream = OpenAiUpstream::new(&base, Secret::new(String::new()));
let _ = upstream
.send(request("m"), "u")
.await
.expect_err("5xx fails");
let _ = handle.join();
let logs = logs.contents();
assert!(logs.contains("status=502"), "the status still logs: {logs}");
assert!(
!logs.contains("RAW_BODY_SECRET"),
"an unparseable body is never logged raw: {logs}"
);
}

#[tokio::test]
async fn control_characters_in_the_error_message_are_escaped() {
// A crafted message cannot forge log lines or inject terminal control:
// newlines, carriage returns, tabs, and escape bytes are escaped.
let (logs, _guard) = capture_logs(tracing::Level::WARN);
let body = r#"{"error":{"message":"forged\r\nwarning: fake\t\u001b[31mred"}}"#;
let (base, handle) = serve_once("500 Internal Server Error", body);
let upstream = OpenAiUpstream::new(&base, Secret::new(String::new()));
let _ = upstream
.send(request("m"), "u")
.await
.expect_err("5xx fails");
let _ = handle.join();
let logs = logs.contents();
assert!(
logs.contains(r"forged\r\nwarning: fake\t"),
"control characters are escaped: {logs}"
);
assert!(
logs.contains(r"\u{1b}[31mred"),
"an ANSI escape is escaped: {logs}"
);
assert!(
!logs.contains("forged\r\nwarning"),
"no raw CRLF survives in the message: {logs}"
);
assert!(
!logs.contains("warning: fake\t"),
"no raw tab survives in the message: {logs}"
);
}

#[tokio::test]
async fn an_over_long_error_message_is_bounded() {
// The message is bounded independently of the body cap so one event
// cannot flood the log with a huge upstream message.
let (logs, _guard) = capture_logs(tracing::Level::WARN);
let message = "z".repeat(MAX_ERROR_MESSAGE_CHARS + 200);
let body = format!("{{\"error\":{{\"message\":\"{message}\"}}}}");
let (base, handle) = serve_once("500 Internal Server Error", &body);
let upstream = OpenAiUpstream::new(&base, Secret::new(String::new()));
let _ = upstream
.send(request("m"), "u")
.await
.expect_err("5xx fails");
let _ = handle.join();
let logs = logs.contents();
assert!(
logs.contains(&"z".repeat(MAX_ERROR_MESSAGE_CHARS)),
"the bound keeps a full-length prefix"
);
assert!(
!logs.contains(&"z".repeat(MAX_ERROR_MESSAGE_CHARS + 1)),
"the message never exceeds the bound: {}",
logs.len()
);
}

/// A server that accepts the connection and then never sends a response, so
/// the client's request deadline (not an idle read) is what must fire.
fn serve_stalled() -> (String, JoinHandle<()>) {
Expand Down
1 change: 1 addition & 0 deletions crates/harness/log/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ turso.workspace = true
workspace-hack.workspace = true

[dev-dependencies]
promptforge-api-types.workspace = true
tempfile.workspace = true
tokio = { workspace = true, features = ["macros", "rt-multi-thread"] }

Expand Down
6 changes: 6 additions & 0 deletions crates/harness/log/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,12 @@
//! hierarchical task path stored as text; timestamps are UTC
//! milliseconds since the Unix epoch. `started_at` is the caller's;
//! `at` and `ended_at` are the log's wall clock.
//! - A stored payload round-trips: `Record::payload` is written with
//! `serde_json::to_string` and read back with `from_str`, and the parsed
//! value equals the original with the same text. The workspace enables
//! `serde_json`'s `float_roundtrip` feature, and `Value::Object` orders
//! keys by `BTreeMap` rather than by insertion, so both hold. The
//! fidelity test in `tests/it/fidelity.rs` pins it.
//! - Every file in this crate stays under 500 lines; split first, then
//! edit.
//! - Nothing in this crate spawns a tokio task directly; the harness
Expand Down
Loading
Loading