feat(logging): persist diagnostics across restarts and redact secrets

Backend half of the logging overhaul.

Retention:
- Keep the last 4 rotated files at 20MB each and stop deleting logs on
  startup, so a crash's prior-run logs survive a restart.
- Apply the persisted log level right after plugin registration instead
  of at the end of setup.
- Bound crash.log with size-based rotation (5MB x 2).

Secret redaction on every log path:
- Proxy: strip userinfo/query from upstream URLs (keep path for
  diagnostics), exact-match redact known auth.api_key/access_token,
  classify request/response bodies instead of logging them, header
  allowlist.
- Redact the Gemini `?key=` in cache-trace endpoints.
- Omit MCP custom-field values (headers may carry tokens).
- Redact deeplink and model-fetch URLs before logging.

Docs:
- FAQ points users to the persistent crash.log for support workflows.
This commit is contained in:
Jason
2026-07-16 10:20:44 +08:00
parent 7f028632b5
commit 22d2872c33
14 changed files with 655 additions and 224 deletions
+36 -32
View File
@@ -1563,7 +1563,9 @@ impl RequestForwarder {
let mut codex_oauth_account_id: Option<String> = None;
let mut should_send_codex_oauth_session_headers = false;
// 获取认证头(提前准备,用于内联替换)
// 获取认证头(提前准备,用于内联替换),同时保留仅用于日志脱敏的
// 精确认证材料。实际日志永远不输出这些值。
let mut log_secrets: Vec<String> = Vec::new();
let mut auth_headers = if let Some(mut auth) = adapter.extract_auth(provider) {
// GitHub Copilot 特殊处理:从 CopilotAuthManager 获取真实 token
if auth.strategy == AuthStrategy::GitHubCopilot {
@@ -1669,6 +1671,12 @@ impl RequestForwarder {
}
}
for secret in std::iter::once(&auth.api_key).chain(auth.access_token.iter()) {
if !secret.is_empty() && !log_secrets.contains(secret) {
log_secrets.push(secret.clone());
}
}
adapter.get_auth_headers(&auth)?
} else {
Vec::new()
@@ -2074,22 +2082,29 @@ impl RequestForwarder {
reject_proxy_placeholder_for_managed_account_upstream(&url, &ordered_headers)?;
// 日志目标 URL 的脱敏分两种情形:
// - 有已知密钥(log_secrets 非空):记录脱敏后的完整 URL,剥 userinfo/query
// 并抹掉已知密钥值,保留 host+path 便于诊断 base_url 配错路径导致的 404。
// - 无已知密钥:凭据可能整个内嵌在 path 里且无从脱敏,只记 origin,
// 避免默认 Info 级把形如 https://gw/<KEY>/v1 的 path 完整落盘。
let target_for_log = if log_secrets.is_empty() {
crate::redact_url_origin_for_log(&url)
} else {
crate::redact_url_for_log_with_secrets(&url, &log_secrets)
};
// 输出请求信息日志
let tag = adapter.name();
let request_model = filtered_body
.get("model")
.and_then(|v| v.as_str())
.unwrap_or("<none>");
log::info!("[{tag}] >>> 请求 URL: {url} (model={request_model})");
if log::log_enabled!(log::Level::Debug) {
if let Ok(body_str) = serde_json::to_string(&filtered_body) {
log::debug!(
"[{tag}] >>> 请求体内容 ({}字节): {}",
body_str.len(),
body_str
);
}
}
log::info!("[{tag}] >>> 请求目标: {target_for_log} (model={request_model})");
log::debug!(
"[{tag}] >>> 请求体已准备: bytes={}, hash={} (content omitted)",
body_bytes.len(),
short_value_hash(Some(&filtered_body))
);
// 确定超时
let timeout = if self.non_streaming_timeout.is_zero() {
@@ -2156,11 +2171,12 @@ impl RequestForwarder {
} else {
// HTTP 代理或直连:走 hyper raw write(保持 header 大小写)
// 如果有 HTTP 代理,hyper_client 会用 CONNECT 隧道穿过代理
let uri: http::Uri = url
.parse()
.map_err(|e| ProxyError::ForwardFailed(format!("Invalid URL '{url}': {e}")))?;
let uri: http::Uri = url.parse().map_err(|e| {
ProxyError::ForwardFailed(format!("Invalid upstream URL ({target_for_log}): {e}"))
})?;
super::hyper_client::send_request(
uri,
&target_for_log,
method.clone(),
ordered_headers,
extensions.clone(),
@@ -3186,11 +3202,11 @@ fn should_force_identity_encoding(
fn map_reqwest_send_error(error: reqwest::Error) -> ProxyError {
if error.is_timeout() {
ProxyError::Timeout(format!("请求超时: {error}"))
ProxyError::Timeout(format!("上游请求超时: {}", error.without_url()))
} else if error.is_connect() {
ProxyError::ForwardFailed(format!("连接失败: {error}"))
ProxyError::ForwardFailed(format!("上游连接失败: {}", error.without_url()))
} else {
ProxyError::ForwardFailed(error.to_string())
ProxyError::ForwardFailed(format!("上游请求发送失败: {}", error.without_url()))
}
}
@@ -3390,7 +3406,8 @@ fn log_prompt_cache_trace(
"[CacheTrace] app={}, provider={}, endpoint={}, api_format={}, session_client_provided={}, prompt_cache_key={}, store={}, stream={}, instructions_hash={}, system_hash={}, tools_hash={}, input_hash={}, messages_hash={}, include_hash={}, cache_controls={}, body_hash={}",
app_type.as_str(),
provider.id,
endpoint,
// Gemini 的 endpoint 带 ?key=<API_KEY>;脱敏剥掉 query 再落盘。
crate::redact_url_for_log(endpoint),
api_format.unwrap_or("native"),
session_client_provided,
prompt_cache_key,
@@ -3527,6 +3544,7 @@ mod tests {
assert_eq!(code, log_fwd::SINGLE_PROVIDER_FAILED);
assert!(message.contains("Provider PackyCode-response 请求失败"));
assert!(message.contains("上游 HTTP 429"));
// 上游错误消息保留(截断),用于诊断失败原因。
assert!(message.contains("rate limit exceeded"));
assert!(!message.contains("切换下一个"));
}
@@ -3559,20 +3577,6 @@ mod tests {
assert!(message.contains("connection reset by peer"));
}
#[test]
fn summarize_upstream_body_prefers_json_message() {
let body = json!({
"error": {
"message": "invalid_request_error: unsupported field"
},
"request_id": "req_123"
});
let summary = summarize_upstream_body(&body.to_string());
assert_eq!(summary, "invalid_request_error: unsupported field");
}
#[test]
fn summarize_text_for_log_collapses_whitespace_and_truncates() {
let summary = summarize_text_for_log("line1\n\n line2 line3", 12);
+89 -51
View File
@@ -538,16 +538,22 @@ async fn handle_claude_transform(
} else {
chat_sse_to_response_value(&body_str)
};
// 聚合也失败时:保留全量 body 服务端日志,并给客户端错误附带同款
// 现场诊断(content-type/body 摘要),否则命中嗅探臂的用户只拿到
// 聚合也失败时:服务端日志只记录长度,并给客户端错误附带同款
// 现场诊断(content-type/body 分类),否则命中嗅探臂的用户只拿到
// 裸聚合错误、丢失非嗅探臂已有的诊断增强(C7)
aggregated.map_err(|e| {
log::error!("[Claude] SSE 聚合兜底失败: {e}, body: {body_str}");
log::error!(
"[Claude] SSE 聚合兜底失败: {e}, body_bytes={}",
body_bytes.len()
);
aggregate_fallback_error(e, &response_headers, &body_str)
})?
}
Err(e) => {
log::error!("[Claude] 解析上游响应失败: {e}, body: {body_str}");
log::error!(
"[Claude] 解析上游响应失败: {e}, body_bytes={}",
body_bytes.len()
);
return Err(upstream_body_parse_error(
"Failed to parse upstream response",
&e,
@@ -1108,14 +1114,20 @@ async fn handle_codex_chat_to_responses_transform(
// 上游对 stream:false 返回未标记 Content-Type 的 SSE 体时按 SSE 聚合。
Err(_) if body_looks_like_sse(&body_str) => {
log::warn!("[Codex] 上游对非流请求返回未标记的 SSE 体,按 Chat SSE 聚合兜底");
// 聚合也失败时:保留全量 body 服务端日志,并给客户端错误附带现场诊断(C7)
// 聚合也失败时:服务端日志只记录长度,并给客户端错误附带现场诊断(C7
chat_sse_to_response_value(&body_str).map_err(|e| {
log::error!("[Codex] SSE 聚合兜底失败: {e}, body: {body_str}");
log::error!(
"[Codex] SSE 聚合兜底失败: {e}, body_bytes={}",
body_bytes.len()
);
aggregate_fallback_error(e, &response_headers, &body_str)
})?
}
Err(e) => {
log::error!("[Codex] 解析 Chat 上游响应失败: {e}, body: {body_str}");
log::error!(
"[Codex] 解析 Chat 上游响应失败: {e}, body_bytes={}",
body_bytes.len()
);
return Err(upstream_body_parse_error(
"Failed to parse upstream chat response",
&e,
@@ -1270,7 +1282,8 @@ async fn handle_codex_anthropic_to_responses_transform(
}
Err(e) => {
log::error!(
"[Codex] Failed to parse Anthropic upstream response: {e}, body: {body_str}"
"[Codex] Failed to parse Anthropic upstream response: {e}, body_bytes={}",
body_bytes.len()
);
return Err(upstream_body_parse_error(
"Failed to parse upstream anthropic response",
@@ -1494,7 +1507,10 @@ async fn handle_codex_chat_error_response(
} else {
lossy.into_owned()
};
log::warn!("[Codex] Chat 错误响应不是合法 JSON,按文本透传: {truncated}");
log::warn!(
"[Codex] Chat 错误响应不是合法 JSON,按文本透传: body_bytes={} (content omitted)",
body_bytes.len()
);
Value::String(truncated)
}
};
@@ -1914,9 +1930,8 @@ fn body_looks_like_sse(body: &str) -> bool {
.any(|prefix| trimmed.starts_with(prefix))
}
/// 构造带现场诊断的上游解析错误:附 content-type / content-encoding 与 body
/// 前缀摘要,让客户端收到的报错自带根因判别("data:"=错标 SSE、"<"=HTML
/// 拦截页、 乱码=未解压二进制),不再依赖向用户索要服务端日志。
/// 构造带现场诊断的上游解析错误:只附结构化分类与元数据,
/// 避免响应正文经错误链间接进入持久化日志。
fn upstream_body_parse_error(
prefix: &str,
err: &serde_json::Error,
@@ -1929,8 +1944,8 @@ fn upstream_body_parse_error(
))
}
/// SSE 聚合兜底失败时,给聚合器内部错误附加同款现场诊断content-type/
/// content-encoding/body 摘要),使命中 #2234 嗅探臂的客户端也拿到根因线索,
/// SSE 聚合兜底失败时,给聚合器内部错误附加同款现场诊断
/// 使命中 #2234 嗅探臂的客户端也拿到根因线索,
/// 而非仅 "No chat completion choices in upstream SSE" 这类无 header/body 的裸消息。
fn aggregate_fallback_error(
err: ProxyError,
@@ -1944,7 +1959,43 @@ fn aggregate_fallback_error(
ProxyError::TransformError(format!("{base} {}", body_diagnostics_suffix(headers, body)))
}
/// 现场诊断后缀:content-type、content-encoding 与 body 前 120 字符摘要
/// 将正文归入有限类别,保留 HTML/SSE/乱码等关键线索而不记录正文
fn classify_body_for_diagnostics(body: &str) -> &'static str {
let trimmed = body.trim_start_matches('\u{feff}').trim_start();
if trimmed.is_empty() {
return "empty";
}
if body_looks_like_sse(trimmed) {
return "sse";
}
// 分类只检查前 4 KiB,避免为了诊断再次线性扫描异常返回的超大正文。
let sample = trimmed.chars().take(4096).collect::<String>();
let prefix = sample
.chars()
.take(256)
.collect::<String>()
.to_ascii_lowercase();
if ["<!doctype html", "<html", "<head", "<body"]
.iter()
.any(|marker| prefix.starts_with(marker))
{
return "html";
}
if sample.contains('\u{fffd}')
|| sample
.chars()
.any(|character| character.is_control() && !matches!(character, '\n' | '\r' | '\t'))
{
return "binary-or-encoded";
}
if prefix.starts_with('{') || prefix.starts_with('[') {
return "json-like";
}
"text"
}
/// 现场诊断后缀:content-type、content-encoding、body 长度与安全分类,不含正文。
fn body_diagnostics_suffix(headers: &axum::http::HeaderMap, body: &str) -> String {
let header_str = |name: &str| {
headers
@@ -1953,10 +2004,11 @@ fn body_diagnostics_suffix(headers: &axum::http::HeaderMap, body: &str) -> Strin
.unwrap_or("<none>")
};
format!(
"(content-type: {}; content-encoding: {}; body[..120]: '{}')",
"(content-type: {}; content-encoding: {}; body-bytes: {}; body-kind: {}; content omitted)",
header_str("content-type"),
header_str("content-encoding"),
body_snippet(body, 120),
body.len(),
classify_body_for_diagnostics(body),
)
}
@@ -1973,24 +2025,6 @@ fn error_event_message(error: &Value) -> Option<String> {
None
}
/// 取 body 前 `max_chars` 个字符的单行摘要:\r 丢弃、\n 折叠为字面 \n、
/// 其余控制字符替换为 ,超长加省略号。
fn body_snippet(body: &str, max_chars: usize) -> String {
let mut snippet = String::new();
for c in body.chars().take(max_chars) {
match c {
'\n' => snippet.push_str("\\n"),
'\r' => {}
c if c.is_control() => snippet.push('\u{FFFD}'),
c => snippet.push(c),
}
}
if body.chars().nth(max_chars).is_some() {
snippet.push('…');
}
snippet
}
/// 解析单个 SSE 块的 event 名与 data 负载(多行 data 按规范以 \n 连接)。
/// 行首允许前导空白后再匹配字段名——与 body_looks_like_sse 的 trim 宽容度对齐,
/// 否则缩进的 ` data:` 行被嗅探接受却在此静默丢失(C4)。返回 None 表示无 data 行。
@@ -2437,9 +2471,9 @@ async fn log_usage(
#[cfg(test)]
mod tests {
use super::{
body_looks_like_sse, body_snippet, chat_sse_to_response_value, codex_proxy_error_json,
responses_sse_to_response_value, should_use_claude_transform_streaming, transform,
upstream_body_parse_error,
body_looks_like_sse, chat_sse_to_response_value, classify_body_for_diagnostics,
codex_proxy_error_json, responses_sse_to_response_value,
should_use_claude_transform_streaming, transform, upstream_body_parse_error,
};
use crate::proxy::ProxyError;
@@ -2480,7 +2514,9 @@ mod tests {
ProxyError::TransformError(msg) => {
assert!(msg.contains("content-type: text/html"), "{msg}");
assert!(msg.contains("content-encoding: gzip"), "{msg}");
assert!(msg.contains("<html>\\nblocked</html>"), "{msg}");
assert!(msg.contains("body-bytes: 21"), "{msg}");
assert!(msg.contains("body-kind: html"), "{msg}");
assert!(!msg.contains("blocked"), "{msg}");
}
other => panic!("expected TransformError, got {other:?}"),
}
@@ -2497,11 +2533,25 @@ mod tests {
ProxyError::TransformError(msg) => {
assert!(msg.contains("content-type: <none>"), "{msg}");
assert!(msg.contains("content-encoding: <none>"), "{msg}");
assert!(msg.contains("body-kind: sse"), "{msg}");
}
other => panic!("expected TransformError, got {other:?}"),
}
}
#[test]
fn body_diagnostics_classifies_without_exposing_content() {
assert_eq!(classify_body_for_diagnostics(""), "empty");
assert_eq!(classify_body_for_diagnostics(" <HTML>blocked"), "html");
assert_eq!(classify_body_for_diagnostics("data: {}\n\n"), "sse");
assert_eq!(classify_body_for_diagnostics("{\"ok\":true}"), "json-like");
assert_eq!(
classify_body_for_diagnostics("decoded\u{fffd}payload"),
"binary-or-encoded"
);
assert_eq!(classify_body_for_diagnostics("Bad Gateway"), "text");
}
#[test]
fn chat_sse_to_response_value_collects_reasoning_alias() {
// OpenRouter/Kimi 用 reasoning(字符串),部分网关用对象形态
@@ -2641,18 +2691,6 @@ data: {\"id\":\"c1\",\"choices\":[{\"index\":0,\"message\":{\"role\":\"assistant
assert_eq!(response["choices"][0]["message"]["content"], "hi");
}
#[test]
fn body_snippet_sanitizes_controls_and_truncates() {
assert_eq!(
body_snippet("<html>\r\nblocked\u{0}</html>", 120),
"<html>\\nblocked\u{FFFD}</html>"
);
let long = "a".repeat(200);
let snippet = body_snippet(&long, 120);
assert_eq!(snippet.chars().count(), 121); // 120 个字符 + 省略号
assert!(snippet.ends_with('…'));
}
#[test]
fn chat_sse_to_response_value_aggregates_text_finish_reason_and_usage() {
let sse = "data: {\"id\":\"chatcmpl-1\",\"object\":\"chat.completion.chunk\",\"created\":123,\"model\":\"gpt-5.4\",\"choices\":[{\"index\":0,\"delta\":{\"role\":\"assistant\",\"content\":\"Hel\"},\"finish_reason\":null}]}\n\n\
+8 -3
View File
@@ -241,8 +241,13 @@ impl ProxyResponse {
/// `proxy_url`: optional upstream HTTP proxy URL (e.g. `http://127.0.0.1:7890`).
/// When set, the raw write path uses HTTP CONNECT tunneling through the proxy,
/// so header-case preservation works even when an upstream proxy is configured.
///
/// `log_display` is a caller-supplied, already-sanitized string used only for
/// logging; this layer never derives a log value from the raw `uri`.
#[allow(clippy::too_many_arguments)]
pub async fn send_request(
uri: http::Uri,
log_display: &str,
method: http::Method,
headers: http::HeaderMap,
original_extensions: http::Extensions,
@@ -256,13 +261,13 @@ pub async fn send_request(
.as_ref()
.map(|c| !c.cases.is_empty())
.unwrap_or(false);
log::debug!(
"[HyperClient] Sending request: uri={uri}, header_count={}, \
"[HyperClient] Sending request: target={}, header_count={}, \
has_host={}, has_original_cases={has_cases}, proxy={:?}",
log_display,
headers.len(),
headers.contains_key(http::header::HOST),
proxy_url,
proxy_url.map(super::http_client::mask_url),
);
if let Some(original_cases) = original_cases
+70 -14
View File
@@ -225,9 +225,9 @@ pub async fn handle_non_streaming(
strip_hop_by_hop_response_headers(&mut response_headers);
log::debug!(
"[{}] 上游响应体内容: {}",
"[{}] 上游响应体已接收: bytes={} (content omitted)",
ctx.tag,
String::from_utf8_lossy(&body_bytes)
body_bytes.len()
);
// 解析并记录使用量。关闭 usage logging 时直接跳过,避免非流式响应整包 JSON parse。
@@ -761,11 +761,10 @@ pub fn create_logged_passthrough_stream(
}
_ => false,
};
if collected {
log::debug!("[{tag}] <<< SSE 事件: {data}");
} else {
log::debug!("[{tag}] <<< SSE 数据: {data}");
}
log::trace!(
"[{tag}] <<< SSE data: bytes={}, usage_collected={collected} (content omitted)",
data.len()
);
} else {
log::debug!("[{tag}] <<< SSE: [DONE]");
}
@@ -798,15 +797,53 @@ pub fn create_logged_passthrough_stream(
}
}
fn is_safe_diagnostic_header(name: &str) -> bool {
matches!(
name,
"content-type"
| "content-encoding"
| "content-length"
| "retry-after"
| "cf-ray"
| "x-request-id"
| "request-id"
| "x-correlation-id"
) || name.starts_with("x-ratelimit-")
|| name.starts_with("ratelimit-")
}
fn bounded_header_value(value: &axum::http::HeaderValue) -> Option<String> {
let value = value.to_str().ok()?;
let mut bounded = value.chars().take(160).collect::<String>();
if value.chars().count() > 160 {
bounded.push('…');
}
Some(bounded)
}
fn format_headers(headers: &HeaderMap) -> String {
headers
.iter()
.map(|(key, value)| {
let value_str = value.to_str().unwrap_or("<non-utf8>");
format!("{key}={value_str}")
let mut entries = headers
.keys()
.map(|key| {
let name = key.as_str();
if !is_safe_diagnostic_header(name) {
return name.to_string();
}
let values = headers
.get_all(key)
.iter()
.filter_map(bounded_header_value)
.collect::<Vec<_>>();
if values.is_empty() {
name.to_string()
} else {
format!("{name}={}", values.join("|"))
}
})
.collect::<Vec<_>>()
.join(", ")
.collect::<Vec<_>>();
entries.sort();
format!("[{}]", entries.join(", "))
}
#[cfg(test)]
@@ -827,6 +864,25 @@ mod tests {
use std::sync::Arc;
use tokio::sync::RwLock;
#[test]
fn format_headers_keeps_only_allowlisted_diagnostic_values() {
let mut headers = HeaderMap::new();
headers.insert("authorization", "Bearer super-secret".parse().unwrap());
headers.insert("set-cookie", "session=cookie-secret".parse().unwrap());
headers.insert("retry-after", "30".parse().unwrap());
headers.insert("x-ratelimit-remaining", "2".parse().unwrap());
headers.insert("cf-ray", "abc123-SJC".parse().unwrap());
let formatted = format_headers(&headers);
assert!(formatted.contains("authorization"), "{formatted}");
assert!(formatted.contains("set-cookie"), "{formatted}");
assert!(formatted.contains("retry-after=30"), "{formatted}");
assert!(formatted.contains("x-ratelimit-remaining=2"), "{formatted}");
assert!(formatted.contains("cf-ray=abc123-SJC"), "{formatted}");
assert!(!formatted.contains("super-secret"), "{formatted}");
assert!(!formatted.contains("cookie-secret"), "{formatted}");
}
#[test]
fn test_strip_sse_field_accepts_optional_space() {
assert_eq!(