diff --git a/library/src/cache/patch_manager.rs b/library/src/cache/patch_manager.rs index 1ae7c67..4c6ca7a 100644 --- a/library/src/cache/patch_manager.rs +++ b/library/src/cache/patch_manager.rs @@ -51,6 +51,11 @@ struct PatchesState { /// - the system initializes (on_init, we take this to mean the patch failed to boot) currently_booting_patch: Option, + /// Unix timestamp (seconds) when the current boot attempt started. + /// Used to compute elapsed time in crash recovery diagnostics. + /// Added in 1.6.93; older state files will deserialize this as None. + boot_started_at: Option, + /// A list of patch numbers that we have tried and failed to install. /// We should never attempt to download or install these again for the /// current release. @@ -89,6 +94,9 @@ pub trait ManagePatches { /// the system crashed). fn currently_booting_patch(&self) -> Option; + /// Unix timestamp (seconds) when the current boot attempt started, if known. + fn boot_started_at(&self) -> Option; + /// Returns the next patch to boot, or None if: /// - no patches have been downloaded /// - we cannot boot from the patch(es) on disk @@ -444,6 +452,10 @@ impl ManagePatches for PatchManager { .map(|patch| self.patch_info_for_number(patch.number)) } + fn boot_started_at(&self) -> Option { + self.patches_state.boot_started_at + } + fn validate_next_boot_patch(&mut self) -> anyhow::Result<()> { let next_boot_patch = match self.patches_state.next_boot_patch.clone() { Some(patch) => patch, @@ -492,6 +504,7 @@ impl ManagePatches for PatchManager { } self.patches_state.currently_booting_patch = Some(next_boot_patch.clone()); + self.patches_state.boot_started_at = Some(crate::time::unix_timestamp()); self.save_patches_state() } @@ -503,6 +516,7 @@ impl ManagePatches for PatchManager { .context("No currently_booting_patch")?; self.patches_state.currently_booting_patch = None; + self.patches_state.boot_started_at = None; self.patches_state.last_booted_patch = Some(boot_patch.clone()); if let Err(e) = self.delete_patch_artifacts_older_than(boot_patch.number) { shorebird_error!( @@ -516,6 +530,7 @@ impl ManagePatches for PatchManager { fn record_boot_failure_for_patch(&mut self, patch_number: usize) -> Result<()> { self.patches_state.currently_booting_patch = None; + self.patches_state.boot_started_at = None; self.patches_state.known_bad_patches.insert(patch_number); self.try_fall_back_from_patch(patch_number) } @@ -597,7 +612,7 @@ mod debug_tests { PatchVerificationMode::default(), ); let actual = format!("{:?}", patch_manager); - assert!(actual.contains(r#"patches_state: PatchesState { last_booted_patch: None, next_boot_patch: None, currently_booting_patch: None, known_bad_patches: {} }, patch_public_key: Some("public_key")"#)); + assert!(actual.contains(r#"patches_state: PatchesState { last_booted_patch: None, next_boot_patch: None, currently_booting_patch: None, boot_started_at: None, known_bad_patches: {} }, patch_public_key: Some("public_key")"#)); } } diff --git a/library/src/cache/updater_state.rs b/library/src/cache/updater_state.rs index 3233190..f5d0d47 100644 --- a/library/src/cache/updater_state.rs +++ b/library/src/cache/updater_state.rs @@ -219,6 +219,11 @@ impl UpdaterState { self.patch_manager.currently_booting_patch() } + /// Unix timestamp (seconds) when the current boot attempt started, if known. + pub fn boot_started_at(&self) -> Option { + self.patch_manager.boot_started_at() + } + /// The last patch that was successfully booted (e.g., for which we record_boot_success was /// called). /// Will be None if: diff --git a/library/src/updater.rs b/library/src/updater.rs index 034489f..cd3cd4d 100644 --- a/library/src/updater.rs +++ b/library/src/updater.rs @@ -224,19 +224,29 @@ pub fn handle_prior_boot_failure_if_necessary() -> Result<(), InitError> { config.patch_verification, ); if let Some(patch) = state.currently_booting_patch() { + let boot_time_info = match state.boot_started_at() { + Some(ts) => format!("boot_started_at={ts}"), + None => "boot_started_at=unknown".to_string(), + }; + + let file_info = match std::fs::metadata(&patch.path) { + Ok(meta) => format!("file_ok=true,file_size={}", meta.len()), + Err(_) => "file_ok=false,file_missing".to_string(), + }; + + let now = crate::time::unix_timestamp(); + let message = format!( + "crash_recovery: patch {} failed to boot (detected_at={now},{boot_time_info},{file_info})", + patch.number + ); + state.record_boot_failure_for_patch(patch.number)?; state.queue_event(PatchEvent::new( config, EventType::PatchInstallFailure, patch.number, state.client_id(), - Some( - format!( - "Patch {} was marked currently_booting in init", - patch.number - ) - .as_ref(), - ), + Some(&message), ))?; } @@ -838,18 +848,13 @@ pub fn report_launch_failure() -> anyhow::Result<()> { shorebird_error!("Failed to mark patch as bad: {:?}", mark_result); } let client_id = state.client_id(); + let message = format!("engine_report: patch {} failed to launch", patch.number); let event = PatchEvent::new( config, EventType::PatchInstallFailure, patch.number, client_id, - Some( - format!( - "Install failure reported from engine for patch {}", - patch.number - ) - .as_ref(), - ), + Some(&message), ); // Queue the failure event for later sending since right after this // function returns the Flutter engine is likely to abort(). @@ -1692,7 +1697,7 @@ patch_verification: bogus_mode platform: current_platform().to_string(), release_version: config.release_version.clone(), timestamp: time::unix_timestamp(), - message: Some("Install failure reported from engine for patch 1".to_string()), + message: Some("engine_report: patch 1 failed to launch".to_string()), }; // Queue 5 events. assert!(state.queue_event(fail_event.clone()).is_ok()); @@ -2913,6 +2918,94 @@ mod state_recovery_tests { crate::events::EventType::PatchInstallFailure ); assert_eq!(events[0].patch_number, 1); + let message = events[0].message.as_ref().unwrap(); + assert!( + message.starts_with("crash_recovery: patch 1 failed to boot"), + "unexpected message: {message}" + ); + assert!( + message.contains("detected_at="), + "message should include detection time: {message}" + ); + assert!( + message.contains("boot_started_at="), + "message should include boot start time: {message}" + ); + assert!( + message.contains("file_ok="), + "message should include file status: {message}" + ); + Ok(()) + })?; + + Ok(()) + } + + /// Crash recovery when the patch file was deleted before recovery runs. + /// The message should report file_ok=false,file_missing. + #[serial] + #[test] + fn crash_recovery_with_missing_file() -> Result<()> { + let tmp_dir = TempDir::new().unwrap(); + init_for_testing(&tmp_dir, None); + + install_fake_patch(1)?; + report_launch_start()?; + + // Delete the patch artifact to simulate file going missing. + let patches_dir = tmp_dir.path().join("patches"); + std::fs::remove_dir_all(&patches_dir)?; + + // Reinitialize — triggers crash recovery. + init_for_testing(&tmp_dir, None); + + with_state(|state| { + let events = state.copy_events(10); + assert_eq!(events.len(), 1); + let message = events[0].message.as_ref().unwrap(); + assert!( + message.contains("file_ok=false,file_missing"), + "expected file_missing in message: {message}" + ); + Ok(()) + })?; + + Ok(()) + } + + /// Crash recovery when boot_started_at is not set (old state file format). + /// The message should report elapsed_secs=unknown. + #[serial] + #[test] + fn crash_recovery_without_boot_timestamp() -> Result<()> { + let tmp_dir = TempDir::new().unwrap(); + init_for_testing(&tmp_dir, None); + + install_fake_patch(1)?; + report_launch_start()?; + + // Manually clear boot_started_at from the state file to simulate + // an old state format that doesn't have this field. + let state_path = tmp_dir.path().join("patches_state.json"); + let state_json = std::fs::read_to_string(&state_path)?; + let mut state_value: serde_json::Value = serde_json::from_str(&state_json)?; + state_value + .as_object_mut() + .unwrap() + .remove("boot_started_at"); + std::fs::write(&state_path, serde_json::to_string(&state_value)?)?; + + // Reinitialize — triggers crash recovery. + init_for_testing(&tmp_dir, None); + + with_state(|state| { + let events = state.copy_events(10); + assert_eq!(events.len(), 1); + let message = events[0].message.as_ref().unwrap(); + assert!( + message.contains("boot_started_at=unknown"), + "expected boot_started_at=unknown in message: {message}" + ); Ok(()) })?;