From 027befd08d0e2de2329bff922befb2bef14b9f15 Mon Sep 17 00:00:00 2001 From: rnhmjoj Date: Thu, 2 Feb 2023 13:19:10 +0100 Subject: [PATCH] nixos/test-driver: drop logging from Machine.send_monitor_command MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Several machine operations, like `send_chars` and `send_key`, are implemented by calling `send_monitor_command`, possibly multiple times. This generates a huge amount of unnecessary noise in the log, because `send_monitor_command` is a low-level operation and an implementation detail. Here's an excerpt from a highlighted log before and afte the change. Before: subtest: Can generate a PGP key machine: sending keys 'gpg --gen-key\n' machine: sending monitor command: sendkey g machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey g, in 0.00 seconds) machine: sending monitor command: sendkey p machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey p, in 0.00 seconds) machine: sending monitor command: sendkey g machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey g, in 0.00 seconds) machine: sending monitor command: sendkey spc machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey spc, in 0.00 seconds) machine: sending monitor command: sendkey 0x0C machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey 0x0C, in 0.00 seconds) machine: sending monitor command: sendkey 0x0C machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey 0x0C, in 0.00 seconds) machine: sending monitor command: sendkey g machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey g, in 0.00 seconds) machine: sending monitor command: sendkey e machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey e, in 0.00 seconds) machine: sending monitor command: sendkey n machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey n, in 0.00 seconds) machine: sending monitor command: sendkey 0x0C machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey 0x0C, in 0.00 seconds) machine: sending monitor command: sendkey k machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey k, in 0.00 seconds) machine: sending monitor command: sendkey e machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey e, in 0.00 seconds) machine: sending monitor command: sendkey y machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey y, in 0.00 seconds) machine: sending monitor command: sendkey ret machine: waiting for monitor prompt (finished: waiting for monitor prompt, in 0.00 seconds) (finished: sending monitor command: sendkey ret, in 0.00 seconds) (finished: sending keys 'gpg --gen-key\n', in 0.15 seconds) After: subtest: Can generate a PGP key machine: sending keys 'gpg --gen-key\n' (finished: sending keys 'gpg --gen-key\n', in 0.15 seconds) --- nixos/lib/test-driver/test_driver/machine.py | 48 ++++++++++---------- 1 file changed, 25 insertions(+), 23 deletions(-) diff --git a/nixos/lib/test-driver/test_driver/machine.py b/nixos/lib/test-driver/test_driver/machine.py index 8f01833bffb4..1c77550bd1fd 100644 --- a/nixos/lib/test-driver/test_driver/machine.py +++ b/nixos/lib/test-driver/test_driver/machine.py @@ -1,4 +1,4 @@ -from contextlib import _GeneratorContextManager +from contextlib import _GeneratorContextManager, nullcontext from pathlib import Path from queue import Queue from typing import Any, Callable, Dict, Iterable, List, Optional, Tuple @@ -406,25 +406,23 @@ class Machine: return rootlog.nested(msg, my_attrs) def wait_for_monitor_prompt(self) -> str: - with self.nested("waiting for monitor prompt"): - assert self.monitor is not None - answer = "" - while True: - undecoded_answer = self.monitor.recv(1024) - if not undecoded_answer: - break - answer += undecoded_answer.decode() - if answer.endswith("(qemu) "): - break - return answer + assert self.monitor is not None + answer = "" + while True: + undecoded_answer = self.monitor.recv(1024) + if not undecoded_answer: + break + answer += undecoded_answer.decode() + if answer.endswith("(qemu) "): + break + return answer def send_monitor_command(self, command: str) -> str: self.run_callbacks() - with self.nested(f"sending monitor command: {command}"): - message = f"{command}\n".encode() - assert self.monitor is not None - self.monitor.send(message) - return self.wait_for_monitor_prompt() + message = f"{command}\n".encode() + assert self.monitor is not None + self.monitor.send(message) + return self.wait_for_monitor_prompt() def wait_for_unit( self, unit: str, user: Optional[str] = None, timeout: int = 900 @@ -685,9 +683,9 @@ class Machine: retry(tty_matches) def send_chars(self, chars: str, delay: Optional[float] = 0.01) -> None: - with self.nested(f"sending keys '{chars}'"): + with self.nested(f"sending keys {repr(chars)}"): for char in chars: - self.send_key(char, delay) + self.send_key(char, delay, log=False) def wait_for_file(self, filename: str) -> None: """Waits until the file exists in machine's file system.""" @@ -860,11 +858,15 @@ class Machine: if matches is not None: return - def send_key(self, key: str, delay: Optional[float] = 0.01) -> None: + def send_key( + self, key: str, delay: Optional[float] = 0.01, log: Optional[bool] = True + ) -> None: key = CHAR_TO_KEY.get(key, key) - self.send_monitor_command(f"sendkey {key}") - if delay is not None: - time.sleep(delay) + context = self.nested(f"sending key {repr(key)}") if log else nullcontext() + with context: + self.send_monitor_command(f"sendkey {key}") + if delay is not None: + time.sleep(delay) def send_console(self, chars: str) -> None: assert self.process