From 2a81e19e574103d06a2edc632f105ccd5c3d6bf4 Mon Sep 17 00:00:00 2001 From: DanConwayDev Date: Sat, 15 Aug 2026 14:18:02 +0000 Subject: [PATCH] fix(logging): report sync outcomes at actionable levels Production logs are dominated by individual repository discoveries and rejected historical announcements, while unsupported NIP-77 responses can repeat for every filter. These entries obscure the aggregate outcomes operators use to judge relay health. Move peer- and event-specific diagnostics to debug, keep complete batch and fallback summaries at info, and share a one-time unsupported-capability gate across RelayConnection clones. Invalid root-event coordinates are parsed by a small tested helper so malformed remote input no longer produces warnings. This assumes rejected announcements and missing repository tags are untrusted input rather than operator-actionable faults. Transient NIP-77 cooldowns, failed internal channel sends, and aggregate fallback behavior deliberately retain their existing operational levels. HTTP and Git client-session classification is excluded for a separate commit. Validated with cargo fmt --check, git diff --check, all self_subscriber unit tests, and the new shared capability-gate test. --- CHANGELOG.md | 3 ++ src/nostr/builder.rs | 8 ++-- src/sync/mod.rs | 2 +- src/sync/relay_connection.rs | 67 +++++++++++++++++++++--------- src/sync/self_subscriber.rs | 79 ++++++++++++++++++++++-------------- 5 files changed, 104 insertions(+), 55 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2dc05c5..0401852 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -63,6 +63,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Scope bare log levels to ngit-grasp while keeping dependencies at warnings; explicit tracing filter expressions remain unchanged. +- 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. - 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/nostr/builder.rs b/src/nostr/builder.rs index c8df8d7..02510f4 100644 --- a/src/nostr/builder.rs +++ b/src/nostr/builder.rs @@ -468,10 +468,10 @@ impl Nip34WritePolicy { } } AnnouncementResult::Reject(reason) => { - tracing::warn!( - "Rejected repository announcement {}: {}", - event_id_str, - reason + tracing::debug!( + event_id = %event_id_str, + reason = %reason, + "Rejected repository announcement" ); reject_invalid(reason) } diff --git a/src/sync/mod.rs b/src/sync/mod.rs index 8e94f74..6b032d3 100644 --- a/src/sync/mod.rs +++ b/src/sync/mod.rs @@ -8654,7 +8654,7 @@ impl SyncManager { } Err(e) => { failed_count += 1; - tracing::warn!( + tracing::debug!( relay = %relay_url, filter_idx = idx, error = %e, diff --git a/src/sync/relay_connection.rs b/src/sync/relay_connection.rs index 98d4930..1ac7cc1 100644 --- a/src/sync/relay_connection.rs +++ b/src/sync/relay_connection.rs @@ -576,7 +576,7 @@ pub struct RelayConnection { /// Local database for negentropy comparison (used for NIP-77 sync) database: Option, /// Whether we've logged NIP-77 not supported for this relay (log once) - nip77_warning_logged: std::sync::Arc, + nip77_unsupported_logged: std::sync::Arc, /// Whether this relay supports NIP-77 negentropy (0 = unknown, 2 = confirmed not supported) nip77_supported: std::sync::Arc, /// Whether an in-session NIP-77 round exhausted the relay's query-rate @@ -716,7 +716,9 @@ impl RelayConnection { policy, client, database: None, - nip77_warning_logged: std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)), + nip77_unsupported_logged: std::sync::Arc::new(std::sync::atomic::AtomicBool::new( + false, + )), nip77_supported: std::sync::Arc::new(std::sync::atomic::AtomicU8::new(0)), nip77_query_rate_limited: std::sync::Arc::new(std::sync::atomic::AtomicBool::new( false, @@ -783,7 +785,9 @@ impl RelayConnection { policy, client, database: Some(database), - nip77_warning_logged: std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)), + nip77_unsupported_logged: std::sync::Arc::new(std::sync::atomic::AtomicBool::new( + false, + )), nip77_supported: std::sync::Arc::new(std::sync::atomic::AtomicU8::new(0)), nip77_query_rate_limited: std::sync::Arc::new(std::sync::atomic::AtomicBool::new( false, @@ -1744,13 +1748,19 @@ impl RelayConnection { || msg.contains("negentropy"); if is_negentropy_notice { - self.mark_negentropy_unsupported(); - - tracing::info!( - relay = %url, - notice = %msg, - "Relay does not support NIP-77 (negentropy)" - ); + if self.mark_negentropy_unsupported_and_should_log() { + tracing::info!( + relay = %url, + notice = %msg, + "Relay does not support NIP-77; using REQ+EOSE" + ); + } else { + tracing::debug!( + relay = %url, + notice = %msg, + "Relay repeated its NIP-77 unsupported notice" + ); + } } else { tracing::debug!(relay = %url, message = %msg, "Received NOTICE"); } @@ -2506,6 +2516,15 @@ impl RelayConnection { .store(2, std::sync::atomic::Ordering::Relaxed); } + /// Mark NIP-77 unsupported and return whether this is the first diagnostic + /// emitted by any clone of this connection. + fn mark_negentropy_unsupported_and_should_log(&self) -> bool { + self.mark_negentropy_unsupported(); + !self + .nip77_unsupported_logged + .swap(true, std::sync::atomic::Ordering::Relaxed) + } + /// Fall back to paced REQs for the rest of this connection session. /// /// rust-nostr owns the messages within a NIP-77 round, while relays can @@ -2703,17 +2722,17 @@ impl RelayConnection { } match classify_negentropy_failure(&e) { NegentropyFailure::Unsupported => { - self.mark_negentropy_unsupported(); - - // Log warning only once per relay to avoid spam - if !self - .nip77_warning_logged - .swap(true, std::sync::atomic::Ordering::Relaxed) - { - tracing::warn!( + if self.mark_negentropy_unsupported_and_should_log() { + tracing::info!( relay = %self.url, error = %e, - "Relay does not support NIP-77, will fall back to REQ+EOSE" + "Relay does not support NIP-77; using REQ+EOSE" + ); + } else { + tracing::debug!( + relay = %self.url, + error = %e, + "Relay repeated its NIP-77 unsupported response" ); } } @@ -2997,6 +3016,16 @@ mod tests { ); } + #[tokio::test] + async fn unsupported_capability_is_logged_once_across_connection_clones() { + let connection = permissive_connection("ws://127.0.0.1:1", Keys::generate()); + let clone = connection.clone(); + + assert!(connection.mark_negentropy_unsupported_and_should_log()); + assert!(!clone.mark_negentropy_unsupported_and_should_log()); + assert!(!connection.supports_negentropy().await); + } + #[tokio::test] async fn fetch_events_targets_the_connections_exact_relay() { let configured = LocalRelayBuilder::default().build(); diff --git a/src/sync/self_subscriber.rs b/src/sync/self_subscriber.rs index 9088b63..aad4931 100644 --- a/src/sync/self_subscriber.rs +++ b/src/sync/self_subscriber.rs @@ -310,7 +310,7 @@ impl SelfSubscriber { // the 1617/1618/1621 event IDs that get added when we receive // root events via handle_root_event. See mod.rs:71 for details. pending.replace_announcement_relays(repo_id.clone(), relays.clone()); - tracing::info!( + tracing::debug!( event_id = %event.id, repo_id = %repo_id, relay_count = relays.len(), @@ -529,33 +529,12 @@ impl SelfSubscriber { /// then updates the RepoSyncIndex with the event ID AND adds to pending /// so that Layer 3 filters will be created in the next batch. async fn handle_root_event(&self, event: &Event, pending: &mut PendingUpdates) { - // Extract 'a' tag to find the repo addressable reference - let repo_a_tag = event.tags.iter().find(|tag| { - let tag_vec = tag.as_slice(); - !tag_vec.is_empty() && tag_vec[0] == "a" - }); - - let repo_ref = match repo_a_tag { - Some(tag) => { - let tag_vec = tag.as_slice(); - // Get first value from tag (the 'a' tag value at index 1) - if tag_vec.len() >= 2 { - tag_vec[1].clone() - } else { - tracing::warn!( - event_id = %event.id, - "Root event has 'a' tag but no content" - ); - return; - } - } - None => { - tracing::warn!( - event_id = %event.id, - "Root event missing 'a' tag" - ); - return; - } + let Some(repo_ref) = root_event_repo_ref(event) else { + tracing::debug!( + event_id = %event.id, + "Ignoring root event without a usable 'a' tag" + ); + return; }; // Look up repo in repo_sync_index - add root event directly and also to pending @@ -619,9 +598,10 @@ impl SelfSubscriber { "Processing batch of repo updates" ); - // Log what repos and relays we discovered + // Preserve per-repository details for diagnosis without flooding the + // default operational stream; the complete batch count remains info. for (repo_id, needs) in &updates { - tracing::info!( + tracing::debug!( repo_id = %repo_id, relay_count = needs.relays.len(), relay_sample = ?needs.relays.iter().take(LOG_COLLECTION_SAMPLE_SIZE).collect::>(), @@ -686,7 +666,7 @@ impl SelfSubscriber { "Failed to send AddFilters action" ); } else { - tracing::info!( + tracing::debug!( relay = %relay_url, "Marked relay dirty for SyncManager recomputation" ); @@ -699,6 +679,16 @@ impl SelfSubscriber { // Helper Functions // ============================================================================= +fn root_event_repo_ref(event: &Event) -> Option { + event.tags.iter().find_map(|tag| { + let values = tag.as_slice(); + (values.first().is_some_and(|name| name == "a")) + .then(|| values.get(1).cloned()) + .flatten() + .filter(|coordinate| !coordinate.is_empty()) + }) +} + /// Convert clone URL to relay URL /// /// Converts http://domain:port/path.git to ws://domain:port @@ -725,6 +715,33 @@ mod tests { use std::sync::Arc; use tokio::sync::RwLock; + #[test] + fn root_event_repo_ref_requires_a_non_empty_coordinate() { + let keys = Keys::generate(); + let missing = EventBuilder::new(Kind::GitIssue, "") + .finalize(&keys) + .expect("build event without repository tag"); + let empty = EventBuilder::new(Kind::GitIssue, "") + .tag(Tag::custom("a", [""])) + .finalize(&keys) + .expect("build event with empty repository tag"); + + assert_eq!(root_event_repo_ref(&missing), None); + assert_eq!(root_event_repo_ref(&empty), None); + } + + #[test] + fn root_event_repo_ref_returns_the_repository_coordinate() { + let keys = Keys::generate(); + let coordinate = format!("30617:{}:logging", keys.public_key()); + let event = EventBuilder::new(Kind::GitIssue, "") + .tag(Tag::custom("a", [coordinate.clone()])) + .finalize(&keys) + .expect("build event with repository tag"); + + assert_eq!(root_event_repo_ref(&event), Some(coordinate)); + } + #[tokio::test] async fn startup_reconstruction_promotes_candidates_only_after_batch_completion() { let keys = Keys::generate();