diff options
| author | DanConwayDev <DanConwayDev@protonmail.com> | 2026-01-09 23:41:55 +0000 |
|---|---|---|
| committer | DanConwayDev <DanConwayDev@protonmail.com> | 2026-01-09 23:41:55 +0000 |
| commit | 215d4d51310545a7be95582e14cc28a7958ad6e3 (patch) | |
| tree | fa195b6195383618565991880841c58ad5a6baab /src/sync | |
| parent | 5c68d55b59cc7e59f2a618926059ac3f405876d0 (diff) | |
fix: downgrade duplicate EOSE log to trace level
EOSE messages can arrive after batch completion due to:
1. Late/duplicate EOSE from relay (e.g., live_sync REQ subscriptions)
2. Race condition between batch confirmation and EOSE arrival
3. EOSE during intentional disconnect cleanup
Since this is expected behavior, downgrade from debug to trace level
to reduce log noise. Added detailed code comment explaining the
scenarios and suggesting how to investigate if needed (tracking
recently-completed subscription IDs).
Resolves issue where duplicate EOSE from live_sync subscriptions
appeared as confusing 'unknown relay' debug messages.
Diffstat (limited to 'src/sync')
| -rw-r--r-- | src/sync/mod.rs | 19 |
1 files changed, 15 insertions, 4 deletions
diff --git a/src/sync/mod.rs b/src/sync/mod.rs index 2c1754d..4b2b61c 100644 --- a/src/sync/mod.rs +++ b/src/sync/mod.rs | |||
| @@ -640,7 +640,18 @@ impl SyncManager { | |||
| 640 | let mut pending = self.pending_sync_index.write().await; | 640 | let mut pending = self.pending_sync_index.write().await; |
| 641 | 641 | ||
| 642 | let Some(batches) = pending.get_mut(relay_url) else { | 642 | let Some(batches) = pending.get_mut(relay_url) else { |
| 643 | // This can happen during disconnect if EOSE arrives after cleanup | 643 | // This can happen when EOSE arrives after batch has already been confirmed/removed. |
| 644 | // Common causes: | ||
| 645 | // 1. During intentional disconnect (cleanup in progress) | ||
| 646 | // 2. Duplicate/late EOSE from relay (e.g., live_sync REQ subscriptions may send | ||
| 647 | // multiple EOSE messages - some relays do this) | ||
| 648 | // 3. Race condition between batch confirmation and EOSE arrival | ||
| 649 | // | ||
| 650 | // NOTE: If we wanted to investigate whether these are truly duplicate EOSEs, | ||
| 651 | // we could track recently-completed subscription IDs (with timestamps) and | ||
| 652 | // check if this sub_id was recently confirmed. This would distinguish between: | ||
| 653 | // - Duplicate EOSE (sub_id was recently in outstanding_subs) | ||
| 654 | // - Truly unknown subscription (sub_id never tracked) | ||
| 644 | if is_disconnecting { | 655 | if is_disconnecting { |
| 645 | // Expected during intentional disconnect - suppress noisy log | 656 | // Expected during intentional disconnect - suppress noisy log |
| 646 | tracing::trace!( | 657 | tracing::trace!( |
| @@ -649,11 +660,11 @@ impl SyncManager { | |||
| 649 | "EOSE received during disconnect cleanup - ignoring" | 660 | "EOSE received during disconnect cleanup - ignoring" |
| 650 | ); | 661 | ); |
| 651 | } else { | 662 | } else { |
| 652 | // Unexpected - log at debug level | 663 | // Expected when batch completes before late/duplicate EOSE arrives |
| 653 | tracing::debug!( | 664 | tracing::trace!( |
| 654 | relay = %relay_url, | 665 | relay = %relay_url, |
| 655 | sub_id = %sub_id, | 666 | sub_id = %sub_id, |
| 656 | "EOSE received for unknown relay" | 667 | "EOSE received after batch already completed (late or duplicate EOSE)" |
| 657 | ); | 668 | ); |
| 658 | } | 669 | } |
| 659 | return; | 670 | return; |