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.
This commit is contained in:
DanConwayDev
2026-08-15 14:18:02 +00:00
parent 7b7b098b8e
commit 2a81e19e57
5 changed files with 104 additions and 55 deletions
+3
View File
@@ -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
+4 -4
View File
@@ -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)
}
+1 -1
View File
@@ -8654,7 +8654,7 @@ impl SyncManager {
}
Err(e) => {
failed_count += 1;
tracing::warn!(
tracing::debug!(
relay = %relay_url,
filter_idx = idx,
error = %e,
+48 -19
View File
@@ -576,7 +576,7 @@ pub struct RelayConnection {
/// Local database for negentropy comparison (used for NIP-77 sync)
database: Option<SharedDatabase>,
/// Whether we've logged NIP-77 not supported for this relay (log once)
nip77_warning_logged: std::sync::Arc<std::sync::atomic::AtomicBool>,
nip77_unsupported_logged: std::sync::Arc<std::sync::atomic::AtomicBool>,
/// Whether this relay supports NIP-77 negentropy (0 = unknown, 2 = confirmed not supported)
nip77_supported: std::sync::Arc<std::sync::atomic::AtomicU8>,
/// 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();
+48 -31
View File
@@ -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::<Vec<_>>(),
@@ -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<String> {
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();