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

["Alex Bennée" <alex.bennee@linaro.org>]

Richard Purdie <richard.purdie@linuxfoundation.org> writes:

> On Wed, 2023-11-29 at 15:11 +0100, Erik Schilling wrote:
>> 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).
>
> I was wondering about that, this would ideally be handled by that
> existing log processing thread. Would you be willing to work out a
> patch to do that?

Sure - but I'm a little unclear about how things are meant to work if
you can offer any pointers. I assume we can just allow the existing
logger to continue once we reach the login point?

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro