Bug 1948042
| Summary: | systemd-networkd fails at system start | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Andrew G. Dunn <andrew> |
| Component: | dbus-broker | Assignee: | David Rheinsberg <daherrma> |
| Status: | CLOSED EOL | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | high | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 34 | CC: | daherrma, dluong, dominik, fedora, fedoraproject, filbranden, flepied, goeran, ipilcher, kasong, leif.liddy, lnykryn, msekleta, redhat-bugzilla, redhat, reescf, scroolik, ssahani, s, systemd-maint, tgunders, thomas, yaneti, yuwatana, zbyszek |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | x86_64 | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2022-06-08 06:33:13 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
I have started to see the same behaviour on one real hardware machine upgraded to the F34 kernel and systemd. My understanding is this happens because a race condition where systemd-networkd on this machine tries to start before dbus is available. (Other machines also updated don't have the problem, but they have slightly different services running which might tilt things the other way.)
I created a service drop in file /etc/systemd/system/systemd-networkd.service.d/after-dbus.conf
[Unit]
After=dbus.socket
With this it seems my machine can reliably boot again.
The AVCs also disappear with this extra configuration. I'm guessing systemd-networkd tries to take some other code path when dbus isn't available, something which SELinux won't allow. But that is just a guess.
Thanks Göran, can confirm this workaround addresses my issues (for both systemd-networkd and systemd-timesyncd) Thanks Göran, your workaround works great! Thanks Göran, can confirm your workaround works great! Possibly related:https://github.com/systemd/systemd/issues/19212. Same here, but without AVCs. Issue started after upgrading my VM to F34. There are two ways to fix this: in dbus-broker, create the dbus socket earlier. This is implemented by https://github.com/bus1/dbus-broker/commit/28af5ac996c94922fc49660e0efa955f57575187. I'll reassign this to dbus-broker to wait for that patch. The second way is in selinux policy, allow systemd-networkd to watch for the socket to appear. This is the same as https://bugzilla.redhat.com/show_bug.cgi?id=1970359. I'll add a comment there to include systemd-networkd in the change too. dbus-broker-29-1 will include this fix. Already available in rawhide, updates for F34 pending. Thanks a lot for the report and the detailed comments on Github! If this does not suffice, let me know! This remains a problem on current Fedora 34. Fully updated. systemd-networkd[3146]: Failed to connect to bus: Permission denied Network units fail on boot. Restarting the service succeeds. Happens every boot. I did not have this problem on Fedora 30 or 32. Essentially nothing has changed on the machine except the upgrade to 34 as I lost access to it during the pandemic and was only recently able to power it back on and run the upgrades (30->32 followed by 32->34 to avoid an unsupported upgrade). Is this fixed in 35? Göran's workaround works great, though - thanks very much for that unit. This message is a reminder that Fedora Linux 34 is nearing its end of life. Fedora will stop maintaining and issuing updates for Fedora Linux 34 on 2022-06-07. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a 'version' of '34'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, change the 'version' to a later Fedora Linux version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora Linux 34 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora Linux, you are encouraged to change the 'version' to a later version prior to this bug being closed. Fedora Linux 34 entered end-of-life (EOL) status on 2022-06-07. Fedora Linux 34 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. Thank you for reporting this bug and we are sorry it could not be fixed. |
Description of problem: At system startup systemd-networkd fails to start. After startup you can restart systemd-networkd and it functions properly. This manifested in VM and I thought it was an oddity, I've not reproduced it consistently on all of my F34 installs. All installs are x86_64, but networking varies between intel and {nvidia,mellanox}, as well as AMD/EPYC and Intel. Asked in #systemd on freenode and others confirmed to have seen the same behavior. Another oddity, that may be related, is that systemd-timesyncd also fails to start in a similar fashion at boot but can be restarted and functions properly. Version-Release number of selected component (if applicable): 248 How reproducible: consistent across multiple installs Steps to Reproduce: 1. Install Fedora 34 from Beta media 2. systemctl disable NetworkManager 3. write configurations for networkd (/etc/systemd/networkd) 4. systemctl enable systemd-networkd 5. reboot Actual results: systemd-networkd fails to start on system boot Expected results: systemd-networkd succeeds to start on system boot Additional info: Talking on IRC: - sarnold: given that the error message about permission denied happens the same moment as the inotify watch denial, that seems pretty plausible as a cause From `journalctl -b` Apr 09 14:52:58 vault systemd[1]: Starting Network Service... Apr 09 14:52:58 vault systemd[1]: Starting Load Kernel Module configfs... Apr 09 14:52:58 vault systemd[1]: modprobe: Deactivated successfully. Apr 09 14:52:58 vault systemd[1]: Finished Load Kernel Module configfs. Apr 09 14:52:58 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=modprobe@configfs comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:58 vault audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=modprobe@configfs comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:58 vault audit[2180]: AVC avc: denied { watch } for pid=2180 comm="systemd-network" path="/" dev="dm-0" ino=128 scontext=system_u:system_r:systemd_networkd_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=dir permissive=0 Apr 09 14:52:58 vault audit[2180]: SYSCALL arch=c000003e syscall=254 success=no exit=-13 a0=e a1=7f4d09eafd42 a2=180 a3=7fffd18cdb54 items=0 ppid=1 pid=2180 auid=4294967295 uid=192 gid=192 euid=192 suid=192 fsuid=192 egid=192 sgid=192 fsg> Apr 09 14:52:58 vault audit: PROCTITLE proctitle="/usr/lib/systemd/systemd-networkd" Apr 09 14:52:58 vault systemd-networkd[2180]: Failed to connect to bus: Permission denied Apr 09 14:52:58 vault systemd-networkd[2180]: Could not connect to bus: Permission denied Apr 09 14:52:58 vault systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE Apr 09 14:52:58 vault systemd[1]: systemd-networkd.service: Failed with result 'exit-code'. Apr 09 14:52:58 vault systemd[1]: Failed to start Network Service. Apr 09 14:52:58 vault systemd[1]: Dependency failed for Wait for Network to be Configured. Apr 09 14:52:58 vault audit: BPF prog-id=32 op=UNLOAD Apr 09 14:52:58 vault systemd[1]: systemd-networkd-wait-online.service: Job systemd-networkd-wait-online.service/start failed with result 'dependency'. Apr 09 14:52:58 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Apr 09 14:52:58 vault systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 1. Apr 09 14:52:58 vault systemd[1]: Stopped Network Service. Apr 09 14:52:58 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:58 vault audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:58 vault audit: BPF prog-id=33 op=LOAD Apr 09 14:52:58 vault systemd[1]: Starting Network Service... Apr 09 14:52:59 vault audit[2198]: AVC avc: denied { watch } for pid=2198 comm="systemd-network" path="/" dev="dm-0" ino=128 scontext=system_u:system_r:systemd_networkd_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=dir permissive=0 Apr 09 14:52:59 vault audit[2198]: SYSCALL arch=c000003e syscall=254 success=no exit=-13 a0=e a1=7f2a390e2d42 a2=180 a3=7fff11742044 items=0 ppid=1 pid=2198 auid=4294967295 uid=192 gid=192 euid=192 suid=192 fsuid=192 egid=192 sgid=192 fsg> Apr 09 14:52:59 vault audit: PROCTITLE proctitle="/usr/lib/systemd/systemd-networkd" Apr 09 14:52:59 vault systemd-networkd[2198]: Failed to connect to bus: Permission denied Apr 09 14:52:59 vault systemd-networkd[2198]: Could not connect to bus: Permission denied Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Failed with result 'exit-code'. Apr 09 14:52:59 vault systemd[1]: Failed to start Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 2. Apr 09 14:52:59 vault systemd[1]: Stopped Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit: BPF prog-id=34 op=LOAD Apr 09 14:52:59 vault systemd[1]: Starting Network Service... Apr 09 14:52:59 vault audit: BPF prog-id=33 op=UNLOAD Apr 09 14:52:59 vault audit[2206]: AVC avc: denied { watch } for pid=2206 comm="systemd-network" path="/" dev="dm-0" ino=128 scontext=system_u:system_r:systemd_networkd_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=dir permissive=0 Apr 09 14:52:59 vault audit[2206]: SYSCALL arch=c000003e syscall=254 success=no exit=-13 a0=e a1=7fad3152fd42 a2=180 a3=7ffede74ec24 items=0 ppid=1 pid=2206 auid=4294967295 uid=192 gid=192 euid=192 suid=192 fsuid=192 egid=192 sgid=192 fsg> Apr 09 14:52:59 vault audit: PROCTITLE proctitle="/usr/lib/systemd/systemd-networkd" Apr 09 14:52:59 vault systemd-networkd[2206]: Failed to connect to bus: Permission denied Apr 09 14:52:59 vault systemd-networkd[2206]: Could not connect to bus: Permission denied Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Failed with result 'exit-code'. Apr 09 14:52:59 vault systemd[1]: Failed to start Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 3. Apr 09 14:52:59 vault systemd[1]: Stopped Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit: BPF prog-id=34 op=UNLOAD Apr 09 14:52:59 vault audit: BPF prog-id=35 op=LOAD Apr 09 14:52:59 vault systemd[1]: Starting Network Service... Apr 09 14:52:59 vault audit[2208]: AVC avc: denied { watch } for pid=2208 comm="systemd-network" path="/" dev="dm-0" ino=128 scontext=system_u:system_r:systemd_networkd_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=dir permissive=0 Apr 09 14:52:59 vault audit[2208]: SYSCALL arch=c000003e syscall=254 success=no exit=-13 a0=e a1=7f6940be4d42 a2=180 a3=7ffebd8b2c64 items=0 ppid=1 pid=2208 auid=4294967295 uid=192 gid=192 euid=192 suid=192 fsuid=192 egid=192 sgid=192 fsg> Apr 09 14:52:59 vault audit: PROCTITLE proctitle="/usr/lib/systemd/systemd-networkd" Apr 09 14:52:59 vault systemd-networkd[2208]: Failed to connect to bus: Permission denied Apr 09 14:52:59 vault systemd-networkd[2208]: Could not connect to bus: Permission denied Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Failed with result 'exit-code'. Apr 09 14:52:59 vault systemd[1]: Failed to start Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 4. Apr 09 14:52:59 vault systemd[1]: Stopped Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit: BPF prog-id=35 op=UNLOAD Apr 09 14:52:59 vault audit: BPF prog-id=36 op=LOAD Apr 09 14:52:59 vault systemd[1]: Starting Network Service... Apr 09 14:52:59 vault kernel: acpi_cpufreq: overriding BIOS provided _PSD data Apr 09 14:52:59 vault audit[2213]: AVC avc: denied { watch } for pid=2213 comm="systemd-network" path="/" dev="dm-0" ino=128 scontext=system_u:system_r:systemd_networkd_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=dir permissive=0 Apr 09 14:52:59 vault audit[2213]: SYSCALL arch=c000003e syscall=254 success=no exit=-13 a0=e a1=7fae78299d42 a2=180 a3=7ffcdb9990f4 items=0 ppid=1 pid=2213 auid=4294967295 uid=192 gid=192 euid=192 suid=192 fsuid=192 egid=192 sgid=192 fsg> Apr 09 14:52:59 vault audit: PROCTITLE proctitle="/usr/lib/systemd/systemd-networkd" Apr 09 14:52:59 vault systemd-networkd[2213]: Failed to connect to bus: Permission denied Apr 09 14:52:59 vault systemd-networkd[2213]: Could not connect to bus: Permission denied Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Failed with result 'exit-code'. Apr 09 14:52:59 vault systemd[1]: Failed to start Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 5. Apr 09 14:52:59 vault systemd[1]: Stopped Network Service. Apr 09 14:52:59 vault audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Start request repeated too quickly. Apr 09 14:52:59 vault systemd[1]: systemd-networkd.service: Failed with result 'exit-code'. Apr 09 14:52:59 vault systemd[1]: Failed to start Network Service. Apr 09 14:52:59 vault systemd[1]: systemd-networkd.socket: Failed with result 'service-start-limit-hit'. Apr 09 14:52:59 vault systemd[1]: Finished Coldplug All udev Devices.