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

[Thomas Huth <thuth@redhat.com>]

On 04/11/2024 13.46, Daniel P. Berrangé wrote:
> 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

Our pycotap setup redirects this to stderr, so we're fine here. But if you 
prefer, we could also directly print it to stderr right from the start instead.

  Thomas