Something is holding up NetworkManager-wait-online.service

I don't think these are relevant to the issue. I still think the same

I have found an incomplete workaround for the network initialization, but not for sddm long delay to show (I am not sure you have the same...).
I have noticed that after login, having no network (no NM-qt icon), I only needed to start NetworkManager-wait-online.service and NM started, connecting successfully.

I edited NetworkManager-wait-online.service and added

[Service]
# Debug failure (added)
Restart=on-failure

# Debug failure (changed)
Environment=NM_ONLINE_TIMEOUT=10
#Environment=NM_ONLINE_TIMEOUT=30

This way I had network after login, but sddm delay was the same. :sob:

My next suspicion is pam , but the error I see just before NM failure is about p2p :face_with_thermometer:

journalctl -u NetworkManager -b-1 --no-hostname --no-pager

... latest part ...
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.2725] device (wlan0): interface index 3 renamed iface from 'wlan0' to 'wlp2s0'
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.2790] device (wlp2s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.6199] device (wlp2s0): supplicant interface state: internal-starting -> disconnected
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.6201] Wi-Fi P2P device controlled by interface wlp2s0 created
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.6205] manager: (p2p-dev-wlp2s0): new 802.11 Wi-Fi P2P device (/org/freedesktop/NetworkManager/Devices/4)
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.6212] device (p2p-dev-wlp2s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.6231] device (wlp2s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Ιαν 26 19:48:09 NetworkManager[399]: <info>  [1611683289.6250] device (p2p-dev-wlp2s0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Ιαν 26 19:48:09 NetworkManager[399]: <warn>  [1611683289.6282] sup-iface[75c873d7735d7f8d,0,wlp2s0]: call-p2p-cancel: failed with P2P cancel failed
Ιαν 26 19:48:56 systemd[1]: NetworkManager.service: Unexpected error response from GetNameOwner(): Connection terminated
Ιαν 26 19:48:56 NetworkManager[399]: <info>  [1611683336.0926] caught SIGTERM, shutting down normally.
Ιαν 26 19:48:56 NetworkManager[399]: <info>  [1611683336.0951] device (wlp2s0): state change: disconnected -> unmanaged (reason 'unmanaged', sys-iface-state: 'managed')
Ιαν 26 19:48:56 NetworkManager[399]: <info>  [1611683336.0983] device (p2p-dev-wlp2s0): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Ιαν 26 19:48:56 NetworkManager[399]: <info>  [1611683336.0993] manager: startup complete
Ιαν 26 19:48:56 NetworkManager[399]: <info>  [1611683336.1252] exiting (success)
Ιαν 26 19:48:56 systemd[1]: NetworkManager.service: Succeeded.

@SvengaliExploit please compare with your logs and confirm if they are alike, or mine is a different one.

1 Like

This is everything from boot forward. Now, here's an interesting tidbit. I updated the system using sudo pacman -Syu, rebooted, system totally hung and never booted, this is after about 15 minutes of sitting. It said that Samba NMB failed to start, and sat there hung up never reaching graphic.target.....I had to restore the most recent Timeshift image to boot, which I've done, and here is the output....I'm going to put an strace on dbus.service and see what it turns up on the next reboot. Also, manually starting NetworkManager-wait-online.service immediately started NetworkManager and my internet connection immediately connected.

  ╭─svengali at DR460NIZED-3900X in ⌁
    ╰─λ sudo systemctl start NetworkManager-wait-online.service                                                                                                                                                                                                                                                                                                                                                                           04:27:29
    [sudo] password for svengali:       
    ╭─svengali at DR460NIZED-3900X in ⌁
    ╰─λ journalctl -u NetworkManager -b-1 --no-hostname --no-pager                                                                                                                                                                                                                                                                                                                                                                        23:28:19
    -- Journal begins at Thu 2021-01-07 05:20:58 EST, ends at Wed 2021-01-27 04:28:10 EST. --
    Jan 27 04:08:25 systemd[1]: Starting Network Manager...
    Jan 27 04:08:25 NetworkManager[831]: <info>  [1611738505.9836] NetworkManager (version 1.28.1dev+7+g3f5df3cdc6-1) is starting... (for the first time)
    Jan 27 04:08:25 NetworkManager[831]: <info>  [1611738505.9836] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 20-connectivity.conf)
    Jan 27 04:08:25 systemd[1]: Started Network Manager.
    Jan 27 04:08:25 NetworkManager[831]: <info>  [1611738505.9846] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
    Jan 27 04:08:25 NetworkManager[831]: <info>  [1611738505.9877] manager[0x564d7ac7d030]: monitoring kernel firmware directory '/lib/firmware'.
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0285] hostname: hostname: using hostnamed
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0285] hostname: hostname changed from (none) to "DR460NIZED-3900X"
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0304] dns-mgr[0x564d7ac35220]: init: dns=default,systemd-resolved rc-manager=resolvconf (auto)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0309] rfkill1: found Wi-Fi radio killswitch (at /sys/devices/pci0000:00/0000:00:01.2/0000:02:00.0/0000:03:03.0/0000:05:00.0/ieee80211/phy0/rfkill1) (driver iwlwifi)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0310] manager[0x564d7ac7d030]: rfkill: Wi-Fi hardware radio set enabled
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0310] manager[0x564d7ac7d030]: rfkill: WWAN hardware radio set enabled
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0324] Loaded device plugin: NMAtmManager (/usr/lib/NetworkManager/1.28.1dev+7+g3f5df3cdc6-1/libnm-device-plugin-adsl.so)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0358] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/1.28.1dev+7+g3f5df3cdc6-1/libnm-device-plugin-bluetooth.so)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0374] Loaded device plugin: NMOvsFactory (/usr/lib/NetworkManager/1.28.1dev+7+g3f5df3cdc6-1/libnm-device-plugin-ovs.so)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0447] Loaded device plugin: NMTeamFactory (/usr/lib/NetworkManager/1.28.1dev+7+g3f5df3cdc6-1/libnm-device-plugin-team.so)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0466] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/1.28.1dev+7+g3f5df3cdc6-1/libnm-device-plugin-wifi.so)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0471] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/1.28.1dev+7+g3f5df3cdc6-1/libnm-device-plugin-wwan.so)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0473] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0474] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0478] manager: Networking is enabled by state file
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0479] dhcp-init: Using DHCP client 'internal'
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0481] settings: Loaded settings plugin: keyfile (internal)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0507] device (lo): carrier: link connected
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0508] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0513] manager: (enp6s0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0521] settings: (enp6s0): created default wired connection 'Wired connection 1'
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.0524] device (enp6s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.2495] manager: (enp7s0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/3)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.2502] settings: (enp7s0): created default wired connection 'Wired connection 2'
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.2504] device (enp7s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.2757] device (wlp5s0): driver supports Access Point (AP) mode
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.2759] manager: (wlp5s0): new 802.11 Wi-Fi device (/org/freedesktop/NetworkManager/Devices/4)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.2764] device (wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.4704] device (wlp5s0): set-hw-addr: set MAC address to 02:C3:A2:63:5D:39 (scanning)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.6594] ovsdb: Could not connect: No such file or directory
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.6604] modem-manager: ModemManager available
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.7312] device (wlp5s0): supplicant interface state: internal-starting -> disconnected
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.7312] Wi-Fi P2P device controlled by interface wlp5s0 created
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.7313] manager: (p2p-dev-wlp5s0): new 802.11 Wi-Fi P2P device (/org/freedesktop/NetworkManager/Devices/5)
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.7315] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.7319] device (wlp5s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
    Jan 27 04:08:26 NetworkManager[831]: <info>  [1611738506.7322] device (p2p-dev-wlp5s0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
    Jan 27 04:08:26 NetworkManager[831]: <warn>  [1611738506.7344] sup-iface[c7ac645c30fd0fef,0,wlp5s0]: call-p2p-cancel: failed with P2P cancel failed
    Jan 27 04:08:32 NetworkManager[831]: <info>  [1611738512.2755] manager: startup complete
    Jan 27 04:15:17 NetworkManager[831]: <info>  [1611738917.8475] device (wlp5s0): set-hw-addr: set MAC address to 62:E3:9E:A7:49:84 (scanning)
    Jan 27 04:15:17 NetworkManager[831]: <info>  [1611738917.8716] device (wlp5s0): supplicant interface state: disconnected -> inactive
    Jan 27 04:15:17 NetworkManager[831]: <info>  [1611738917.8716] device (p2p-dev-wlp5s0): supplicant management interface state: disconnected -> inactive
    Jan 27 04:22:10 NetworkManager[831]: <info>  [1611739330.7614] device (wlp5s0): set-hw-addr: set MAC address to FE:D2:A3:5E:AC:CB (scanning)
    Jan 27 04:22:10 NetworkManager[831]: <info>  [1611739330.7805] device (wlp5s0): supplicant interface state: inactive -> disconnected
    Jan 27 04:22:10 NetworkManager[831]: <info>  [1611739330.7805] device (p2p-dev-wlp5s0): supplicant management interface state: inactive -> disconnected
    Jan 27 04:22:10 NetworkManager[831]: <info>  [1611739330.7856] device (wlp5s0): supplicant interface state: disconnected -> inactive
    Jan 27 04:22:10 NetworkManager[831]: <info>  [1611739330.7856] device (p2p-dev-wlp5s0): supplicant management interface state: disconnected -> inactive
    Jan 27 04:22:25 NetworkManager[831]: <info>  [1611739345.0157] modem-manager: ModemManager no longer available
    Jan 27 04:22:25 systemd[1]: Stopping Network Manager...
    Jan 27 04:22:25 NetworkManager[831]: <info>  [1611739345.0652] caught SIGTERM, shutting down normally.
    Jan 27 04:22:25 NetworkManager[831]: <info>  [1611739345.0660] device (wlp5s0): state change: disconnected -> unmanaged (reason 'unmanaged', sys-iface-state: 'managed')
    Jan 27 04:22:25 NetworkManager[831]: <info>  [1611739345.0669] device (wlp5s0): set-hw-addr: reset MAC address to 3C:F0:11:3C:9E:1B (unmanage)
    Jan 27 04:22:25 NetworkManager[831]: <info>  [1611739345.0694] device (p2p-dev-wlp5s0): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
    Jan 27 04:22:25 NetworkManager[831]: <info>  [1611739345.0702] exiting (success)
    Jan 27 04:22:25 systemd[1]: NetworkManager.service: Succeeded.
    Jan 27 04:22:25 systemd[1]: Stopped Network Manager.
    ╭─svengali at DR460NIZED-3900X in ⌁
    ╰─λ

It seems it should be the same issue with mine.
The suspected villains IMHO are one or a combination of NM, dbus, pam, sddm.

Questions:

sup-iface[c7ac645c30fd0fef,0,wlp5s0]: call-p2p-cancel: failed with P2P cancel failed

  1. Why would P2P make connection attempt to fail, when WiFi is managed?
  2. Why would SDDM greeter wait for a network connection?
Ιαν 27 13:31:03 systemd[1]: Failed to start Network Manager Wait Online.
Ιαν 27 13:31:03 systemd[1]: bluetooth.service: Unexpected error response from GetNameOwner(): Connection terminated
Ιαν 27 13:31:03 systemd[1]: systemd-logind.service: Unexpected error response from GetNameOwner(): Connection terminated
Ιαν 27 13:31:03 systemd[1]: NetworkManager.service: Unexpected error response from GetNameOwner(): Connection terminated
Ιαν 27 13:31:03 systemd[1]: wpa_supplicant.service: Unexpected error response from GetNameOwner(): Connection terminated
Ιαν 27 13:31:03 sddm-helper[676]: pam_systemd(sddm-greeter:session): Failed to create session: Message recipient disconnected from message bus without replying
Ιαν 27 13:31:03 sddm[440]: Failed to read display number from pipe
Ιαν 27 13:31:06 sddm[440]: Failed to read display number from pipe
Ιαν 27 13:31:08 sddm[440]: Failed to read display number from pipe
Ιαν 27 13:31:08 sddm[440]: Could not start Display server on vt 1
Ιαν 27 13:31:17 sddm-helper[966]: gkr-pam: unable to locate daemon control file

  1. What's this Unexpected error response from GetNameOwner() about?
  2. Is PAM sick? sddm-helper[676]: pam_systemd(sddm-greeter:session): Failed to create session: Message recipient disconnected from message bus without replying, or SDDM needs to send a better request?

I have scanned and browsed several relevant code issues and sources from the above apps and my general idea is... it's a mess and a headache to me.

Maybe later (when I find some time) I'll post to Arch forum to investigate.

3 Likes

You could always try switching to connman. Its interface takes a bit of getting used to, but its a good solid manager. It is usually impacted far less than NM with internet breaking bugs.

2 Likes

Post#44 above by @tbg is what I have been using now for many months. ( actually forgot about it )

'## group: files systemd'

This was the only line I had to comment out for things to work again in /etc/nsswitch.conf.

2 Likes

Thanks for reminding me, I had forgotten to try what was suggested.
Actually the proper almost solution is in another comment, which worked out immediately!!!
@SvengaliExploit try it out:

sudo pacman -S dbus-broker
sudo systemctl enable dbus-broker.service
sudo systemctl --global enable dbus-broker.service

and reboot to check. Remove all other workarounds first.

4 Likes

Tried out the above and rebooted twice as whenever I made a change it would work after the first boot as expected but would fail on the second boot.
I can confirm it works after the second boot.
Thanks

3 Likes

I have also read posts stating that setting IPv6 to "ignore" in Network Manager may help with this.

I had IPv6 set to ignore in Network Manager from day one and the problem which is now some what fix started years afterwards. :wink:

Yes, I always disable IPv6 normally myself as well. For those that don't I just thought I'd put it out there as a suggestion as I'd read one comment on the Arch forum that it improved things for them.

1 Like

Only problem for me is that I've got a few things that require IPv6 and UPnP opening a stateless port through my router, so I kind of need IPv6......I had tried the dbus-broker fix, but didn't have any luck the last time, except I'd changed kernels at that point when at last I tried. I'm going to give it a try with the current config and see what happens. I also found my patch file for nsswitch.conf and have reverted it back to it's original state and am going to try that first, before giving dbus-broker another try......Although I feel like, if dbus-broker can fix the issue it's a better solution than using a deprecated nsswitch.conf file, mainly because I'm not sure what the ramifications are of removing the updated lines. Only lines 4, 5, & 10 were changed with the update to nsswitch.....

1 Like

OOOOOOkkkkkk......soooooooo, it's fixed lol I have no idea how or what happened, but it just booted perfectly, and I'm not sure what did the trick.....it was NOT dbus-broker, as it's currently disabled and not running. COULD be the edits to nsswitch.conf- I'm going to revert my reversion (lol) and see if the issue returns. What happened on the PREVIOUS boot is that the system hung where X should have started, but I was able to Ctrl+Alt+F3 to another TTY, and automatically thinking that it was the same issue I went through several things- I enabled and started NetworkManager-wait-online, I also enabled and started nohang.service, but before that I disabled dbus-broker, thinking that IT was the change that was preventing me from reaching graphical.target<-----in fact, the issue was that the grub menu was defaulting to the xanmod kernel, which I suppose for some reason failed to properly add the Nvidia kernel module when it installed, because THAT is what prevented me from getting a normal boot. I rebooted once I noticed that and switched to the zen2 kernel and voila! she booted up perfectly, and practically INSTANTLY (you've gotta love a Sabrent Rocket NVMe PCI-e Gen4 x4 SSD!! WHEW that thing is FAST!), without the slightest bit of hesitation, and when I logged in, low-and-behond everything was working perfectly.....so now I'm going to reboot one more time to see if it holds true a second time and then start figuring out which of those things was the solution.....

except

despite

But, we got there in the end.

indeed we did....and certainly not for lack of effort! Thanks to all you guys for helping out, too!

Glad to hear your issue has been resolved. Some posts on this topic claimed two reboots were necessary for the fix to take. Maybe that's why things started to work all of a sudden. Here's another thing others could test if searching for a solution.

This changes the NetworkManager-wait-online.service default behavior with an override file:

 /etc/systemd/system/NetworkManager-wait-online.service.d/override.conf

Contents:

[Service]
ExecStart=
ExecStart=/usr/bin/nm-online -q

Whenever I had a new kernel or made changes while testing different things it always worked the first boot as expected but would fail the second time taking about 3 or 4 min to boot.
Don't celebrate till you reboot a few times. :shushing_face:

1 Like

I had a laptop that was hanging for a while on boot, and I traced the issue to the journal entry "Unexpected error response from GetNameOwner(): Connection terminated" bug mentioned above. Editing nsswitch.conf was necessary.

A recent update to nsswitch.conf (which now includes the line "group: files [SUCCESS=merge] systemd") has resolved the issue for me; perhaps that update was the actual solution here, too.

6 Likes

So you think it was the kernel?
What about now? Does the broken kernel boot properly.
Or explain what you think was the problem.
And how was it fixed/resolved?

The linked issue is very complicated, several users reported weird observations, like yours (issue cleared with dbus-broker and still no issue after disabling dbus-broker, and others).
FWIW I did my tests/troubleshooting on the same kernel, although I tested my backup one.

2 Likes

well I've taken my time and run through a lot of scenarios, and I believe the culprit to be this nsswitch.conf update that I applied last week. Every other situation results in similar issues, albeit from varying "directions" (sometimes dbus-broker seems culpable, other times another process), but in the end adjusting nsswitch.conf and removing the additional lines that were added from the update last week (I need to look through my pacman log and see if I can find the version number where the changes are first applied or maybe look up the commit in the repo). I still have the patch file I created from diff'ing the original and .pacnew files after the update....it is as follows:

4,5c4,5
< passwd: files 
< group: files 
---
> passwd: files systemd
> group: files [SUCCESS=merge] systemd
10c10
< hosts: files mymachines myhostname mdns_minimal [NOTFOUND=return] resolve [!UNAVAIL=return] dns wins
---
> hosts: files mymachines myhostname resolve [!UNAVAIL=return] dns

Hopefully that helps anyone who no longer has the original file to know what to revert....but, personally, I think this is the root of the issue- at least from my limited knowledge. Whoever is responsible for the nsswitch package may be dealing with bigger fish, because obviously the new config additions aren't performing as intended, but that's honestly over my head at this point....but give me 6 months :wink:

5 Likes

It's an odd little bug that only affects a small number of users. In my case, it affected only one out of 6 computers, all running essentially the same Arch installation. One of my other laptops is identical to the affected one, but did not hang at boot. :man_shrugging:

There are several workarounds that help some people but not others; removing the "systemd" mention from nsswitch.conf is the only "fix" that seems to work reliably for everyone.

The new nsswitch config did correct the issue with my laptop; I can confirm that it was the conf file by using the old config, which brings the hang back. Very strange bug, and again, it only affects a small group of users.

5 Likes