Created attachment 2655 [details] results of nightly-qa-systemd build 423, sanity tests 2 When running sanity tests 2 on nightly-qa-systemd for core-image-sato (do_testimage task), avahi daemon fails to start, which causes test_systemd_failed and test_systemd_status test to fail. Builder: nightly-qa-systemd Build: 423 Buildslave: fedora21.osl.yoctoproject.org Failed task: do_testimage fails due to test_systemd_failed and test_systemd_status test failures URL: https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/423/steps/Running%20Sanity%20Tests_2/logs/stdio/text See atttachment [1]
I tried to reproduce it without success, The errors.yp.org don't report any about this kind of error [1], the build said that was in master-next branch. [1] http://errors.yoctoproject.org/Errors/Search/?query=avahi+failed
There is another issue (8141) that fails in the same hash of master-next that was, 005a5b60f00a898b701de6df7095adf7440acebf
Created attachment 2714 [details] systemd avahi timeout sanity tests 2 The avahi startup fails due to timeout after 16 minutes.
| Aug 07 22:12:34 qemux86-64 avahi-daemon[133]: Got SIGTERM, quitting. So sometime (at least 44secs) after starting, the daemon receives SIGTERM. The only thing inside avahi that might do it is the D-Bus protocol code: there is a timeout that seems to send a SIGTERM in some cases if connection to D-Bus is not there for 30 seconds. Is there a test that would have failed before this if D-Bus isn't working?
(In reply to comment #4) > | Aug 07 22:12:34 qemux86-64 avahi-daemon[133]: Got SIGTERM, quitting. > > > So sometime (at least 44secs) after starting, the daemon receives SIGTERM. > The only thing inside avahi that might do it is the D-Bus protocol code: > there is a timeout that seems to send a SIGTERM in some cases if connection > to D-Bus is not there for 30 seconds. Is there a test that would have failed > before this if D-Bus isn't working? Systemd sent SIGTERM to avahi due to timeout (causes by QEMU is running slow), now i'm doing some system debug one path that i'm following is disable timeouts on systemd (sysvinit don't handle timeouts) but new errors appears related to dependencies.
Created attachment 2764 [details] systemd avahi timeout 3 This recent failure looks like the same thing even though the failed units were different: bluetooth.service and wpa_supplicant.service this time): https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/494/steps/Running%20Sanity%20Tests/logs/stdio
(In reply to comment #6) > Created attachment 2764 [details] > systemd avahi timeout 3 > > This recent failure looks like the same thing even though the failed units > were different: bluetooth.service and wpa_supplicant.service this time): > > https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/ > 494/steps/Running%20Sanity%20Tests/logs/stdio This confirm my theory that when qemu becoming slow the systemd timeout logic start to kill services.
I found a ticket about timeouts discussion. https://bugs.freedesktop.org/show_bug.cgi?id=68217
(In reply to comment #7) > (In reply to comment #6) > > This recent failure looks like the same thing even though the failed units > > were different: bluetooth.service and wpa_supplicant.service this time): > > > > https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/ > > 494/steps/Running%20Sanity%20Tests/logs/stdio > > This confirm my theory that when qemu becoming slow the systemd timeout > logic start to kill services. Also of note is that all of these services are of type dbus (so timeout means "did not acquire specified bus name in X seconds"): I can't tell from the logs if it's just D-Bus stalling somewhere or whole Qemu becoming slow. I guess increasing DefaultTimeoutStartSec would help but there has to be something wrong if acquiring a bus name takes tens of seconds, right?
(In reply to comment #9) > (In reply to comment #7) > > (In reply to comment #6) > > > This recent failure looks like the same thing even though the failed units > > > were different: bluetooth.service and wpa_supplicant.service this time): > > > > > > https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/ > > > 494/steps/Running%20Sanity%20Tests/logs/stdio > > > > This confirm my theory that when qemu becoming slow the systemd timeout > > logic start to kill services. > > Also of note is that all of these services are of type dbus (so timeout > means "did not acquire specified bus name in X seconds"): I can't tell from > the logs if it's just D-Bus stalling somewhere or whole Qemu becoming slow. > > I guess increasing DefaultTimeoutStartSec would help but there has to be > something wrong if acquiring a bus name takes tens of seconds, right? I disabled timeouts before [1] and this variable didn't affect dbus method calls that start to fail. The system show's boot in a good state but when execute systemctl status you will get a dbus method call timeout. [1] http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/commit/?h=alimon/systemd_fixes&id=de41bbcee84f579f59d629438da52b2f7c69512a
From my testing using a lot (a few thousand runs) of tests using rewitt's testin containers this is caused by the same ioload issues as bug 8141. My ionice comment from 8141 should apply/work here as well.
We added ioprio code to bitbake: http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=290534d3ff53b3c0a50e480863474d1785088c5a and enabled it in the autobuilder: http://git.yoctoproject.org/cgit.cgi/yocto-autobuilder/commit/?id=2f18ff6807f90543773602554da52083f3f64d0a In many repeated tests (thousands), this change resolved the issues see here. If we see this again we can reconsider.
We get similar failures again on nightly tests: | ====================================================================== | FAIL: test_systemd_failed (oeqa.runtime.systemd.SystemdBasicTests) | ---------------------------------------------------------------------- | Traceback (most recent call last): | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 106, in wrapped_f | return func(*args, **kwargs) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 94, in wrapped_f | return f(*args, **kwargs) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/runtime/systemd.py", line 65, in test_systemd_failed | self.assertTrue(match, msg="Some systemd units failed:\n%s" % output) | AssertionError: None is not true : Some systemd units failed: | UNIT LOAD ACTIVE SUB DESCRIPTION | ● bluetooth.service loaded failed failed Bluetooth service | ● ofono.service loaded failed failed Telephony service | ● wpa_supplicant.service loaded failed failed WPA supplicant | | LOAD = Reflects whether the unit definition was properly loaded. | ACTIVE = The high-level unit activation state, i.e. generalization of SUB. | SUB = The low-level unit activation state, values depend on unit type. | | 3 loaded units listed. Pass --all to see loaded but inactive units, too. | To show all installed unit files use 'systemctl list-unit-files'.● qemux86-64 | State: degraded | Jobs: 0 queued | Failed: 3 units | Since: Fri 2015-11-27 00:39:43 UTC; 26min ago | CGroup: / | ├─ 1 /sbin/init | ├─79 /sbin/v86d | └─system.slice | ├─avahi-daemon.service | │ ├─414 avahi-daemon: running [qemux86-64.local | │ └─441 avahi-daemon: chroot helpe | ├─dbus.service | ��� └─322 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation | ├─distcc.service | │ ├─498 /usr/bin/distccd --verbose --no-detach --daemon --allow 192.168.7.0/24 | │ ├─503 /usr/bin/distccd --verbose --no-detach --daemon --allow 192.168.7.0/24 | │ ├─504 /usr/bin/distccd --verbose --no-detach --daemon --allow 192.168.7.0/24 | │ └─510 /usr/bin/distccd --verbose --no-detach --daemon --allow 192.168.7.0/24 | ├─busybox-klogd.service | │ └─303 /sbin/klogd -n | ├─system-serial\x2dgetty.slice | │ ├─serial-getty@ttyS1.service | │ │ └─500 -sh | │ └─serial-getty@ttyS0.service | │ └─501 /sbin/agetty -8 -L --keep-baud ttyS0 115200 xterm | ├─systemd-journald.service | │ └─78 /lib/systemd/systemd-journald | ├─connman.service | │ └─462 /usr/sbin/connmand -n | ├─systemd-timesyncd.service | │ └─660 /lib/systemd/systemd-timesyncd | ├─systemd-logind.service | │ └─502 /lib/systemd/systemd-logind | ├─system-getty.slice | │ └─getty@tty1.service | │ └─304 /sbin/agetty --noclear tty1 linux | ├─systemd-udevd.service | │ └─100 /lib/systemd/systemd-udevd | ├─busybox-syslog.service | │ └─581 /sbin/syslogd -n -C | ├─system-dropbear.slice | │ ├─dropbear@90-192.168.7.4:22-192.168.7.3:52952.service | │ │ └─1511 /usr/bin/psplash --angle 0 | │ ├─dropbear@134-192.168.7.4:22-192.168.7.3:52996.service | │ │ ├─1762 /usr/sbin/dropbear -i -r /etc/dropbear/dropbear_rsa_host_key -B | │ │ ├─1763 sh -c . /etc/profile; systemctl status --full --failed | │ │ └─1764 systemctl status --full --failed | │ └─dropbear@13-192.168.7.4:22-192.168.7.3:52867.service | │ └─612 x11vnc -display :0 -bg -o x11vnc.log | └─xserver-nodm.service | ├─269 xinit /etc/X11/Xsession -- /usr/bin/Xorg :0 -br -pn | ├─294 /usr/bin/Xorg :0 -br -pn | ├─362 matchbox-window-manager -theme Sato -use_desktop_mode decorated -use_cursor no | ├─367 dbus-launch --sh-syntax --exit-with-session | ├─368 /usr/bin/dbus-daemon --fork --print-pid 4 --print-address 6 --session | ├─385 connman-applet | ├─395 /usr/lib/gconf/gconfd-2 | ├─410 matchbox-desktop | ├─411 matchbox-panel --titlebar --start-applets showdesktop,windowselector --end-applets clock,battery,,systray,startup-notify,notify | └─412 /usr/bin/settings-daemon | | ====================================================================== | FAIL: test_systemd_stop_start (oeqa.runtime.systemd.SystemdServiceTests) | ---------------------------------------------------------------------- | Traceback (most recent call last): | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 106, in wrapped_f | return func(*args, **kwargs) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/utils/decorators.py", line 94, in wrapped_f | return f(*args, **kwargs) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/runtime/systemd.py", line 85, in test_systemd_stop_start | self.systemctl('start','avahi-daemon.service') | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/lib/oeqa/runtime/systemd.py", line 21, in systemctl | self.assertEqual(status, expected, message) | AssertionError: 1 != 0 : systemctl start avahi-daemon.service | Job for avahi-daemon.service failed because a timeout was exceeded. See "systemctl status avahi-daemon.service" and "journalctl -xe" for details. | | ---------------------------------------------------------------------- | Ran 51 tests in 1584.597s | | FAILED (failures=2, skipped=1) | NOTE: Stopping logging thread | NOTE: Stop event received | NOTE: Tearing down logging thread | NOTE: Sending SIGTERM to runqemu | DEBUG: Python function do_testimage finished | ERROR: Function failed: core-image-sato - FAILED - check the task log and the ssh log NOTE: recipe core-image-sato-1.0-r0: task do_testimage: Failed ERROR: Task 0 (/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/recipes-sato/images/core-image-sato.bb, do_testimage) failed with exit code '1' NOTE: Tasks Summary: Attempted 323 tasks of which 322 didn't need to be rerun and 1 failed. NOTE: The errors for this build are stored in /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/build/tmp/log/error-report/error_report_20151127003840.txt You can send the errors to a reports server by running: send-error-report /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/build/tmp/log/error-report/error_report_20151127003840.txt [-s server] NOTE: The contents of these logs will be posted in public if you use the above command with the default server. Please ensure you remove any identifying or proprietary information when prompted before sending. Summary: 1 task failed: /home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-systemd/build/meta/recipes-sato/images/core-image-sato.bb, do_testimage Summary: There was 1 ERROR message shown, returning a non-zero exit code. program finished with exit code 1 elapsedTime=1857.440831
Created attachment 2877 [details] https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/542/steps/Running%20Sanity%20Tests_2/logs/stdio Complete Log file
*** Bug 8937 has been marked as a duplicate of this bug. ***
For have a better understanding and argue that this issue is due to timeouts, we need to enable tracing of boot and process times so add 9299 as dependency.
My fault, moving it to M1 again. CCB should agree on any milestone moved.
This is a random issue and has not been observed recently. For a better understanding (more log), the 9299 bug should be done first.
I found another way (working on #9299) to make systemd fail by timeout on tty-SN devices, If you enable systemd.log_level=debug systemd.log_target=journal into the kernelcmd modifying the runqemu-internal, --- a/scripts/runqemu-internal +++ b/scripts/runqemu-internal @@ -725,7 +725,7 @@ elif [ "$FSTYPE" = "iso" -o "$FSTYPE" = "wic" ]; then else QEMU_FIRE="$QEMUBIN -kernel $KERNEL $QEMUOPTIONS $SLIRP_CMD $SERIALOPTS -no-reboot $SCRIPT_QEMU_OPT $SCRIPT_QEMU_EXTRA_OPT" echo $QEMU_FIRE -append '"'$KERNCMDLINE $SCRIPT_KERNEL_OPT'"' - LD_PRELOAD="$GL_LD_PRELOAD" $QEMU_FIRE -append "$KERNCMDLINE $SCRIPT_KERNEL_OPT" + LD_PRELOAD="$GL_LD_PRELOAD" $QEMU_FIRE -append "$KERNCMDLINE systemd.log_level=debug systemd.log_target=journal $SCRIPT_KERNEL_OPT" fi ret=$? if [ "$SLIRP_ENABLED" != "yes" ]; then It fails because the journalctl did a lot of I/O (saving debug log) and the systemd devices timeout is reach (4 min).
We recently enabled KVM [1] into the main autobuilder cluster. This will help to avoid this kind of issues. [1] https://lists.yoctoproject.org/pipermail/yocto/2016-August/031586.html
A patch for fix systemd ttySN timeout issues, http://lists.openembedded.org/pipermail/openembedded-core/2016-September/126166.html
The tty-SN device timeout issue fix was merged at, http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=d41968d8a8bd572b2892762f7092868950465014 With the enable of KVM into AB LF cluster, i hope this problem don't appear again.