Re: [RFC PATCH] qemurunner.py: ensure we drain stdout after boot prompt

["Erik Schilling" <erik.schilling@linaro.org>]

On Wed Nov 29, 2023 at 1:45 PM CET, Alex Bennée wrote:
> If qemurunner doesn't continuously drain stdout we will eventually
> cause QEMU to block while trying to write to the pipe. This can
> manifest itself if the guest has for example configured its serial
> ports to output via stdio even if the test itself is using a TCP
> console or SSH to run things.
>
> This doesn't address a potential overflow of stderr although generally
> stderr from QEMU will be a lot less likely to block due to the volume
> of data.
>
> Suggested-by: Erik Schilling <erik.schilling@linaro.org>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Cc: Mikko Rapeli <mikko.rapeli@linaro.org>
>
> ---
> AJB:
>   As a QEMU developer I should note that we've had to solve a lot of
>   similar problems within our own internal testing (e.g.
>   https://gitlab.com/qemu-project/qemu/-/blob/master/python/qemu/machine/console_socket.py?ref_type=heads).
>   Perhaps in the longer term it might make sense to consider using
>   QEMU's own python tooling for configuring and launching QEMU?
> ---
>  meta/lib/oeqa/utils/qemurunner.py | 12 ++++++++++++
>  1 file changed, 12 insertions(+)
>
> diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py
> index 29fe271976..1ec472c49e 100644
> --- a/meta/lib/oeqa/utils/qemurunner.py
> +++ b/meta/lib/oeqa/utils/qemurunner.py
> @@ -243,6 +243,7 @@ class QemuRunner:
>          # to be a proper fix but this will suffice for now.
>          self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
>          output = self.runqemu.stdout
> +        output_drain = output
>          launch_time = time.time()
>  
>          #
> @@ -539,6 +540,17 @@ class QemuRunner:
>                  self.logger.warning("The output:\n%s" % output)
>          except:
>              self.logger.warning("Serial console failed while trying to login")
> +
> +        def drain_log():
> +            while not output_drain.closed:
> +                more_output = self.getOutput(output_drain)
> +                if len(more_output) > 0:
> +                    self.logger.debug("Logs since boot: %s", more_output)
> +                time.sleep(0.1)
> +
> +        t = threading.Thread(target=drain_log)
> +        t.start()
> +
>          return True
>  
>      def stop(self):

This is of course just a hack to demonstrate this was the problem. A
better solution would probably be to collect the logs through the
existing supervision process that gets forked off... That then also
solves the problem for the earlier code (and would transition nicely to
also drain stderr).

- Erik