Re: check-function failing on func-arm-arm_aspeed

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

On Mon, Nov 04, 2024 at 01:12:16PM +0100, Thomas Huth wrote:
> On 28/10/2024 18.14, Peter Maydell wrote:
> > Trying a "make check-functional" I find that the func-arm-arm_aspeed
> > test seems to hit a timeout:
> > 
> > 18/18 qemu:func-thorough+func-arm-thorough+thorough /
> > func-arm-arm_aspeed              TIMEOUT        600.08s   killed by
> > signal 15 SIGTERM
> > 
> > This is with commit cea8ac78545a.
> 
> Cédric, is it working reliable for you?
> 
> > Does anybody else see this, or is it some oddity happening only
> > on my local dev machine?
> > 
> > The "full log" in testlog-thorough.txt doesn't seem to be
> > very full. All it has for this test is:
> > 
> > =================================== 18/18 ====================================
> > test:         qemu:func-thorough+func-arm-thorough+thorough /
> > func-arm-arm_aspeed
> > start time:   16:54:50
> > duration:     600.08s
> > result:       killed by signal 15 SIGTERM
> > command:      G_TEST_SLOW=1
> > PYTHONPATH=/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/python:/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/tests/functional
> > UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1
> > MALLOC_PERTURB_=238
> > ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1
> > MESON_TEST_ITERATION=1
> > QEMU_TEST_QEMU_IMG=/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/qemu-img
> > MSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1
> > QEMU_TEST_QEMU_BINARY=/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/qemu-system-arm
> > QEMU_BUILD_ROOT=/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang
> > /mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/pyvenv/bin/python3
> > /mnt/nvmedisk/linaro/qemu-from-laptop/qemu/tests/functional/test_arm_aspeed.py
> > ----------------------------------- stdout -----------------------------------
> > TAP version 13
> > ok 1 test_arm_aspeed.AST1030Machine.test_ast1030_zephyros_1_04
> > ok 2 test_arm_aspeed.AST1030Machine.test_ast1030_zephyros_1_07
> > ok 3 test_arm_aspeed.AST2x00Machine.test_arm_ast2400_palmetto_openbmc_v2_9_0
> > ==============================================================================
> > 
> > Is it possible to get the log to include a pointer to the
> > actual log for the test (including the guest console output)?
> > It's hard to debug tests if they don't report what they're doing.
> 
> I tried to add something to the log iff the test case failed (e.g. by
> checking defaultTestResult().wasSuccessful() or something similar in the
> tearDown() function of the test), but that does not seem to work ...
> so all I can suggest right now is to print out the path to the test log
> unconditionally, something like:
> 
> diff --git a/tests/functional/qemu_test/testcase.py b/tests/functional/qemu_test/testcase.py
> index aa0146265a..7436f37bc5 100644
> --- a/tests/functional/qemu_test/testcase.py
> +++ b/tests/functional/qemu_test/testcase.py
> @@ -47,13 +47,14 @@ def setUp(self, bin_prefix):
>          self.logdir = self.workdir
>          self.log = logging.getLogger('qemu-test')
>          self.log.setLevel(logging.DEBUG)
> -        self._log_fh = logging.FileHandler(os.path.join(self.logdir,
> -                                                        'base.log'), mode='w')
> +        log_file_name = os.path.join(self.logdir, 'base.log')
> +        self._log_fh = logging.FileHandler(log_file_name, mode='w')
>          self._log_fh.setLevel(logging.DEBUG)
>          fileFormatter = logging.Formatter(
>              '%(asctime)s - %(levelname)s: %(message)s')
>          self._log_fh.setFormatter(fileFormatter)
>          self.log.addHandler(self._log_fh)
> +        print(self.id() + ' log file: ' + log_file_name)

Surely this is going to break TAP format parsing of test output, as
diagnostics need to be prefixed with a '# '. I'm fairly sure it was
meson that complained about such stuff in the past when I converted
the acpibits test to the functional test

>      def tearDown(self):
>          self.log.removeHandler(self._log_fh)
> 
> Downside is that the message is also always printed if you e.g. run
> "make check-functional V=1" ... does that still sound ok to you?



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