Re: [PATCH 2/2] tests/functional: include the lower level QMP log messages

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

On Wed, Oct 29, 2025 at 09:30:03AM +0100, Thomas Huth wrote:
> On 29/10/2025 09.12, Daniel P. Berrangé wrote:
> > On Wed, Oct 29, 2025 at 08:12:31AM +0100, Thomas Huth wrote:
> > > On 28/10/2025 19.26, Daniel P. Berrangé wrote:
> > > > We've seen a GitLab CI timeout failure in the test_pseries.py test,
> > > > where it appears likely that the test has hung in a self.qmp('quit')
> > > > call, but we don't have conclusive proof. Adding the QMP log category
> > > > to what we capture should help us diagnose this, at the cost of the
> > > > base.log file becoming significantly more verbose. The previous
> > > > commit to include the logger category name and function should at
> > > > least help understanding the more verbose logs.
> > > > 
> > > > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > > > ---
> > > >    tests/functional/qemu_test/testcase.py | 4 ++++
> > > >    1 file changed, 4 insertions(+)
> > > > 
> > > > diff --git a/tests/functional/qemu_test/testcase.py b/tests/functional/qemu_test/testcase.py
> > > > index 6fc6e1ac0a..5ab84ce674 100644
> > > > --- a/tests/functional/qemu_test/testcase.py
> > > > +++ b/tests/functional/qemu_test/testcase.py
> > > > @@ -225,6 +225,9 @@ def setUp(self):
> > > >            self.machinelog = logging.getLogger('qemu.machine')
> > > >            self.machinelog.setLevel(logging.DEBUG)
> > > >            self.machinelog.addHandler(self._log_fh)
> > > > +        self.qmplog = logging.getLogger('qemu.qmp')
> > > > +        self.qmplog.setLevel(logging.DEBUG)
> > > > +        self.qmplog.addHandler(self._log_fh)
> > > >            if not self.assets_available():
> > > >                self.skipTest('One or more assets is not available')
> > > > @@ -235,6 +238,7 @@ def tearDown(self):
> > > >            if self.socketdir is not None:
> > > >                shutil.rmtree(self.socketdir.name)
> > > >                self.socketdir = None
> > > > +        self.qmplog.removeHandler(self._log_fh)
> > > >            self.machinelog.removeHandler(self._log_fh)
> > > >            self.log.removeHandler(self._log_fh)
> > > >            self._log_fh.close()
> > > 
> > >   Hi,
> > > 
> > > I tested this patch, and now I'm seeing Python stack traces in the base.log,
> > > like this:
> > > 
> > > 2025-10-29 07:22:45,264 - DEBUG: qemu.qmp.protocol.default._bh_loop_forever
> > > Task.Reader: failure:
> > >    | Traceback (most recent call last):
> > >    |   File "../python/qemu/qmp/protocol.py", line 914, in _bh_loop_forever
> > >    |     await async_fn()
> > >    |   File "../python/qemu/qmp/protocol.py", line 952, in _bh_recv_message
> > >    |     msg = await self._recv()
> > >    |           ^^^^^^^^^^^^^^^^^^
> > >    |   File "../python/qemu/qmp/protocol.py", line 1053, in _recv
> > >    |     message = await self._do_recv()
> > >    |               ^^^^^^^^^^^^^^^^^^^^^
> > >    |   File "../python/qemu/qmp/qmp_client.py", line 459, in _do_recv
> > >    |     msg_bytes = await self._readline()
> > >    |                 ^^^^^^^^^^^^^^^^^^^^^^
> > >    |   File "../python/qemu/qmp/protocol.py", line 1021, in _readline
> > >    |     raise EOFError
> > >    | EOFError
> > > 
> > > If if it's harmless, I think that's very confusing for the casual user when
> > > trying to debug a problem. Can we avoid these?
> > 
> > That comes from this code in qemu/qmp/protocol.py
> > 
> >          except BaseException as err:
> >              self.logger.log(
> >                  logging.INFO if isinstance(err, EOFError) else logging.ERROR,
> >                  "Task.%s: %s",
> >                  name, exception_summary(err)
> >              )
> >              self.logger.debug("Task.%s: failure:\n%s\n",
> >                                name, pretty_traceback())
> >              self._schedule_disconnect()
> >              raise
> > 
> > Given EOF is a "normal" thing, I'm not convinced it justifies printing
> > a traceback.  I'd be inclined to suggest a new "except EOFError" clause
> > that catches that normal exception and thus skips the traceback.
> 
> Sounds reasonable, could you please send a patch for qemu.qmp?

https://gitlab.com/qemu-project/python-qemu-qmp/-/merge_requests/46


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 :|