check-function failing on func-arm-arm_aspeed

check-function failing on func-arm-arm_aspeed

[Peter Maydell]

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.

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.

thanks
-- PMM

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

[Pierrick Bouvier]

Hi Peter,

On 10/28/24 10: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.
> 
> 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.
> 
> thanks
> -- PMM
> 

I didn't observe such failure in last run for my dev branch (which 
includes commit you mentioned) [1].

97/148 qemu:func-thorough+func-arm-thorough+thorough / 
func-arm-arm_aspeed                                         OK 
    141.44s   8 subtests passed

[1] 
https://github.com/pbo-linaro/qemu-ci/actions/runs/11559006814/job/32172747854

Regards,
Pierrick

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

[Thomas Huth]

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)
  
      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?

  Thomas

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

[Cédric Le Goater]

On 11/4/24 13:12, 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?

I have never seen this issue on the systems I use. Let me try again.


Thanks,

C.



  

> 
>> 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)
> 
>       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?
> 
>   Thomas
> 

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

[Daniel P. Berrangé]

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

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

[Thomas Huth]

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

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

[Cédric Le Goater]

On 11/4/24 13:19, Cédric Le Goater wrote:
> On 11/4/24 13:12, 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?
> 
> I have never seen this issue on the systems I use. Let me try again.

On a (slow) ARM SBC, I am seeing a timeout indeed.

The log file contains :

2024-11-04 13:59:01,219: Starting dropbear sshd: OK
2024-11-04 13:59:01,628: Aspeed AST2600 EVB
2024-11-04 13:59:01,829: ast2600-evb login: root
2024-11-04 13:59:01,847: passw0rd
2024-11-04 13:59:01,850: echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device
2024-11-04 14:00:13,916: Password:
2024-11-04 14:00:13,917: Login timed out after 60 seconds
2024-11-04 14:00:15,418: Aspeed AST2600 EVB

This means that the sleep workaround failed :/

         # the line before login:
         self.wait_for_console_pattern(pattern)
         time.sleep(0.1)
         exec_command(self, 'root')
         time.sleep(0.1)
         exec_command(self, "passw0rd")

C.

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

[Cédric Le Goater]

On 11/4/24 14:16, Cédric Le Goater wrote:
> On 11/4/24 13:19, Cédric Le Goater wrote:
>> On 11/4/24 13:12, 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?
>>
>> I have never seen this issue on the systems I use. Let me try again.
> 
> On a (slow) ARM SBC, I am seeing a timeout indeed.
> 
> The log file contains :
> 
> 2024-11-04 13:59:01,219: Starting dropbear sshd: OK
> 2024-11-04 13:59:01,628: Aspeed AST2600 EVB
> 2024-11-04 13:59:01,829: ast2600-evb login: root
> 2024-11-04 13:59:01,847: passw0rd
> 2024-11-04 13:59:01,850: echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device
> 2024-11-04 14:00:13,916: Password:
> 2024-11-04 14:00:13,917: Login timed out after 60 seconds
> 2024-11-04 14:00:15,418: Aspeed AST2600 EVB
> 
> This means that the sleep workaround failed :/
> 
>          # the line before login:
>          self.wait_for_console_pattern(pattern)
>          time.sleep(0.1)
>          exec_command(self, 'root')
>          time.sleep(0.1)
>          exec_command(self, "passw0rd")
> 
> C.

Also, curiously, I can't reproduce when run "manually" :

   $ QEMU_TEST_QEMU_BINARY=build/qemu-system-arm PYTHONPATH=python:tests/functional build/pyvenv/bin/python3 tests/functional/test_arm_aspeed.py
   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
   ok 4 test_arm_aspeed.AST2x00Machine.test_arm_ast2500_evb_buildroot
   ok 5 test_arm_aspeed.AST2x00Machine.test_arm_ast2500_romulus_openbmc_v2_9_0
   ok 6 test_arm_aspeed.AST2x00Machine.test_arm_ast2600_evb_buildroot
   ok 7 test_arm_aspeed.AST2x00Machine.test_arm_ast2600_evb_buildroot_tpm
   ok 8 test_arm_aspeed.AST2x00MachineMMC.test_arm_aspeed_emmc_boot
   1..8


C.

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

[Peter Maydell]

On Mon, 4 Nov 2024 at 13:16, Cédric Le Goater <clg@kaod.org> wrote:
>
> On 11/4/24 13:19, Cédric Le Goater wrote:
> > On 11/4/24 13:12, 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?
> >
> > I have never seen this issue on the systems I use. Let me try again.
>
> On a (slow) ARM SBC, I am seeing a timeout indeed.
>
> The log file contains :
>
> 2024-11-04 13:59:01,219: Starting dropbear sshd: OK
> 2024-11-04 13:59:01,628: Aspeed AST2600 EVB
> 2024-11-04 13:59:01,829: ast2600-evb login: root
> 2024-11-04 13:59:01,847: passw0rd
> 2024-11-04 13:59:01,850: echo lm75 0x4d > /sys/class/i2c-dev/i2c-3/device/new_device
> 2024-11-04 14:00:13,916: Password:
> 2024-11-04 14:00:13,917: Login timed out after 60 seconds
> 2024-11-04 14:00:15,418: Aspeed AST2600 EVB
>
> This means that the sleep workaround failed :/
>
>          # the line before login:
>          self.wait_for_console_pattern(pattern)
>          time.sleep(0.1)
>          exec_command(self, 'root')
>          time.sleep(0.1)
>          exec_command(self, "passw0rd")

Those sleeps are definitely dubious, but I did try a local
change of bumping them to 2 seconds and it didn't fix the problem.
Looking at
 tests/functional/arm/test_arm_aspeed.AST2x00Machine.test_arm_ast2500_evb_buildroot/console.log
in the build tree (which I assume is the relevant log)
it did log in OK, and proceeded through the test to try
to power the machine off:

2024-11-04 14:39:59,092: cat /sys/class/hwmon/hwmon1/temp1_input
2024-11-04 14:39:59,110: # cat /sys/class/hwmon/hwmon1/temp1_input
2024-11-04 14:39:59,131: 18000
2024-11-04 14:39:59,131: poweroff
2024-11-04 14:39:59,139: # poweroff
2024-11-04 14:39:59,323: # Stopping dropbear sshd: OK
2024-11-04 14:40:00,615: Stopping network:

but that's where the log ends.

Digging even further I have just found

tests/functional/arm/test_arm_aspeed.AST2x00Machine.test_arm_ast2500_evb_buildroot/qemu-machine-cgjbonzx/7f39a8515f90.log

which has what looks like QEMU's stderr output, which reveals
the culprit:

../../net/checksum.c:106:9: runtime error: member access within
misaligned address 0x55a2d1887a5e for type 'struct ip_header', which
requires 4 byte alignment
0x55a2d1887a5e: note: pointer points here
 04 a8 08 00 45 00  01 48 37 9a 40 00 40 11  e9 fa 0a 00 02 0f 0a 00
02 02 00 44 00 43 01 34  19 56
             ^
    #0 0x55a2cc1f87d4 in net_checksum_calculate
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../net/checksum.c:106:9
    #1 0x55a2cbcf00ad in ftgmac100_do_tx
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../hw/net/ftgmac100.c:611:17
    #2 0x55a2cbcf00ad in ftgmac100_write
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../hw/net/ftgmac100.c:843:13
    #3 0x55a2cc7af5af in memory_region_write_accessor
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/memory.c:497:5
    #4 0x55a2cc7aec6a in access_with_adjusted_size
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/memory.c:573:18
    #5 0x55a2cc7ae717 in memory_region_dispatch_write
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/memory.c
    #6 0x55a2cc7e5c85 in flatview_write_continue_step
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/physmem.c:2786:18
    #7 0x55a2cc7dba0c in flatview_write_continue
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/physmem.c:2816:19
    #8 0x55a2cc7dba0c in flatview_write
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/physmem.c:2847:12
    #9 0x55a2cc7e4efa in subpage_write
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/physmem.c:2425:12
    #10 0x55a2cc7afa66 in memory_region_write_with_attrs_accessor
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/memory.c:518:12
    #11 0x55a2cc7aec6a in access_with_adjusted_size
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/memory.c:573:18
    #12 0x55a2cc7ae717 in memory_region_dispatch_write
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../system/memory.c
    #13 0x55a2cc86f2c8 in int_st_mmio_leN
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../accel/tcg/cputlb.c:2489:13
    #14 0x55a2cc86f2c8 in do_st_mmio_leN
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../accel/tcg/cputlb.c:2524:12
    #15 0x55a2cc85d2e0 in do_st_4
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../accel/tcg/cputlb.c:2694:9
    #16 0x55a2cc85d2e0 in do_st4_mmu
/mnt/nvmedisk/linaro/qemu-from-laptop/qemu/build/arm-clang/../../accel/tcg/cputlb.c:2770:9
    #17 0x7fb73a213e05  (<unknown module>)

SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior
../../net/checksum.c:106:9 in


So the network device in this board has hit an undefined
behaviour which clang's sanitizer has detected and
made QEMU abort.

The test framework here seems to be severely lacking:

(1) If QEMU exits with failure or crashes then we should
report the test as a failure, not a timeout
(2) If QEMU prints warnings or errors to stderr, we
should collect these in the main log file, not buried
under a rock with no pointers from the main log file
to that rock
(3) Ideally we should print at least a summary of that
failure to the terminal so the user can clearly see
"oh, this test failed because QEMU asserted or whatever"
without having to dig through all the log files

If the actual cause of the test failure had been
better reported to the user running the tests I would
have figured this out a lot faster.

thanks
-- PMM

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

[Thomas Huth]

On 04/11/2024 13.12, 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 ...

I think I likely finally found a way: Run unittest.main() with exit=False, 
then I can iterate over the results in our main() function. I'll try to come 
up with a patch...

  Thomas