From 662491c99ce41f4bcabca54b4fbf98ba2a3c3994 Mon Sep 17 00:00:00 2001 From: DanConwayDev Date: Fri, 7 Aug 2026 11:50:15 +0000 Subject: [PATCH] fix(logging): demote routine unclean disconnects Public WebSocket clients commonly reset TCP connections without completing the close handshake. rust-nostr reports that transport outcome as an ERROR, causing production error logs to be dominated by expected client churn and obscuring actionable relay failures. Add a per-event tracing filter that suppresses only the exact rust-nostr local-relay target and reset-without-close message. Other WebSocket protocol errors, client-send failures, and database failures from the same module retain their configured severity. The match deliberately remains narrow instead of changing the whole dependency target log level. Reclassifying other disconnect variants or changing rust-nostr upstream is excluded. Validated with focused classification unit tests and cargo check --bin ngit-grasp in nix develop. --- CHANGELOG.md | 3 ++ src/lib.rs | 1 + src/logging.rs | 77 ++++++++++++++++++++++++++++++++++++++++++++++++++ src/main.rs | 13 +++++---- 4 files changed, 89 insertions(+), 5 deletions(-) create mode 100644 src/logging.rs diff --git a/CHANGELOG.md b/CHANGELOG.md index bbd4da9..6605d9c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -59,6 +59,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- Stopped routine client connection resets without a WebSocket close handshake + from being reported as server errors, while retaining other embedded-relay + failures at their original severity. - Adapted historic pagination to each relay's observed page size and guarded NIP-11 `default_limit` hint, so omitted-limit filters continue past relays that return small pages without trusting unrelated maximum-limit metadata. diff --git a/src/lib.rs b/src/lib.rs index 35ee23a..6dd989d 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -4,6 +4,7 @@ pub mod config; pub mod git; pub mod grasp06; pub mod http; +pub mod logging; pub mod metrics; pub mod nostr; pub mod outbound; diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 0000000..d2bf920 --- /dev/null +++ b/src/logging.rs @@ -0,0 +1,77 @@ +//! Application-specific tracing filters. + +use tracing::{field::Visit, Event, Subscriber}; +use tracing_subscriber::layer::{Context, Filter}; + +const LOCAL_RELAY_TARGET: &str = "nostr_sdk::local_relay::local::inner"; +const UNCLEAN_RESET: &str = "WebSocket protocol error: Connection reset without closing handshake"; + +/// Suppresses the routine unclean-disconnect event emitted by the embedded relay. +/// +/// Internet clients commonly disappear without completing the WebSocket close +/// handshake. That is useful at debug level but is not a server failure. Match +/// the exact target and error text so database and outbound-send failures from +/// the same rust-nostr module remain visible at their original severity. +#[derive(Debug, Clone, Copy, Default)] +pub struct SuppressRoutineDisconnects; + +impl Filter for SuppressRoutineDisconnects +where + S: Subscriber, +{ + fn enabled(&self, _meta: &tracing::Metadata<'_>, _cx: &Context<'_, S>) -> bool { + true + } + + fn event_enabled(&self, event: &Event<'_>, _cx: &Context<'_, S>) -> bool { + if event.metadata().target() != LOCAL_RELAY_TARGET { + return true; + } + + let mut visitor = MessageVisitor::default(); + event.record(&mut visitor); + !visitor + .message + .as_deref() + .is_some_and(is_routine_disconnect_message) + } +} + +#[derive(Default)] +struct MessageVisitor { + message: Option, +} + +impl Visit for MessageVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() == "message" { + self.message = Some(format!("{value:?}")); + } + } +} + +fn is_routine_disconnect_message(message: &str) -> bool { + message.contains("Can't handle websocket msg:") && message.contains(UNCLEAN_RESET) +} + +#[cfg(test)] +mod tests { + use super::is_routine_disconnect_message; + + #[test] + fn identifies_reset_without_close_handshake() { + assert!(is_routine_disconnect_message( + "Can't handle websocket msg: WebSocket protocol error: Connection reset without closing handshake" + )); + } + + #[test] + fn retains_other_websocket_and_relay_errors() { + assert!(!is_routine_disconnect_message( + "Can't handle websocket msg: WebSocket protocol error: invalid opcode" + )); + assert!(!is_routine_disconnect_message( + "Can't save event into database: disk I/O error" + )); + } +} diff --git a/src/main.rs b/src/main.rs index 2d56d96..314d970 100644 --- a/src/main.rs +++ b/src/main.rs @@ -2,9 +2,12 @@ use anyhow::Result; use clap::Parser; use tokio::signal; use tracing::info; -use tracing_subscriber::{EnvFilter, FmtSubscriber}; +use tracing_subscriber::{filter::FilterExt, layer::SubscriberExt, EnvFilter, Layer}; -use ngit_grasp::{cleanup_empty_repos, config::Config, nostr, server::RelayServer}; +use ngit_grasp::{ + cleanup_empty_repos, config::Config, logging::SuppressRoutineDisconnects, nostr, + server::RelayServer, +}; /// Top-level CLI dispatcher. /// @@ -66,9 +69,9 @@ async fn main() -> Result<()> { /// the global tracing subscriber and signal handling. async fn run_relay(config: Config) -> Result<()> { // Initialize tracing with configured log level - let subscriber = FmtSubscriber::builder() - .with_env_filter(EnvFilter::new(&config.log_level)) - .finish(); + let filter = EnvFilter::new(&config.log_level).and(SuppressRoutineDisconnects); + let subscriber = + tracing_subscriber::registry().with(tracing_subscriber::fmt::layer().with_filter(filter)); tracing::subscriber::set_global_default(subscriber)?; info!("Starting ngit-grasp with log level: {}", config.log_level);