Some tests are creating their on logger category which means any
output they log is not captured in base.log.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/functional/aarch64/test_virt.py     |  4 +--
 tests/functional/arm/test_integratorcp.py |  3 +-
 tests/functional/mips64el/test_malta.py   |  3 +-
 tests/functional/replay_kernel.py         | 16 ++++-----
 tests/functional/reverse_debugging.py     | 41 +++++++++++------------
 tests/functional/x86_64/test_acpi_bits.py | 31 +++++++++--------
 6 files changed, 44 insertions(+), 54 deletions(-)

diff --git a/tests/functional/aarch64/test_virt.py b/tests/functional/aarch64/test_virt.py
index 4d0ad90ff8..63071f9b51 100755
--- a/tests/functional/aarch64/test_virt.py
+++ b/tests/functional/aarch64/test_virt.py
@@ -72,8 +72,6 @@ def common_aarch64_virt(self, machine):
         self.set_machine('virt')
         self.require_accelerator("tcg")
 
-        logger = logging.getLogger('aarch64_virt')
-
         kernel_path = self.ASSET_KERNEL.fetch()
 
         self.vm.set_console()
@@ -91,7 +89,7 @@ def common_aarch64_virt(self, machine):
                          'rng-random,id=rng0,filename=/dev/urandom')
 
         # Also add a scratch block device
-        logger.info('creating scratch qcow2 image')
+        self.log.info('creating scratch qcow2 image')
         image_path = self.scratch_file('scratch.qcow2')
         qemu_img = get_qemu_img(self)
         check_call([qemu_img, 'create', '-f', 'qcow2', image_path, '8M'],
diff --git a/tests/functional/arm/test_integratorcp.py b/tests/functional/arm/test_integratorcp.py
index 4f00924aa0..23ae919359 100755
--- a/tests/functional/arm/test_integratorcp.py
+++ b/tests/functional/arm/test_integratorcp.py
@@ -77,7 +77,6 @@ def test_framebuffer_tux_logo(self):
                           command_line='screendump %s' % screendump_path)
         if 'unknown command' in res:
             self.skipTest('screendump not available')
-        logger = logging.getLogger('framebuffer')
 
         cpu_count = 1
         match_threshold = 0.92
@@ -88,7 +87,7 @@ def test_framebuffer_tux_logo(self):
         loc = np.where(result >= match_threshold)
         tux_count = 0
         for tux_count, pt in enumerate(zip(*loc[::-1]), start=1):
-            logger.debug('found Tux at position [x, y] = %s', pt)
+            self.log.debug('found Tux at position [x, y] = %s', pt)
         self.assertGreaterEqual(tux_count, cpu_count)
 
 if __name__ == '__main__':
diff --git a/tests/functional/mips64el/test_malta.py b/tests/functional/mips64el/test_malta.py
index 8fdc49b300..170147bfcc 100755
--- a/tests/functional/mips64el/test_malta.py
+++ b/tests/functional/mips64el/test_malta.py
@@ -159,7 +159,6 @@ def do_test_i6400_framebuffer_logo(self, cpu_cores_count):
                           command_line='screendump %s' % screendump_path)
         if 'unknown command' in res:
             self.skipTest('screendump not available')
-        logger = logging.getLogger('framebuffer')
 
         match_threshold = 0.95
         screendump_bgr = cv2.imread(screendump_path, cv2.IMREAD_COLOR)
@@ -171,7 +170,7 @@ def do_test_i6400_framebuffer_logo(self, cpu_cores_count):
         h, w = tuxlogo_bgr.shape[:2]
         debug_png = os.getenv('QEMU_TEST_CV2_SCREENDUMP_PNG_PATH')
         for tuxlogo_count, pt in enumerate(zip(*loc[::-1]), start=1):
-            logger.debug('found Tux at position (x, y) = %s', pt)
+            self.log.debug('found Tux at position (x, y) = %s', pt)
             cv2.rectangle(screendump_bgr, pt,
                           (pt[0] + w, pt[1] + h), (0, 0, 255), 2)
         if debug_png:
diff --git a/tests/functional/replay_kernel.py b/tests/functional/replay_kernel.py
index 80795eb052..acb1d29a1b 100644
--- a/tests/functional/replay_kernel.py
+++ b/tests/functional/replay_kernel.py
@@ -32,15 +32,14 @@ def run_vm(self, kernel_path, kernel_command_line, console_pattern,
         # icount requires TCG to be available
         self.require_accelerator('tcg')
 
-        logger = logging.getLogger('replay')
         start_time = time.time()
         vm = self.get_vm(name='recording' if record else 'replay')
         vm.set_console()
         if record:
-            logger.info('recording the execution...')
+            self.log.info('recording the execution...')
             mode = 'record'
         else:
-            logger.info('replaying the execution...')
+            self.log.info('replaying the execution...')
             mode = 'replay'
         vm.add_args('-icount', 'shift=%s,rr=%s,rrfile=%s' %
                     (shift, mode, replay_path),
@@ -54,15 +53,15 @@ def run_vm(self, kernel_path, kernel_command_line, console_pattern,
         self.wait_for_console_pattern(console_pattern, vm)
         if record:
             vm.shutdown()
-            logger.info('finished the recording with log size %s bytes'
+            self.log.info('finished the recording with log size %s bytes'
                         % os.path.getsize(replay_path))
             self.run_replay_dump(replay_path)
-            logger.info('successfully tested replay-dump.py')
+            self.log.info('successfully tested replay-dump.py')
         else:
             vm.wait()
-            logger.info('successfully finished the replay')
+            self.log.info('successfully finished the replay')
         elapsed = time.time() - start_time
-        logger.info('elapsed time %.2f sec' % elapsed)
+        self.log.info('elapsed time %.2f sec' % elapsed)
         return elapsed
 
     def run_replay_dump(self, replay_path):
@@ -80,5 +79,4 @@ def run_rr(self, kernel_path, kernel_command_line, console_pattern,
                          True, shift, args, replay_path)
         t2 = self.run_vm(kernel_path, kernel_command_line, console_pattern,
                          False, shift, args, replay_path)
-        logger = logging.getLogger('replay')
-        logger.info('replay overhead {:.2%}'.format(t2 / t1 - 1))
+        self.log.info('replay overhead {:.2%}'.format(t2 / t1 - 1))
diff --git a/tests/functional/reverse_debugging.py b/tests/functional/reverse_debugging.py
index fbb5adbcce..be5d70f97f 100644
--- a/tests/functional/reverse_debugging.py
+++ b/tests/functional/reverse_debugging.py
@@ -35,14 +35,13 @@ class ReverseDebugging(LinuxKernelTest):
     endian_is_le = True
 
     def run_vm(self, record, shift, args, replay_path, image_path, port):
-        logger = logging.getLogger('replay')
         vm = self.get_vm(name='record' if record else 'replay')
         vm.set_console()
         if record:
-            logger.info('recording the execution...')
+            self.log.info('recording the execution...')
             mode = 'record'
         else:
-            logger.info('replaying the execution...')
+            self.log.info('replaying the execution...')
             mode = 'replay'
             vm.add_args('-gdb', 'tcp::%d' % port, '-S')
         vm.add_args('-icount', 'shift=%s,rr=%s,rrfile=%s,rrsnapshot=init' %
@@ -95,10 +94,8 @@ def vm_get_icount(vm):
         return vm.qmp('query-replay')['return']['icount']
 
     def reverse_debugging(self, shift=7, args=None):
-        logger = logging.getLogger('replay')
-
         # create qcow2 for snapshots
-        logger.info('creating qcow2 image for VM snapshots')
+        self.log.info('creating qcow2 image for VM snapshots')
         image_path = os.path.join(self.workdir, 'disk.qcow2')
         qemu_img = get_qemu_img(self)
         if qemu_img is None:
@@ -106,7 +103,7 @@ def reverse_debugging(self, shift=7, args=None):
                           'create the temporary qcow2 image')
         out = check_output([qemu_img, 'create', '-f', 'qcow2', image_path, '128M'],
                            encoding='utf8')
-        logger.info("qemu-img: %s" % out)
+        self.log.info("qemu-img: %s" % out)
 
         replay_path = os.path.join(self.workdir, 'replay.bin')
 
@@ -117,13 +114,13 @@ def reverse_debugging(self, shift=7, args=None):
         last_icount = self.vm_get_icount(vm)
         vm.shutdown()
 
-        logger.info("recorded log with %s+ steps" % last_icount)
+        self.log.info("recorded log with %s+ steps" % last_icount)
 
         # replay and run debug commands
         with Ports() as ports:
             port = ports.find_free_port()
             vm = self.run_vm(False, shift, args, replay_path, image_path, port)
-        logger.info('connecting to gdbstub')
+        self.log.info('connecting to gdbstub')
         g = GDBRemote('127.0.0.1', port, False, False)
         g.connect()
         r = g.cmd(b'qSupported')
@@ -134,59 +131,59 @@ def reverse_debugging(self, shift=7, args=None):
         if b'ReverseContinue+' not in r:
             self.fail('Reverse continue is not supported by QEMU')
 
-        logger.info('stepping forward')
+        self.log.info('stepping forward')
         steps = []
         # record first instruction addresses
         for _ in range(self.STEPS):
             pc = self.get_pc(g)
-            logger.info('saving position %x' % pc)
+            self.log.info('saving position %x' % pc)
             steps.append(pc)
             self.gdb_step(g)
 
         # visit the recorded instruction in reverse order
-        logger.info('stepping backward')
+        self.log.info('stepping backward')
         for addr in steps[::-1]:
             self.gdb_bstep(g)
             self.check_pc(g, addr)
-            logger.info('found position %x' % addr)
+            self.log.info('found position %x' % addr)
 
         # visit the recorded instruction in forward order
-        logger.info('stepping forward')
+        self.log.info('stepping forward')
         for addr in steps:
             self.check_pc(g, addr)
             self.gdb_step(g)
-            logger.info('found position %x' % addr)
+            self.log.info('found position %x' % addr)
 
         # set breakpoints for the instructions just stepped over
-        logger.info('setting breakpoints')
+        self.log.info('setting breakpoints')
         for addr in steps:
             # hardware breakpoint at addr with len=1
             g.cmd(b'Z1,%x,1' % addr, b'OK')
 
         # this may hit a breakpoint if first instructions are executed
         # again
-        logger.info('continuing execution')
+        self.log.info('continuing execution')
         vm.qmp('replay-break', icount=last_icount - 1)
         # continue - will return after pausing
         # This could stop at the end and get a T02 return, or by
         # re-executing one of the breakpoints and get a T05 return.
         g.cmd(b'c')
         if self.vm_get_icount(vm) == last_icount - 1:
-            logger.info('reached the end (icount %s)' % (last_icount - 1))
+            self.log.info('reached the end (icount %s)' % (last_icount - 1))
         else:
-            logger.info('hit a breakpoint again at %x (icount %s)' %
+            self.log.info('hit a breakpoint again at %x (icount %s)' %
                         (self.get_pc(g), self.vm_get_icount(vm)))
 
-        logger.info('running reverse continue to reach %x' % steps[-1])
+        self.log.info('running reverse continue to reach %x' % steps[-1])
         # reverse continue - will return after stopping at the breakpoint
         g.cmd(b'bc', b'T05thread:01;')
 
         # assume that none of the first instructions is executed again
         # breaking the order of the breakpoints
         self.check_pc(g, steps[-1])
-        logger.info('successfully reached %x' % steps[-1])
+        self.log.info('successfully reached %x' % steps[-1])
 
         g.close()
 
-        logger.info('exiting gdb and qemu')
+        self.log.info('exiting gdb and qemu')
         vm.shutdown()
diff --git a/tests/functional/x86_64/test_acpi_bits.py b/tests/functional/x86_64/test_acpi_bits.py
index 8e0563a97b..9a2816533d 100755
--- a/tests/functional/x86_64/test_acpi_bits.py
+++ b/tests/functional/x86_64/test_acpi_bits.py
@@ -121,10 +121,10 @@ def __init__(self, *args, **kwargs):
         self._debugcon_log = 'debugcon-log.txt'
 
     def _print_log(self, log):
-        self.logger.info('\nlogs from biosbits follows:')
-        self.logger.info('==========================================\n')
-        self.logger.info(log)
-        self.logger.info('==========================================\n')
+        self.log.info('\nlogs from biosbits follows:')
+        self.log.info('==========================================\n')
+        self.log.info(log)
+        self.log.info('==========================================\n')
 
     def copy_bits_config(self):
         """ copies the bios bits config file into bits.
@@ -138,8 +138,8 @@ def copy_bits_config(self):
         self.assertTrue(os.path.exists(bits_config_file))
         self.assertTrue(os.path.exists(target_config_dir))
         shutil.copy2(bits_config_file, target_config_dir)
-        self.logger.info('copied config file %s to %s',
-                         bits_config_file, target_config_dir)
+        self.log.info('copied config file %s to %s',
+                      bits_config_file, target_config_dir)
 
     def copy_test_scripts(self):
         """copies the python test scripts into bits. """
@@ -163,8 +163,8 @@ def copy_test_scripts(self):
                 newfilename = os.path.splitext(filename)[0] + '.py'
                 shutil.copy2(os.path.join(bits_test_dir, filename),
                              os.path.join(target_test_dir, newfilename))
-                self.logger.info('copied test file %s to %s',
-                                 filename, target_test_dir)
+                self.log.info('copied test file %s to %s',
+                              filename, target_test_dir)
 
                 # now remove the pyc test file if it exists, otherwise the
                 # changes in the python test script won't be executed.
@@ -172,9 +172,9 @@ def copy_test_scripts(self):
                 if os.access(os.path.join(target_test_dir, testfile_pyc),
                              os.F_OK):
                     os.remove(os.path.join(target_test_dir, testfile_pyc))
-                    self.logger.info('removed compiled file %s',
-                                     os.path.join(target_test_dir,
-                                     testfile_pyc))
+                    self.log.info('removed compiled file %s',
+                                  os.path.join(target_test_dir,
+                                               testfile_pyc))
 
     def fix_mkrescue(self, mkrescue):
         """ grub-mkrescue is a bash script with two variables, 'prefix' and
@@ -216,7 +216,7 @@ def generate_bits_iso(self):
 
         self.fix_mkrescue(mkrescue_script)
 
-        self.logger.info('using grub-mkrescue for generating biosbits iso ...')
+        self.log.info('using grub-mkrescue for generating biosbits iso ...')
 
         try:
             if os.getenv('V') or os.getenv('BITS_DEBUG'):
@@ -225,7 +225,7 @@ def generate_bits_iso(self):
                                       stdout=subprocess.PIPE,
                                       stderr=subprocess.STDOUT,
                                       check=True)
-                self.logger.info("grub-mkrescue output %s" % proc.stdout)
+                self.log.info("grub-mkrescue output %s" % proc.stdout)
             else:
                 subprocess.check_call([mkrescue_script, '-o',
                                       iso_file, bits_dir],
@@ -238,11 +238,10 @@ def generate_bits_iso(self):
 
         self.assertTrue(os.access(iso_file, os.R_OK))
 
-        self.logger.info('iso file %s successfully generated.', iso_file)
+        self.log.info('iso file %s successfully generated.', iso_file)
 
     def setUp(self): # pylint: disable=arguments-differ
         super().setUp()
-        self.logger = self.log
 
         prebuiltDir = self.scratch_file('prebuilt')
         if not os.path.isdir(prebuiltDir):
@@ -333,7 +332,7 @@ def test_acpi_smbios_bits(self):
         # in batch mode and then automatically initiate a vm shutdown.
         self._vm.event_wait('SHUTDOWN', timeout=BITS_TIMEOUT)
         self._vm.wait(timeout=None)
-        self.logger.debug("Checking console output ...")
+        self.log.debug("Checking console output ...")
         self.parse_log()
 
 if __name__ == '__main__':
-- 
2.50.1

Daniel P. Berrangé <berrange@redhat.com> writes:

> Some tests are creating their on logger category which means any
> output they log is not captured in base.log.

This seems unrelated to reverse debugging and perhaps should be split to
each test. But otherwise LGTM:

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

On Mon, Sep 15, 2025 at 11:19:21AM +0100, Alex Bennée wrote:
> Daniel P. Berrangé <berrange@redhat.com> writes:
> 
> > Some tests are creating their on logger category which means any
> > output they log is not captured in base.log.
> 
> This seems unrelated to reverse debugging and perhaps should be split to
> each test. But otherwise LGTM:

The reverse_debugging.py changes were because I wanted to see the log
messages from that test when debugging this series. I then noticed
several other tests had the same problem of logging to a category
that is not saved.

> 
> Reviewed-by: Alex Bennée <alex.bennee@linaro.org>
> 
> -- 
> Alex Bennée
> Virtualisation Tech Lead @ Linaro
> 

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