| Summary: | AB-INT: psplash: AssertionError: 3 != 0 : SYSTEMD_BUS_TIMEOUT=240s systemctl status --full --failed | ||
|---|---|---|---|
| Product: | [QA/Testing] Runtime Testing | Reporter: | Mathieu Dubois-Briand <mathieu.dubois-briand> |
| Component: | general | Assignee: | Mikko Rapeli <mikko.rapeli> |
| Status: | RESOLVED FIXED | QA Contact: | |
| Severity: | normal | ||
| Priority: | Medium+ | CC: | randy.macleod, yi.zhao |
| Version: | unspecified | ||
| Target Milestone: | 5.2 M3 | ||
| Hardware: | x86 | ||
| OS: | Multiple | ||
| Whiteboard: | AB-INT | ||
| OS type for building Yocto: | --- | Type of Regression: | --- |
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |
meta-arm debian12-vk-5 mathieu/master-next completed at 2025-02-18T14:22:14Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/986/steps/22/logs/stdio meta-arm opensuse156-vk-1 master-next completed at 2025-02-18T16:14:46Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/991/steps/23/logs/stdio meta-arm ubuntu2204-vk-3 mathieu/master-next completed at 2025-02-18T18:28:41Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/992/steps/22/logs/stdio meta-arm ubuntu2204-vk-3 master completed at 2025-02-19T01:42:09Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/994/steps/22/logs/stdio meta-arm alma9-vk-1 master-next completed at 2025-02-19T10:42:12Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/997/steps/22/logs/stdio meta-arm fedora39-vk-2 master completed at 2025-02-22T01:50:42Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1017/steps/22/logs/stdio meta-arm fedora40-vk-2 master completed at 2025-02-24T01:45:23Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1021/steps/22/logs/stdio meta-arm alma8-vk-2 master-next completed at 2025-02-25T17:39:30Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1036/steps/23/logs/stdio meta-arm stream9-vk-1 master completed at 2025-02-27T01:53:58Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1053/steps/22/logs/stdio meta-arm debian11-vk-2 mathieu/master-next completed at 2025-02-27T10:54:31Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1054/steps/22/logs/stdio Patch on the list. meta-arm stream9-vk-1 mathieu/master-next completed at 2025-02-27T18:13:15Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1058/steps/22/logs/stdio https://git.openembedded.org/openembedded-core/commit/?id=580ae81e102bf999cb89f05430c737210253d90a helps but there's more work to do. Is this bug still happening in CI builds and tests with qemu? It looks like we didn't get the issue for one week now. (In reply to Mathieu Dubois-Briand from comment #7) > It looks like we didn't get the issue for one week now. I think this is because the previous failing build was missing https://git.openembedded.org/openembedded-core/commit/?id=580ae81e102bf999cb89f05430c737210253d90a which was applied Feb 28th and the build ran Feb 27th without it. Would be nice to confirm this but I can't check this from the logs or the non-public commits. Did meta meta-poky meta-yocto-bsp = "mathieu/master-next:ffe27fc69ff0de826e3d8dbffaa6e099c2d6b588" contain the fix above or not? If not, then I think this is fixed now. No I believe it did not. Branch of the said build can be found at https://git.yoctoproject.org/poky-ci-archive/log/?h=autobuilder.yoctoproject.org/valkyrie/a-full-1097 . So this is probably fixed. Marking as fixed then. I got this one on master, yet I believe the fix is still present. Only change I can see so far is a psplash update. meta-arm debian12-vk-5 master completed at 2025-05-12T01:26:07Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/1509/steps/22/logs/stdio https://git.yoctoproject.org/meta-arm/commit/?id=a86f62f1449ce0e341ccf1a1004a1177e4db4e9d and https://git.yoctoproject.org/meta-arm/commit/?id=45daeba052758831e5b589e6fab9f5a040cc6d37 show that meta-arm sbsa machine has had framebuffer related issues since the beginning. So psplash may hit this too. I had this one last week. Waited a bit to see if it reproduces, but it looks like it is a loner. Not sure if it is the intermittent issue coming back or just something that was bad in my build. meta-arm fedora40-vk-3 mathieu/master-next completed at 2025-08-13 20:59:10+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/2097/steps/22/logs/stdio (In reply to Mathieu Dubois-Briand from comment #13) > I had this one last week. Waited a bit to see if it reproduces, but it looks > like it is a loner. Not sure if it is the intermittent issue coming back or > just > something that was bad in my build. > > meta-arm fedora40-vk-3 mathieu/master-next completed at 2025-08-13 > 20:59:10+00:00 > https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/2097/ > steps/22/logs/stdio Traceback (most recent call last): File "/srv/pokybuild/yocto-worker/meta-arm/build/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^ File "/srv/pokybuild/yocto-worker/meta-arm/build/meta/lib/oeqa/runtime/cases/systemd.py", line 100, in test_systemd_failed output += self.systemctl('status --full --failed') ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/srv/pokybuild/yocto-worker/meta-arm/build/meta/lib/oeqa/runtime/cases/systemd.py", line 26, in systemctl self.assertEqual(status, expected, message) AssertionError: 3 != 0 : SYSTEMD_BUS_TIMEOUT=240s systemctl status --full --failed x psplash-start@fb0.service - Start psplash boot splash screen Loaded: loaded (/usr/lib/systemd/system/psplash-start@.service; static) Active: failed (Result: timeout) since Wed 2025-08-13 20:56:27 UTC; 1min 54s ago Invocation: 7508512f9cb84905bd737ad9c91a6c39 Process: 263 ExecStart=/usr/bin/psplash (code=killed, signal=TERM) Main PID: 263 (code=killed, signal=TERM) Mem peak: 1.1M CPU: 56ms Aug 13 20:52:27 sbsa-ref systemd[1]: Starting Start psplash boot splash screen... Aug 13 20:56:27 sbsa-ref systemd[1]: psplash-start@fb0.service: start operation timed out. Terminating. Aug 13 20:56:27 sbsa-ref systemd[1]: psplash-start@fb0.service: Failed with result 'timeout'. Aug 13 20:56:27 sbsa-ref systemd[1]: Failed to start Start psplash boot splash screen. Would be nice to see the kernel dmesg logs from the device. There could be framebuffer related errors there. Not sure but the communication with qemu framebuffer device all the way to the graphics stack of the host system so I guess there can be delays which the qemu machine SW simply can't deal with. Hum, again :( meta-arm alma8-vk-1 master-next completed at 2025-11-25 15:55:21+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/75/builds/2655/steps/24/logs/stdio Traceback (most recent call last):
File "/srv/pokybuild/yocto-worker/meta-arm/build/layers/openembedded-core/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f
return func(*args, **kwargs)
File "/srv/pokybuild/yocto-worker/meta-arm/build/layers/openembedded-core/meta/lib/oeqa/runtime/cases/systemd.py", line 100, in test_systemd_failed
output += self.systemctl('status --full --failed')
~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/srv/pokybuild/yocto-worker/meta-arm/build/layers/openembedded-core/meta/lib/oeqa/runtime/cases/systemd.py", line 26, in systemctl
self.assertEqual(status, expected, message)
~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 3 != 0 : SYSTEMD_BUS_TIMEOUT=240s systemctl status --full --failed
x psplash-start@fb0.service - Start psplash boot splash screen
Loaded: loaded (/usr/lib/systemd/system/psplash-start@.service; static)
Active: failed (Result: timeout) since Tue 2025-11-25 15:50:27 UTC; 4min 2s ago
Invocation: 6518720d00f74bf7800994ff3646e4f3
Process: 265 ExecStart=/usr/bin/psplash (code=killed, signal=TERM)
Main PID: 265 (code=killed, signal=TERM)
Mem peak: 1.1M
CPU: 99ms
Nov 25 15:46:27 sbsa-ref systemd[1]: Starting Start psplash boot splash screen...
Nov 25 15:50:27 sbsa-ref systemd[1]: psplash-start@fb0.service: start operation timed out. Terminating.
Nov 25 15:50:27 sbsa-ref systemd[1]: psplash-start@fb0.service: Failed with result 'timeout'.
Nov 25 15:50:27 sbsa-ref systemd[1]: Failed to start Start psplash boot splash screen.
Startup finished in 4.233s (firmware) + 5.340s (loader) + 3.030s (kernel) + 4min 17.571s (userspace) = 4min 30.175s.
Target boot time 270.175 exceeds systemd's TimeoutStartSec 90
This boot time feels quite slow. Was the machine really loaded? How frequently is this being hit? I presume this is pretty rare.
We could try to trace the psplash syscalls a bit more to see what is hanging for so long but I suspect it's just one of the framebuffer operations which takes for ever. This then can be caused by qemu and even the host system graphics stack which is highly loaded and slow.
What server host system was running this? Is it possible to know what kind of load the system had at the time when this happened?
|
We see this AB-INT quite often for a week or two: 304 Traceback (most recent call last): 305 File "/srv/pokybuild/yocto-worker/meta-arm/build/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f 306 return func(*args, **kwargs) 307 ^^^^^^^^^^^^^^^^^^^^^ 308 File "/srv/pokybuild/yocto-worker/meta-arm/build/meta/lib/oeqa/runtime/cases/systemd.py", line 100, in test_systemd_failed 309 output += self.systemctl('status --full --failed') 310 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 311 File "/srv/pokybuild/yocto-worker/meta-arm/build/meta/lib/oeqa/runtime/cases/systemd.py", line 26, in systemctl 312 self.assertEqual(status, expected, message) 313 AssertionError: 3 != 0 : SYSTEMD_BUS_TIMEOUT=240s systemctl status --full --failed 314 x psplash-systemd.service - Start psplash-systemd progress communication helper 315 Loaded: loaded (/usr/lib/systemd/system/psplash-systemd.service; static) 316 Active: failed (Result: exit-code) since Mon 2025-02-24 01:28:17 UTC; 15min ago 317 Duration: 531ms 318 Invocation: 463bbdc34ab1465495d76e402819f06a 319 Main PID: 262 (code=exited, status=1/FAILURE) 320 Mem peak: 1.1M 321 CPU: 165ms 322 323 Feb 24 01:28:17 sbsa-ref systemd[1]: Started Start psplash-systemd progress communication helper. 324 Feb 24 01:28:17 sbsa-ref psplash-systemd[262]: Error unable to open fifo 325 Feb 24 01:28:17 sbsa-ref systemd[1]: psplash-systemd.service: Main process exited, code=exited, status=1/FAILURE 326 Feb 24 01:28:17 sbsa-ref systemd[1]: psplash-systemd.service: Failed with result 'exit-code'.