From cdff4da4135127d185b55941533b78cd3a115ead Mon Sep 17 00:00:00 2001 From: Sankalp Thakur Date: Sat, 1 Aug 2026 14:30:11 +0530 Subject: [PATCH 1/2] tests/tail: speed up follow/retry tests with event-based waits Replace fixed multi-second sleeps in the slowest test_tail::* cases with polling helpers that return as soon as the expected stdout/stderr appears. Also add short -s.1/--max-unchanged-stats=1 where follow/polling latency was dominated by the default 1s sleep interval. Helpers added to UChild (non-consuming peeks + wait_until / wait_for_{stdout,stderr}_contains / wait_until_exited) keep later assertions intact while allowing generous timeouts for slow CI. Fixes #10097 AI disclosure: this change was developed with AI assistance (Grok). I reviewed the full diff and the approach (event-based waits rather than shorter fixed sleeps) follows maintainer guidance on the issue. --- tests/by-util/test_tail.rs | 367 +++++++++++++++++++++------------- tests/uutests/src/lib/util.rs | 133 ++++++++++++ 2 files changed, 364 insertions(+), 136 deletions(-) diff --git a/tests/by-util/test_tail.rs b/tests/by-util/test_tail.rs index 11480021a06..70adbd92302 100644 --- a/tests/by-util/test_tail.rs +++ b/tests/by-util/test_tail.rs @@ -37,6 +37,7 @@ use std::io::{Seek, SeekFrom}; ))] use std::path::Path; use std::process::Stdio; +use std::time::Duration; use tail::chunks::BUFFER_SIZE as CHUNK_BUFFER_SIZE; #[cfg(all( not(target_vendor = "apple"), @@ -74,6 +75,10 @@ const DEFAULT_SLEEP_INTERVAL_MILLIS: u64 = 1500; #[cfg(not(target_vendor = "apple"))] const DEFAULT_SLEEP_INTERVAL_MILLIS: u64 = 1000; +/// Generous upper bound for event-based waits. Tests return as soon as the +/// expected output appears, so the common case is far below this timeout. +const WAIT_TIMEOUT: Duration = Duration::from_secs(5); + // The binary integer "10000000" is *not* a valid UTF-8 encoding // of a character: https://en.wikipedia.org/wiki/UTF-8#Encoding #[cfg(unix)] @@ -503,12 +508,16 @@ fn test_null_default() { fn test_follow_single() { let (at, mut ucmd) = at_and_ucmd!(); - let mut child = ucmd.arg("-f").arg(FOOBAR_TXT).run_no_wait(); + let mut child = ucmd + .args(&["-f", "-s.1", "--max-unchanged-stats=1", FOOBAR_TXT]) + .run_no_wait(); let expected_fixture = "foobar_single_default.expected"; + let initial = at.read(expected_fixture); child - .make_assertion_with_delay(200) + .wait_for_stdout_contains(&initial, WAIT_TIMEOUT) + .make_assertion() .is_alive() .with_current_output() .stdout_only_fixture(expected_fixture); @@ -518,7 +527,8 @@ fn test_follow_single() { at.append(FOOBAR_TXT, expected); child - .make_assertion_with_delay(DEFAULT_SLEEP_INTERVAL_MILLIS) + .wait_for_stdout_contains(expected, WAIT_TIMEOUT) + .make_assertion() .is_alive(); child .kill() @@ -533,10 +543,14 @@ fn test_follow_single() { fn test_follow_non_utf8_bytes() { // Tail the test file and start following it. let (at, mut ucmd) = at_and_ucmd!(); - let mut child = ucmd.arg("-f").arg(FOOBAR_TXT).run_no_wait(); + let mut child = ucmd + .args(&["-f", "-s.1", "--max-unchanged-stats=1", FOOBAR_TXT]) + .run_no_wait(); + let initial = at.read("foobar_single_default.expected"); child - .make_assertion_with_delay(500) + .wait_for_stdout_contains(&initial, WAIT_TIMEOUT) + .make_assertion() .is_alive() .with_current_output() .stdout_only_fixture("foobar_single_default.expected"); @@ -552,8 +566,22 @@ fn test_follow_non_utf8_bytes() { let expected = [INVALID_UTF8, b'\n']; at.append_bytes(FOOBAR_TXT, &expected); + // Poll raw bytes (invalid UTF-8 is not representable via the str helpers). + let start = std::time::Instant::now(); + loop { + let all = child.stdout_all_bytes_peek(); + if all.windows(expected.len()).any(|w| w == expected) { + break; + } + assert!( + start.elapsed() < WAIT_TIMEOUT, + "timeout waiting for non-utf8 bytes in stdout" + ); + child.delay(10); + } + child - .make_assertion_with_delay(DEFAULT_SLEEP_INTERVAL_MILLIS) + .make_assertion() .with_current_output() .stdout_only_bytes(expected); @@ -590,13 +618,18 @@ fn test_permission_denied_is_not_reported_as_not_found() { fn test_follow_multiple() { let (at, mut ucmd) = at_and_ucmd!(); let mut child = ucmd - .arg("-f") - .arg(FOOBAR_TXT) - .arg(FOOBAR_2_TXT) + .args(&[ + "-f", + "-s.1", + "--max-unchanged-stats=1", + FOOBAR_TXT, + FOOBAR_2_TXT, + ]) .run_no_wait(); child - .make_assertion_with_delay(500) + .wait_for_stdout_contains("==> foobar2.txt <==", WAIT_TIMEOUT) + .make_assertion() .is_alive() .with_current_output() .stdout_only_fixture("foobar_follow_multiple.expected"); @@ -605,7 +638,8 @@ fn test_follow_multiple() { at.append(FOOBAR_2_TXT, first_append); child - .make_assertion_with_delay(DEFAULT_SLEEP_INTERVAL_MILLIS) + .wait_for_stdout_contains(first_append, WAIT_TIMEOUT) + .make_assertion() .with_current_output() .stdout_only(first_append); @@ -613,7 +647,8 @@ fn test_follow_multiple() { at.append(FOOBAR_TXT, second_append); child - .make_assertion_with_delay(DEFAULT_SLEEP_INTERVAL_MILLIS) + .wait_for_stdout_contains("thirty\n", WAIT_TIMEOUT) + .make_assertion() .with_current_output() .stdout_only_fixture("foobar_follow_multiple_appended.expected"); @@ -627,20 +662,19 @@ fn test_follow_name_multiple() { for argument in ["--follow=name", "--follo=nam", "--f=n"] { let (at, mut ucmd) = at_and_ucmd!(); let mut child = ucmd - .arg(argument) - .arg(FOOBAR_TXT) - .arg(FOOBAR_2_TXT) + .args(&[ + argument, + "-s.1", + "--max-unchanged-stats=1", + FOOBAR_TXT, + FOOBAR_2_TXT, + ]) .run_no_wait(); - #[cfg(target_os = "linux")] - let delay = 100; - #[cfg(target_os = "macos")] - let delay = 2000; - #[cfg(not(any(target_os = "linux", target_os = "macos")))] - let delay = 1000; - + // Wait until the initial multi-file headers/content have been printed. child - .make_assertion_with_delay(delay) + .wait_for_stdout_contains("==> foobar2.txt <==", WAIT_TIMEOUT) + .make_assertion() .is_alive() .with_all_output() .stdout_only_fixture("foobar_follow_multiple.expected"); @@ -649,7 +683,8 @@ fn test_follow_name_multiple() { at.append(FOOBAR_2_TXT, first_append); child - .make_assertion_with_delay(delay) + .wait_for_stdout_contains(first_append, WAIT_TIMEOUT) + .make_assertion() .with_current_output() .stdout_only(first_append); @@ -657,7 +692,8 @@ fn test_follow_name_multiple() { at.append(FOOBAR_TXT, second_append); child - .make_assertion_with_delay(delay) + .wait_for_stdout_contains("thirty\n", WAIT_TIMEOUT) + .make_assertion() .with_current_output() .stdout_only_fixture("foobar_follow_multiple_appended.expected"); @@ -1358,18 +1394,26 @@ fn test_retry3() { tail: 'missing' has appeared; following new file\n"; let expected_stdout = "X\n"; - let mut delay = 1500; - let mut args = vec!["--follow=name", "--retry", missing, "--use-polling"]; + let mut args = vec![ + "-s.1", + "--max-unchanged-stats=1", + "--follow=name", + "--retry", + missing, + "--use-polling", + ]; for _ in 0..2 { let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot open 'missing'", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.touch(missing); - p.delay(delay); + p.wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); at.truncate(missing, "X\n"); - p.delay(delay); + p.wait_for_stdout_contains("X\n", WAIT_TIMEOUT); p.kill() .make_assertion() @@ -1379,7 +1423,6 @@ fn test_retry3() { at.remove(missing); args.pop(); - delay /= 3; } } @@ -1413,20 +1456,22 @@ fn test_retry4() { missing, "---disable-inotify", ]; - let mut delay = 150; for _ in 0..2 { let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot open 'missing'", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.touch(missing); - p.delay(delay); + p.wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); at.truncate(missing, "X1\n"); - p.delay(delay); + p.wait_for_stdout_contains("X1\n", WAIT_TIMEOUT); at.truncate(missing, "X\n"); - p.delay(delay); + p.wait_for_stderr_contains("file truncated", WAIT_TIMEOUT) + .wait_for_stdout_contains("X1\nX\n", WAIT_TIMEOUT); p.make_assertion().is_alive(); p.kill() @@ -1437,7 +1482,6 @@ fn test_retry4() { at.remove(missing); args.pop(); - delay /= 3; } } @@ -1462,17 +1506,24 @@ fn test_retry5() { tail: 'missing' has been replaced with an untailable file; giving up on this name\n\ tail: no files remaining\n"; - let mut delay = 1500; - let mut args = vec!["--follow=descriptor", "--retry", missing, "--use-polling"]; + let mut args = vec![ + "-s.1", + "--max-unchanged-stats=1", + "--follow=descriptor", + "--retry", + missing, + "--use-polling", + ]; for _ in 0..2 { let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot open 'missing'", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.mkdir(missing); - p.delay(delay); - - p.make_assertion() + p.wait_until_exited(WAIT_TIMEOUT) + .make_assertion() .is_not_alive() .with_all_output() .stderr_only(expected_stderr) @@ -1480,7 +1531,6 @@ fn test_retry5() { at.rmdir(missing); args.pop(); - delay /= 3; } } @@ -1506,22 +1556,26 @@ fn test_retry6() { let mut p = ts .ucmd() - .arg("--follow=descriptor") - .arg("missing") - .arg("existing") + .args(&[ + "-s.1", + "--max-unchanged-stats=1", + "--follow=descriptor", + "missing", + "existing", + ]) .run_no_wait(); - #[cfg(target_vendor = "apple")] - let delay = 1500; - #[cfg(not(target_vendor = "apple"))] - let delay = 1000; - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot open 'missing'", WAIT_TIMEOUT) + .wait_for_stdout_contains("==> existing <==", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.truncate(missing, "Y\n"); - p.delay(delay); + // Without --retry, missing must stay ignored. Brief settle before writing existing. + p.delay(50); at.truncate(existing, "X\n"); - p.delay(delay); + p.wait_for_stdout_contains("X\n", WAIT_TIMEOUT); p.make_assertion().is_alive(); p.kill() @@ -1563,35 +1617,40 @@ fn test_retry7() { "--use-polling", ]; - let mut delay = 500; for _ in 0..2 { at.mkdir(untailable); let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot follow end of this type of file", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); // tail: 'untailable' has become accessible // or (The first is the common case, "has appeared" arises with slow rmdir): // tail: 'untailable' has appeared; following new file at.rmdir(untailable); at.truncate(untailable, "foo\n"); - p.delay(delay); + p.wait_for_stdout_contains("foo\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has become accessible", WAIT_TIMEOUT); // NOTE: GNU's `tail` only shows "become inaccessible" - // if there's a delay between rm and mkdir. + // if there's a gap between rm and mkdir — wait for the event before mkdir. // tail: 'untailable' has become inaccessible: No such file or directory at.remove(untailable); - p.delay(delay); + p.wait_for_stderr_contains("has become inaccessible", WAIT_TIMEOUT); // tail: 'untailable' has been replaced with an untailable file\n"; at.mkdir(untailable); - p.delay(delay); + p.wait_for_stderr_contains("has been replaced with an untailable file", WAIT_TIMEOUT); // full circle, back to the beginning at.rmdir(untailable); at.truncate(untailable, "bar\n"); - p.delay(delay); + p.wait_for_stdout_contains("foo\nbar\n", WAIT_TIMEOUT) + .wait_until(WAIT_TIMEOUT, |_, stderr| { + stderr.matches("has become accessible").count() >= 2 + }); p.make_assertion().is_alive(); p.kill() @@ -1602,7 +1661,6 @@ fn test_retry7() { args.pop(); at.remove(untailable); - delay /= 3; } } @@ -1673,8 +1731,6 @@ fn test_retry8() { tail: 'parent_dir/watched_file' has appeared; following new file\n"; let expected_stdout = "foo\nbar\n"; - let delay = 1000; - let mut p = ts .ucmd() .arg("-F") @@ -1683,7 +1739,9 @@ fn test_retry8() { .arg(user_path) .run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot open 'parent_dir/watched_file'", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); // 'parent_dir/watched_file' is orphan // tail: cannot open 'parent_dir/watched_file' for reading: No such file or directory\n\ @@ -1691,18 +1749,22 @@ fn test_retry8() { // tail: 'parent_dir/watched_file' has appeared; following new file\n\ at.mkdir(parent_dir); // not an orphan anymore at.append(user_path, "foo\n"); - p.delay(delay); + p.wait_for_stdout_contains("foo\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); // tail: 'parent_dir/watched_file' has become inaccessible: No such file or directory\n\ at.remove(user_path); at.rmdir(parent_dir); // 'parent_dir/watched_file' is orphan *again* - p.delay(delay); + p.wait_for_stderr_contains("has become inaccessible", WAIT_TIMEOUT); // Since 'parent_dir/watched_file' is orphan, this needs to be picked up by polling // tail: 'parent_dir/watched_file' has appeared; following new file\n"; at.mkdir(parent_dir); // not an orphan anymore at.append(user_path, "bar\n"); - p.delay(delay); + p.wait_for_stdout_contains("foo\nbar\n", WAIT_TIMEOUT) + .wait_until(WAIT_TIMEOUT, |_, stderr| { + stderr.matches("has appeared").count() >= 2 + }); p.make_assertion().is_alive(); p.kill() @@ -1748,43 +1810,51 @@ fn test_retry9() { ); let expected_stdout = "foo\nbar\nfoo\nbar\n"; - let delay = 400; - at.mkdir(parent_dir); at.truncate(user_path, "foo\n"); let mut p = ts .ucmd() .arg("-F") - .arg("-s.2") + .arg("-s.1") .arg("--max-unchanged-stats=1") .arg(user_path) .run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stdout_contains("foo\n", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.remove(user_path); at.rmdir(parent_dir); - p.delay(delay); + p.wait_for_stderr_contains("reverting to polling", WAIT_TIMEOUT); at.mkdir(parent_dir); at.truncate(user_path, "bar\n"); - p.delay(delay); + p.wait_for_stdout_contains("foo\nbar\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); at.remove(user_path); at.rmdir(parent_dir); - p.delay(delay); + p.wait_until(WAIT_TIMEOUT, |_, stderr| { + stderr.matches("has become inaccessible").count() >= 2 + }); at.mkdir(parent_dir); at.truncate(user_path, "foo\n"); - p.delay(delay); + p.wait_for_stdout_contains("foo\nbar\nfoo\n", WAIT_TIMEOUT); at.remove(user_path); at.rmdir(parent_dir); - p.delay(delay); + p.wait_until(WAIT_TIMEOUT, |_, stderr| { + stderr.matches("has become inaccessible").count() >= 3 + }); at.mkdir(parent_dir); at.truncate(user_path, "bar\n"); - p.delay(delay); + p.wait_for_stdout_contains(expected_stdout, WAIT_TIMEOUT) + .wait_until(WAIT_TIMEOUT, |_, stderr| { + stderr.matches("has appeared").count() >= 3 + }); p.make_assertion().is_alive(); p.kill() @@ -1824,28 +1894,28 @@ fn test_follow_descriptor_vs_rename1() { "---disable-inotify", ]; - let mut delay = 100; for _ in 0..2 { at.touch(file_a); let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.make_assertion().is_alive(); at.append(file_a, "A\n"); - p.delay(delay); + p.wait_for_stdout_contains("A\n", WAIT_TIMEOUT); at.rename(file_a, file_b); - p.delay(delay); + // Descriptor follow keeps watching the same inode across renames; brief settle. + p.delay(50); at.append(file_b, "B\n"); - p.delay(delay); + p.wait_for_stdout_contains("A\nB\n", WAIT_TIMEOUT); at.rename(file_b, file_c); - p.delay(delay); + p.delay(50); at.append(file_c, "C\n"); - p.delay(delay); + p.wait_for_stdout_contains("A\nB\nC\n", WAIT_TIMEOUT); p.make_assertion().is_alive(); p.kill() @@ -1854,7 +1924,6 @@ fn test_follow_descriptor_vs_rename1() { .stdout_only("A\nB\nC\n"); args.pop(); - delay /= 3; } } @@ -1886,19 +1955,24 @@ fn test_follow_descriptor_vs_rename2() { "---disable-inotify", ]; - let mut delay = 150; for _ in 0..2 { at.touch(file_a); at.touch(file_b); let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stdout_contains("==> FILE_B <==", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.rename(file_a, file_c); - p.delay(delay); + // Descriptor follow keeps watching the same inode; brief settle before append. + p.delay(50); at.append(file_c, "X\n"); - p.delay(delay); + p.wait_for_stdout_contains( + "==> FILE_A <==\n\n==> FILE_B <==\n\n==> FILE_A <==\nX\n", + WAIT_TIMEOUT, + ); p.make_assertion().is_alive(); p.kill() @@ -1907,7 +1981,6 @@ fn test_follow_descriptor_vs_rename2() { .stdout_only("==> FILE_A <==\n\n==> FILE_B <==\n\n==> FILE_A <==\nX\n"); args.pop(); - delay /= 3; } } @@ -1951,17 +2024,20 @@ fn test_follow_name_retry_headers() { "---disable-inotify", ]; - let mut delay = 150; for _ in 0..2 { let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stderr_contains("cannot open 'b'", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.truncate(file_a, "x\n"); - p.delay(delay); + p.wait_for_stdout_contains("==> a <==\nx\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("'a' has appeared", WAIT_TIMEOUT); at.truncate(file_b, "y\n"); - p.delay(delay); + p.wait_for_stdout_contains("==> b <==\ny\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("'b' has appeared", WAIT_TIMEOUT); let expected_stderr = "tail: cannot open 'a' for reading: No such file or directory\n\ tail: cannot open 'b' for reading: No such file or directory\n\ @@ -1979,7 +2055,6 @@ fn test_follow_name_retry_headers() { at.remove(file_a); at.remove(file_b); args.pop(); - delay /= 3; } } @@ -2276,18 +2351,23 @@ fn test_follow_name_move_create1() { #[cfg(not(target_os = "linux"))] let expected_stderr = format!("{}: {source}: No such file or directory\n", ts.util_name); - let delay = 500; - let args = ["--follow=name", source]; + let args = ["-s.1", "--max-unchanged-stats=1", "--follow=name", source]; let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + // Wait until the initial file content has been printed before renaming. + p.wait_until(WAIT_TIMEOUT, |stdout, _| !stdout.is_empty()) + .make_assertion() + .is_alive(); at.rename(source, backup); - p.delay(delay); + p.wait_for_stderr_contains("No such file or directory", WAIT_TIMEOUT); at.copy(backup, source); - p.delay(delay); + #[cfg(target_os = "linux")] + p.wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); + #[cfg(not(target_os = "linux"))] + p.delay(100); p.make_assertion().is_alive(); p.kill() @@ -2332,20 +2412,20 @@ fn test_follow_name_move_create2() { "9", ]; - let mut delay = 100; for i in 0..2 { let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.make_assertion().is_alive(); at.truncate("9", "x\n"); - p.delay(delay); + p.wait_for_stdout_contains("x\n", WAIT_TIMEOUT); at.rename("1", "f"); - p.delay(delay); + p.wait_for_stderr_contains("has become inaccessible", WAIT_TIMEOUT); at.truncate("1", "a\n"); - p.delay(delay); + p.wait_for_stdout_contains("a\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); // NOTE: Because "gnu/tests/tail-2/inotify-hash-abuse.sh" 'forgets' to clear the files used // during the first loop iteration, we also don't clear them to get the same side-effects. @@ -2373,7 +2453,6 @@ fn test_follow_name_move_create2() { if i == 0 { args.push("---disable-inotify"); } - delay *= 3; } } @@ -2405,17 +2484,18 @@ fn test_follow_name_move1() { ), ]; - let mut args = vec!["--follow=name", source]; + let mut args = vec!["-s.1", "--max-unchanged-stats=1", "--follow=name", source]; - let mut delay = 500; #[allow(clippy::needless_range_loop)] for i in 0..2 { let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stdout_contains(&expected_stdout, WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.rename(source, backup); - p.delay(delay); + p.wait_for_stderr_contains("No such file or directory", WAIT_TIMEOUT); if i == 0 { p.make_assertion().is_alive(); @@ -2425,7 +2505,8 @@ fn test_follow_name_move1() { .stderr_is(&expected_stderr[i]) .stdout_is(&expected_stdout); } else { - p.make_assertion() + p.wait_until_exited(WAIT_TIMEOUT) + .make_assertion() .is_not_alive() .with_all_output() .stderr_is(&expected_stderr[i]) @@ -2435,7 +2516,6 @@ fn test_follow_name_move1() { at.rename(backup, source); args.push("--use-polling"); - delay *= 3; } } @@ -2485,24 +2565,33 @@ fn test_follow_name_move2() { ts.util_name, file1, file2 ); - let mut args = vec!["--follow=name", file1, file2]; + let mut args = vec![ + "-s.1", + "--max-unchanged-stats=1", + "--follow=name", + file1, + file2, + ]; - let mut delay = 500; for i in 0..2 { at.truncate(file1, "file1_content\n"); at.truncate(file2, "file2_content\n"); let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stdout_contains("file2_content\n", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.rename(file1, file2); - p.delay(delay); + p.wait_for_stderr_contains("has been replaced", WAIT_TIMEOUT) + .wait_for_stderr_contains("No such file or directory", WAIT_TIMEOUT); at.append(file2, "more_file2_content\n"); - p.delay(delay); + p.wait_for_stdout_contains("more_file2_content\n", WAIT_TIMEOUT); at.append(file1, "more_file1_content\n"); - p.delay(delay); + p.wait_for_stdout_contains("more_file1_content\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); p.make_assertion().is_alive(); p.kill() @@ -2514,7 +2603,6 @@ fn test_follow_name_move2() { if i == 0 { args.push("--use-polling"); } - delay *= 3; // NOTE: Switch the first and second line because the events come in this order from // `notify::PollWatcher`. However, for GNU's tail, the order between polling and not // polling does not change. @@ -2552,27 +2640,33 @@ fn test_follow_name_move_retry1() { ); let expected_stdout = "tailed\nnew content\n"; - let mut args = vec!["--follow=name", "--retry", source, "--use-polling"]; + let mut args = vec![ + "-s.1", + "--max-unchanged-stats=1", + "--follow=name", + "--retry", + source, + "--use-polling", + ]; - let mut delay = 1500; for _ in 0..2 { at.touch(source); let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.make_assertion().is_alive(); at.append(source, "tailed\n"); - p.delay(delay); + p.wait_for_stdout_contains("tailed\n", WAIT_TIMEOUT); // with --follow=name, tail should stop monitoring the renamed file at.rename(source, backup); - p.delay(delay); + p.wait_for_stderr_contains("has become inaccessible", WAIT_TIMEOUT); // overwrite backup while it's not monitored at.truncate(backup, "new content\n"); - p.delay(delay); // move back, tail should pick this up and print new content at.rename(backup, source); - p.delay(delay); + p.wait_for_stdout_contains("new content\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); p.make_assertion().is_alive(); p.kill() @@ -2583,7 +2677,6 @@ fn test_follow_name_move_retry1() { at.remove(source); args.pop(); - delay /= 3; } } @@ -2645,28 +2738,31 @@ fn test_follow_name_move_retry2() { let mut args = vec!["-s.1", "--max-unchanged-stats=1", "-F", file1, file2]; - let mut delay = 60; for i in 0..2 { at.touch(file1); at.touch(file2); let mut p = ts.ucmd().args(&args).run_no_wait(); - p.make_assertion_with_delay(delay).is_alive(); + p.wait_for_stdout_contains("==> b <==", WAIT_TIMEOUT) + .make_assertion() + .is_alive(); at.truncate(file1, "x\n"); - p.delay(delay); + p.wait_for_stdout_contains("==> a <==\nx\n", WAIT_TIMEOUT); at.rename(file1, file2); - p.delay(delay); + p.wait_for_stderr_contains("has been replaced", WAIT_TIMEOUT) + .wait_for_stderr_contains("has become inaccessible", WAIT_TIMEOUT); at.truncate(file1, "x2\n"); - p.delay(delay); + p.wait_for_stdout_contains("x2\n", WAIT_TIMEOUT) + .wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); at.append(file2, "y\n"); - p.delay(delay); + p.wait_for_stdout_contains("y\n", WAIT_TIMEOUT); at.append(file1, "z\n"); - p.delay(delay); + p.wait_for_stdout_contains("z\n", WAIT_TIMEOUT); p.make_assertion().is_alive(); p.kill() @@ -2680,7 +2776,6 @@ fn test_follow_name_move_retry2() { if i == 0 { args.push("--use-polling"); } - delay *= 3; // NOTE: Switch the first and second line because the events come in this order from // `notify::PollWatcher`. However, for GNU's tail, the order between polling and not // polling does not change. diff --git a/tests/uutests/src/lib/util.rs b/tests/uutests/src/lib/util.rs index 0325ba49e91..636477416f0 100644 --- a/tests/uutests/src/lib/util.rs +++ b/tests/uutests/src/lib/util.rs @@ -2173,6 +2173,17 @@ impl CapturedOutput { buffer } + /// Return all captured output so far without advancing the consuming cursor. + /// + /// Unlike [`CapturedOutput::output_all_bytes`], later calls to consuming methods such as + /// [`CapturedOutput::output_bytes`] still see the same unread data. + fn output_all_bytes_peek(&mut self) -> Vec { + let mut buffer = Vec::::new(); + let mut file = self.output.reopen().unwrap(); + file.read_to_end(&mut buffer).unwrap(); + buffer + } + /// Return the exact amount of bytes. /// /// Subsequent calls to any of the other output methods will operate on the subsequent output. @@ -2364,6 +2375,128 @@ impl UChild { self } + /// Return all stdout captured so far as a [`String`] without consuming it. + /// + /// Subsequent consuming reads (`stdout`, `stdout_bytes`, …) are unaffected. + pub fn stdout_all_peek(&mut self) -> String { + String::from_utf8_lossy(&self.stdout_all_bytes_peek()).into_owned() + } + + /// Return all stdout captured so far as bytes without consuming it. + pub fn stdout_all_bytes_peek(&mut self) -> Vec { + match self.captured_stdout.as_mut() { + Some(output) => output.output_all_bytes_peek(), + None => { + panic!("Usage error: This method cannot be used if the output wasn't captured.") + } + } + } + + /// Return all stderr captured so far as a [`String`] without consuming it. + /// + /// Subsequent consuming reads (`stderr`, `stderr_bytes`, …) are unaffected. + pub fn stderr_all_peek(&mut self) -> String { + String::from_utf8_lossy(&self.stderr_all_bytes_peek()).into_owned() + } + + /// Return all stderr captured so far as bytes without consuming it. + pub fn stderr_all_bytes_peek(&mut self) -> Vec { + match self.captured_stderr.as_mut() { + Some(output) => output.output_all_bytes_peek(), + None if self.stderr_to_stdout => vec![], + None => { + panic!("Usage error: This method cannot be used if the output wasn't captured.") + } + } + } + + /// Poll until `predicate(stdout_all_peek, stderr_all_peek)` is true, or `timeout` elapses. + /// + /// Uses short sleeps between polls so tests finish as soon as the child produces the expected + /// output, while still allowing a generous timeout for slow CI hosts. + pub fn try_wait_until(&mut self, timeout: Duration, mut predicate: F) -> Result<()> + where + F: FnMut(&str, &str) -> bool, + { + let start = Instant::now(); + loop { + let stdout = self.stdout_all_peek(); + let stderr = self.stderr_all_peek(); + if predicate(&stdout, &stderr) { + return Ok(()); + } + if start.elapsed() >= timeout { + return Err(io::Error::other(format!( + "try_wait_until: timeout of '{}s' reached\nstdout: {stdout}\nstderr: {stderr}", + timeout.as_secs_f64() + ))); + } + self.delay(10); + } + } + + /// Like [`UChild::try_wait_until`], but panics on timeout. + #[track_caller] + pub fn wait_until(&mut self, timeout: Duration, predicate: F) -> &mut Self + where + F: FnMut(&str, &str) -> bool, + { + self.try_wait_until(timeout, predicate).unwrap(); + self + } + + /// Poll until accumulated stdout contains `s`, or `timeout` elapses. + pub fn try_wait_for_stdout_contains(&mut self, s: &str, timeout: Duration) -> Result<()> { + let expected = s.to_owned(); + self.try_wait_until(timeout, move |stdout, _| stdout.contains(&expected)) + } + + /// Like [`UChild::try_wait_for_stdout_contains`], but panics on timeout. + #[track_caller] + pub fn wait_for_stdout_contains(&mut self, s: &str, timeout: Duration) -> &mut Self { + self.try_wait_for_stdout_contains(s, timeout).unwrap(); + self + } + + /// Poll until accumulated stderr contains `s`, or `timeout` elapses. + pub fn try_wait_for_stderr_contains(&mut self, s: &str, timeout: Duration) -> Result<()> { + let expected = s.to_owned(); + self.try_wait_until(timeout, move |_, stderr| stderr.contains(&expected)) + } + + /// Like [`UChild::try_wait_for_stderr_contains`], but panics on timeout. + #[track_caller] + pub fn wait_for_stderr_contains(&mut self, s: &str, timeout: Duration) -> &mut Self { + self.try_wait_for_stderr_contains(s, timeout).unwrap(); + self + } + + /// Poll until the child process has exited, or `timeout` elapses. + pub fn try_wait_until_exited(&mut self, timeout: Duration) -> Result<()> { + let start = Instant::now(); + loop { + if self.is_not_alive() { + return Ok(()); + } + if start.elapsed() >= timeout { + return Err(io::Error::other(format!( + "try_wait_until_exited: timeout of '{}s' reached\nstdout: {}\nstderr: {}", + timeout.as_secs_f64(), + self.stdout_all_peek(), + self.stderr_all_peek() + ))); + } + self.delay(10); + } + } + + /// Like [`UChild::try_wait_until_exited`], but panics on timeout. + #[track_caller] + pub fn wait_until_exited(&mut self, timeout: Duration) -> &mut Self { + self.try_wait_until_exited(timeout).unwrap(); + self + } + /// Return the pid of the child process, similar to [`Child::id`]. pub fn id(&self) -> u32 { self.raw.id() From cf343cbe1c258dba64abc7ed05860eb673c574eb Mon Sep 17 00:00:00 2001 From: Sankalp Thakur Date: Sat, 1 Aug 2026 15:18:57 +0530 Subject: [PATCH 2/2] tests/tail: wait for full initial and reappeared content test_follow_name_move_create1 raced under event-based waits: renaming as soon as stdout was non-empty, and killing after "has appeared" before the recreated file content was printed. Wait for END(25) before rename and START(0) after re-open on Linux. --- tests/by-util/test_tail.rs | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/tests/by-util/test_tail.rs b/tests/by-util/test_tail.rs index 70adbd92302..b698783e998 100644 --- a/tests/by-util/test_tail.rs +++ b/tests/by-util/test_tail.rs @@ -2355,8 +2355,10 @@ fn test_follow_name_move_create1() { let mut p = ts.ucmd().args(&args).run_no_wait(); - // Wait until the initial file content has been printed before renaming. - p.wait_until(WAIT_TIMEOUT, |stdout, _| !stdout.is_empty()) + // Wait until the initial last-N lines have been fully printed before renaming. + // Waiting only for non-empty stdout races with the first write and can truncate + // the captured initial chunk on busy CI hosts. + p.wait_for_stdout_contains("END(25)", WAIT_TIMEOUT) .make_assertion() .is_alive(); @@ -2365,9 +2367,13 @@ fn test_follow_name_move_create1() { at.copy(backup, source); #[cfg(target_os = "linux")] - p.wait_for_stderr_contains("has appeared", WAIT_TIMEOUT); + { + // After re-open, tail emits the recreated file content (START…END). + p.wait_for_stderr_contains("has appeared", WAIT_TIMEOUT) + .wait_for_stdout_contains("START(0)", WAIT_TIMEOUT); + } #[cfg(not(target_os = "linux"))] - p.delay(100); + p.delay(500); p.make_assertion().is_alive(); p.kill()