#922550 ifupdown: network hangs for 5 minutes at startup / Failed to start Wait for network to be configured by ifupdown

Package:
ifupdown
Source:
ifupdown
Description:
high level tools to configure network interfaces
Submitter:
Vincent Lefevre
Date:
2022-01-20 20:39:05 UTC
Severity:
important
Tags:
#922550#5
Date:
2019-02-17 22:50:34 UTC
From:
To:
After the ifupdown upgrade from 0.8.33 to 0.8.35, I now need to wait
for 5 minutes before eth0 is up.

I've attached the beginning of "journalctl -b -1" output. At the end
of these 5 minutes, one can see:

Feb 17 23:15:24 zira systemd[1]: ifupdown-wait-online.service: Main process exited, code=exited, status=1/FAILURE
Feb 17 23:15:24 zira systemd[1]: ifupdown-wait-online.service: Failed with result 'exit-code'.
Feb 17 23:15:24 zira systemd[1]: Failed to start Wait for network to be configured by ifupdown.

Then everything can resume, and it is netplug that puts eth0 up.

With ifupdown 0.8.33, it was also netplug that put eth0 up, but it
did that 2 seconds after the start of the boot. Now, ifupdown 0.8.35
seems to block some units (including netplug).
--- /etc/network/interfaces.d/*:
cat: '/etc/network/interfaces.d/*': No such file or directory

--- up and down scripts installed:
/etc/network/if-down.d:
total 8
lrwxrwxrwx 1 vinc17 vinc17   12 2016-06-02 03:12:12 0ifupdown -> ../0ifupdown
-rwxr-xr-x 1 root   root   1015 2015-04-13 22:26:48 avahi-autoipd
-rwxr-xr-x 1 root   root    800 2017-01-09 15:25:22 postfix
lrwxrwxrwx 1 root   root     32 2019-01-29 18:11:01 wpasupplicant -> ../../wpa_supplicant/ifupdown.sh

/etc/network/if-post-down.d:
total 4
lrwxrwxrwx 1 vinc17 vinc17   12 2016-06-02 03:12:12 0ifupdown -> ../0ifupdown
lrwxrwxrwx 1 root   root     23 2018-10-10 10:17:36 avahi-daemon -> ../if-up.d/avahi-daemon
-rwxr-xr-x 1 root   root   1409 2016-03-24 18:38:26 wireless-tools
lrwxrwxrwx 1 root   root     32 2019-01-29 18:11:01 wpasupplicant -> ../../wpa_supplicant/ifupdown.sh

/etc/network/if-pre-up.d:
total 12
lrwxrwxrwx 1 vinc17 vinc17   12 2016-06-02 03:12:12 0ifupdown -> ../0ifupdown
-rwxr-xr-x 1 root   root    344 2014-09-22 01:13:29 ethtool
-rwxr-xr-x 1 root   root   4191 2018-09-15 16:13:34 wireless-tools
lrwxrwxrwx 1 root   root     32 2019-01-29 18:11:01 wpasupplicant -> ../../wpa_supplicant/ifupdown.sh

/etc/network/if-up.d:
total 32
lrwxrwxrwx 1 vinc17 vinc17   12 2016-06-02 03:12:12 0ifupdown -> ../0ifupdown
-rwxr-xr-x 1 root   root    923 2015-04-13 22:26:48 avahi-autoipd
-rwxr-xr-x 1 root   root    484 2015-04-13 22:26:48 avahi-daemon
-rwxr-xr-x 1 root   root   1685 2014-09-22 01:22:24 ethtool
-rwxr-xr-x 1 root   root   4948 2019-01-05 12:21:53 mountnfs
-rwxr-xr-x 1 root   root    278 2015-03-02 21:32:26 openntpd
-rwxr-xr-x 1 root   root   1117 2017-01-09 15:25:22 postfix
lrwxrwxrwx 1 root   root     32 2019-01-29 18:11:01 wpasupplicant -> ../../wpa_supplicant/ifupdown.sh
-rwxr-xr-x 1 root   root    370 2016-06-02 03:25:26 z_home_net
#922550#10
Date:
2019-02-17 23:34:32 UTC
From:
To:
This problem occurs only when an Ethernet cable is already plugged in
before the boot.

Downgrading to 0.8.33 made the problem disappear.
#922550#15
Date:
2019-04-26 17:56:38 UTC
From:
To:
xxxx@debian:~$ sudo systemd-analyze blame
      5min 804ms ifupdown-wait-online.service
          5.515s sickrage.service
          3.448s NetworkManager-wait-online.service
          1.128s systemd-udev-settle.service
          1.005s alsa-restore.service
#922550#20
Date:
2019-08-12 10:48:36 UTC
From:
To:
This problem still occurs with ifupdown 0.8.35+b1.
#922550#25
Date:
2021-08-21 23:29:25 UTC
From:
To:
I don't know whether this still occurs as I now use NetworkManager
(ifupdown 0.8.36+nmu1 is installed, and I don't see any problem,
but it is no longer used to bring up the network...).

Feel free to close the bug, assuming no-one else has the same issue
with the latest version.
#922550#30
Date:
2022-01-17 10:14:21 UTC
From:
To:
Network sometimes starts and quite often doesn't start and I have to
restart server manually:

ifupdown-pre.service: Main process exited, code=exited, status=1/FAILURE



# dpkg -l | grep ifupdown
ii  ifupdown                      0.8.35 amd64        high level tools
to configure network interfaces



# systemd-analyze blame | head -n3
     2min 24.182s systemd-update-utmp-runlevel.service
           3.098s ifupdown-pre.service
           2.177s dev-sda2.device



# cat syslog.1 | grep -Ei 'ifupd|8169|netw'
Jan 16 22:42:11 pegaz systemd[1]: Starting Helper to synchronize boot up
for ifupdown...
Jan 16 22:42:11 pegaz systemd[1]: Starting Network Time Synchronization...
Jan 16 22:42:11 pegaz systemd[1]: Started Network Time Synchronization.
Jan 16 22:42:11 pegaz kernel: [    0.390218] pci 0000:05:03.0:
[10ec:8169] type 00 class 0x020000
Jan 16 22:42:11 pegaz kernel: [    1.111744] r8169 0000:03:00.0: can't
disable ASPM; OS doesn't have ASPM control
Jan 16 22:42:11 pegaz kernel: [    1.127328] libphy: r8169: probed
Jan 16 22:42:11 pegaz kernel: [    1.127743] r8169 0000:03:00.0 eth0:
RTL8168evl/8111evl, 74:d4:35:99:d4:ed, XID 2c900800, IRQ 26
Jan 16 22:42:11 pegaz kernel: [    1.127744] r8169 0000:03:00.0 eth0:
jumbo features [frames: 9200 bytes, tx checksumming: ko]
Jan 16 22:42:11 pegaz kernel: [    1.127903] r8169 0000:05:03.0: not PCI
Express
Jan 16 22:42:11 pegaz kernel: [    1.132465] libphy: r8169: probed
Jan 16 22:42:11 pegaz kernel: [    1.132587] r8169 0000:05:03.0 eth1:
RTL8169sb/8110sb, aa:aa:aa:00:75:9c, XID 10000000, IRQ 18
Jan 16 22:42:11 pegaz kernel: [    1.132588] r8169 0000:05:03.0 eth1:
jumbo features [frames: 7152 bytes, tx checksumming: ok]
Jan 16 22:42:11 pegaz kernel: [    1.140967] r8169 0000:03:00.0 wan:
renamed from eth0
Jan 16 22:42:11 pegaz kernel: [    1.154870] r8169 0000:05:03.0 lan:
renamed from eth1
Jan 16 22:44:07 pegaz systemd[1]: ifupdown-pre.service: Main process
exited, code=exited, status=1/FAILURE
Jan 16 22:44:07 pegaz systemd[1]: ifupdown-pre.service: Failed with
result 'exit-code'.
Jan 16 22:44:07 pegaz systemd[1]: Failed to start Helper to synchronize
boot up for ifupdown.
Jan 16 22:44:07 pegaz systemd[1]: Dependency failed for Raise network
interfaces.
Jan 16 22:44:07 pegaz systemd[1]: networking.service: Job
networking.service/start failed with result 'dependency'.
Jan 16 22:44:07 pegaz systemd[1]: Reached target Network.
Jan 16 22:44:07 pegaz systemd[1]: Reached target Network is Online.
#922550#35
Date:
2022-01-20 15:39:12 UTC
From:
To:
Hi,

Thanks for reporting this issue.

El 17/01/22 a las 11:14, Leszek Dubiel escribió:

Could you please share your /etc/network/interfaces?

If I am not wrong, ifupdown-pre.service relies on udevadm. Could you add
some debugging on it, and could you share its log please?
I wonder if this has something to do with the interfaces being renamed.
If possible, could you change your configuration to avoid renaming them
and confirm this?

And, could you give a try to the latest version in sid?

Cheers,
#922550#42
Date:
2022-01-20 20:36:30 UTC
From:
To:
Server has been upgradeded to bullseye.
Booting takes 2 minutes... quite long...



 > Could you please share your /etc/network/interfaces?



# cat /etc/network/interfaces

auto lo lan

iface lo inet loopback

iface lan inet static
     address 192.168.18.3/21
     gateway 192.168.18.1



# cat /etc/udev/rules.d/69-leszek-net.rules | sed -r 's/^#.*//;
s/^\s+//' | sort | uniq

SUBSYSTEM=="net", ATTR{address}=="00:19:99:ee:2c:87", NAME="lan"
SUBSYSTEM=="net", ATTR{address}=="00:e0:4c:68:0f:61", NAME="lan"
SUBSYSTEM=="net", ATTR{address}=="4c:cc:6a:4a:14:6f", NAME="wan"
SUBSYSTEM=="net", ATTR{address}=="74:d4:35:99:d4:ed", NAME="wan"
SUBSYSTEM=="net", ATTR{address}=="aa:aa:aa:00:75:9c", NAME="lan"
SUBSYSTEM=="net", ATTR{address}=="b4:2e:99:37:41:5d", NAME="lan"
SUBSYSTEM=="net", ATTR{address}=="bc:5f:f4:c0:8f:82", NAME="lan"





 > If I am not wrong, ifupdown-pre.service relies on udevadm. Could you add
 > some debugging on it, and could you share its log please?



# systemd-analyze blame | head -n5
1min 28.234s systemd-journal-flush.service
       5.107s ifupdown-pre.service
       4.663s dev-sda2.device
       3.751s ssh.service
       3.676s smartmontools.service



# systemctl status ifupdown-pre.service
● ifupdown-pre.service - Helper to synchronize boot up for ifupdown
      Loaded: loaded (/lib/systemd/system/ifupdown-pre.service; static)
      Active: active (exited) since Thu 2022-01-20 13:20:15 CET; 8h ago
     Process: 261 ExecStart=/bin/sh -c if [ "$CONFIGURE_INTERFACES" !=
"no" ] && [ -n "$(ifquery --read-environment --list --exclude=lo)" ] &&
[ -x /bin/udevadm ]; then udevadm settle; fi (code=exited, status=0/>
    Main PID: 261 (code=exited, status=0/SUCCESS)
         CPU: 30ms

sty 20 13:20:15 pegaz systemd[1]: Finished Helper to synchronize boot up
for ifupdown.




# cat /var/log/kern.log | grep -E 'net|ifup|rtl|eth|lan|wan'
Jan 20 13:21:40 pegaz kernel: [    0.217092] audit: initializing netlink
subsys (disabled)
Jan 20 13:21:40 pegaz kernel: [    1.083508] r8169 0000:03:00.0 eth0:
RTL8168evl/8111evl, 74:d4:35:99:d4:ed, XID 2c9, IRQ 30
Jan 20 13:21:40 pegaz kernel: [    1.083510] r8169 0000:03:00.0 eth0:
jumbo features [frames: 9194 bytes, tx checksumming: ko]
Jan 20 13:21:40 pegaz kernel: [    1.086417] r8169 0000:05:03.0 eth1:
RTL8169sb/8110sb, aa:aa:aa:00:75:9c, XID 100, IRQ 18
Jan 20 13:21:40 pegaz kernel: [    1.086419] r8169 0000:05:03.0 eth1:
jumbo features [frames: 7146 bytes, tx checksumming: ok]
Jan 20 13:21:40 pegaz kernel: [    1.087414] r8169 0000:03:00.0 wan:
renamed from eth0
Jan 20 13:21:40 pegaz kernel: [    1.108361] r8169 0000:05:03.0 lan:
renamed from eth1
Jan 20 13:21:40 pegaz kernel: [   41.027982] RTL8211C Gigabit Ethernet
r8169-0-518:00: attached PHY driver [RTL8211C Gigabit Ethernet]
(mii_bus:phy_addr=r8169-0-518:00, irq=IGNORE)
Jan 20 13:21:40 pegaz kernel: [   41.089635] r8169 0000:05:03.0 lan:
Link is Down
Jan 20 13:21:40 pegaz kernel: [   43.407167] r8169 0000:05:03.0 lan:
Link is Up - 1Gbps/Full - flow control rx/tx
Jan 20 13:21:40 pegaz kernel: [   43.407187] IPv6:
ADDRCONF(NETDEV_CHANGE): lan: link becomes ready




# cat /var/log/kern.log | grep fault.addr | sed -r 's/.*DMAR://; s/addr
[a-z0-9]+/addr XXXXX/' | uniq -c
     550  [DMA Read] Request device [05:00.0] PASID ffffffff fault addr
XXXXX [fault reason 06] PTE Read access is not set




 > I wonder if this has something to do with the interfaces being renamed.
 > If possible, could you change your configuration to avoid renaming them
 > and confirm this?

This is production server, I don't have free phisical access to it, so I
can't do experiments...



 > And, could you give a try to the latest version in sid?

I can't unfortunatelly, because this is production server.

After upgrade to bullseye there are lots of errors:

[29466.139246] DMAR: DRHD: handling fault status reg 2
[29466.139255] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ff97f000 [fault reason 06] PTE Read access is not set
[29483.284987] DMAR: DRHD: handling fault status reg 2
[29483.284997] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ff97e000 [fault reason 06] PTE Read access is not set
[29483.285137] DMAR: DRHD: handling fault status reg 2
[29483.285144] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ff9e9000 [fault reason 06] PTE Read access is not set
[29483.286685] DMAR: DRHD: handling fault status reg 2
[29483.286692] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ffbcf000 [fault reason 06] PTE Read access is not set
[29483.286762] DMAR: DRHD: handling fault status reg 2
[29667.451183] dmar_fault: 20 callbacks suppressed
[29667.451184] DMAR: DRHD: handling fault status reg 2
[29667.451204] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ff9c4000 [fault reason 06] PTE Read access is not set
[29720.179279] DMAR: DRHD: handling fault status reg 2
[29720.179301] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ff9a2000 [fault reason 06] PTE Read access is not set
[29720.179725] DMAR: DRHD: handling fault status reg 2
[29720.179738] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ffabe000 [fault reason 06] PTE Read access is not set
[29720.179913] DMAR: DRHD: handling fault status reg 2
[29720.179923] DMAR: [DMA Read] Request device [05:00.0] PASID ffffffff
fault addr ff8b1000 [fault reason 06] PTE Read access is not set
[29720.180654] DMAR: DRHD: handling fault status reg 2