[PATCH 0/2] tests/functional: collect more info in base.log file

[PATCH 0/2] tests/functional: collect more info in base.log file

[Daniel P. Berrangé]

This came about from looking at info in

https://gitlab.com/qemu-project/qemu/-/jobs/11877115717

where it appears we've hung in a QMP 'quit' command

https://gitlab.com/qemu-project/qemu/-/jobs/11877115717/artifacts/external_file/build/tests/functional/ppc64/test_pseries.pseriesMachine.test_ppc64_linux_big_boot/base.log

but don't have conclusive proof since we're not capturing
logs for qemu.qmp.

Daniel P. Berrangé (2):
  tests/functional: include logger name and function in messages
  tests/functional: include the lower level QMP log messages

 tests/functional/qemu_test/testcase.py | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

-- 
2.51.1

[PATCH 1/2] tests/functional: include logger name and function in messages

[Daniel P. Berrangé]

As we collect debug logs from a wide range of code it becomes
increasingly confusing to understand where each log messages comes
from. Adding "%(name)s" gives us the logger name, which is usually
based on the python __name__ symbol, aka the code module name.
Then "%(funcName)s" completes the story by identifying the function.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/functional/qemu_test/testcase.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/functional/qemu_test/testcase.py b/tests/functional/qemu_test/testcase.py
index 2c0abde395..6fc6e1ac0a 100644
--- a/tests/functional/qemu_test/testcase.py
+++ b/tests/functional/qemu_test/testcase.py
@@ -217,7 +217,7 @@ def setUp(self):
         self._log_fh = logging.FileHandler(self.log_filename, mode='w')
         self._log_fh.setLevel(logging.DEBUG)
         fileFormatter = logging.Formatter(
-            '%(asctime)s - %(levelname)s: %(message)s')
+            '%(asctime)s - %(levelname)s: %(name)s.%(funcName)s %(message)s')
         self._log_fh.setFormatter(fileFormatter)
         self.log.addHandler(self._log_fh)
 
-- 
2.51.1

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

[Daniel P. Berrangé]

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()
-- 
2.51.1

Re: [PATCH 1/2] tests/functional: include logger name and function in messages

[Thomas Huth]

On 28/10/2025 19.26, Daniel P. Berrangé wrote:
> As we collect debug logs from a wide range of code it becomes
> increasingly confusing to understand where each log messages comes
> from. Adding "%(name)s" gives us the logger name, which is usually
> based on the python __name__ symbol, aka the code module name.
> Then "%(funcName)s" completes the story by identifying the function.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/functional/qemu_test/testcase.py | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tests/functional/qemu_test/testcase.py b/tests/functional/qemu_test/testcase.py
> index 2c0abde395..6fc6e1ac0a 100644
> --- a/tests/functional/qemu_test/testcase.py
> +++ b/tests/functional/qemu_test/testcase.py
> @@ -217,7 +217,7 @@ def setUp(self):
>           self._log_fh = logging.FileHandler(self.log_filename, mode='w')
>           self._log_fh.setLevel(logging.DEBUG)
>           fileFormatter = logging.Formatter(
> -            '%(asctime)s - %(levelname)s: %(message)s')
> +            '%(asctime)s - %(levelname)s: %(name)s.%(funcName)s %(message)s')
>           self._log_fh.setFormatter(fileFormatter)
>           self.log.addHandler(self._log_fh)
>   

Reviewed-by: Thomas Huth <thuth@redhat.com>

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

[Thomas Huth]

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?

Or maybe rather log the qmp stuff into a separate file, e.g. qmp.log ?

  Thomas

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

[Daniel P. Berrangé]

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.

I don't think we need to block this patch waiting for that improvement
though. When collecting DEBUG logs there are always going to be weird
things like this present, and anything misleading just needs to be
fixed when we uncover it.

> Or maybe rather log the qmp stuff into a separate file, e.g. qmp.log ?

I really don't want separate files for different log categories, as then
you have created a problem of merging the two files in order to interpret
the flow. That doesn't doesn't scale as we capture yet more log categories.

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

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

[Thomas Huth]

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?

> I don't think we need to block this patch waiting for that improvement
> though. When collecting DEBUG logs there are always going to be weird
> things like this present, and anything misleading just needs to be
> fixed when we uncover it.

Ack.

>> Or maybe rather log the qmp stuff into a separate file, e.g. qmp.log ?
> 
> I really don't want separate files for different log categories, as then
> you have created a problem of merging the two files in order to interpret
> the flow. That doesn't doesn't scale as we capture yet more log categories.

Ok, fine with me, we still can refine later if we feel that it is necessary. So:

Reviewed-by: Thomas Huth <thuth@redhat.com>

I'll queue this for my next pull request.

  Thomas

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

[Daniel P. Berrangé]

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