Re: [PATCH] tests/functional: add --debug CLI arg

["Daniel P. Berrangé" <berrange@redhat.com>]

On Thu, Jul 17, 2025 at 12:27:08PM +0300, Manos Pitsidianakis wrote:
> On Thu, Jul 17, 2025 at 12:22 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
> >
> > On Wed, Jul 16, 2025 at 09:08:00AM +0300, Manos Pitsidianakis wrote:
> > > Add argument parsing to functional tests to improve developer experience
> > > when running individual tests. All logs are printed to stdout
> > > interspersed with TAP output.
> > >
> > >   ./pyvenv/bin/python3 ../tests/functional/test_aarch64_virt.py --help
> > >   usage: test_aarch64_virt [-h] [-d]
> > >
> > >   QEMU Functional test
> > >
> > >   options:
> > >     -h, --help   show this help message and exit
> > >     -d, --debug  Also print test and console logs on stdout. This will
> > >                  make the TAP output invalid and is meant for debugging
> > >                  only.
> > >
> > > Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
> > > ---
> > >  docs/devel/testing/functional.rst      |  2 ++
> > >  tests/functional/qemu_test/testcase.py | 51 ++++++++++++++++++++++++++++++++--
> > >  2 files changed, 50 insertions(+), 3 deletions(-)
> > >
> > > diff --git a/docs/devel/testing/functional.rst b/docs/devel/testing/functional.rst
> > > index 9e56dd1b1189216b9b4aede00174c15203f38b41..9d08abe2848277d635befb0296f578cfaa4bd66d 100644
> > > --- a/docs/devel/testing/functional.rst
> > > +++ b/docs/devel/testing/functional.rst
> > > @@ -63,6 +63,8 @@ directory should be your build folder. For example::
> > >    $ export QEMU_TEST_QEMU_BINARY=$PWD/qemu-system-x86_64
> > >    $ pyvenv/bin/python3 ../tests/functional/test_file.py
> > >
> > > +By default, functional tests redirect informational logs and console output to
> > > +log files. Specify the ``--debug`` flag to also print those to standard output.
> > >  The test framework will automatically purge any scratch files created during
> > >  the tests. If needing to debug a failed test, it is possible to keep these
> > >  files around on disk by setting ```QEMU_TEST_KEEP_SCRATCH=1``` as an env
> > > diff --git a/tests/functional/qemu_test/testcase.py b/tests/functional/qemu_test/testcase.py
> > > index 2082c6fce43b0544d4e4258cd4155f555ed30cd4..fad7a946c6677e9ef5c42b8f77187ba836c11aeb 100644
> > > --- a/tests/functional/qemu_test/testcase.py
> > > +++ b/tests/functional/qemu_test/testcase.py
> > > @@ -11,6 +11,7 @@
> > >  # This work is licensed under the terms of the GNU GPL, version 2 or
> > >  # later.  See the COPYING file in the top-level directory.
> > >
> > > +import argparse
> > >  import logging
> > >  import os
> > >  from pathlib import Path
> > > @@ -31,6 +32,20 @@
> > >  from .uncompress import uncompress
> > >
> > >
> > > +def parse_args(test_name: str) -> argparse.Namespace:
> > > +    parser = argparse.ArgumentParser(
> > > +        prog=test_name, description="QEMU Functional test"
> > > +    )
> > > +    parser.add_argument(
> > > +        "-d",
> > > +        "--debug",
> > > +        action="store_true",
> > > +        help="Also print test and console logs on stdout. This will make the"
> > > +        " TAP output invalid and is meant for debugging only.",
> > > +    )
> > > +    return parser.parse_args()
> > > +
> > > +
> > >  class QemuBaseTest(unittest.TestCase):
> > >
> > >      '''
> > > @@ -196,6 +211,9 @@ def assets_available(self):
> > >          return True
> > >
> > >      def setUp(self):
> > > +        path = os.path.basename(sys.argv[0])[:-3]
> > > +        args = parse_args(path)
> >
> > IMHO this is not code that belongs in setUp. Indeed, I don't think
> > it belongs in this file at all, better have a helper for parsing
> > args in 'utils', and expose a global 'debug_enabled' flag from utils
> > that we can reference elsewhere.
> 
> setUp is where the logs are setup, do you mean logs should be split
> into another function/file altogether? Maybe out of scope for this
> patch, I can another one that does it before adding the --debug
> option. What do you think?

I'm saying 'parse_args' should be in util.py

> > > +        self.debug_output = args.debug
> > >          self.qemu_bin = os.getenv('QEMU_TEST_QEMU_BINARY')
> > >          self.assertIsNotNone(self.qemu_bin, 'QEMU_TEST_QEMU_BINARY must be set')
> > >          self.arch = self.qemu_bin.split('-')[-1]
> > > @@ -221,6 +239,16 @@ def setUp(self):
> > >          self.machinelog.setLevel(logging.DEBUG)
> > >          self.machinelog.addHandler(self._log_fh)
> > >
> > > +        if self.debug_output:
> > > +            handler = logging.StreamHandler(sys.stdout)
> > > +            handler.setLevel(logging.DEBUG)
> > > +            formatter = logging.Formatter(
> > > +                "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
> > > +            )
> > > +            handler.setFormatter(formatter)
> > > +            self.log.addHandler(handler)
> > > +            self.machinelog.addHandler(handler)
> >
> > There was already a lot of effectively duplicated code between
> > this and the console_log stuff below. This new addition makes
> > that duplication even more substantial, such that I think it
> > all needs to be spun out into a helper method.
> 
> Ditto

This should be a method we can call like:

  handlers = create_loggers("base.log", "qemu-test",
                            "%(asctime)s - %(levelname)s - %(message)s")

which is able to return multiple handlers. Initially it would just
return the current "self.log_fh" handler, and then this patch would
extend it to return a second handler for the console stream when
'--debug' is set.


> > > @@ -230,11 +258,16 @@ def tearDown(self):
> > >          if self.socketdir is not None:
> > >              shutil.rmtree(self.socketdir.name)
> > >              self.socketdir = None
> > > -        self.machinelog.removeHandler(self._log_fh)
> > > -        self.log.removeHandler(self._log_fh)
> > > +        for handler in [self._log_fh, logging.StreamHandler(sys.stdout)]:
> >
> > We should have stashed the original handler when created,
> > rather than re-creating StreamHandler at time of removal.
> > I'm kinda of surprised it even works to re-create it.
> 
> It's the same file descriptor, after all. I'd be surprised if it didn't work.

log.removeHandler has no visibility of the file descriptiors.

It will just compare the python handler object instances, which
I very much doubt will match with this code

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|