Arch Linux

zebus

Member

Registered: 2019-03-11

Posts: 2

NetworkManager not working correctly on boot, only after restarting

Set the service to start on boot, but wifi applet shows device not ready, here is the output:

-- Reboot --
Mar 10 21:33:11 mr-robot systemd[1]: Starting Network Manager...
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.1541] NetworkManager (version 1.14.7dev+3+g353743b99-1) is starting... (for the first time)
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.1543] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 20-connectivity.conf) (etc>
Mar 10 21:33:11 mr-robot systemd[1]: Started Network Manager.
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.1634] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.1722] manager[0x55b1fb1c7080]: monitoring kernel firmware directory '/lib/firmware'.
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2392] hostname: hostname: using hostnamed
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2392] hostname: hostname changed from (none) to "mr-robot"
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2395] dns-mgr[0x55b1fb1d3130]: init: dns=default, rc-manager=symlink
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2406] rfkill2: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.1/0000:03>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2409] manager[0x55b1fb1c7080]: rfkill: WiFi hardware radio set enabled
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2409] manager[0x55b1fb1c7080]: rfkill: WWAN hardware radio set enabled
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2751] settings: Loaded settings plugin: NMSKeyfilePlugin (internal)
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2760] settings: Loaded settings plugin: NMSIbftPlugin ("/usr/lib/NetworkManager/1.14.7dev+3>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2786] keyfile: new connection /etc/NetworkManager/system-connections/Wu Tang LAN.nmconnecti>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2821] manager: rfkill: WiFi enabled by radio killswitch; enabled by state file
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2824] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2827] manager: Networking is enabled by state file
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2842] dhcp-init: Using DHCP client 'dhclient'
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2885] Loaded device plugin: NMOvsFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1/>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2899] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.2965] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99->
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3147] Loaded device plugin: NMTeamFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3154] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3162] Loaded device plugin: NMAtmManager (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1/>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3167] wifi-nl80211: (wlan0): using nl80211 for WiFi device control
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3174] device (lo): carrier: link connected
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3178] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3190] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3215] keyfile: add connection /var/run/NetworkManager/system-connections/Wired connection 1>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3220] settings: (eth0): created default wired connection 'Wired connection 1'
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.3226] device (eth0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-st>
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.5668] manager: (wlan0): new 802.11 WiFi device (/org/freedesktop/NetworkManager/Devices/3)
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.5716] ovsdb: Could not connect: No such file or directory
Mar 10 21:33:11 mr-robot NetworkManager[389]: <info>  [1552271591.5752] device (wlan0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-s>
Mar 10 21:33:17 mr-robot NetworkManager[389]: <info>  [1552271597.5665] manager: startup complete

After restarting service, everything works perfectly:

Mar 10 21:40:52 mr-robot systemd[1]: Stopping Network Manager...
Mar 10 21:40:52 mr-robot NetworkManager[389]: <info>  [1552272052.6327] caught SIGTERM, shutting down normally.
Mar 10 21:40:52 mr-robot NetworkManager[389]: <info>  [1552272052.6407] exiting (success)
Mar 10 21:40:52 mr-robot systemd[1]: NetworkManager.service: Succeeded.
Mar 10 21:40:52 mr-robot systemd[1]: Stopped Network Manager.
Mar 10 21:40:52 mr-robot systemd[1]: Starting Network Manager...
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.6778] NetworkManager (version 1.14.7dev+3+g353743b99-1) is starting... (after a restart)
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.6779] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 20-connectivity.conf) (etc>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.6785] wifi-nl80211: (wlan0): using nl80211 for WiFi device control
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.6840] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Mar 10 21:40:52 mr-robot systemd[1]: Started Network Manager.
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.6846] manager[0x55f10893d0c0]: monitoring kernel firmware directory '/lib/firmware'.
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7390] hostname: hostname: using hostnamed
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7390] hostname: hostname changed from (none) to "mr-robot"
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7393] dns-mgr[0x55f108948120]: init: dns=default, rc-manager=symlink
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7408] rfkill2: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.1/0000:03>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7412] manager[0x55f10893d0c0]: rfkill: WiFi hardware radio set enabled
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7412] manager[0x55f10893d0c0]: rfkill: WWAN hardware radio set enabled
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7616] settings: Loaded settings plugin: NMSKeyfilePlugin (internal)
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7619] settings: Loaded settings plugin: NMSIbftPlugin ("/usr/lib/NetworkManager/1.14.7dev+3>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7642] keyfile: new connection /var/run/NetworkManager/system-connections/Wired connection 1>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7663] keyfile: new connection /etc/NetworkManager/system-connections/Wu Tang LAN.nmconnecti>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7682] manager: rfkill: WiFi enabled by radio killswitch; enabled by state file
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7684] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7686] manager: Networking is enabled by state file
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7688] dhcp-init: Using DHCP client 'dhclient'
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7698] Loaded device plugin: NMOvsFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1/>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7702] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7719] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99->
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7760] Loaded device plugin: NMTeamFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7762] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7765] Loaded device plugin: NMAtmManager (/usr/lib/NetworkManager/1.14.7dev+3+g353743b99-1/>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7771] device (lo): carrier: link connected
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7774] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7781] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7788] device (eth0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-st>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7805] manager: (wlan0): new 802.11 WiFi device (/org/freedesktop/NetworkManager/Devices/3)
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7815] device (wlan0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-s>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7848] device (wlan0): new IWD device state is connected
Mar 10 21:40:52 mr-robot NetworkManager[611]: <warn>  [1552272052.7850] device (wlan0): Unsolicited connection success, asking IWD to disconnect
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7856] ovsdb: Could not connect: No such file or directory
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7860] device (wlan0): new IWD device state is disconnecting
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.7880] device (wlan0): state change: unavailable -> disconnected (reason 'supplicant-availab>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8144] device (wlan0): new IWD device state is disconnected
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8219] policy: auto-activating connection 'Wu Tang LAN' (448047d9-5e5b-411b-8daa-dbe0f706574>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8226] device (wlan0): Activation: starting connection 'Wu Tang LAN' (448047d9-5e5b-411b-8da>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8228] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8232] manager: NetworkManager state is now CONNECTING
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8237] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'man>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.8250] device (wlan0): new IWD device state is connecting
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.9945] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful.  Conne>
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.9947] device (wlan0): new IWD device state is connected
Mar 10 21:40:52 mr-robot NetworkManager[611]: <info>  [1552272052.9951] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'm>
Mar 10 21:40:53 mr-robot NetworkManager[611]: <info>  [1552272053.0058] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Mar 10 21:40:53 mr-robot NetworkManager[611]: <info>  [1552272053.0191] dhcp4 (wlan0): dhclient started with pid 626

zebus

Member

Registered: 2019-03-11

Posts: 2

Re: NetworkManager not working correctly on boot, only after restarting

Well I was trying to use IWD because I had read it was better, but just to see if it made a difference I switched back to using wpa_supplicant and the issue stopped. So might not even be worth answering now.

damjan

Member

Registered: 2006-05-30

Posts: 462

Re: NetworkManager not working correctly on boot, only after restarting

you need to make sure iwd is started before NetworkManager (there's a long standing issue about it in NM). easiest to do, is just to enable the iwd service.

jpegxguy

Member

From: Earth

Registered: 2018-06-18

Posts: 38

Re: NetworkManager not working correctly on boot, only after restarting

you need to make sure iwd is started before NetworkManager (there's a long standing issue about it in NM). easiest to do, is just to enable the iwd service.

The problem with that is that it won't work after NetworkManager restarts it after, say, a suspend and resume. For some reason NM disregards the fact that it started iwd ITSELF.
Also, it takes at least 1 0seconds to connect to Wi-Fi after you start your DE.

---

hi

damjan

Member

Registered: 2006-05-30

Posts: 462

Re: NetworkManager not working correctly on boot, only after restarting

The problem with that is that it won't work after NetworkManager restarts it after, say, a suspend and resume.

first time I hear that NetworkManager would restart anything on suspend/resume

jpegxguy

Member

From: Earth

Registered: 2018-06-18

Posts: 38

Re: NetworkManager not working correctly on boot, only after restarting

The problem with that is that it won't work after NetworkManager restarts it after, say, a suspend and resume.

first time I hear that NetworkManager would restart anything on suspend/resume

Doesn't it communicate with stuff like dnsmasq (if configured) or the wireless supplicant through dbus?

Last edited by jpegxguy (2019-03-16 00:19:47)

---

hi

jpegxguy

Member

From: Earth

Registered: 2018-06-18

Posts: 38

Re: NetworkManager not working correctly on boot, only after restarting

It seems like the delay is gone upon restart, at least. Maybe it's because of NM 1.16 or my luck for now. I'll be running with systemctl enabled iwd for testing

---

hi