Nicholas Piggin <npig...@gmail.com> writes:
> Occasionally some avocado tests will fail waiting for console line
> despite the machine running correctly. Console data goes missing, as can
> be seen in the console log. This is due to _console_interaction calling
> makefile() on the console socket each time it is invoked, which must be
> losing old buffer contents when going out of scope.
>
> It is not enough to makefile() with buffered=0. That helps significantly
> but data loss is still possible. My guess is that readline() has a line
> buffer even when the file is in unbuffered mode, that can eat data.
>
> Fix this by providing a console file that persists for the life of the
> console.
>
> Signed-off-by: Nicholas Piggin <npig...@gmail.com>
Queued to testing/next, thanks.
> ---
>
> For some reason, ppc_prep_40p.py:IbmPrep40pMachine.test_openbios_192m
> was flakey for me due to this bug. I don't know why that in particular,
> 3 calls to wait_for_console_pattern probably helps.
>
> I didn't pinpoint when the bug was introduced because the original
> was probably not buggy because it was only run once at the end of the
> test. At some point after it was moved to common code, something would
> have started to call it more than once which is where potential for bug
> is introduced.
There is a sprawling mass somewhere between:
- pythons buffering of IO
- device models dropping chars when blocked
- noisy tests with competing console output
that adds up to unreliable tests that rely on seeing certain patterns on
the console.
>
> Thanks,
> Nick
>
> python/qemu/machine/machine.py | 19 +++++++++++++++++++
> tests/avocado/avocado_qemu/__init__.py | 2 +-
> 2 files changed, 20 insertions(+), 1 deletion(-)
>
> diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
> index c16a0b6fed..35d5a672db 100644
> --- a/python/qemu/machine/machine.py
> +++ b/python/qemu/machine/machine.py
> @@ -191,6 +191,7 @@ def __init__(self,
> self.sock_dir, f"{self._name}.con"
> )
> self._console_socket: Optional[socket.socket] = None
> + self._console_file: Optional[socket.SocketIO] = None
> self._remove_files: List[str] = []
> self._user_killed = False
> self._quit_issued = False
> @@ -509,6 +510,11 @@ def _early_cleanup(self) -> None:
> # If we keep the console socket open, we may deadlock waiting
> # for QEMU to exit, while QEMU is waiting for the socket to
> # become writable.
> + if self._console_file is not None:
> + LOG.debug("Closing console file")
> + self._console_file.close()
> + self._console_file = None
> +
> if self._console_socket is not None:
> LOG.debug("Closing console socket")
> self._console_socket.close()
> @@ -874,12 +880,25 @@ def console_socket(self) -> socket.socket:
> Returns a socket connected to the console
> """
> if self._console_socket is None:
> + LOG.debug("Opening console socket")
> self._console_socket = console_socket.ConsoleSocket(
> self._console_address,
> file=self._console_log_path,
> drain=self._drain_console)
> return self._console_socket
>
> + @property
> + def console_file(self) -> socket.SocketIO:
> + """
> + Returns a file associated with the console socket
> + """
> + if self._console_file is None:
> + LOG.debug("Opening console file")
> + self._console_file = self.console_socket.makefile(mode='rb',
> + buffering=0,
> +
> encoding='utf-8')
> + return self._console_file
> +
> @property
> def temp_dir(self) -> str:
> """
> diff --git a/tests/avocado/avocado_qemu/__init__.py
> b/tests/avocado/avocado_qemu/__init__.py
> index 33090903f1..0172a359b7 100644
> --- a/tests/avocado/avocado_qemu/__init__.py
> +++ b/tests/avocado/avocado_qemu/__init__.py
> @@ -137,7 +137,7 @@ def _console_interaction(test, success_message,
> failure_message,
> assert not keep_sending or send_string
> if vm is None:
> vm = test.vm
> - console = vm.console_socket.makefile(mode='rb', encoding='utf-8')
> + console = vm.console_file
> console_logger = logging.getLogger('console')
> while True:
> if send_string:
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
