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 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/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_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/nvx_tools/microvm_tests.py b/scripts/nvx_tools/microvm_tests.py index a2e9a2329..cd643451b 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 " @@ -6360,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 4b4920c61..c0d8479f2 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,301 @@ 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 + ) + + 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): descriptor = microvm_tests.guest_descriptor("ubuntu") @@ -3951,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" @@ -4415,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' @@ -6391,7 +6705,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 ) @@ -6407,7 +6726,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 @@ -6417,10 +6736,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 ) @@ -6738,6 +7055,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 +7094,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 +7143,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 +7167,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 +7197,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 +7229,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 ( + ( + "missing", + status, + output.replace(counting, ""), + "without the counting-LAPIC marker", + ), + # Only the script's own output counts. ( - passing.replace("NVX-SMP-LAPIC-COUNTING-OK\r\n", ""), + "before the start line", + status + counting, + output.replace(counting, ""), "without the counting-LAPIC marker", ), - (passing.replace("cpus=4 tsc_hz", "cpus=2 tsc_hz"), "cpus=2 is not 4"), + ( + "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 +7378,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 +7937,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 +7953,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 +8393,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 +8406,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 +8982,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 +8999,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 +12318,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 +12348,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"),