diff --git a/integration-tests/tests/integration/fixtures.rs b/integration-tests/tests/integration/fixtures.rs index 91df6f0e36c..df588cffae1 100644 --- a/integration-tests/tests/integration/fixtures.rs +++ b/integration-tests/tests/integration/fixtures.rs @@ -1278,7 +1278,7 @@ fn verify_junit(expected: &ExpectedTestResults, junit_path: &Utf8Path, propertie // Expected JUnit type strings. These match the strings produced by nextest in // junit.rs. The Rust test harness always uses exit code 101 for test failures. const JUNIT_FAIL: &str = "test failure with exit code 101"; -const JUNIT_FAIL_LEAK: &str = "test failure with exit code 101, and leaked handles"; +const JUNIT_FAIL_LEAK: &str = "test failure with exit code 101 (leaked handles)"; const JUNIT_FLAKY_FAIL: &str = "flaky failure"; const JUNIT_ABORT: &str = "test abort"; @@ -1383,7 +1383,7 @@ impl JunitExpectedMessage<'_> { /// /// Expected formats from nextest-runner/src/reporter/aggregator/junit.rs: /// - Fail (exit code, no leak): "test failure with exit code 101" -/// - Fail (exit code, leaked): "test failure with exit code 101, and leaked handles" +/// - Fail (exit code, leaked): "test failure with exit code 101 (leaked handles)" /// - Abort (no leak): "test abort" /// - LeakFail: "test exited with code 0, but leaked handles so was marked failed" /// - Timeout: "test timeout" or "benchmark timeout" diff --git a/nextest-runner/src/reporter/aggregator/junit.rs b/nextest-runner/src/reporter/aggregator/junit.rs index f212d953703..7c6b239534c 100644 --- a/nextest-runner/src/reporter/aggregator/junit.rs +++ b/nextest-runner/src/reporter/aggregator/junit.rs @@ -372,7 +372,7 @@ fn non_success_kind_and_type( } => ( NonSuccessKind::Failure, format!( - "{} abort with leaked handles", + "{} abort (leaked handles)", DisplayUnitKind::new(mode, kind), ), ), @@ -389,7 +389,7 @@ fn non_success_kind_and_type( } => ( NonSuccessKind::Failure, format!( - "{} failure with exit code {code}, and leaked handles", + "{} failure with exit code {code} (leaked handles)", DisplayUnitKind::new(mode, kind), ), ), @@ -727,7 +727,7 @@ mod tests { * error waiting for child process to exit caused by: - huh - * process aborted with signal 15 (SIGTERM), and also leaked handles + * process aborted with signal 15 (SIGTERM) (leaked handles) * thread 'foo' panicked at xyz.rs:40 "}), system_out: None, diff --git a/nextest-runner/src/reporter/displayer/imp.rs b/nextest-runner/src/reporter/displayer/imp.rs index 747b2c538d7..b5d6235aff6 100644 --- a/nextest-runner/src/reporter/displayer/imp.rs +++ b/nextest-runner/src/reporter/displayer/imp.rs @@ -2039,9 +2039,8 @@ impl<'a> DisplayReporterImpl<'a> { DisplayUnitKind::new(self.mode, kind) )?; - let tentative_desc = tentative_result.map(ExecutionResultDescription::from); self.write_info_execution_result( - tentative_desc.as_ref(), + tentative_result.as_ref(), slow_after.is_some(), writer, )?; @@ -2083,8 +2082,7 @@ impl<'a> DisplayReporterImpl<'a> { "{status_str}: {attempt_str}{} ", DisplayUnitKind::new(self.mode, kind) )?; - let result_desc = ExecutionResultDescription::from(*result); - self.write_info_execution_result(Some(&result_desc), slow_after.is_some(), writer)?; + self.write_info_execution_result(Some(result), slow_after.is_some(), writer)?; write!(writer, " after {:.3?}s", time_taken.as_secs_f64())?; if let Some(slow_after) = slow_after { write!( @@ -2106,8 +2104,7 @@ impl<'a> DisplayReporterImpl<'a> { "{status_str}: {attempt_str}{} ", DisplayUnitKind::new(self.mode, kind) )?; - let previous_desc = ExecutionResultDescription::from(*previous_result); - self.write_info_execution_result(Some(&previous_desc), *previous_slow, writer)?; + self.write_info_execution_result(Some(previous_result), *previous_slow, writer)?; writeln!( writer, ", currently {} before next attempt", @@ -2255,9 +2252,7 @@ impl<'a> DisplayReporterImpl<'a> { } Some(ExecutionResultDescription::Fail { failure: FailureDescription::Abort { abort }, - // TODO: show leaked info here like in FailureDescription::ExitCode - // below? - leaked: _, + leaked, }) => { // The errors are shown in the output. write!(writer, "{}", "aborted".style(self.styles.fail))?; @@ -2270,27 +2265,25 @@ impl<'a> DisplayReporterImpl<'a> { write!(writer, ": SIG{s}")?; } } + if *leaked { + write!(writer, " (leaked handles)")?; + } Ok(()) } Some(ExecutionResultDescription::Fail { failure: FailureDescription::ExitCode { code }, leaked, }) => { + write!( + writer, + "{} with exit code {}", + "failed".style(self.styles.fail), + code.style(self.styles.count), + )?; if *leaked { - write!( - writer, - "{} with exit code {}, and leaked handles", - "failed".style(self.styles.fail), - code.style(self.styles.count), - ) - } else { - write!( - writer, - "{} with exit code {}", - "failed".style(self.styles.fail), - code.style(self.styles.count), - ) + write!(writer, " (leaked handles)")?; } + Ok(()) } Some(ExecutionResultDescription::ExecFail) => { write!(writer, "{}", "failed to execute".style(self.styles.fail)) @@ -3698,6 +3691,7 @@ mod tests { let test_name2 = TestCaseName::new("test2"); let test_name3 = TestCaseName::new("test3"); let test_name4 = TestCaseName::new("test4"); + let test_name5 = TestCaseName::new("test5"); let mut out = String::new(); @@ -3743,7 +3737,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 0, - total: 20, + total: 21, // Technically, you won't get setup script and test responses in the // same response, but it's easiest to test in this manner. response: InfoResponse::SetupScript(SetupScriptInfoResponse { @@ -3774,7 +3768,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 1, - total: 20, + total: 21, response: InfoResponse::SetupScript(SetupScriptInfoResponse { stress_index: None, script_id: ScriptId::new(SmolStr::new("setup-slow")).unwrap(), @@ -3804,7 +3798,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 2, - total: 20, + total: 21, response: InfoResponse::SetupScript(SetupScriptInfoResponse { stress_index: None, script_id: ScriptId::new(SmolStr::new("setup-terminating")) @@ -3846,7 +3840,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 3, - total: 20, + total: 21, response: InfoResponse::SetupScript(SetupScriptInfoResponse { stress_index: Some(StressIndex { current: 0, @@ -3862,7 +3856,7 @@ mod tests { // Even if exit_status is 0, the presence of // exec-fail errors should be considered // part of the output. - tentative_result: Some(ExecutionResult::ExecFail), + tentative_result: Some(ExecutionResultDescription::ExecFail), waiting_duration: Duration::from_millis(10467), remaining: Duration::from_millis(335), }, @@ -3882,7 +3876,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 4, - total: 20, + total: 21, response: InfoResponse::SetupScript(SetupScriptInfoResponse { stress_index: Some(StressIndex { current: 1, @@ -3892,8 +3886,8 @@ mod tests { program: "setup-exited".to_owned(), args: args.clone(), state: UnitState::Exited { - result: ExecutionResult::Fail { - failure_status: FailureStatus::ExitCode(1), + result: ExecutionResultDescription::Fail { + failure: FailureDescription::ExitCode { code: 1 }, leaked: true, }, time_taken: Duration::from_millis(9999), @@ -3915,7 +3909,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 5, - total: 20, + total: 21, response: InfoResponse::Test(TestInfoResponse { stress_index: None, test_instance: TestInstanceId { @@ -3944,7 +3938,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 6, - total: 20, + total: 21, response: InfoResponse::Test(TestInfoResponse { stress_index: Some(StressIndex { current: 0, @@ -3979,7 +3973,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 7, - total: 20, + total: 21, response: InfoResponse::Test(TestInfoResponse { stress_index: None, test_instance: TestInstanceId { @@ -4011,7 +4005,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 8, - total: 20, + total: 21, response: InfoResponse::Test(TestInfoResponse { stress_index: Some(StressIndex { current: 1, @@ -4026,7 +4020,7 @@ mod tests { total_attempts: 5, }, state: UnitState::Exited { - result: ExecutionResult::Pass, + result: ExecutionResultDescription::Pass, time_taken: Duration::from_millis(99999), slow_after: Some(Duration::from_millis(33333)), }, @@ -4049,7 +4043,7 @@ mod tests { elapsed: Duration::ZERO, kind: TestEventKind::InfoResponse { index: 9, - total: 20, + total: 21, response: InfoResponse::Test(TestInfoResponse { stress_index: None, test_instance: TestInstanceId { @@ -4064,7 +4058,7 @@ mod tests { total_attempts: 5, }, state: UnitState::DelayBeforeNextAttempt { - previous_result: ExecutionResult::ExecFail, + previous_result: ExecutionResultDescription::ExecFail, previous_slow: true, waiting_duration: Duration::from_millis(1234), remaining: Duration::from_millis(5678), @@ -4085,6 +4079,43 @@ mod tests { }) .unwrap(); + // A test that was aborted by a signal and leaked handles. + reporter + .write_event(&TestEvent { + timestamp: Local::now().into(), + elapsed: Duration::ZERO, + kind: TestEventKind::InfoResponse { + index: 10, + total: 21, + response: InfoResponse::Test(TestInfoResponse { + stress_index: None, + test_instance: TestInstanceId { + binary_id: &binary_id, + test_name: &test_name5, + }, + retry_data: RetryData { + attempt: 1, + total_attempts: 1, + }, + state: UnitState::Exited { + result: ExecutionResultDescription::Fail { + failure: FailureDescription::Abort { + abort: AbortDescription::UnixSignal { + signal: 11, + name: Some("SEGV".into()), + }, + }, + leaked: true, + }, + time_taken: Duration::from_millis(5678), + slow_after: None, + }, + output: make_split_output(None, "segfault output", ""), + }), + }, + }) + .unwrap(); + reporter .write_event(&TestEvent { timestamp: Local::now().into(), diff --git a/nextest-runner/src/reporter/displayer/snapshots/nextest_runner__reporter__displayer__imp__tests__info_response_output.snap b/nextest-runner/src/reporter/displayer/snapshots/nextest_runner__reporter__displayer__imp__tests__info_response_output.snap index c230bb00cb4..ea570b55ef0 100644 --- a/nextest-runner/src/reporter/displayer/snapshots/nextest_runner__reporter__displayer__imp__tests__info_response_output.snap +++ b/nextest-runner/src/reporter/displayer/snapshots/nextest_runner__reporter__displayer__imp__tests__info_response_output.snap @@ -5,7 +5,7 @@ expression: out ──────────── info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being leaky), 1 exec failed, 1 timed out, 5 skipped in 0.000s -* 1/20: setup: setup arg1 arg2 +* 1/21: setup: setup arg1 arg2 status: script running for 1.234s as PID 4567 stdout: script stdout 1 @@ -15,7 +15,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 2/20: setup-slow: setup-slow arg1 arg2 +* 2/21: setup-slow: setup-slow arg1 arg2 status: script running for 1.234s as PID 4568 (marked slow after 1.000s) errors: error reading standard output @@ -27,7 +27,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 3/20: setup-terminating: setup-terminating arg1 arg2 +* 3/21: setup-terminating: setup-terminating arg1 arg2 status: terminating script PID 5094 due to signal (script ran for 1.234s) note: fake termination method; spent 6.789s waiting for script to exit, will kill after another 9.786s errors: @@ -47,7 +47,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 4/20: [1] setup-exiting: setup-exiting arg1 arg2 +* 4/21: [1] setup-exiting: setup-exiting arg1 arg2 status: script failed to execute after 1.234s (marked slow after 1.000s) note: spent 10.467s waiting for script PID 9987 to shut down, will mark as leaky after another 0.335s errors: @@ -58,8 +58,8 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 5/20: [2/3] setup-exited: setup-exited arg1 arg2 - status: script failed with exit code 1, and leaked handles after 9.999s (marked slow after 3.000s) +* 5/21: [2/3] setup-exited: setup-exited arg1 arg2 + status: script failed with exit code 1 (leaked handles) after 9.999s (marked slow after 3.000s) errors: error spawning child process caused by: @@ -68,7 +68,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 6/20: my-binary-id test1 +* 6/21: my-binary-id test1 status: test running for 0.400s as PID 12345 stdout: abc @@ -78,7 +78,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 7/20: [1] my-binary-id test2 +* 7/21: [1] my-binary-id test2 status: (attempt 2/3) terminating test PID 12346 due to timeout (test ran for 99.999s) note: fake termination method; spent 6.789s waiting for test to exit, will kill after another 9.786s stdout: @@ -89,7 +89,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 8/20: my-binary-id test3 +* 8/21: my-binary-id test3 status: (attempt 2/3) test failed with unknown status after 99.999s (marked slow after 33.333s) stdout: abc @@ -99,7 +99,7 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 9/20: [2/3] my-binary-id test4 +* 9/21: [2/3] my-binary-id test4 status: test passed after 99.999s (marked slow after 33.333s) errors: error waiting for child process to exit @@ -113,9 +113,17 @@ info: 30 running, 17 passed (4 slow, 2 flaky, 1 leaky), 2 failed (2 due to being ──────── -* 10/20: my-binary-id test4 +* 10/21: my-binary-id test4 status: (attempt 1/5) test failed to execute, currently waiting before next attempt note: waited 1.234s so far, will wait another 5.678s before retrying test +──────── + +* 11/21: my-binary-id test5 + status: test aborted with signal 11: SIGSEGV (leaked handles) after 5.678s + stdout: + segfault output + + info: missing 2 responses ──────────── diff --git a/nextest-runner/src/reporter/error_description.rs b/nextest-runner/src/reporter/error_description.rs index 387465cf536..c15e2dc1992 100644 --- a/nextest-runner/src/reporter/error_description.rs +++ b/nextest-runner/src/reporter/error_description.rs @@ -160,7 +160,7 @@ impl fmt::Display for UnitAbortDescription { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { write!(f, "process {}", self.description)?; if self.leaked { - write!(f, ", and also leaked handles")?; + write!(f, " (leaked handles)")?; } Ok(()) } diff --git a/nextest-runner/src/reporter/events.rs b/nextest-runner/src/reporter/events.rs index b335c04e79f..0bd1ab39283 100644 --- a/nextest-runner/src/reporter/events.rs +++ b/nextest-runner/src/reporter/events.rs @@ -2422,7 +2422,7 @@ pub enum UnitState { /// /// None means that the exit status could not be read, and should be /// treated as a failure. - tentative_result: Option, + tentative_result: Option, /// How long has been spent waiting for the process to exit. waiting_duration: Duration, @@ -2437,7 +2437,7 @@ pub enum UnitState { /// The unit has finished running and the process has exited. Exited { /// The result of executing the unit. - result: ExecutionResult, + result: ExecutionResultDescription, /// The amount of time the unit ran for. time_taken: Duration, @@ -2451,7 +2451,7 @@ pub enum UnitState { /// started. (Only relevant for tests.) DelayBeforeNextAttempt { /// The previous execution result. - previous_result: ExecutionResult, + previous_result: ExecutionResultDescription, /// Whether the previous attempt was marked as slow. previous_slow: bool, diff --git a/nextest-runner/src/runner/executor.rs b/nextest-runner/src/runner/executor.rs index 74336473b62..525ba14546f 100644 --- a/nextest-runner/src/runner/executor.rs +++ b/nextest-runner/src/runner/executor.rs @@ -25,8 +25,9 @@ use crate::{ errors::{ChildError, ChildFdError, ChildStartError, ErrorList}, list::{TestExecuteContext, TestInstance, TestInstanceWithSettings, TestList}, reporter::events::{ - ExecutionResult, FailureStatus, InfoResponse, RetryData, SetupScriptInfoResponse, - StressIndex, TestInfoResponse, TestSlotAssignment, UnitKind, UnitState, + ExecutionResult, ExecutionResultDescription, FailureStatus, InfoResponse, RetryData, + SetupScriptInfoResponse, StressIndex, TestInfoResponse, TestSlotAssignment, UnitKind, + UnitState, }, runner::{ ExecutorEvent, InternalExecuteStatus, InternalSetupScriptExecuteStatus, @@ -325,8 +326,9 @@ impl<'a> ExecutorContext<'a> { .next() .expect("backoff delay must be non-empty"); - // Capture the internal result before converting to external. - let previous_result = run_status.result; + // Convert the internal result to a platform-independent + // description before converting to external. + let previous_result = ExecutionResultDescription::from(run_status.result); let run_status = run_status.into_external(); let previous_slow = run_status.is_slow; @@ -624,12 +626,21 @@ impl<'a> ExecutorContext<'a> { } }; - // Build a tentative status using status and the exit status. - let tentative_status = status.or_else(|| { - res.as_ref().ok().map(|res| { - create_execution_result(*res, &child_acc.errors, false, LeakTimeoutResult::Pass) + // Build a tentative status using status and the exit status, + // then convert to a platform-independent description for info + // responses. + let tentative_status = status + .or_else(|| { + res.as_ref().ok().map(|res| { + create_execution_result( + *res, + &child_acc.errors, + false, + LeakTimeoutResult::Pass, + ) + }) }) - }); + .map(ExecutionResultDescription::from); let leak_info = detect_fd_leaks( &cx, @@ -1044,12 +1055,21 @@ impl<'a> ExecutorContext<'a> { }; }; - // Build a tentative status using status and the exit status. - let tentative_status = status.or_else(|| { - res.as_ref().ok().map(|res| { - create_execution_result(*res, &child_acc.errors, false, LeakTimeoutResult::Pass) + // Build a tentative status using status and the exit status, + // then convert to a platform-independent description for info + // responses. + let tentative_status = status + .or_else(|| { + res.as_ref().ok().map(|res| { + create_execution_result( + *res, + &child_acc.errors, + false, + LeakTimeoutResult::Pass, + ) + }) }) - }); + .map(ExecutionResultDescription::from); let leak_info = if self.interceptor.should_skip_leak_detection() { // Skip leak detection when running under an interceptor. @@ -1366,7 +1386,7 @@ fn drain_req_rx<'a>( async fn handle_delay_between_attempts<'a>( packet: &TestPacket<'a>, - previous_result: ExecutionResult, + previous_result: ExecutionResultDescription, previous_slow: bool, delay: Duration, req_rx: &mut UnboundedReceiver>, @@ -1413,7 +1433,7 @@ async fn handle_delay_between_attempts<'a>( _ = tx.send( packet.info_response( UnitState::DelayBeforeNextAttempt { - previous_result, + previous_result: previous_result.clone(), previous_slow, waiting_duration: waiting_snapshot.active, remaining: delay @@ -1464,7 +1484,7 @@ async fn detect_fd_leaks<'a>( cx: &UnitContext<'a>, child_pid: u32, child_acc: &mut ChildAccumulator, - tentative_result: Option, + tentative_result: Option, leak_timeout: LeakTimeout, stopwatch: &mut StopwatchStart, req_rx: &mut UnboundedReceiver>, @@ -1510,7 +1530,7 @@ async fn detect_fd_leaks<'a>( pid: child_pid, time_taken: stopwatch.snapshot().active, slow_after: cx.slow_after, - tentative_result, + tentative_result: tentative_result.clone(), waiting_duration: snapshot.active, remaining: leak_timeout.period .checked_sub(snapshot.active) diff --git a/nextest-runner/src/runner/internal_events.rs b/nextest-runner/src/runner/internal_events.rs index e47678bb723..d653aff4c0d 100644 --- a/nextest-runner/src/runner/internal_events.rs +++ b/nextest-runner/src/runner/internal_events.rs @@ -20,8 +20,9 @@ use crate::{ TestOutputDisplay, UnitErrorDescription, events::{ ChildExecutionOutputDescription, ErrorSummary, ExecuteStatus, ExecutionResult, - InfoResponse, OutputErrorSlice, RetryData, SetupScriptEnvMap, SetupScriptExecuteStatus, - StressIndex, TestSlotAssignment, UnitKind, UnitState, + ExecutionResultDescription, InfoResponse, OutputErrorSlice, RetryData, + SetupScriptEnvMap, SetupScriptExecuteStatus, StressIndex, TestSlotAssignment, UnitKind, + UnitState, }, }, signal::ShutdownEvent, @@ -142,7 +143,7 @@ impl<'a> UnitExecuteStatus<'a, '_> { match self { Self::Test(status) => status.test.info_response( UnitState::Exited { - result: status.result, + result: ExecutionResultDescription::from(status.result), time_taken: status.stopwatch_end.active, slow_after: status.slow_after, }, @@ -150,7 +151,7 @@ impl<'a> UnitExecuteStatus<'a, '_> { ), Self::SetupScript(status) => status.script.info_response( UnitState::Exited { - result: status.result, + result: ExecutionResultDescription::from(status.result), time_taken: status.stopwatch_end.active, slow_after: status.slow_after, },