From 0dab30ee4fa38c6ca89d82c75755c49fa6473ce0 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 28 Oct 2026 18:20:42 -0700 Subject: [PATCH 1/4] scripts: keep the console's echo out of guest script output test-microvm typed each guest script into the guest's interactive shell line by line. The guest's terminal echoes console input that arrives while a command runs into whatever that command prints, so when a slow guest received a script in pieces, the echo of its later lines could land inside the markers that its earlier lines printed (#785). In CI run 39902391325, the ipv6-egress-policy case allow-ipv6-tcp-range read 'none0000 &' as its DNS server: the tail of the UDP probe's line had landed before the newline of "NVX-IPV6-EGRESS-DNS none". The scenarios that boot through nvx-rs run send their script as soon as the boot marker appears, without the time ABI status query that the other cold boots wait for, so their input can even reach the guest before its shell starts. run_guest_script now stores the script in the guest with a here-document, which the shell reads whole before it runs anything. Its last input line prints NVX-GUEST-SCRIPT-START and sources the script into the same shell, which keeps the semantics of typed lines, such as an exit that powers the guest off. No input is left to echo once the script runs. The result's new output field holds what the console printed after the start line, which the scenarios now parse, and the completion marker must be one of its lines, so that an echoed fragment of the staged script can stand for no marker. text keeps the whole transcript, whose status query lines precede the script and which the counting-LAPIC check still reads. _stage_script shares the here-document, which now refuses a script that holds its delimiter line or lacks a final newline. Every script now runs only once the guest has read it, so the comment that justified the exhaustive time ABI check's single input line goes. lifecycle.sh's bytes to the debug port now end with a newline: the next prompt of a typed script used to end their line, and the script's marker now follows them at once. The new tests drive the real harness against a fake console whose input arrives in pieces while commands run and whose terminal echoes each piece into the line being printed: typed line by line, the script reproduces CI's 'none0000 &', and staged, its output keeps the exact marker. The fakes of run_guest_script return the new field. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../microvm_test_scripts/lifecycle.sh | 3 +- scripts/nvx_tools/microvm_tests.py | 107 ++++- scripts/test_microvm_tests.py | 401 ++++++++++++++++-- 3 files changed, 458 insertions(+), 53 deletions(-) diff --git a/scripts/nvx_tools/microvm_test_scripts/lifecycle.sh b/scripts/nvx_tools/microvm_test_scripts/lifecycle.sh index dfa848ca8..cfddcd159 100644 --- a/scripts/nvx_tools/microvm_test_scripts/lifecycle.sh +++ b/scripts/nvx_tools/microvm_test_scripts/lifecycle.sh @@ -18,7 +18,8 @@ uptime_before="$(awk '{ print int($1); exit }' /proc/uptime)" sleep 1 uptime_after="$(awk '{ print int($1); exit }' /proc/uptime)" [ $((uptime_after - uptime_before)) -ge 1 ] || fail 43 -for octal in 000 015 012 177 377; do +# The last byte ends the debug port's line, so that the marker starts one. +for octal in 000 015 012 177 377 012; do printf "\\$octal" | dd of=/dev/port bs=1 seek=233 count=1 conv=notrunc 2>/dev/null done echo NVX-LIFECYCLE-OK diff --git a/scripts/nvx_tools/microvm_tests.py b/scripts/nvx_tools/microvm_tests.py index a2e9a2329..ab4719248 100644 --- a/scripts/nvx_tools/microvm_tests.py +++ b/scripts/nvx_tools/microvm_tests.py @@ -181,6 +181,12 @@ SMP_LAPIC_COUNTING_MARKER = b"NVX-SMP-LAPIC-COUNTING-OK" MICROVM_PROCESSOR_COUNTS = (1, 2, 4, 8) MICROVM_TEST_SCRIPTS_DIR = Path(__file__).with_name("microvm_test_scripts") +# run_guest_script stores each script at GUEST_SCRIPT_PATH with a +# here-document that GUEST_SCRIPT_DELIMITER ends, and the guest prints the +# start line just before the script's first command. +GUEST_SCRIPT_PATH = "/tmp/nvx-guest-script" +GUEST_SCRIPT_DELIMITER = "NVX_GUEST_SCRIPT" +GUEST_SCRIPT_START_MARKER = b"NVX-GUEST-SCRIPT-START" LIFECYCLE_COMPLETION_MARKER = b"NVX-LIFECYCLE-OK" SANDBOX_BLOCKS_COMPLETION_MARKER = b"NVX-SANDBOX-BLOCKS-OK" VIRTIO_NET_COMPLETION_MARKER = b"NVX-VIRTIO-NET-OK" @@ -577,6 +583,14 @@ def configure_shard_parser(parser: argparse.ArgumentParser) -> None: ) +class GuestScriptResult(GuestCommandResult): + """A guest script's run. ``text`` is the whole console transcript, and + ``output`` what the console printed after the script's start line, which + is the script's own output.""" + + output: str + + def run_guest_script( command: Sequence[str], script: str, @@ -587,10 +601,29 @@ def run_guest_script( teardown_mode: str = "guest-exit", log_path: Path | None = None, contain_process_tree: bool = False, -) -> GuestCommandResult: - return _run_guest_script( +) -> GuestScriptResult: + """Run ``script`` in the shell of the guest that ``command`` boots, and + require it to print the line ``completion_marker``. + + The guest's terminal echoes console input that arrives while a command + runs into whatever that command prints, so a script that the console typed + line by line could find the echo of its later lines inside the output of + its earlier ones (#785). The console therefore stages the whole script at + GUEST_SCRIPT_PATH first. Its last line prints GUEST_SCRIPT_START_MARKER + and sources the script, which runs in the shell as typed lines did, but + only once the guest has consumed all the input. The console output after + that line, ``output``, is thus the script's own, and ``completion_marker`` + must be one of its lines. + """ + result = _run_guest_script( command, - script, + _staged_script( + GUEST_SCRIPT_PATH, + GUEST_SCRIPT_DELIMITER, + script, + # The quotes keep the start line out of this line's echo. + f'echo NVX-GUEST-SCRIPT-"START"; . {GUEST_SCRIPT_PATH}', + ), completion_marker, timeout=timeout, windows_cpus=windows_cpus, @@ -600,6 +633,31 @@ def run_guest_script( contain_process_tree=contain_process_tree, time_abi_status=True, ) + output = _guest_script_output(result["text"]) + if not contains_output_line(output.encode("utf-8"), completion_marker): + raise RuntimeError( + f"guest script did not print {completion_marker.decode()!r} after " + f"its start line\n--- OpenVMM output ---\n{result['text'][-4096:]}" + ) + return GuestScriptResult( + text=result["text"], + wall_ms=result["wall_ms"], + peak_rss_bytes=result["peak_rss_bytes"], + output=output, + ) + + +def _guest_script_output(text: str) -> str: + """Return what the console printed after a staged script's start line.""" + start = GUEST_SCRIPT_START_MARKER.decode() + lines = text.split("\n") + for index, line in enumerate(lines): + if line.removesuffix("\r") == start: + return "\n".join(lines[index + 1 :]) + raise RuntimeError( + f"guest never printed the start line {start!r} of its script" + f"\n--- OpenVMM output ---\n{text[-4096:]}" + ) def capture_snapshot( @@ -651,17 +709,28 @@ def _render_script(name: str, **values: str) -> str: return script +def _staged_script(path: str, delimiter: str, script: str, run: str) -> str: + """Return console input that stores ``script`` at ``path`` and then runs + the command line ``run``. + + The shell reads a here-document whole before it runs the command that + reads it, so none of the script runs before the guest has consumed all of + it, and ``run`` follows it as the input's last line. + """ + if not script.endswith("\n"): + raise ValueError("a staged guest script must end with a newline") + if delimiter in script.split("\n"): + raise ValueError(f"a staged guest script cannot hold the line {delimiter!r}") + return f"cat >{path} <<'{delimiter}'\n{script}{delimiter}\n{run}\n" + + def _stage_script( process: OpenvmmProcess, path: str, delimiter: str, script: str, ) -> None: - process.send_bytes( - f"cat >{path} <<'{delimiter}'\n".encode() - + script.encode() - + f"{delimiter}\nsh {path}\n".encode() - ) + process.send_bytes(_staged_script(path, delimiter, script, f"sh {path}").encode()) def _output_lines(output: bytes) -> list[bytes]: @@ -1469,7 +1538,7 @@ def run_smp( timeout=timeout, log_path=log_path, ) - output = result["text"].encode("utf-8") + output = result["output"].encode("utf-8") if not contains_output_line(output, SMP_PROBE_COMPLETION_MARKER): raise RuntimeError( f"{processors}-vCPU guest finished without the SMP probe marker " @@ -1482,16 +1551,17 @@ def run_smp( f"marker {SMP_LAPIC_COUNTING_MARKER.decode()!r}" ) # The boot line must also report the backend's LAPIC rate for all - # the CPUs; the status query alone doesn't check the CPU count. + # the CPUs; the status query alone doesn't check the CPU count. The + # query ran before the script, so its lines are in the transcript. monitor = TimeAbiMonitor(command) - monitor.feed(output) + monitor.feed(result["text"].encode("utf-8")) monitor.finish() try: monitor.require_boot("the counting-LAPIC check", online_cpus=processors) except TimeAbiFailure as error: raise RuntimeError(f"{processors}-vCPU smp-lapic: {error}") from error check_warp_probe( - result["text"], + result["output"], cpus=processors, context=f"{processors}-vCPU boot", rounds=warp_rounds(processors), @@ -1701,7 +1771,6 @@ def run_time_abi_conformance( "quiet loglevel=0", processors=processors, ) - # One input line: the console echoes all of it before the check prints. result = run_guest_script( command, f"{TIME_ABI_EXHAUSTIVE_COMMAND}; " @@ -1711,7 +1780,7 @@ def run_time_abi_conformance( timeout=timeout, log_path=log_path, ) - _check_exhaustive_report(result["text"], processors=processors) + _check_exhaustive_report(result["output"], processors=processors) def run_virtio_net( @@ -1799,7 +1868,7 @@ def boot(padding: int, log_name: str) -> str: log_path=output_dir / log_name, ) return _single_marker_value( - result["text"].encode("utf-8"), COMMAND_LINE_PREFIX + result["output"].encode("utf-8"), COMMAND_LINE_PREFIX ).decode("utf-8") padding_token = f"{COMMAND_LINE_PADDING}x" @@ -2558,7 +2627,7 @@ def run_l3_l4_egress_protocols( contain_process_tree=True, ) host_reached = server.finish() - guest_reports = _egress_probe_reports(result["text"]) + guest_reports = _egress_probe_reports(result["output"]) _check_egress_case( "protocol", case, L3_L4_EGRESS_PROBES, guest_reports, host_reached ) @@ -2759,7 +2828,7 @@ def run_l3_l4_egress_port_ranges( contain_process_tree=True, ) host_reached = server.finish() - guest_reports = _egress_probe_reports(result["text"]) + guest_reports = _egress_probe_reports(result["output"]) _check_egress_case( "port-range", case, @@ -3199,11 +3268,11 @@ def run_ipv6_egress_policy( contain_process_tree=True, ) host_reached = server.finish() - guest_reports = _egress_probe_reports(result["text"]) + guest_reports = _egress_probe_reports(result["output"]) _check_egress_case( "IPv6 egress", case, IPV6_EGRESS_PROBES, guest_reports, host_reached ) - dns = _ipv6_egress_dns_report(result["text"]) + dns = _ipv6_egress_dns_report(result["output"]) if dns != (case.dns or "none"): raise RuntimeError( f"IPv6 egress case {case.name}: the guest named {dns!r} as its " diff --git a/scripts/test_microvm_tests.py b/scripts/test_microvm_tests.py index 4b4920c61..e7b1b3ea3 100644 --- a/scripts/test_microvm_tests.py +++ b/scripts/test_microvm_tests.py @@ -14,6 +14,7 @@ import os import queue import re +import shlex import shutil import socket import subprocess @@ -208,6 +209,20 @@ def _warp_probe_output(cpus: int, *, offset_ns: int = 40) -> bytes: return (probe_round * time_abi.warp_rounds(cpus) + "NVX-WARP-PROBE-OK\r\n").encode() +def _guest_script_result( + output: str, *, transcript: str = "" +) -> microvm_tests.GuestScriptResult: + """Return what run_guest_script returns for a staged script that printed + ``output``, after the console printed ``transcript`` and the start line.""" + start = microvm_tests.GUEST_SCRIPT_START_MARKER.decode() + return microvm_tests.GuestScriptResult( + text=f"{transcript}{start}\r\n{output}", + wall_ms=0.0, + peak_rss_bytes=0, + output=output, + ) + + def _restore_status_output( backend: str, cpus: int, *, boot_cpus: int | None = None ) -> bytes: @@ -2293,6 +2308,271 @@ def test_probe_script_reports_each_status(self): ) +class _ExitingProcess: + """An OpenVMM process that exits with status 0 once its console ends.""" + + pid = 123 + + def __init__(self) -> None: + self.exited = False + + def poll(self) -> int | None: + return 0 if self.exited else None + + def wait(self, timeout: float | None = None) -> int: + del timeout + self.exited = True + return 0 + + +class _EchoingGuestConsole: + """A guest console whose input arrives in pieces of ``piece`` characters + while commands run, as a slow guest's did in #785. The terminal echoes + each piece as it arrives, into what the running command prints, before + the newline of its line. + + The shell reads one line at a time and echoes it after its prompt, and it + waits for the rest of a line that has not arrived. It runs ``echo``, + ``cat >PATH <<'DELIMITER'``, ``. PATH``, and ``nvx-exit``, with ``; `` + between commands, and ignores other commands. + """ + + def __init__(self, piece: int) -> None: + self.process = _ExitingProcess() + self.containment = None + self._piece = piece + self._input: queue.Queue[bytes] = queue.Queue() + + def write_input(self, data: bytes) -> None: + self._input.put(data) + + def close(self) -> None: + pass + + def read_output(self, chunks: queue.Queue[bytes | None]) -> None: + chunks.put(b"NVX-GUEST-BOOT-OK: alpine\r\n") + typed = self._input.get(timeout=5).decode() + files: dict[str, list[str]] = {} + arrived = 0 + consumed = 0 + + def emit(text: str) -> None: + if text: + chunks.put(text.encode()) + + def read_line(prompt: str) -> str: + nonlocal arrived, consumed + end = typed.index("\n", consumed) + arrived = max(arrived, end + 1) + line = typed[consumed:end] + consumed = end + 1 + emit(f"{prompt}{line}\r\n") + return line + + def run(line: str) -> bool: + """Run the commands of ``line``, and return whether the guest + still runs.""" + nonlocal arrived + for command in line.split("; "): + heredoc = re.fullmatch(r"cat >(\S+) <<'(\w+)'", command) + if heredoc is not None: + # The shell reads the here-document before cat runs. + path, delimiter = heredoc.groups() + files[path] = [] + while (body := read_line("> ")) != delimiter: + files[path].append(body) + piece = typed[arrived : arrived + self._piece] + arrived += len(piece) + echo = piece.replace("\n", "\r\n") + words = shlex.split(command, comments=True) + if words[:1] == ["echo"]: + emit(" ".join(words[1:]) + echo + "\r\n") + continue + emit(echo) + if words[:1] == ["."]: + if not all(run(stored) for stored in files[words[1]]): + return False + elif words[:1] == ["nvx-exit"]: + return False + return True + + while consumed < len(typed) and run(read_line("/ # ")): + pass + self.process.exited = True + chunks.put(None) + + +class GuestConsoleEchoTests(unittest.TestCase): + """The guest's terminal echoes console input that arrives while a command + runs into what the command prints (#785); no scenario may parse it.""" + + # Typed line by line, this script printed its DNS marker while the guest + # was still receiving the UDP probe's line, as in CI. + ECHOED_SCRIPT = ( + "set -eu\n" + "echo NVX-IPV6-EGRESS-DNS none\n" + "probe_udp udp6-named fd00::c000:201 20000 &\n" + "probe_icmp icmp6 fd00::c000:201 &\n" + "echo NVX-IPV6-EGRESS-OK\n" + "nvx-exit 0\n" + ) + # The piece that arrives while the script's first line runs ends where + # CI's did, inside the UDP probe's port. + ECHOED_PIECE = ECHOED_SCRIPT.index("0000 &") - len("set -eu\n") + + def test_typed_script_lets_the_echo_cut_into_its_dns_marker(self): + console = _EchoingGuestConsole(self.ECHOED_PIECE) + with patch.object(benchmark, "InteractiveProcess", return_value=console): + result = benchmark.run_guest_script( + ["nvx-rs", "run"], + self.ECHOED_SCRIPT, + microvm_tests.IPV6_EGRESS_COMPLETION_MARKER, + timeout=5, + boot_marker=microvm_tests.BOOT_MARKER, + ) + self.assertIn("NVX-IPV6-EGRESS-DNS none0000 &\r\n", result["text"]) + self.assertEqual( + microvm_tests._ipv6_egress_dns_report(result["text"]), "none0000 &" + ) + + def test_staged_script_keeps_the_echo_out_of_its_output(self): + console = _EchoingGuestConsole(self.ECHOED_PIECE) + with patch.object(benchmark, "InteractiveProcess", return_value=console): + result = microvm_tests.run_guest_script( + ["nvx-rs", "run"], + self.ECHOED_SCRIPT, + microvm_tests.IPV6_EGRESS_COMPLETION_MARKER, + timeout=5, + ) + self.assertEqual( + result["output"], "NVX-IPV6-EGRESS-DNS none\r\nNVX-IPV6-EGRESS-OK\r\n" + ) + self.assertEqual( + microvm_tests._ipv6_egress_dns_report(result["output"]), "none" + ) + # The terminal still echoed the input that arrived while cat ran, but + # before the start line. + before, _, _ = result["text"].partition("NVX-GUEST-SCRIPT-START\r\n") + self.assertIn('\r\necho NVX-GUEST-SCRIPT-"START"; . /tmp/', before) + + def test_scripts_run_once_the_guest_has_consumed_them(self): + script = 'echo "NVX-OUT ${value:-none}"\necho NVX-DONE\nnvx-exit 0\n' + transcript = ( + "NVX-GUEST-BOOT-OK: alpine\r\n" + # An echoed fragment of the staged script, cut before a marker. + "NVX-DONE\r\n" + '/ # echo NVX-GUEST-SCRIPT-"START"; . /tmp/nvx-guest-script\r\n' + "NVX-GUEST-SCRIPT-START\r\n" + "NVX-OUT none\r\n" + "NVX-DONE\r\n" + ) + with patch.object( + microvm_tests, + "_run_guest_script", + return_value={"text": transcript, "wall_ms": 5.0, "peak_rss_bytes": 7}, + ) as run: + result = microvm_tests.run_guest_script( + ["openvmm"], + script, + b"NVX-DONE", + timeout=30, + log_path=Path("guest.log"), + contain_process_tree=True, + ) + run.assert_called_once_with( + ["openvmm"], + "cat >/tmp/nvx-guest-script <<'NVX_GUEST_SCRIPT'\n" + + script + + "NVX_GUEST_SCRIPT\n" + + 'echo NVX-GUEST-SCRIPT-"START"; . /tmp/nvx-guest-script\n', + b"NVX-DONE", + timeout=30, + windows_cpus=None, + teardown_mode="guest-exit", + log_path=Path("guest.log"), + boot_marker=microvm_tests.BOOT_MARKER, + contain_process_tree=True, + time_abi_status=True, + ) + self.assertEqual(result["output"], "NVX-OUT none\r\nNVX-DONE\r\n") + self.assertEqual(result["text"], transcript) + self.assertEqual((result["wall_ms"], result["peak_rss_bytes"]), (5.0, 7)) + + def test_staged_input_sources_the_script_in_the_console_shell(self): + shell = _posix_shell() + if shell is None: + self.skipTest("POSIX shell is unavailable") + script = 'value=staged\necho "NVX-OUT $value"\n' + with ( + tempfile.TemporaryDirectory() as temporary, + patch.object( + microvm_tests, + "_run_guest_script", + return_value={ + "text": "NVX-GUEST-SCRIPT-START\nNVX-OUT staged\n", + "wall_ms": 0.0, + "peak_rss_bytes": 0, + }, + ) as run, + ): + microvm_tests.run_guest_script( + ["openvmm"], script, b"NVX-OUT staged", timeout=1 + ) + staged = run.call_args.args[1].replace( + microvm_tests.GUEST_SCRIPT_PATH, + (Path(temporary) / "script").as_posix(), + ) + # The shell that reads the input keeps the script's variables. + result = subprocess.run( + [shell], + input=(staged + 'echo "NVX-AFTER $value"\n').encode(), + capture_output=True, + timeout=10, + check=False, + ) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual( + result.stdout.decode().replace("\r\n", "\n"), + "NVX-GUEST-SCRIPT-START\nNVX-OUT staged\nNVX-AFTER staged\n", + ) + + def test_scripts_cannot_end_their_staging_early(self): + for script, message in ( + ("echo NVX-DONE", "must end with a newline"), + ("echo one\nNVX_GUEST_SCRIPT\necho NVX-DONE\n", "cannot hold the line"), + ): + with ( + self.subTest(message=message), + patch.object(microvm_tests, "_run_guest_script") as run, + self.assertRaisesRegex(ValueError, message), + ): + microvm_tests.run_guest_script( + ["openvmm"], script, b"NVX-DONE", timeout=1 + ) + run.assert_not_called() + + def test_markers_count_only_after_the_start_line(self): + for text, message in ( + ( + "NVX-DONE\r\nNVX-GUEST-SCRIPT-START\r\nNVX-OTHER\r\n", + "did not print 'NVX-DONE' after its start line", + ), + ('NVX-GUEST-SCRIPT-"START"\r\nNVX-DONE\r\n', "never printed the start"), + ): + with ( + self.subTest(message=message), + patch.object( + microvm_tests, + "_run_guest_script", + return_value={"text": text, "wall_ms": 0.0, "peak_rss_bytes": 0}, + ), + self.assertRaisesRegex(RuntimeError, message), + ): + microvm_tests.run_guest_script( + ["openvmm"], "echo NVX-DONE\n", b"NVX-DONE", timeout=1 + ) + + class GuestIdentityScriptTests(unittest.TestCase): def test_guest_identity_checks_fail_before_success_markers(self): descriptor = microvm_tests.guest_descriptor("ubuntu") @@ -6738,6 +7018,29 @@ def test_lifecycle_script_exits_on_unexpected_command_failure(self): ["NVX-LIFECYCLE-FAIL code=1", "NVX-EXIT 1"], ) + def test_lifecycle_script_ends_its_debug_port_line(self): + shell = _posix_shell() + if shell is None: + self.skipTest("POSIX shell is unavailable") + script = microvm_tests._read_script("lifecycle.sh") + tail = script[script.index("for octal in") : script.index("nvx-exit 0")] + # OpenVMM prints the debug port's bytes in the console stream, where + # the staged script prints its marker right after them. + result = subprocess.run( + [shell], + input=b"dd() { cat; }\n" + tail.encode(), + capture_output=True, + timeout=10, + check=False, + ) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertTrue( + microvm_tests.contains_output_line( + result.stdout, microvm_tests.LIFECYCLE_COMPLETION_MARKER + ), + result.stdout, + ) + def test_smp_uses_requested_processor_count(self): text = ( b"NVX-SMP-PROBE-OK\r\n" + _warp_probe_output(4) + b"nvx-exit 0\r\n" @@ -6754,7 +7057,9 @@ def test_smp_uses_requested_processor_count(self): return_value="probe\n", ) as smp_probe_script, patch.object( - microvm_tests, "run_guest_script", return_value={"text": text} + microvm_tests, + "run_guest_script", + return_value=_guest_script_result(text), ) as run_guest_script, ): microvm_tests.run_smp( @@ -6801,7 +7106,9 @@ def test_smp_requires_the_probe_marker_and_a_passing_warp_probe(self): for text, message in cases: with self.subTest(message=message): with patch.object( - microvm_tests, "run_guest_script", return_value={"text": text} + microvm_tests, + "run_guest_script", + return_value=_guest_script_result(text), ): with self.assertRaisesRegex(RuntimeError, message): microvm_tests.run_smp( @@ -6823,7 +7130,7 @@ def test_smp_exercises_the_counting_lapic_without_a_duplicate_scenario(self): self.assertNotIn("smp-lapic", microvm_tests.DEBUG_KERNEL_SCENARIOS) text = (b"NVX-SMP-PROBE-OK\r\n" + _warp_probe_output(4)).decode() with patch.object( - microvm_tests, "run_guest_script", return_value={"text": text} + microvm_tests, "run_guest_script", return_value=_guest_script_result(text) ) as run: microvm_tests.run_smp( Path("openvmm"), @@ -6853,20 +7160,24 @@ def test_smp_lapic_remains_an_explicit_scenario(self): def test_smp_lapic_asserts_the_counting_lapic_facts(self): rates = f"tsc_hz=2793437000 lapic_hz={time_abi.LAPIC_HZ['kvm']}" - passing = ( + # The status query runs before the staged script, which prints the + # markers. + status = ( f"NVX-TIME-ABI: v=1 phase=boot status=ok cpus=4 {rates} " "generation=0 elapsed_us=2390\r\n" "NVX-TIME-ABI: v=1 phase=runtime status=synchronized generation=0 " "discontinuities=0 offset_ns=-1200 uncertainty_ns=900 " "rejected_samples=0 last_sample_error=none\r\n" "NVX-TIME-STATUS-EXIT status=0\r\n" - "NVX-SMP-LAPIC-COUNTING-OK\r\n" - "NVX-SMP-PROBE-OK\r\n" + _warp_probe_output(4).decode() ) + counting = "NVX-SMP-LAPIC-COUNTING-OK\r\n" + output = counting + "NVX-SMP-PROBE-OK\r\n" + _warp_probe_output(4).decode() - def run_smp_lapic(text: str) -> MagicMock: + def run_smp_lapic(transcript: str, output: str) -> MagicMock: with patch.object( - microvm_tests, "run_guest_script", return_value={"text": text} + microvm_tests, + "run_guest_script", + return_value=_guest_script_result(output, transcript=transcript), ) as run: microvm_tests.run_smp( Path("openvmm"), @@ -6881,23 +7192,37 @@ def run_smp_lapic(text: str) -> MagicMock: ) return run - command, script, marker = run_smp_lapic(passing).call_args.args + command, script, marker = run_smp_lapic(status, output).call_args.args self.assertEqual(command[command.index("--cmdline") + 1], "quiet loglevel=0") self.assertTrue(script.startswith(microvm_tests.counting_lapic_script(4))) self.assertIn(benchmark.smp_probe_script(4, exit_guest=False), script) self.assertEqual(marker, time_abi.WARP_PROBE_COMPLETION_MARKER) - for text, message in ( + for label, transcript, printed, message in ( ( - passing.replace("NVX-SMP-LAPIC-COUNTING-OK\r\n", ""), + "missing", + status, + output.replace(counting, ""), "without the counting-LAPIC marker", ), - (passing.replace("cpus=4 tsc_hz", "cpus=2 tsc_hz"), "cpus=2 is not 4"), + # Only the script's own output counts. + ( + "before the start line", + status + counting, + output.replace(counting, ""), + "without the counting-LAPIC marker", + ), + ( + "two CPUs", + status.replace("cpus=4 tsc_hz", "cpus=2 tsc_hz"), + output, + "cpus=2 is not 4", + ), ): with ( - self.subTest(message=message), + self.subTest(label), self.assertRaisesRegex(RuntimeError, message), ): - run_smp_lapic(text) + run_smp_lapic(transcript, printed) def test_counting_lapic_check_requires_the_counting_lapic_on_every_cpu(self): shell = _posix_shell() @@ -7016,10 +7341,12 @@ def line(padding: int) -> str: 1, b"Error: " + microvm_tests.COMMAND_LINE_LIMIT_ERROR + b"\n" ) - def guest(text: str) -> dict[str, object]: - return { - "text": f"NVX-COMMAND-LINE: {text}\r\nNVX-COMMAND-LINE-LIMIT-OK\r\n" - } + def guest(text: str) -> microvm_tests.GuestScriptResult: + return _guest_script_result( + f"NVX-COMMAND-LINE: {text}\r\nNVX-COMMAND-LINE-LIMIT-OK\r\n", + # The echo of the staged script, cut before its marker. + transcript='NVX-COMMAND-LINE: %s\\n\' "$(cat /proc/cmdline)"\r\n', + ) def run_scenario( longest: str, over: openvmm_process.OpenvmmProcessResult @@ -7573,7 +7900,7 @@ def _run_egress_protocols( def guest( command: list[str], _script: str, _marker: bytes, **_kwargs: object - ) -> dict[str, str]: + ) -> microvm_tests.GuestScriptResult: policy = Path(command[command.index("--network-egress-policy-file") + 1]) name = policy.name.removeprefix("l3-l4-egress-").removesuffix( "-policy.json" @@ -7589,12 +7916,15 @@ def guest( } if guest_report is not None and guest_report[0] == name: reports[guest_report[1]] = guest_report[2] - # The tty echoes script lines, which must not count as reports. - text = 'echo "NVX-L3-L4-PROBE icmp=echoed"\r\n' + "".join( + text = "".join( f"NVX-L3-L4-PROBE {probe}={value}\r\n" for probe, value in reports.items() ) - return {"text": text + "NVX-L3-L4-EGRESS-PROTOCOLS-OK\r\n"} + return _guest_script_result( + text + "NVX-L3-L4-EGRESS-PROTOCOLS-OK\r\n", + # The tty echoes script lines, which must not count as reports. + transcript='> echo "NVX-L3-L4-PROBE icmp=echoed"\r\n', + ) class FakeServer: def __init__( @@ -8026,7 +8356,7 @@ def policy_name(command: list[str]) -> str: def guest( command: list[str], _script: str, _marker: bytes, **_kwargs: object - ) -> dict[str, str]: + ) -> microvm_tests.GuestScriptResult: name = policy_name(command) current.append(name) reports = { @@ -8039,12 +8369,15 @@ def guest( } if guest_report is not None and guest_report[0] == name: reports[guest_report[1]] = guest_report[2] - # The tty echoes script lines, which must not count as reports. - text = 'echo "NVX-L3-L4-PROBE tcp-first=echoed"\r\n' + "".join( + text = "".join( f"NVX-L3-L4-PROBE {probe}={value}\r\n" for probe, value in reports.items() ) - return {"text": text + "NVX-L3-L4-EGRESS-PORT-RANGES-OK\r\n"} + return _guest_script_result( + text + "NVX-L3-L4-EGRESS-PORT-RANGES-OK\r\n", + # The tty echoes script lines, which must not count as reports. + transcript='> echo "NVX-L3-L4-PROBE tcp-first=echoed"\r\n', + ) class FakeServer: def __init__( @@ -8612,7 +8945,7 @@ def _run_ipv6_egress( def guest( command: list[str], _script: str, _marker: bytes, **_kwargs: object - ) -> dict[str, str]: + ) -> microvm_tests.GuestScriptResult: policy = Path(command[command.index("--network-egress-policy-file") + 1]) name = policy.name.removeprefix("ipv6-egress-").removesuffix("-policy.json") current.append(name) @@ -8629,14 +8962,16 @@ def guest( dns = cases[name].dns or "none" if dns_report is not None and dns_report[0] == name: dns = dns_report[1] - # The tty echoes script lines, which must not count as reports. - text = 'echo "NVX-IPV6-EGRESS-DNS ${dns:-none}"\r\n' - text += f"NVX-IPV6-EGRESS-DNS {dns}\r\n" + text = f"NVX-IPV6-EGRESS-DNS {dns}\r\n" text += "".join( f"NVX-L3-L4-PROBE {probe}={value}\r\n" for probe, value in reports.items() ) - return {"text": text + "NVX-IPV6-EGRESS-OK\r\n"} + return _guest_script_result( + text + "NVX-IPV6-EGRESS-OK\r\n", + # The tty echoes script lines, which must not count as reports. + transcript='> echo "NVX-IPV6-EGRESS-DNS ${dns:-none}"\r\n', + ) class FakeServer: def __init__( @@ -11946,7 +12281,7 @@ def test_conformance_runs_nvx_time_exhaustive_at_the_requested_vcpus(self): with patch.object( microvm_tests, "run_guest_script", - return_value={"text": self._exhaustive_report(8)}, + return_value=_guest_script_result(self._exhaustive_report(8)), ) as run: microvm_tests.run_time_abi_conformance( Path("openvmm"), @@ -11976,7 +12311,7 @@ def test_conformance_guest_line_reports_the_check_exit_status(self): with patch.object( microvm_tests, "run_guest_script", - return_value={"text": self._exhaustive_report(1)}, + return_value=_guest_script_result(self._exhaustive_report(1)), ) as run: microvm_tests.run_time_abi_conformance( Path("openvmm"), From a55fc4a7b1a5723d4c00f65e762657eaf051608d Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 28 Oct 2026 18:22:18 -0700 Subject: [PATCH 2/4] scripts: type the canceled-capture checks as one console line After snapshot-core's no-destination source released its snapshot request, the console typed two lines at once: the time ABI status query, then the line that reports whether RCU stall detection is still suppressed. nvx-time status may wait up to 30 s for pending checks, and a slow guest could receive the second line while the query printed the status lines that check_canceled_capture parses, which the terminal would then echo that line into, as in #785. The checks now form one console line, which the shell reads whole before it runs any of it, so no input is left to echo while they print. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- scripts/nvx_tools/microvm_tests.py | 11 ++++++++--- scripts/test_microvm_tests.py | 15 +++++++++------ 2 files changed, 17 insertions(+), 9 deletions(-) diff --git a/scripts/nvx_tools/microvm_tests.py b/scripts/nvx_tools/microvm_tests.py index ab4719248..cd643451b 100644 --- a/scripts/nvx_tools/microvm_tests.py +++ b/scripts/nvx_tools/microvm_tests.py @@ -6429,14 +6429,19 @@ def run_restore_memory( def canceled_capture_checks() -> str: """Return the guest checks after a snapshot request that OpenVMM released: - the time ABI status, then whether RCU stall detection is still suppressed.""" + the time ABI status, then whether RCU stall detection is still suppressed. + + They form one console line, which the shell reads whole before it runs + any of it, so that the terminal echoes none of it into the status lines + (#785). + """ rcu = CANCELED_CAPTURE_RCU_PREFIX.decode() done = CANCELED_CAPTURE_DONE_MARKER.decode() # A quote pair splits each marker, so the console's echo of the command, # which the tty may wrap, never contains it. return ( - status_script() - + f'echo "{rcu[:4]}""{rcu[4:]}$(cat {RCU_STALL_SUPPRESS_PATH})"; ' + status_script().removesuffix("\n") + + f'; echo "{rcu[:4]}""{rcu[4:]}$(cat {RCU_STALL_SUPPRESS_PATH})"; ' + f'echo "{done[:4]}""{done[4:]}"\n' ) diff --git a/scripts/test_microvm_tests.py b/scripts/test_microvm_tests.py index e7b1b3ea3..b1e569c6d 100644 --- a/scripts/test_microvm_tests.py +++ b/scripts/test_microvm_tests.py @@ -6671,7 +6671,12 @@ def wait(self, _timeout: float) -> openvmm_process.OpenvmmProcessResult: def test_canceled_capture_checks_query_status_and_rcu_suppression(self): script = microvm_tests.canceled_capture_checks() - self.assertTrue(script.startswith(time_abi.status_script())) + query = time_abi.status_script().removesuffix("\n") + "; " + self.assertTrue(script.startswith(query)) + # One console line, which the shell reads whole before it runs any of + # it, so that the terminal echoes none of it into the status lines. + self.assertEqual(script.count("\n"), 1) + self.assertTrue(script.endswith("\n")) self.assertIn( "$(cat /sys/module/rcupdate/parameters/rcu_cpu_stall_suppress)", script ) @@ -6687,7 +6692,7 @@ def test_canceled_capture_checks_query_status_and_rcu_suppression(self): if shell is None: self.skipTest("no POSIX shell") answers = subprocess.run( - [shell, "-c", script.removeprefix(time_abi.status_script())], + [shell, "-c", script.removeprefix(query)], capture_output=True, check=True, ).stdout @@ -6697,10 +6702,8 @@ def test_canceled_capture_checks_query_status_and_rcu_suppression(self): def test_canceled_capture_requires_generation_zero_and_no_suppression(self): command = ["openvmm", "--hypervisor", "kvm", "--kernel", "vmlinux"] - echoed = ( - b'~ # echo "NVX-""CANCELED-CAPTURE-RCU $(cat /sys/module/rcupdate/' - b'parameters/rcu_cpu_stall_suppress)"; echo "NVX-""CANCELED-CAPTURE-DONE"\r\n' - ) + checks = microvm_tests.canceled_capture_checks().encode() + echoed = b"~ # " + checks.replace(b"\n", b"\r\n") microvm_tests.check_canceled_capture( echoed + _canceled_capture_output("kvm"), command ) From 6c5e10aa0a81500d6b23c421dfd6a0cfa5ff8e95 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 28 Oct 2026 18:22:37 -0700 Subject: [PATCH 3/4] scripts: turn the echo off before guest scripts await the host The guests of directional-network-policy, host-loopback-policy, private-network-ingress, and platform-network-policy announce that they listen and then read the host's release from the console. The release arrives while the script runs, so the terminal echoed it, and that echo could land inside a marker that the script printed afterwards, before the line's newline (#785). The host requires the completion markers of host-loopback-policy and private-network-ingress, and the probe report of platform-network-policy, as exact lines, which such an echo would hide. Each of these scripts now turns the terminal's echo off before it announces that it listens, and fails with a code of its own if it cannot. The read still receives the release, which no longer reaches the console. The tests that run two of these scripts in a local shell stub stty, since their input is a pipe there. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../directional-network-policy.sh.in | 2 ++ .../host-loopback-policy.sh.in | 2 ++ .../platform-network-policy.sh.in | 2 ++ .../private-network-ingress.sh.in | 2 ++ scripts/test_microvm_tests.py | 34 +++++++++++++++++++ 5 files changed, 42 insertions(+) diff --git a/scripts/nvx_tools/microvm_test_scripts/directional-network-policy.sh.in b/scripts/nvx_tools/microvm_test_scripts/directional-network-policy.sh.in index 104ffa324..270c491d8 100644 --- a/scripts/nvx_tools/microvm_test_scripts/directional-network-policy.sh.in +++ b/scripts/nvx_tools/microvm_test_scripts/directional-network-policy.sh.in @@ -31,6 +31,8 @@ allow) nc -l -p @INGRESS_PORT@ >/dev/null 2>&1 & ingress_pid=$! sleep 0.1 kill -0 "$ingress_pid" 2>/dev/null || fail 25 + # The terminal would echo the host's release into the lines after it. + stty -echo || fail 31 echo NVX-DIRECTIONAL-INGRESS-"READY" read -r ingress_release || fail 26 [ "$ingress_release" = NVX-DIRECTIONAL-INGRESS-CHECKED ] || fail 27 diff --git a/scripts/nvx_tools/microvm_test_scripts/host-loopback-policy.sh.in b/scripts/nvx_tools/microvm_test_scripts/host-loopback-policy.sh.in index 4cae3becf..d884548d3 100644 --- a/scripts/nvx_tools/microvm_test_scripts/host-loopback-policy.sh.in +++ b/scripts/nvx_tools/microvm_test_scripts/host-loopback-policy.sh.in @@ -116,6 +116,8 @@ allow) wait_for_socket "^0100007F:$private_hex\$" 0A /proc/net/tcp || fail 96 wait_for_socket "^00000000000000000000000001000000:$private_hex\$" 0A \ /proc/net/tcp6 || fail 96 + # The terminal would echo the host's release into the lines after it. + stty -echo || fail 78 echo NVX-HOST-LOOPBACK-INGRESS-READY read -r release || fail 76 diff --git a/scripts/nvx_tools/microvm_test_scripts/platform-network-policy.sh.in b/scripts/nvx_tools/microvm_test_scripts/platform-network-policy.sh.in index 8cdcd2e93..aa3c327b9 100644 --- a/scripts/nvx_tools/microvm_test_scripts/platform-network-policy.sh.in +++ b/scripts/nvx_tools/microvm_test_scripts/platform-network-policy.sh.in @@ -54,6 +54,8 @@ while ! awk -v pattern=":$port_hex\$" \ tries=$((tries + 1)) sleep 0.05 done +# The terminal would echo the host's release into the lines after it. +stty -echo || fail "the terminal kept echoing" 85 echo NVX-PLATFORM-NETWORK-LISTENING # The host's release says whether it exchanged a line with the server through # a forward. Its request may still be on the way when the release arrives, so diff --git a/scripts/nvx_tools/microvm_test_scripts/private-network-ingress.sh.in b/scripts/nvx_tools/microvm_test_scripts/private-network-ingress.sh.in index 76b221484..37f55df86 100644 --- a/scripts/nvx_tools/microvm_test_scripts/private-network-ingress.sh.in +++ b/scripts/nvx_tools/microvm_test_scripts/private-network-ingress.sh.in @@ -48,6 +48,8 @@ rm -f /tmp/nvx-ingress-tcp /tmp/nvx-ingress-udp } | nc -u -l -p @UDP_PORT@ -w 20 >/tmp/nvx-ingress-udp 2>/dev/null & wait_for_socket @TCP_PORT@ 0A /proc/net/tcp /proc/net/tcp6 || fail 74 wait_for_socket @UDP_PORT@ 07 /proc/net/udp /proc/net/udp6 || fail 75 +# The terminal would echo the host's release into the lines after it. +stty -echo || fail 85 echo NVX-PRIVATE-INGRESS-LISTENING read -r release || fail 76 diff --git a/scripts/test_microvm_tests.py b/scripts/test_microvm_tests.py index b1e569c6d..c0d8479f2 100644 --- a/scripts/test_microvm_tests.py +++ b/scripts/test_microvm_tests.py @@ -2572,6 +2572,36 @@ def test_markers_count_only_after_the_start_line(self): ["openvmm"], "echo NVX-DONE\n", b"NVX-DONE", timeout=1 ) + def test_scripts_awaiting_a_release_turn_the_echo_off_first(self): + # The host's release arrives while the script runs. + for name, ready, release in ( + ( + "directional-network-policy.sh.in", + 'echo NVX-DIRECTIONAL-INGRESS-"READY"', + "read -r ingress_release", + ), + ( + "host-loopback-policy.sh.in", + f"echo {microvm_tests.HOST_LOOPBACK_INGRESS_READY_MARKER.decode()}", + "read -r release", + ), + ( + "private-network-ingress.sh.in", + f"echo {microvm_tests.PRIVATE_INGRESS_LISTENING_MARKER.decode()}", + "read -r release", + ), + ( + "platform-network-policy.sh.in", + f"echo {microvm_tests.PLATFORM_NETWORK_LISTENING_MARKER.decode()}", + "read -r release exchange", + ), + ): + with self.subTest(name=name): + script = microvm_tests._read_script(name) + self.assertEqual(script.count("stty -echo"), 1) + self.assertLess(script.index("stty -echo"), script.index(ready)) + self.assertLess(script.index(ready), script.index(release)) + class GuestIdentityScriptTests(unittest.TestCase): def test_guest_identity_checks_fail_before_success_markers(self): @@ -4231,6 +4261,8 @@ def _run_private_ingress_script( path = root / "private-network-ingress.sh" path.write_text( "sleep() { :; }\n" + # The script's input is a pipe here, not the guest's terminal. + 'stty() { [ "$*" = -echo ]; }\n' f"pidof() {{ return {0 if ingress_running else 1}; }}\n" 'nc() { case "$*" in\n' f"'-l -p '*) {tcp} ;;\n" @@ -4695,6 +4727,8 @@ def _run_host_loopback_allow_script( path = root / "host-loopback-policy.sh" path.write_text( "sleep() { :; }\n" + # The script's input is a pipe here, not the guest's terminal. + 'stty() { [ "$*" = -echo ]; }\n' f"pidof() {{ return {0 if announcer else 1}; }}\n" "wget() { echo NVX-HOST-LOOPBACK-GENERAL; }\n" 'nc() { case "$*" in\n' From 31b0ac28d073651944d9088d93ce763653f6b15f Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 28 Oct 2026 18:23:01 -0700 Subject: [PATCH 4/4] doc: describe how the microVM tests keep the console's echo out The CI guide explains why the test runners wait for the time ABI status query before any other input. Describe as well how they keep the guest terminal's echo out of the output of the scripts that follow (#785): the runners stage each script whole with a here-document before it runs, a scenario that parses its script's output reads only what follows NVX-GUEST-SCRIPT-START, and a script that waits for a line from the host turns the echo off first. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/ci.md | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/doc/ci.md b/doc/ci.md index a63ca3872..c2664a973 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -97,6 +97,14 @@ intervals stay quiet. An OpenVMM exit status of 193, 194, or 195 is reported as the guest's time ABI conformance, runtime-violation, or restore-repair power-off, together with the event that preceded it, instead of as a generic exit status. +The guest's terminal also echoes console input that arrives while a command +runs into whatever that command prints (#785), so the test runners never +type a guest script line by line. They stage it whole in a file with a +here-document, then run it with the last input line. When a scenario parses +the script's output, that line first prints `NVX-GUEST-SCRIPT-START` and then +sources the script into the shell, and the scenario reads only what follows. +A staged script that waits for a line from the host turns the terminal's +echo off before it announces that it waits. The `smp`, `smp-snapshot`, and `restore-processors` scenarios run the guest warp probe, `/sbin/nvx-time-probe warp --bound-ns 1000`, over every pair of online CPUs after each boot or restore, in two rounds with all vCPUs halted