diff --git a/4bc5-relay-ngit-dev-migration-v2.md b/4bc5-relay-ngit-dev-migration-v2.md index c263222..4fdf674 100644 --- a/4bc5-relay-ngit-dev-migration-v2.md +++ b/4bc5-relay-ngit-dev-migration-v2.md @@ -490,7 +490,7 @@ This is a **different and more serious issue** than the `expired_events` blackli - Review event handler registration timing 2. **Validate scope of issue:** - - Check other repos from needs-resync.txt with purgatory context "none" + - Check other repos from needs-resync.txt with purgarity context "none" - Determine how many are affected by silent drop vs expired_events blacklist - Test manual republishing on a sample set @@ -504,6 +504,83 @@ This is a **different and more serious issue** than the `expired_events` blackli 1. **Silent event drops during historic sync** (this finding - HIGH PRIORITY) 2. **`expired_events` blacklist persisted across restarts** (previous finding - MEDIUM PRIORITY) +### 2026-01-27 [Session 07:00 - ROOT CAUSE FOUND: Database Query Fix Bug] + +**Investigated why commit 4162c90 (database query fix) didn't work:** + +**Root Cause: `last_connected` timestamp set BEFORE `load_existing_events()` is called** + +**The Bug (src/sync/self_subscriber.rs:424-447):** + +```rust +// Line 425: Sets last_connected to NOW +self.last_connected = Some(Timestamp::now()); + +// Line 427: Subscribe to relay +if let Err(e) = client.subscribe(filter, None).await { ... } + +// Line 447: Load existing events - BUT last_connected is already set! +let mut pending = self.load_existing_events().await; +``` + +When `load_existing_events()` runs, it checks `self.last_connected` and applies `.since()` filter: + +```rust +if let Some(timestamp) = self.last_connected { + announcement_filter = announcement_filter.since(timestamp); +} +``` + +Since `last_connected` was just set to `Timestamp::now()`, the database query becomes: +```sql +SELECT * FROM events WHERE kind=30617 AND created_at >= +``` + +**No events have `created_at >= current_time`, so query returns 0 results.** + +**Evidence from logs (work/migration-analysis-20260127-074741/202601270826-journald-2h.log):** + +``` +Line 11272: Loading events incrementally from database (reconnect) since=1769498542 +Line 11275: Loaded announcements from database count=0 +Line 11276: Loaded root events from database count=0 +Line 11280: Processed existing events from database announcements_loaded=0 root_events_processed=0 +``` + +Timestamp `1769498542` = `2026-01-27T07:22:22 UTC` = exactly the service startup time. + +**Why Manual Publish Works:** + +When manually publishing a state event: +1. It arrives via WebSocket (not database query) +2. It's processed through normal event flow +3. No `.since()` filter is applied to incoming WebSocket events + +**The Fix:** + +Move `load_existing_events()` to run BEFORE setting `last_connected`: + +```rust +// Load existing events FIRST (before setting last_connected) +let mut pending = self.load_existing_events().await; + +// NOW set last_connected for future reconnects +self.last_connected = Some(Timestamp::now()); + +// Subscribe to relay +if let Err(e) = client.subscribe(filter, None).await { ... } +``` + +**Location:** `src/sync/self_subscriber.rs:424-447` + +**Impact:** This explains ALL ~190 missing state events. The database query returned 0 results, so no Layer 2/3 filters were created, so no state events were fetched. + +**Next Steps:** +1. Implement the fix (reorder lines 447 to come before line 425) +2. Test locally to verify database query returns events +3. Deploy to VPS and verify state events sync +4. Re-run migration analysis to confirm all repos sync + ## Key Findings (Analysis Results) **Latest Analysis (2026-01-23, after script fixes):**