diff options
| author | DanConwayDev <DanConwayDev@protonmail.com> | 2026-02-03 21:21:33 +0000 |
|---|---|---|
| committer | DanConwayDev <DanConwayDev@protonmail.com> | 2026-02-03 21:41:19 +0000 |
| commit | d392f0bc14bcd687e918d4653ae016226496b4c4 (patch) | |
| tree | 2738b66be231c90615b15d2da1266e16704c510d | |
| parent | c163d717147b92b16d89da2fbccef775647b5a07 (diff) | |
feat: add diagnostic logging for partial state event matches
Improves observability when pushes are rejected due to state events that
only partially match the pushed refs. Previously, logs only showed 'No
state event found' even when state events existed but didn't match.
Changes:
- Add diagnose_state_mismatch() to explain why state events don't match
- Log specific reasons: missing refs, wrong SHAs, or extra refs
- Update rejection message to 'No matching state event found' (more accurate)
- Add 4 unit tests for diagnostic function
Example diagnostic output:
WARN State event abc123 from authorized author doesn't match push:
refs/heads/main missing (state declares 9cc3d93b)
This addresses the issue where a push with only refs/heads/test was
rejected because the state event also declared refs/heads/main, but
logs didn't explain why the match failed.
| -rw-r--r-- | src/git/authorization.rs | 80 | ||||
| -rw-r--r-- | src/git/handlers.rs | 2 | ||||
| -rw-r--r-- | src/purgatory/helpers.rs | 204 | ||||
| -rw-r--r-- | src/purgatory/mod.rs | 2 |
4 files changed, 284 insertions, 4 deletions
diff --git a/src/git/authorization.rs b/src/git/authorization.rs index db2b992..27107db 100644 --- a/src/git/authorization.rs +++ b/src/git/authorization.rs | |||
| @@ -666,12 +666,88 @@ pub async fn get_state_authorization_for_specific_owner_repo( | |||
| 666 | debug!("Purgatory events found but none from authorized authors"); | 666 | debug!("Purgatory events found but none from authorized authors"); |
| 667 | } | 667 | } |
| 668 | } else { | 668 | } else { |
| 669 | debug!("No matching state events found in purgatory"); | 669 | // Check if there are ANY state events in purgatory for this identifier |
| 670 | let all_purgatory_states = purgatory.find_state(identifier); | ||
| 671 | |||
| 672 | if !all_purgatory_states.is_empty() { | ||
| 673 | // There are state events but none match the push - diagnose why | ||
| 674 | debug!( | ||
| 675 | "Found {} state event(s) in purgatory for {} but none match the push", | ||
| 676 | all_purgatory_states.len(), | ||
| 677 | identifier | ||
| 678 | ); | ||
| 679 | |||
| 680 | // Count authorized state events and collect diagnostic info | ||
| 681 | let mut authorized_count = 0; | ||
| 682 | let mut diagnostic_reasons = Vec::new(); | ||
| 683 | |||
| 684 | // Diagnose why each authorized state event doesn't match | ||
| 685 | for entry in all_purgatory_states.iter() { | ||
| 686 | let author_hex = entry.event.pubkey.to_hex(); | ||
| 687 | if authorized.contains(&author_hex) { | ||
| 688 | authorized_count += 1; | ||
| 689 | if let Some(reason) = crate::purgatory::diagnose_state_mismatch( | ||
| 690 | &entry.event, | ||
| 691 | &pushed_updates, | ||
| 692 | &local_refs, | ||
| 693 | ) { | ||
| 694 | debug!( | ||
| 695 | "State event {} from authorized author {} doesn't match push: {}", | ||
| 696 | entry.event.id, | ||
| 697 | entry | ||
| 698 | .event | ||
| 699 | .pubkey | ||
| 700 | .to_bech32() | ||
| 701 | .unwrap_or_else(|_| author_hex.clone()), | ||
| 702 | reason | ||
| 703 | ); | ||
| 704 | diagnostic_reasons.push(reason); | ||
| 705 | } | ||
| 706 | } | ||
| 707 | } | ||
| 708 | |||
| 709 | // Create concise WARN message summarizing the rejection | ||
| 710 | let summary = if authorized_count > 0 { | ||
| 711 | let reason_summary = if !diagnostic_reasons.is_empty() { | ||
| 712 | // Take the first diagnostic reason as representative | ||
| 713 | format!(" ({})", diagnostic_reasons[0]) | ||
| 714 | } else { | ||
| 715 | String::new() | ||
| 716 | }; | ||
| 717 | format!( | ||
| 718 | "{} state event{} in purgatory from authorized publisher{} but doesn't match push{}", | ||
| 719 | authorized_count, | ||
| 720 | if authorized_count == 1 { "" } else { "s" }, | ||
| 721 | if authorized_count == 1 { "" } else { "s" }, | ||
| 722 | reason_summary | ||
| 723 | ) | ||
| 724 | } else { | ||
| 725 | format!( | ||
| 726 | "{} state event{} in purgatory but none from authorized publishers", | ||
| 727 | all_purgatory_states.len(), | ||
| 728 | if all_purgatory_states.len() == 1 { | ||
| 729 | "" | ||
| 730 | } else { | ||
| 731 | "s" | ||
| 732 | } | ||
| 733 | ) | ||
| 734 | }; | ||
| 735 | |||
| 736 | warn!("Push rejected for {}: {}", identifier, summary); | ||
| 737 | return Ok(AuthorizationResult::denied(summary)); | ||
| 738 | } else { | ||
| 739 | debug!("No state events found in purgatory for {}", identifier); | ||
| 740 | warn!( | ||
| 741 | "Push rejected for {}: No state events in purgatory", | ||
| 742 | identifier | ||
| 743 | ); | ||
| 744 | return Ok(AuthorizationResult::denied("No state events in purgatory")); | ||
| 745 | } | ||
| 670 | } | 746 | } |
| 671 | 747 | ||
| 672 | // No matching state found in purgatory | 748 | // No matching state found in purgatory |
| 673 | Ok(AuthorizationResult::denied( | 749 | Ok(AuthorizationResult::denied( |
| 674 | "No state event found in purgatory from authorized publishers", | 750 | "No matching state event found in purgatory from authorized publishers", |
| 675 | )) | 751 | )) |
| 676 | } | 752 | } |
| 677 | 753 | ||
diff --git a/src/git/handlers.rs b/src/git/handlers.rs index e3a6ad4..7244abb 100644 --- a/src/git/handlers.rs +++ b/src/git/handlers.rs | |||
| @@ -254,7 +254,7 @@ pub async fn handle_receive_pack( | |||
| 254 | } | 254 | } |
| 255 | 255 | ||
| 256 | // GRASP Authorization Check | 256 | // GRASP Authorization Check |
| 257 | info!( | 257 | debug!( |
| 258 | "Authorizing push for {} owned by {} via database query", | 258 | "Authorizing push for {} owned by {} via database query", |
| 259 | identifier, owner_pubkey | 259 | identifier, owner_pubkey |
| 260 | ); | 260 | ); |
diff --git a/src/purgatory/helpers.rs b/src/purgatory/helpers.rs index 193ef99..a9f6e66 100644 --- a/src/purgatory/helpers.rs +++ b/src/purgatory/helpers.rs | |||
| @@ -225,6 +225,117 @@ pub fn get_unpushed_refs(event: &Event, pushed_refs: &[RefPair]) -> Vec<RefPair> | |||
| 225 | .collect() | 225 | .collect() |
| 226 | } | 226 | } |
| 227 | 227 | ||
| 228 | /// Diagnose why a state event doesn't match the push. | ||
| 229 | /// | ||
| 230 | /// Returns a human-readable explanation of the mismatch between the state event | ||
| 231 | /// and what would result from applying the push to local refs. | ||
| 232 | /// | ||
| 233 | /// # Arguments | ||
| 234 | /// * `event` - The state event to check | ||
| 235 | /// * `pushed_updates` - Ref updates in the current push operation | ||
| 236 | /// * `local_refs` - Refs already existing locally (ref_name -> SHA) | ||
| 237 | /// | ||
| 238 | /// # Returns | ||
| 239 | /// String explaining why the state doesn't match, or None if it matches | ||
| 240 | pub fn diagnose_state_mismatch( | ||
| 241 | event: &Event, | ||
| 242 | pushed_updates: &[RefUpdate], | ||
| 243 | local_refs: &HashMap<String, String>, | ||
| 244 | ) -> Option<String> { | ||
| 245 | let state_refs = extract_refs_from_state(event); | ||
| 246 | |||
| 247 | // Filter local_refs to only branches and tags | ||
| 248 | let mut would_be_state: HashMap<String, String> = local_refs | ||
| 249 | .iter() | ||
| 250 | .filter(|(ref_name, _)| { | ||
| 251 | ref_name.starts_with("refs/heads/") || ref_name.starts_with("refs/tags/") | ||
| 252 | }) | ||
| 253 | .map(|(k, v)| (k.clone(), v.clone())) | ||
| 254 | .collect(); | ||
| 255 | |||
| 256 | // Apply all pushed updates to create the would-be state | ||
| 257 | for update in pushed_updates { | ||
| 258 | // Only process branches and tags | ||
| 259 | if !update.ref_name.starts_with("refs/heads/") && !update.ref_name.starts_with("refs/tags/") | ||
| 260 | { | ||
| 261 | continue; | ||
| 262 | } | ||
| 263 | |||
| 264 | if update.is_deletion() { | ||
| 265 | would_be_state.remove(&update.ref_name); | ||
| 266 | } else { | ||
| 267 | would_be_state.insert(update.ref_name.clone(), update.new_oid.clone()); | ||
| 268 | } | ||
| 269 | } | ||
| 270 | |||
| 271 | // Convert event's state refs to a HashMap for comparison | ||
| 272 | let declared_state: HashMap<String, String> = state_refs | ||
| 273 | .into_iter() | ||
| 274 | .map(|r| (r.ref_name, r.object_sha)) | ||
| 275 | .collect(); | ||
| 276 | |||
| 277 | // Check if they match | ||
| 278 | if would_be_state == declared_state { | ||
| 279 | return None; // No mismatch | ||
| 280 | } | ||
| 281 | |||
| 282 | // Build diagnostic message | ||
| 283 | let mut reasons = Vec::new(); | ||
| 284 | |||
| 285 | // Check for refs in declared state but not in would-be state | ||
| 286 | for (ref_name, declared_sha) in &declared_state { | ||
| 287 | if let Some(would_be_sha) = would_be_state.get(ref_name) { | ||
| 288 | if would_be_sha != declared_sha { | ||
| 289 | let would_be_short = if would_be_sha.len() >= 8 { | ||
| 290 | &would_be_sha[..8] | ||
| 291 | } else { | ||
| 292 | would_be_sha.as_str() | ||
| 293 | }; | ||
| 294 | let declared_short = if declared_sha.len() >= 8 { | ||
| 295 | &declared_sha[..8] | ||
| 296 | } else { | ||
| 297 | declared_sha.as_str() | ||
| 298 | }; | ||
| 299 | reasons.push(format!( | ||
| 300 | "{} would be at {} but state declares {}", | ||
| 301 | ref_name, would_be_short, declared_short | ||
| 302 | )); | ||
| 303 | } | ||
| 304 | } else { | ||
| 305 | let declared_short = if declared_sha.len() >= 8 { | ||
| 306 | &declared_sha[..8] | ||
| 307 | } else { | ||
| 308 | declared_sha.as_str() | ||
| 309 | }; | ||
| 310 | reasons.push(format!( | ||
| 311 | "{} missing (state declares {})", | ||
| 312 | ref_name, declared_short | ||
| 313 | )); | ||
| 314 | } | ||
| 315 | } | ||
| 316 | |||
| 317 | // Check for refs in would-be state but not in declared state | ||
| 318 | for (ref_name, would_be_sha) in &would_be_state { | ||
| 319 | if !declared_state.contains_key(ref_name) { | ||
| 320 | let would_be_short = if would_be_sha.len() >= 8 { | ||
| 321 | &would_be_sha[..8] | ||
| 322 | } else { | ||
| 323 | would_be_sha.as_str() | ||
| 324 | }; | ||
| 325 | reasons.push(format!( | ||
| 326 | "{} would exist at {} but state doesn't declare it", | ||
| 327 | ref_name, would_be_short | ||
| 328 | )); | ||
| 329 | } | ||
| 330 | } | ||
| 331 | |||
| 332 | if reasons.is_empty() { | ||
| 333 | Some("Unknown mismatch".to_string()) | ||
| 334 | } else { | ||
| 335 | Some(reasons.join("; ")) | ||
| 336 | } | ||
| 337 | } | ||
| 338 | |||
| 228 | #[cfg(test)] | 339 | #[cfg(test)] |
| 229 | mod tests { | 340 | mod tests { |
| 230 | use super::*; | 341 | use super::*; |
| @@ -695,4 +806,97 @@ mod tests { | |||
| 695 | // Should return true - real OID exists, symbolic ref skipped | 806 | // Should return true - real OID exists, symbolic ref skipped |
| 696 | assert!(can_apply_state(&event, repo_path)); | 807 | assert!(can_apply_state(&event, repo_path)); |
| 697 | } | 808 | } |
| 809 | |||
| 810 | #[test] | ||
| 811 | fn test_diagnose_state_mismatch_missing_ref() { | ||
| 812 | // State declares both main and test branches | ||
| 813 | let event = create_test_state_event( | ||
| 814 | "test-repo", | ||
| 815 | vec![("refs/heads/main", "abc123"), ("refs/heads/test", "def456")], | ||
| 816 | ); | ||
| 817 | |||
| 818 | // Push only creates test branch | ||
| 819 | let pushed_updates = vec![RefUpdate { | ||
| 820 | old_oid: "0000000000000000000000000000000000000000".to_string(), | ||
| 821 | new_oid: "def456".to_string(), | ||
| 822 | ref_name: "refs/heads/test".to_string(), | ||
| 823 | }]; | ||
| 824 | |||
| 825 | // No local refs | ||
| 826 | let local_refs = HashMap::new(); | ||
| 827 | |||
| 828 | let diagnosis = diagnose_state_mismatch(&event, &pushed_updates, &local_refs); | ||
| 829 | assert!(diagnosis.is_some()); | ||
| 830 | let msg = diagnosis.unwrap(); | ||
| 831 | assert!(msg.contains("refs/heads/main")); | ||
| 832 | assert!(msg.contains("missing")); | ||
| 833 | } | ||
| 834 | |||
| 835 | #[test] | ||
| 836 | fn test_diagnose_state_mismatch_wrong_sha() { | ||
| 837 | // State declares main at abc123 | ||
| 838 | let event = create_test_state_event("test-repo", vec![("refs/heads/main", "abc123")]); | ||
| 839 | |||
| 840 | // Push updates main to different SHA | ||
| 841 | let pushed_updates = vec![RefUpdate { | ||
| 842 | old_oid: "0000000000000000000000000000000000000000".to_string(), | ||
| 843 | new_oid: "wrong123".to_string(), | ||
| 844 | ref_name: "refs/heads/main".to_string(), | ||
| 845 | }]; | ||
| 846 | |||
| 847 | let local_refs = HashMap::new(); | ||
| 848 | |||
| 849 | let diagnosis = diagnose_state_mismatch(&event, &pushed_updates, &local_refs); | ||
| 850 | assert!(diagnosis.is_some()); | ||
| 851 | let msg = diagnosis.unwrap(); | ||
| 852 | assert!(msg.contains("refs/heads/main")); | ||
| 853 | assert!(msg.contains("would be at")); | ||
| 854 | assert!(msg.contains("state declares")); | ||
| 855 | } | ||
| 856 | |||
| 857 | #[test] | ||
| 858 | fn test_diagnose_state_mismatch_extra_ref() { | ||
| 859 | // State declares only main | ||
| 860 | let event = create_test_state_event("test-repo", vec![("refs/heads/main", "abc123")]); | ||
| 861 | |||
| 862 | // Push creates both main and test | ||
| 863 | let pushed_updates = vec![ | ||
| 864 | RefUpdate { | ||
| 865 | old_oid: "0000000000000000000000000000000000000000".to_string(), | ||
| 866 | new_oid: "abc123".to_string(), | ||
| 867 | ref_name: "refs/heads/main".to_string(), | ||
| 868 | }, | ||
| 869 | RefUpdate { | ||
| 870 | old_oid: "0000000000000000000000000000000000000000".to_string(), | ||
| 871 | new_oid: "def456".to_string(), | ||
| 872 | ref_name: "refs/heads/test".to_string(), | ||
| 873 | }, | ||
| 874 | ]; | ||
| 875 | |||
| 876 | let local_refs = HashMap::new(); | ||
| 877 | |||
| 878 | let diagnosis = diagnose_state_mismatch(&event, &pushed_updates, &local_refs); | ||
| 879 | assert!(diagnosis.is_some()); | ||
| 880 | let msg = diagnosis.unwrap(); | ||
| 881 | assert!(msg.contains("refs/heads/test")); | ||
| 882 | assert!(msg.contains("doesn't declare")); | ||
| 883 | } | ||
| 884 | |||
| 885 | #[test] | ||
| 886 | fn test_diagnose_state_mismatch_no_mismatch() { | ||
| 887 | // State declares main | ||
| 888 | let event = create_test_state_event("test-repo", vec![("refs/heads/main", "abc123")]); | ||
| 889 | |||
| 890 | // Push creates main at correct SHA | ||
| 891 | let pushed_updates = vec![RefUpdate { | ||
| 892 | old_oid: "0000000000000000000000000000000000000000".to_string(), | ||
| 893 | new_oid: "abc123".to_string(), | ||
| 894 | ref_name: "refs/heads/main".to_string(), | ||
| 895 | }]; | ||
| 896 | |||
| 897 | let local_refs = HashMap::new(); | ||
| 898 | |||
| 899 | let diagnosis = diagnose_state_mismatch(&event, &pushed_updates, &local_refs); | ||
| 900 | assert!(diagnosis.is_none()); // No mismatch | ||
| 901 | } | ||
| 698 | } | 902 | } |
diff --git a/src/purgatory/mod.rs b/src/purgatory/mod.rs index 8094450..2c278f6 100644 --- a/src/purgatory/mod.rs +++ b/src/purgatory/mod.rs | |||
| @@ -16,7 +16,7 @@ pub mod persistence; | |||
| 16 | pub mod sync; | 16 | pub mod sync; |
| 17 | mod types; | 17 | mod types; |
| 18 | 18 | ||
| 19 | pub use helpers::{can_apply_state, can_satisfy_state, extract_refs_from_state, get_unpushed_refs}; | 19 | pub use helpers::{can_apply_state, can_satisfy_state, diagnose_state_mismatch, extract_refs_from_state, get_unpushed_refs}; |
| 20 | pub use types::{EventSource, PrPurgatoryEntry, RefPair, RefUpdate, StatePurgatoryEntry}; | 20 | pub use types::{EventSource, PrPurgatoryEntry, RefPair, RefUpdate, StatePurgatoryEntry}; |
| 21 | 21 | ||
| 22 | use dashmap::DashMap; | 22 | use dashmap::DashMap; |