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.
This commit is contained in:
DanConwayDev
2026-08-15 14:22:59 +00:00
parent 2a81e19e57
commit 1448d4d2db
3 changed files with 158 additions and 15 deletions
+3
View File
@@ -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
+43 -5
View File
@@ -253,6 +253,12 @@ pub(crate) fn is_git_protocol_error(exit_code: Option<i32>, 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<S, E>(
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<S, E>(
} 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:
+112 -10
View File
@@ -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<Request<Incoming>> 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<Request<Incoming>> 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<Request<Incoming>> 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:?}"
);
}
}
}