From 1448d4d2db1794c4bec89c3f56799353576b7390 Mon Sep 17 00:00:00 2001 From: DanConwayDev Date: Sat, 15 Aug 2026 14:22:59 +0000 Subject: [PATCH] fix(logging): demote routine client session failures Production logs currently report normal WebSocket disconnects, canceled HTTP upgrades, incomplete requests, and Git missing-object probes as errors or high-volume lifecycle info. These client-controlled outcomes make the error stream look less healthy than the relay is. Classify known peer-scoped SDK and Hyper error kinds at debug, move WebSocket session lifecycle records to debug, and recognize the two standard upload-pack missing-object messages. A conservative allowlist keeps database, policy, state, and other internal SDK failures at error. The classification assumes SDK I/O, transport, protocol, timeout, rejection, limit, and WebSocket Other errors returned from LocalRelay::take_connection describe the current client session. Unrecognized Hyper failures and non-routine Git subprocess failures deliberately remain errors; generic Git protocol failures remain warnings. Validated with cargo fmt --check, git diff --check, the HTTP classification tests, and the full git::handlers test module. --- CHANGELOG.md | 3 ++ src/git/handlers.rs | 48 +++++++++++++++-- src/http/mod.rs | 122 ++++++++++++++++++++++++++++++++++++++++---- 3 files changed, 158 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0401852..1cf6226 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -66,6 +66,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Keep per-event discovery and validation details at debug, retain aggregate sync outcomes at info, and report unsupported NIP-77 once per connection instead of warning once per filter. +- Treat routine client disconnects, incomplete HTTP/WebSocket sessions, and + Git missing-object probes as debug diagnostics while preserving internal + service and database failures as errors. - Metrics compatibility: removed the `ngit_sync_naughty_relay_info{relay,category,reason}` metric because its relay and raw reason labels were peer-controlled and unbounded. Use the unchanged diff --git a/src/git/handlers.rs b/src/git/handlers.rs index dbbce6a..9b28d15 100644 --- a/src/git/handlers.rs +++ b/src/git/handlers.rs @@ -253,6 +253,12 @@ pub(crate) fn is_git_protocol_error(exit_code: Option, stderr: &[u8]) -> bo exit_code == Some(128) && !stderr.is_empty() } +fn is_routine_missing_object_error(stderr: &[u8]) -> bool { + let stderr = String::from_utf8_lossy(stderr); + stderr.contains("not our ref") + || stderr.contains("Server does not allow request for unadvertised object") +} + /// Build the common channel-backed Git response used by streaming handlers. /// /// The handler returns this response before the Git child has necessarily @@ -556,7 +562,13 @@ async fn stream_upload_pack_output( stderr_str.to_string() }; - if is_git_protocol_error(status.code(), &stderr_output) { + if is_routine_missing_object_error(&stderr_output) { + debug!( + exit_code = ?status.code(), + stderr = %stderr_str.trim(), + "Git upload-pack request referenced an unavailable object" + ); + } else if is_git_protocol_error(status.code(), &stderr_output) { warn!( "Git upload-pack protocol error (returning ERR pkt-line): {}", stderr_str @@ -574,10 +586,23 @@ async fn stream_upload_pack_output( } else if !status.success() { record_git_operation(&metrics, "clone", "error"); let stderr_str = String::from_utf8_lossy(&stderr_output); - error!( - "Git upload-pack failed after streaming stdout: {}", - stderr_str - ); + if is_routine_missing_object_error(&stderr_output) { + debug!( + exit_code = ?status.code(), + stderr = %stderr_str.trim(), + "Git upload-pack stream referenced an unavailable object" + ); + } else if is_git_protocol_error(status.code(), &stderr_output) { + warn!( + "Git upload-pack protocol error after streaming stdout: {}", + stderr_str + ); + } else { + error!( + "Git upload-pack failed after streaming stdout: {}", + stderr_str + ); + } } else if matches!(pump_result, PumpResult::Eof { .. }) { debug!("Git upload-pack stream completed successfully"); record_git_operation(&metrics, "clone", "success"); @@ -971,6 +996,19 @@ mod tests { use super::*; use http_body_util::BodyExt; + #[test] + fn missing_object_probe_errors_are_routine_client_diagnostics() { + assert!(is_routine_missing_object_error( + b"fatal: git upload-pack: not our ref deadbeef" + )); + assert!(is_routine_missing_object_error( + b"error: Server does not allow request for unadvertised object deadbeef" + )); + assert!(!is_routine_missing_object_error( + b"fatal: unable to read repository data" + )); + } + /// Build a single-update receive-pack request body pkt-line for tests. /// /// Matches the smart-HTTP format: diff --git a/src/http/mod.rs b/src/http/mod.rs index a5e979a..e46ed2b 100644 --- a/src/http/mod.rs +++ b/src/http/mod.rs @@ -21,6 +21,7 @@ use hyper::server::conn::http1; use hyper::service::Service; use hyper::{Method, Request, Response}; use hyper_util::rt::TokioIo; +use nostr_sdk::error::ErrorKind as RelayErrorKind; use nostr_sdk::local_relay::LocalRelay; use nostr_sdk::prelude::PublicKey; use tokio::net::TcpListener; @@ -40,6 +41,27 @@ use crate::sync::rejected_index::RejectedEventsIndex; type HttpBody = GitResponseBody; +fn is_peer_scoped_relay_error(kind: RelayErrorKind) -> bool { + matches!( + kind, + RelayErrorKind::Protocol + | RelayErrorKind::IO + | RelayErrorKind::Transport + | RelayErrorKind::Timeout + | RelayErrorKind::Rejected + | RelayErrorKind::LimitExceeded + | RelayErrorKind::Other + ) +} + +fn is_peer_scoped_http_error(error: &hyper::Error) -> bool { + error.is_parse() + || error.is_canceled() + || error.is_closed() + || error.is_incomplete_message() + || error.is_body_write_aborted() +} + /// CORS headers required by GRASP-01 specification (lines 48-51) const CORS_ALLOW_ORIGIN: &str = "*"; const CORS_ALLOW_METHODS: &str = "GET, POST"; @@ -784,7 +806,7 @@ impl Service> for HttpService { tokio::spawn(async move { match hyper::upgrade::on(req).await { Ok(upgraded) => { - tracing::info!( + tracing::debug!( client_ip = %addr.ip(), peer = %peer, "WebSocket connection established" @@ -815,14 +837,25 @@ impl Service> for HttpService { } else if let Err(e) = relay.take_connection(TokioIo::new(upgraded), addr).await { - tracing::error!( - client_ip = %addr.ip(), - peer = %peer, - error = %e, - "Relay connection failed" - ); + if is_peer_scoped_relay_error(e.kind()) { + tracing::debug!( + client_ip = %addr.ip(), + peer = %peer, + error_kind = ?e.kind(), + error = %e, + "Relay client session ended with an error" + ); + } else { + tracing::error!( + client_ip = %addr.ip(), + peer = %peer, + error_kind = ?e.kind(), + error = %e, + "Relay connection failed" + ); + } } - tracing::info!( + tracing::debug!( client_ip = %addr.ip(), peer = %peer, "WebSocket connection closed" @@ -832,7 +865,23 @@ impl Service> for HttpService { m.connection_tracker().on_disconnect(addr.ip()); } } - Err(e) => tracing::error!("Upgrade error: {}", e), + Err(e) => { + if is_peer_scoped_http_error(&e) { + tracing::debug!( + client_ip = %addr.ip(), + peer = %peer, + error = %e, + "WebSocket upgrade ended before completion" + ); + } else { + tracing::error!( + client_ip = %addr.ip(), + peer = %peer, + error = %e, + "WebSocket upgrade failed" + ); + } + } } }); @@ -1024,8 +1073,61 @@ pub async fn run_server_on_listener( .with_upgrades() .await { - tracing::error!("Failed to handle request from {}: {}", addr, e); + if is_peer_scoped_http_error(&e) { + tracing::debug!( + peer = %addr, + error = %e, + "HTTP client connection ended before completion" + ); + } else { + tracing::error!( + peer = %addr, + error = %e, + "Failed to handle HTTP request" + ); + } } }); } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn relay_client_failures_are_peer_scoped() { + for kind in [ + RelayErrorKind::Protocol, + RelayErrorKind::IO, + RelayErrorKind::Transport, + RelayErrorKind::Timeout, + RelayErrorKind::Rejected, + RelayErrorKind::LimitExceeded, + RelayErrorKind::Other, + ] { + assert!( + is_peer_scoped_relay_error(kind), + "unexpected kind: {kind:?}" + ); + } + } + + #[test] + fn relay_internal_failures_remain_operator_actionable() { + for kind in [ + RelayErrorKind::Database, + RelayErrorKind::Gossip, + RelayErrorKind::Policy, + RelayErrorKind::NotFound, + RelayErrorKind::Invalid, + RelayErrorKind::State, + RelayErrorKind::Unsupported, + ] { + assert!( + !is_peer_scoped_relay_error(kind), + "unexpected kind: {kind:?}" + ); + } + } +}