* check-function failing on func-arm-arm_aspeed @ 2024-10-28 17:14 Peter Maydell 2024-10-28 21:21 ` Pierrick Bouvier 2024-11-04 12:12 ` Thomas Huth 0 siblings, 2 replies; 10+ messages in thread From: Peter Maydell @ 2024-10-28 17:14 UTC (permalink / raw) To: QEMU Developers; +Cc: Cédric Le Goater, Thomas Huth 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-10-28 17:14 check-function failing on func-arm-arm_aspeed Peter Maydell @ 2024-10-28 21:21 ` Pierrick Bouvier 2024-11-04 12:12 ` Thomas Huth 1 sibling, 0 replies; 10+ messages in thread From: Pierrick Bouvier @ 2024-10-28 21:21 UTC (permalink / raw) To: Peter Maydell, QEMU Developers; +Cc: Cédric Le Goater, Thomas Huth 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-10-28 17:14 check-function failing on func-arm-arm_aspeed Peter Maydell 2024-10-28 21:21 ` Pierrick Bouvier @ 2024-11-04 12:12 ` Thomas Huth 2024-11-04 12:19 ` Cédric Le Goater ` (2 more replies) 1 sibling, 3 replies; 10+ messages in thread From: Thomas Huth @ 2024-11-04 12:12 UTC (permalink / raw) To: Peter Maydell, QEMU Developers; +Cc: Cédric Le Goater, Daniel P. Berrange 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 ^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 12:12 ` Thomas Huth @ 2024-11-04 12:19 ` Cédric Le Goater 2024-11-04 13:16 ` Cédric Le Goater 2024-11-04 12:46 ` Daniel P. Berrangé 2024-11-05 12:10 ` Thomas Huth 2 siblings, 1 reply; 10+ messages in thread From: Cédric Le Goater @ 2024-11-04 12:19 UTC (permalink / raw) To: Thomas Huth, Peter Maydell, QEMU Developers; +Cc: Daniel P. Berrange 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 > ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 12:19 ` Cédric Le Goater @ 2024-11-04 13:16 ` Cédric Le Goater 2024-11-04 13:43 ` Cédric Le Goater 2024-11-04 15:12 ` Peter Maydell 0 siblings, 2 replies; 10+ messages in thread From: Cédric Le Goater @ 2024-11-04 13:16 UTC (permalink / raw) To: Thomas Huth, Peter Maydell, QEMU Developers; +Cc: Daniel P. Berrange 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. ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 13:16 ` Cédric Le Goater @ 2024-11-04 13:43 ` Cédric Le Goater 2024-11-04 15:12 ` Peter Maydell 1 sibling, 0 replies; 10+ messages in thread From: Cédric Le Goater @ 2024-11-04 13:43 UTC (permalink / raw) To: Thomas Huth, Peter Maydell, QEMU Developers; +Cc: Daniel P. Berrange 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. ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 13:16 ` Cédric Le Goater 2024-11-04 13:43 ` Cédric Le Goater @ 2024-11-04 15:12 ` Peter Maydell 1 sibling, 0 replies; 10+ messages in thread From: Peter Maydell @ 2024-11-04 15:12 UTC (permalink / raw) To: Cédric Le Goater; +Cc: Thomas Huth, QEMU Developers, Daniel P. Berrange 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 12:12 ` Thomas Huth 2024-11-04 12:19 ` Cédric Le Goater @ 2024-11-04 12:46 ` Daniel P. Berrangé 2024-11-04 13:01 ` Thomas Huth 2024-11-05 12:10 ` Thomas Huth 2 siblings, 1 reply; 10+ messages in thread From: Daniel P. Berrangé @ 2024-11-04 12:46 UTC (permalink / raw) To: Thomas Huth; +Cc: Peter Maydell, QEMU Developers, Cédric Le Goater 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 :| ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 12:46 ` Daniel P. Berrangé @ 2024-11-04 13:01 ` Thomas Huth 0 siblings, 0 replies; 10+ messages in thread From: Thomas Huth @ 2024-11-04 13:01 UTC (permalink / raw) To: Daniel P. Berrangé Cc: Peter Maydell, QEMU Developers, Cédric Le Goater 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: check-function failing on func-arm-arm_aspeed 2024-11-04 12:12 ` Thomas Huth 2024-11-04 12:19 ` Cédric Le Goater 2024-11-04 12:46 ` Daniel P. Berrangé @ 2024-11-05 12:10 ` Thomas Huth 2 siblings, 0 replies; 10+ messages in thread From: Thomas Huth @ 2024-11-05 12:10 UTC (permalink / raw) To: Peter Maydell, QEMU Developers; +Cc: Cédric Le Goater, Daniel P. Berrange 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2024-11-05 12:12 UTC | newest] Thread overview: 10+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2024-10-28 17:14 check-function failing on func-arm-arm_aspeed Peter Maydell 2024-10-28 21:21 ` Pierrick Bouvier 2024-11-04 12:12 ` Thomas Huth 2024-11-04 12:19 ` Cédric Le Goater 2024-11-04 13:16 ` Cédric Le Goater 2024-11-04 13:43 ` Cédric Le Goater 2024-11-04 15:12 ` Peter Maydell 2024-11-04 12:46 ` Daniel P. Berrangé 2024-11-04 13:01 ` Thomas Huth 2024-11-05 12:10 ` Thomas Huth
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).