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

[Richard Purdie <richard.purdie@linuxfoundation.org>]

On Wed, 2023-11-29 at 15:56 +0000, Alex Bennée wrote:
> 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?

I was a little unsure about that when I recently worked on that code. I
think you're right, we should keep the data flowing to the log files
after login.

Cheers,

Richard