diff --git a/cloud-hypervisor/tests/common/tests_wrappers.rs b/cloud-hypervisor/tests/common/tests_wrappers.rs index d1d055254..693702b55 100644 --- a/cloud-hypervisor/tests/common/tests_wrappers.rs +++ b/cloud-hypervisor/tests/common/tests_wrappers.rs @@ -1059,9 +1059,11 @@ pub(crate) fn _test_virtio_fs( event: "device-removed".to_string(), device_id: Some("myfs0".to_string()), }; - assert!(wait_until(Duration::from_secs(10), || { - check_sequential_events(&[&removed_event], &event_path) - })); + assert!(wait_for_sequential_events( + Duration::from_secs(10), + &[&removed_event], + &event_path + )); } }); @@ -1635,9 +1637,11 @@ pub(crate) fn _test_simple_launch(guest: &Guest) { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(20), || { - check_latest_events_exact(&latest_events, &event_path) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(20), + &latest_events, + &event_path + )); }); kill_child(&mut child); @@ -3173,9 +3177,11 @@ pub(crate) fn _test_pvpanic(guest: &Guest) { event: "panic".to_string(), device_id: None, }]; - assert!(wait_until(Duration::from_secs(10), || { - check_latest_events_exact(&expected_sequential_events, &event_path) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(10), + &expected_sequential_events, + &event_path + )); }); kill_child(&mut child); diff --git a/cloud-hypervisor/tests/common/utils.rs b/cloud-hypervisor/tests/common/utils.rs index fe22d5230..f5747f310 100644 --- a/cloud-hypervisor/tests/common/utils.rs +++ b/cloud-hypervisor/tests/common/utils.rs @@ -486,8 +486,8 @@ pub(crate) fn fw_path(_fw_type: FwType) -> String { fw_path.to_str().unwrap().to_string() } -// Parse the event_monitor file based on the format that each event -// is followed by a double newline +/// Parse the event_monitor file based on the format that each event +/// is followed by a double newline fn parse_event_file(event_file: &str) -> Vec { let content = fs::read(event_file).unwrap(); let mut ret = Vec::new(); @@ -502,9 +502,34 @@ fn parse_event_file(event_file: &str) -> Vec { ret } -// Return true if all events from the input 'expected_events' are matched sequentially -// with events from the 'event_file' +/// Return true if all events from the input 'expected_events' are matched sequentially +/// with events from the 'event_file' pub(crate) fn check_sequential_events(expected_events: &[&MetaEvent], event_file: &str) -> bool { + check_sequential_events_with_options(expected_events, event_file, true) +} + +/// Wait for a sequential event match and print diagnostics only after timeout. +pub(crate) fn wait_for_sequential_events( + timeout: Duration, + expected_events: &[&MetaEvent], + event_file: &str, +) -> bool { + if wait_until(timeout, || { + check_sequential_events_with_options(expected_events, event_file, false) + }) { + return true; + } + + check_sequential_events(expected_events, event_file); + false +} + +/// Check sequential events with optional mismatch diagnostics. +fn check_sequential_events_with_options( + expected_events: &[&MetaEvent], + event_file: &str, + print_diagnostics: bool, +) -> bool { if !Path::new(event_file).exists() { return false; } @@ -522,7 +547,7 @@ pub(crate) fn check_sequential_events(expected_events: &[&MetaEvent], event_file let ret = idx == len; - if !ret { + if !ret && print_diagnostics { eprintln!( "\n\n==== Start 'check_sequential_events' failed ==== \ \n\nexpected_events={expected_events:?}\nactual_events={json_events:?} \ @@ -563,9 +588,34 @@ pub(crate) fn check_sequential_events_exact( true } -// Return true if events from the input 'latest_events' are matched exactly -// with the most recent events from the 'event_file' +/// Return true if events from the input 'latest_events' are matched exactly +/// with the most recent events from the 'event_file' pub(crate) fn check_latest_events_exact(latest_events: &[&MetaEvent], event_file: &str) -> bool { + check_latest_events_exact_with_options(latest_events, event_file, true) +} + +/// Wait for an exact latest-event match and print diagnostics only after timeout. +pub(crate) fn wait_for_latest_events_exact( + timeout: Duration, + latest_events: &[&MetaEvent], + event_file: &str, +) -> bool { + if wait_until(timeout, || { + check_latest_events_exact_with_options(latest_events, event_file, false) + }) { + return true; + } + + check_latest_events_exact(latest_events, event_file); + false +} + +/// Check latest events with optional mismatch diagnostics. +fn check_latest_events_exact_with_options( + latest_events: &[&MetaEvent], + event_file: &str, + print_diagnostics: bool, +) -> bool { if !Path::new(event_file).exists() { return false; } @@ -577,11 +627,13 @@ pub(crate) fn check_latest_events_exact(latest_events: &[&MetaEvent], event_file for (idx, e) in json_events.iter().enumerate() { if !latest_events[idx].match_with_json_event(e) { - eprintln!( - "\n\n==== Start 'check_latest_events_exact' failed ==== \ - \n\nexpected_events={latest_events:?}\nactual_events={json_events:?} \ - \n\n==== End 'check_latest_events_exact' failed ====", - ); + if print_diagnostics { + eprintln!( + "\n\n==== Start 'check_latest_events_exact' failed ==== \ + \n\nexpected_events={latest_events:?}\nactual_events={json_events:?} \ + \n\n==== End 'check_latest_events_exact' failed ====", + ); + } return false; } diff --git a/cloud-hypervisor/tests/integration.rs b/cloud-hypervisor/tests/integration.rs index 0411820c5..7b085a487 100644 --- a/cloud-hypervisor/tests/integration.rs +++ b/cloud-hypervisor/tests/integration.rs @@ -5783,9 +5783,11 @@ mod common_parallel { event: "panic".to_string(), device_id: None, }]; - assert!(wait_until(Duration::from_secs(3), || { - check_latest_events_exact(&expected_sequential_events, &event_path) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(3), + &expected_sequential_events, + &event_path + )); }); kill_child(&mut child); @@ -7537,9 +7539,11 @@ mod ivshmem { device_id: None, }]; // Wait for the restored event to show up in the monitor file. - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); // Remove the snapshot dir let _ = remove_dir_all(snapshot_dir.as_str()); @@ -7562,9 +7566,11 @@ mod ivshmem { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); // Check the number of vCPUs assert_eq!(guest.get_cpu_count().unwrap_or_default(), 2); @@ -7663,9 +7669,11 @@ mod snapshot_restore_common { }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, event_path) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + event_path + )); // Take a snapshot from the VM assert!(remote_command( @@ -7685,9 +7693,11 @@ mod snapshot_restore_common { }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, event_path) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + event_path + )); } pub(crate) fn _test_snapshot_restore(use_hotplug: bool, use_resume_option: bool) { @@ -7800,9 +7810,11 @@ mod snapshot_restore_common { event: "device-removed".to_string(), device_id: Some(net_id.to_string()), }]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path + )); // Plug the virtio-net device again assert!(remote_command( @@ -7874,9 +7886,11 @@ mod snapshot_restore_common { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_sequential_events(&expected_events, &event_path_restored) - })); + assert!(wait_for_sequential_events( + Duration::from_secs(30), + &expected_events, + &event_path_restored + )); if use_resume_option { let latest_events = [ &MetaEvent { @@ -7892,17 +7906,21 @@ mod snapshot_restore_common { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); } else { let latest_events = [&MetaEvent { event: "restored".to_string(), device_id: None, }]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); } // Wait until the restored VM API is ready before issuing follow-up requests. @@ -7938,9 +7956,11 @@ mod snapshot_restore_common { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); } // Perform same checks to validate VM has been properly restored @@ -8062,9 +8082,11 @@ mod snapshot_restore_common { device_id: None, }]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); let r = std::panic::catch_unwind(|| { assert!(wait_until(Duration::from_secs(30), || remote_command( @@ -8084,9 +8106,11 @@ mod snapshot_restore_common { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); assert_eq!(guest.get_cpu_count().unwrap_or_default(), 4); assert!(guest.get_total_memory().unwrap_or_default() > min_total_memory_kib); @@ -8191,9 +8215,11 @@ mod snapshot_restore_common { event: "restored".to_string(), device_id: None, }]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); let _ = remove_dir_all(snapshot_dir.as_str()); @@ -8214,9 +8240,11 @@ mod snapshot_restore_common { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); assert_eq!(guest.get_cpu_count().unwrap_or_default(), 2); guest.check_devices_common(Some(&socket), Some(&console_text), None); @@ -8451,16 +8479,20 @@ mod common_sequential { }, ]; // Wait for the restore event sequence to be recorded. - assert!(wait_until(Duration::from_secs(30), || { - check_sequential_events(&expected_events, &event_path_restored) - })); + assert!(wait_for_sequential_events( + Duration::from_secs(30), + &expected_events, + &event_path_restored + )); let latest_events = [&MetaEvent { event: "restored".to_string(), device_id: None, }]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); // Remove the snapshot dir let _ = remove_dir_all(snapshot_dir.as_str()); @@ -8484,9 +8516,11 @@ mod common_sequential { device_id: None, }, ]; - assert!(wait_until(Duration::from_secs(30), || { - check_latest_events_exact(&latest_events, &event_path_restored) - })); + assert!(wait_for_latest_events_exact( + Duration::from_secs(30), + &latest_events, + &event_path_restored + )); // Perform same checks to validate VM has been properly restored assert_eq!(guest.get_cpu_count().unwrap_or_default(), n_cpu);