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é <[email protected]>
> > > > ---
> > > > 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 :|
