diff options
| author | DanConwayDev <DanConwayDev@protonmail.com> | 2026-01-23 11:41:10 +0000 |
|---|---|---|
| committer | DanConwayDev <DanConwayDev@protonmail.com> | 2026-01-27 20:37:58 +0000 |
| commit | 73a366cbd7be4edf9c74194cd0891c80a15236a5 (patch) | |
| tree | c4a631a28496d48ad2bce6c2dfd4eff7ae0e4866 /src | |
| parent | 28cc7820953efeafb2bc4d41ebcf3d682da86711 (diff) | |
Add structured logging for migration analysis
- Add [PARSE_FAIL] logging when event parsing fails
- Add [PURGATORY_EXPIRED] logging when repos expire from purgatory
- Logs include: kind, event_id, repo, npub, reason
- Supports Phase 4 migration scripts (30-extract-*.sh)
- All 382 tests pass
Diffstat (limited to 'src')
| -rw-r--r-- | src/nostr/builder.rs | 135 | ||||
| -rw-r--r-- | src/purgatory/mod.rs | 103 |
2 files changed, 206 insertions, 32 deletions
diff --git a/src/nostr/builder.rs b/src/nostr/builder.rs index 34014db..629c111 100644 --- a/src/nostr/builder.rs +++ b/src/nostr/builder.rs | |||
| @@ -98,6 +98,62 @@ impl Nip34WritePolicy { | |||
| 98 | self.ctx.set_local_relay(relay); | 98 | self.ctx.set_local_relay(relay); |
| 99 | } | 99 | } |
| 100 | 100 | ||
| 101 | /// Extract repository identifier from event's 'd' tag. | ||
| 102 | /// | ||
| 103 | /// Used for structured logging when parsing fails - we try to extract | ||
| 104 | /// the identifier even if full parsing failed. | ||
| 105 | fn extract_identifier_from_event(event: &Event) -> String { | ||
| 106 | use nostr_relay_builder::prelude::TagKind; | ||
| 107 | event | ||
| 108 | .tags | ||
| 109 | .iter() | ||
| 110 | .find(|t| t.kind() == TagKind::d()) | ||
| 111 | .and_then(|t| t.content()) | ||
| 112 | .map(|s| s.to_string()) | ||
| 113 | .unwrap_or_else(|| "unknown".to_string()) | ||
| 114 | } | ||
| 115 | |||
| 116 | /// Extract ALL repository identifiers from PR event's 'a' tags. | ||
| 117 | /// | ||
| 118 | /// PR events can reference multiple repositories via multiple 'a' tags | ||
| 119 | /// (e.g., when there are multiple maintainers). Each tag has format | ||
| 120 | /// `30617:<owner_pubkey>:<identifier>`. | ||
| 121 | /// | ||
| 122 | /// Returns a vector of unique identifiers, or `["unknown"]` if none found. | ||
| 123 | fn extract_repos_from_pr_event(event: &Event) -> Vec<String> { | ||
| 124 | let repos: Vec<String> = event | ||
| 125 | .tags | ||
| 126 | .iter() | ||
| 127 | .filter_map(|tag| { | ||
| 128 | let tag_vec = tag.clone().to_vec(); | ||
| 129 | if tag_vec.len() >= 2 && tag_vec[0] == "a" && tag_vec[1].starts_with("30617:") { | ||
| 130 | // Format: 30617:<owner_pubkey>:<identifier> | ||
| 131 | let parts: Vec<&str> = tag_vec[1].split(':').collect(); | ||
| 132 | if parts.len() >= 3 { | ||
| 133 | Some(parts[2].to_string()) | ||
| 134 | } else { | ||
| 135 | None | ||
| 136 | } | ||
| 137 | } else { | ||
| 138 | None | ||
| 139 | } | ||
| 140 | }) | ||
| 141 | .collect(); | ||
| 142 | |||
| 143 | // Deduplicate while preserving order | ||
| 144 | let mut seen = std::collections::HashSet::new(); | ||
| 145 | let unique_repos: Vec<String> = repos | ||
| 146 | .into_iter() | ||
| 147 | .filter(|r| seen.insert(r.clone())) | ||
| 148 | .collect(); | ||
| 149 | |||
| 150 | if unique_repos.is_empty() { | ||
| 151 | vec!["unknown".to_string()] | ||
| 152 | } else { | ||
| 153 | unique_repos | ||
| 154 | } | ||
| 155 | } | ||
| 156 | |||
| 101 | /// Handle repository announcement event | 157 | /// Handle repository announcement event |
| 102 | async fn handle_announcement(&self, event: &Event) -> WritePolicyResult { | 158 | async fn handle_announcement(&self, event: &Event) -> WritePolicyResult { |
| 103 | let event_id_str = event.id.to_bech32().unwrap_or_else(|_| event.id.to_hex()); | 159 | let event_id_str = event.id.to_bech32().unwrap_or_else(|_| event.id.to_hex()); |
| @@ -129,10 +185,18 @@ impl Nip34WritePolicy { | |||
| 129 | WritePolicyResult::Accept | 185 | WritePolicyResult::Accept |
| 130 | } | 186 | } |
| 131 | Err(e) => { | 187 | Err(e) => { |
| 188 | let npub = event.pubkey.to_bech32().unwrap_or_else(|_| event.pubkey.to_hex()); | ||
| 189 | let event_id_short = &event.id.to_hex()[..12]; | ||
| 190 | // Try to extract repo identifier from 'd' tag even if parsing failed | ||
| 191 | let repo = Self::extract_identifier_from_event(event); | ||
| 192 | // Structured log for migration scripts | ||
| 132 | tracing::warn!( | 193 | tracing::warn!( |
| 133 | "Failed to parse repository announcement {}: {}", | 194 | "[PARSE_FAIL] kind={} event_id={}... reason=\"{}\" repo={} npub={}", |
| 134 | event_id_str, | 195 | event.kind.as_u16(), |
| 135 | e | 196 | event_id_short, |
| 197 | e, | ||
| 198 | repo, | ||
| 199 | npub | ||
| 136 | ); | 200 | ); |
| 137 | WritePolicyResult::reject(format!("Failed to parse announcement: {}", e)) | 201 | WritePolicyResult::reject(format!("Failed to parse announcement: {}", e)) |
| 138 | } | 202 | } |
| @@ -157,10 +221,18 @@ impl Nip34WritePolicy { | |||
| 157 | WritePolicyResult::Accept | 221 | WritePolicyResult::Accept |
| 158 | } | 222 | } |
| 159 | Err(e) => { | 223 | Err(e) => { |
| 224 | let npub = event.pubkey.to_bech32().unwrap_or_else(|_| event.pubkey.to_hex()); | ||
| 225 | let event_id_short = &event.id.to_hex()[..12]; | ||
| 226 | // Try to extract repo identifier from 'd' tag even if parsing failed | ||
| 227 | let repo = Self::extract_identifier_from_event(event); | ||
| 228 | // Structured log for migration scripts | ||
| 160 | tracing::warn!( | 229 | tracing::warn!( |
| 161 | "Failed to parse maintainer announcement {}: {}", | 230 | "[PARSE_FAIL] kind={} event_id={}... reason=\"{}\" repo={} npub={}", |
| 162 | event_id_str, | 231 | event.kind.as_u16(), |
| 163 | e | 232 | event_id_short, |
| 233 | e, | ||
| 234 | repo, | ||
| 235 | npub | ||
| 164 | ); | 236 | ); |
| 165 | WritePolicyResult::reject(format!("Failed to parse announcement: {}", e)) | 237 | WritePolicyResult::reject(format!("Failed to parse announcement: {}", e)) |
| 166 | } | 238 | } |
| @@ -183,8 +255,6 @@ impl Nip34WritePolicy { | |||
| 183 | /// * `event` - The state event to validate | 255 | /// * `event` - The state event to validate |
| 184 | /// * `is_synced` - True if this event came from proactive sync (vs user-submitted) | 256 | /// * `is_synced` - True if this event came from proactive sync (vs user-submitted) |
| 185 | async fn handle_state(&self, event: &Event, is_synced: bool) -> WritePolicyResult { | 257 | async fn handle_state(&self, event: &Event, is_synced: bool) -> WritePolicyResult { |
| 186 | let event_id_str = event.id.to_bech32().unwrap_or_else(|_| event.id.to_hex()); | ||
| 187 | |||
| 188 | match self.state_policy.validate(event) { | 258 | match self.state_policy.validate(event) { |
| 189 | StateResult::Accept => { | 259 | StateResult::Accept => { |
| 190 | // Process state alignment asynchronously | 260 | // Process state alignment asynchronously |
| @@ -195,7 +265,19 @@ impl Nip34WritePolicy { | |||
| 195 | { | 265 | { |
| 196 | Ok(poilicy_result) => poilicy_result, | 266 | Ok(poilicy_result) => poilicy_result, |
| 197 | Err(e) => { | 267 | Err(e) => { |
| 198 | tracing::warn!("Failed to process state event {}: {}", event_id_str, e); | 268 | let npub = event.pubkey.to_bech32().unwrap_or_else(|_| event.pubkey.to_hex()); |
| 269 | let event_id_short = &event.id.to_hex()[..12]; | ||
| 270 | // Try to extract repo identifier from 'd' tag even if parsing failed | ||
| 271 | let repo = Self::extract_identifier_from_event(event); | ||
| 272 | // Structured log for migration scripts | ||
| 273 | tracing::warn!( | ||
| 274 | "[PARSE_FAIL] kind={} event_id={}... reason=\"{}\" repo={} npub={}", | ||
| 275 | event.kind.as_u16(), | ||
| 276 | event_id_short, | ||
| 277 | e, | ||
| 278 | repo, | ||
| 279 | npub | ||
| 280 | ); | ||
| 199 | // reject if processing failed | 281 | // reject if processing failed |
| 200 | WritePolicyResult::Reject { | 282 | WritePolicyResult::Reject { |
| 201 | status: false, | 283 | status: false, |
| @@ -205,7 +287,19 @@ impl Nip34WritePolicy { | |||
| 205 | } | 287 | } |
| 206 | } | 288 | } |
| 207 | StateResult::Reject(reason) => { | 289 | StateResult::Reject(reason) => { |
| 208 | tracing::warn!("Rejected repository state {}: {}", event_id_str, reason); | 290 | let npub = event.pubkey.to_bech32().unwrap_or_else(|_| event.pubkey.to_hex()); |
| 291 | let event_id_short = &event.id.to_hex()[..12]; | ||
| 292 | // Try to extract repo identifier from 'd' tag even if parsing failed | ||
| 293 | let repo = Self::extract_identifier_from_event(event); | ||
| 294 | // Structured log for migration scripts | ||
| 295 | tracing::warn!( | ||
| 296 | "[PARSE_FAIL] kind={} event_id={}... reason=\"{}\" repo={} npub={}", | ||
| 297 | event.kind.as_u16(), | ||
| 298 | event_id_short, | ||
| 299 | reason, | ||
| 300 | repo, | ||
| 301 | npub | ||
| 302 | ); | ||
| 209 | WritePolicyResult::reject(reason) | 303 | WritePolicyResult::reject(reason) |
| 210 | } | 304 | } |
| 211 | } | 305 | } |
| @@ -323,11 +417,22 @@ impl Nip34WritePolicy { | |||
| 323 | } | 417 | } |
| 324 | Err(e) => { | 418 | Err(e) => { |
| 325 | // Error checking git data - reject event | 419 | // Error checking git data - reject event |
| 326 | tracing::warn!( | 420 | let npub = event.pubkey.to_bech32().unwrap_or_else(|_| event.pubkey.to_hex()); |
| 327 | "Failed to check git data for PR event {}: {}", | 421 | let event_id_short = &event.id.to_hex()[..12]; |
| 328 | event_id_str, | 422 | // Extract ALL repo identifiers from 'a' tags for PR events |
| 329 | e | 423 | // (PR events can reference multiple repos when there are multiple maintainers) |
| 330 | ); | 424 | let repos = Self::extract_repos_from_pr_event(event); |
| 425 | // Structured log for migration scripts - log once per repo | ||
| 426 | for repo in &repos { | ||
| 427 | tracing::warn!( | ||
| 428 | "[PARSE_FAIL] kind={} event_id={}... reason=\"git data check failed: {}\" repo={} npub={}", | ||
| 429 | event.kind.as_u16(), | ||
| 430 | event_id_short, | ||
| 431 | e, | ||
| 432 | repo, | ||
| 433 | npub | ||
| 434 | ); | ||
| 435 | } | ||
| 331 | WritePolicyResult::reject(format!("Failed to check git data: {}", e)) | 436 | WritePolicyResult::reject(format!("Failed to check git data: {}", e)) |
| 332 | } | 437 | } |
| 333 | } | 438 | } |
diff --git a/src/purgatory/mod.rs b/src/purgatory/mod.rs index 47798a6..8b75351 100644 --- a/src/purgatory/mod.rs +++ b/src/purgatory/mod.rs | |||
| @@ -21,6 +21,7 @@ pub use types::{PrPurgatoryEntry, RefPair, RefUpdate, StatePurgatoryEntry}; | |||
| 21 | 21 | ||
| 22 | use dashmap::DashMap; | 22 | use dashmap::DashMap; |
| 23 | use nostr_sdk::prelude::*; | 23 | use nostr_sdk::prelude::*; |
| 24 | use nostr_sdk::ToBech32; | ||
| 24 | use serde::{Deserialize, Serialize}; | 25 | use serde::{Deserialize, Serialize}; |
| 25 | use std::collections::HashMap; | 26 | use std::collections::HashMap; |
| 26 | use std::collections::HashSet; | 27 | use std::collections::HashSet; |
| @@ -608,6 +609,9 @@ impl Purgatory { | |||
| 608 | /// prevent infinite re-sync loops. Events that expire without finding git data | 609 | /// prevent infinite re-sync loops. Events that expire without finding git data |
| 609 | /// will be filtered out during future negentropy/REQ sync operations. | 610 | /// will be filtered out during future negentropy/REQ sync operations. |
| 610 | /// | 611 | /// |
| 612 | /// Emits structured `[PURGATORY_EXPIRED]` log entries for each expired event | ||
| 613 | /// to support migration scripts and operational monitoring. | ||
| 614 | /// | ||
| 611 | /// # Returns | 615 | /// # Returns |
| 612 | /// Tuple of (num_state_removed, num_pr_removed) | 616 | /// Tuple of (num_state_removed, num_pr_removed) |
| 613 | pub fn cleanup(&self) -> (usize, usize) { | 617 | pub fn cleanup(&self) -> (usize, usize) { |
| @@ -615,18 +619,24 @@ impl Purgatory { | |||
| 615 | let mut state_removed = 0; | 619 | let mut state_removed = 0; |
| 616 | 620 | ||
| 617 | // Remove expired state events and mark them as expired | 621 | // Remove expired state events and mark them as expired |
| 618 | self.state_events.retain(|_, entries| { | 622 | self.state_events.retain(|identifier, entries| { |
| 619 | let original_len = entries.len(); | 623 | let original_len = entries.len(); |
| 620 | // Collect event IDs before removing | ||
| 621 | let expired_ids: Vec<EventId> = entries | ||
| 622 | .iter() | ||
| 623 | .filter(|entry| entry.expires_at <= now) | ||
| 624 | .map(|entry| entry.event.id) | ||
| 625 | .collect(); | ||
| 626 | 624 | ||
| 627 | // Mark as expired to prevent re-sync | 625 | // Log and collect expired entries before removing |
| 628 | for event_id in expired_ids { | 626 | for entry in entries.iter().filter(|e| e.expires_at <= now) { |
| 629 | self.mark_expired(event_id); | 627 | let npub = entry.author.to_bech32().unwrap_or_else(|_| entry.author.to_hex()); |
| 628 | let event_id_short = &entry.event.id.to_hex()[..12]; | ||
| 629 | |||
| 630 | // Structured log for migration scripts | ||
| 631 | tracing::warn!( | ||
| 632 | "[PURGATORY_EXPIRED] repo={} npub={} event_id={}... kind={} reason=\"git data not received within 30 minutes\"", | ||
| 633 | identifier, | ||
| 634 | npub, | ||
| 635 | event_id_short, | ||
| 636 | entry.event.kind.as_u16() | ||
| 637 | ); | ||
| 638 | |||
| 639 | self.mark_expired(entry.event.id); | ||
| 630 | } | 640 | } |
| 631 | 641 | ||
| 632 | // Remove expired entries | 642 | // Remove expired entries |
| @@ -636,21 +646,80 @@ impl Purgatory { | |||
| 636 | }); | 646 | }); |
| 637 | 647 | ||
| 638 | // Remove expired PR events and mark them as expired | 648 | // Remove expired PR events and mark them as expired |
| 639 | let expired_prs: Vec<(String, Option<EventId>)> = self | 649 | let expired_prs: Vec<_> = self |
| 640 | .pr_events | 650 | .pr_events |
| 641 | .iter() | 651 | .iter() |
| 642 | .filter(|entry| entry.value().expires_at <= now) | 652 | .filter(|entry| entry.value().expires_at <= now) |
| 643 | .map(|entry| { | 653 | .map(|entry| { |
| 644 | let event_id = entry.value().event.as_ref().map(|e| e.id); | 654 | let pr_entry = entry.value(); |
| 645 | (entry.key().clone(), event_id) | 655 | let event_id_str = entry.key().clone(); |
| 656 | let event_opt = pr_entry.event.clone(); | ||
| 657 | let commit = pr_entry.commit.clone(); | ||
| 658 | (event_id_str, event_opt, commit) | ||
| 646 | }) | 659 | }) |
| 647 | .collect(); | 660 | .collect(); |
| 648 | 661 | ||
| 649 | let pr_removed = expired_prs.len(); | 662 | let pr_removed = expired_prs.len(); |
| 650 | for (event_id_str, event_id_opt) in expired_prs { | 663 | for (event_id_str, event_opt, commit) in expired_prs { |
| 651 | // Mark actual PR events as expired (not placeholders) | 664 | // Log structured entry for PR events (not placeholders) |
| 652 | if let Some(event_id) = event_id_opt { | 665 | if let Some(ref event) = event_opt { |
| 653 | self.mark_expired(event_id); | 666 | let npub = event.pubkey.to_bech32().unwrap_or_else(|_| event.pubkey.to_hex()); |
| 667 | let event_id_short = &event.id.to_hex()[..12]; | ||
| 668 | |||
| 669 | // Extract ALL repo identifiers from 'a' tags | ||
| 670 | // (PR events can reference multiple repos when there are multiple maintainers) | ||
| 671 | let repos: Vec<String> = event | ||
| 672 | .tags | ||
| 673 | .iter() | ||
| 674 | .filter_map(|tag| { | ||
| 675 | let tag_vec = tag.clone().to_vec(); | ||
| 676 | if tag_vec.len() >= 2 && tag_vec[0] == "a" && tag_vec[1].starts_with("30617:") { | ||
| 677 | // Format: 30617:<owner_pubkey>:<identifier> | ||
| 678 | let parts: Vec<&str> = tag_vec[1].split(':').collect(); | ||
| 679 | if parts.len() >= 3 { | ||
| 680 | Some(parts[2].to_string()) | ||
| 681 | } else { | ||
| 682 | None | ||
| 683 | } | ||
| 684 | } else { | ||
| 685 | None | ||
| 686 | } | ||
| 687 | }) | ||
| 688 | .collect(); | ||
| 689 | |||
| 690 | // Deduplicate while preserving order | ||
| 691 | let mut seen = std::collections::HashSet::new(); | ||
| 692 | let unique_repos: Vec<String> = repos | ||
| 693 | .into_iter() | ||
| 694 | .filter(|r| seen.insert(r.clone())) | ||
| 695 | .collect(); | ||
| 696 | |||
| 697 | let repos_to_log = if unique_repos.is_empty() { | ||
| 698 | vec!["unknown".to_string()] | ||
| 699 | } else { | ||
| 700 | unique_repos | ||
| 701 | }; | ||
| 702 | |||
| 703 | // Structured log for migration scripts - log once per repo | ||
| 704 | for repo in &repos_to_log { | ||
| 705 | tracing::warn!( | ||
| 706 | "[PURGATORY_EXPIRED] repo={} npub={} event_id={}... kind={} commit={} reason=\"git data not received within 30 minutes\"", | ||
| 707 | repo, | ||
| 708 | npub, | ||
| 709 | event_id_short, | ||
| 710 | event.kind.as_u16(), | ||
| 711 | &commit[..commit.len().min(12)] | ||
| 712 | ); | ||
| 713 | } | ||
| 714 | |||
| 715 | self.mark_expired(event.id); | ||
| 716 | } else { | ||
| 717 | // Placeholder (git data arrived first, but PR event never came) | ||
| 718 | tracing::debug!( | ||
| 719 | "[PURGATORY_EXPIRED] placeholder event_id={} commit={} reason=\"PR event not received within 30 minutes\"", | ||
| 720 | &event_id_str[..event_id_str.len().min(12)], | ||
| 721 | &commit[..commit.len().min(12)] | ||
| 722 | ); | ||
| 654 | } | 723 | } |
| 655 | self.pr_events.remove(&event_id_str); | 724 | self.pr_events.remove(&event_id_str); |
| 656 | } | 725 | } |