From b0f92d01fc4928946709be4c20b20d58d82b3526 Mon Sep 17 00:00:00 2001 From: Philipp Schuster Date: Wed, 13 May 2026 10:57:32 +0200 Subject: [PATCH] tests: avoid event wait log spam Event expectation helpers print detailed diagnostics when the observed event stream does not match the expected one. That is useful for direct assertions, but it becomes extremely noisy [0] when the helper is used as the predicate for wait_until(), because every polling attempt emits the full mismatch dump. Add quiet wait wrappers for event polling and emit the existing detailed diagnostics only once after the timeout expires. [0] https://github.com/cloud-hypervisor/cloud-hypervisor/actions/runs/25745401604/job/75619840718?pr=8021 On-behalf-of: Philipp Schuster@sap.com Signed-off-by: Philipp Schuster --- .../tests/common/tests_wrappers.rs | 24 ++-- cloud-hypervisor/tests/common/utils.rs | 76 ++++++++-- cloud-hypervisor/tests/integration.rs | 136 +++++++++++------- 3 files changed, 164 insertions(+), 72 deletions(-) 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);