Bug 1948042 - systemd-networkd fails at system start
Summary: systemd-networkd fails at system start
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: dbus-broker
Version: 34
Hardware: x86_64
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: David Rheinsberg
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-04-09 20:13 UTC by Andrew G. Dunn
Modified: 2022-06-08 06:33 UTC (History)
25 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2022-06-08 06:33:13 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)

Description Andrew G. Dunn 2021-04-09 20:13:50 UTC 
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.
Comment 1 Göran Uddeborg 2021-04-11 17:31:36 UTC 
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.
Comment 2 Andrew G. Dunn 2021-04-12 01:01:20 UTC 
Thanks Göran, can confirm this workaround addresses my issues (for both systemd-networkd and systemd-timesyncd)
Comment 3 Leif Liddy 2021-05-01 03:23:51 UTC 
Thanks Göran, your workaround works great!
Comment 4 Gerhard Wiesinger 2021-05-02 17:01:05 UTC 
Thanks Göran, can confirm your workaround works great!
Comment 5 Zbigniew Jędrzejewski-Szmek 2021-05-07 13:59:47 UTC 
Possibly related:https://github.com/systemd/systemd/issues/19212.
Comment 6 Dominik 'Rathann' Mierzejewski 2021-05-17 08:53:01 UTC 
Same here, but without AVCs. Issue started after upgrading my VM to F34.
Comment 7 Zbigniew Jędrzejewski-Szmek 2021-06-21 16:41:07 UTC 
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.
Comment 8 David Rheinsberg 2021-06-24 09:51:13 UTC 
dbus-broker-29-1 will include this fix. Already available in rawhide, updates for F34 pending.
Comment 9 David Rheinsberg 2021-06-24 09:51:54 UTC 
Thanks a lot for the report and the detailed comments on Github! If this does not suffice, let me know!
Comment 10 reescf 2022-03-11 13:48:12 UTC 
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?
Comment 11 reescf 2022-03-11 13:54:22 UTC 
Göran's workaround works great, though - thanks very much for that unit.
Comment 12 Ben Cotton 2022-05-12 16:59:15 UTC 
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.
Comment 13 Ben Cotton 2022-06-08 06:33:13 UTC 
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.
Note You need to log in before you can comment on or make changes to this bug.