kata-containers/cloud-hypervisor
1
0
Fork 0
mirror of https://github.com/cloud-hypervisor/cloud-hypervisor.git synced 2026-08-05 02:19:16 +00:00
Code Issues Packages Projects Releases Wiki Activity

tests: avoid event wait log spam

Browse Source 
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 <philipp.schuster@cyberus-technology.de>
This commit is contained in:
Philipp Schuster
2026-05-13 10:57:32 +02:00
committed by Bo Chen
parent 96c83168a1
commit b0f92d01fc
3 changed files with 164 additions and 72 deletions
Download Patch File Download Diff File Expand all files Collapse all files

24
cloud-hypervisor/tests/common/tests_wrappers.rs
View File

@@ -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);

76
cloud-hypervisor/tests/common/utils.rs
View File

@@ -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<serde_json::Value> {
let content = fs::read(event_file).unwrap();
let mut ret = Vec::new();
@@ -502,9 +502,34 @@ fn parse_event_file(event_file: &str) -> Vec<serde_json::Value> {
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;
}

136
cloud-hypervisor/tests/integration.rs
View File

@@ -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);