NM fails with 'config-failed' despite successful MM connection

Thu Jan 5 23:04:31 UTC 2017

Dan Williams <dcbw at redhat.com> writes:

> On Thu, 2017-01-05 at 22:21 +0100, Bjørn Mork wrote:
>> Dan Williams <dcbw at redhat.com> writes:
>> 
>> > so I guess the answer is 'systemd'.
>> 
>> And I am actually running systemd on this laptop, even if I am old
>> and
>> grumpy enough to whine about how it changes everything I'm familiar
>> with.
>
> Hah :)  So yeah, looks like you're running systemd.
>
>> > Do you see NM log lines about "suspending" and "waking up"?
>> 
>> "journalctl --unit=NetworkManager|egrep -i 'suspend|resume'" got me
>> this:
>> 
>> Jan 05 20:46:05 miraculix NetworkManager[8315]:
>> <info>  [1483645565.8375] manager: logging: level 'TRACE' domains
>> 'PLATFORM,RFKILL,ETHER,WIFI,BT,MB,DHCP4,DHCP6,PPP,IP4,IP6,AUTOIP4,DNS
>> ,VPN,SHARING,SUPPLICANT,AGENTS,SETTINGS,SUSPEND,CORE,DEVICE,OLPC,INFI
>> NIBAND,FIREWALL,ADSL,BOND,VLAN,BRIDGE,TEAM,CONCHECK,DCB,DISPATCH,AUDI
>> T,SYSTEMD'
>> Jan 05 20:46:22 miraculix NetworkManager[8315]: <debug>
>> [1483645582.2054] sleep-monitor-sd: received RESUME signal
>> Jan 05 20:57:31 miraculix NetworkManager[8315]: <debug>
>> [1483646251.1373] sleep-monitor-sd: received RESUME signal
>> Jan 05 22:03:36 miraculix NetworkManager[8315]: <debug>
>> [1483650216.0202] sleep-monitor-sd: received RESUME signal
>
> I'd expect to see:
>
> Jan 04 18:00:58 <info>  [1483574458.1798] manager: sleep requested (sleeping: no  enabled: yes)
> Jan 04 18:00:58 <info>  [1483574458.1801] manager: sleeping...
> Jan 04 18:00:58 <info>  [1483574458.1810] manager: NetworkManager state is now ASLEEP
> ... time passes ...
> Jan 04 20:41:57 <info>  [1483584117.6135] manager: wake requested (sleeping: yes  enabled: yes)
> Jan 04 20:41:57 <info>  [1483584117.6137] manager: waking up...
> Jan 04 20:41:57 <info>  [1483584117.6139] device (enp0s25): state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
> Jan 04 20:41:57 <info>  [1483584117.7148] device (enp0s25): state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
> Jan 04 20:41:57 <info>  [1483584117.9160] device (wlp4s0): state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
>
> and that's logging at the Info level, so you should see that without
> jumping to TRACE level.  Quite odd that you don't.

Uhm, right "sleep".  That's something else :)

This is an extract of "journalctl --unit=NetworkManager|egrep -i 'sleep|resume|udev'":

Jan 05 23:17:50 miraculix NetworkManager[8315]: <debug> [1483654670.8605] sleep-monitor-sd: received SLEEP signal
Jan 05 23:17:50 miraculix NetworkManager[8315]: <debug> [1483654670.8607] manager: Received sleeping signal
Jan 05 23:17:50 miraculix NetworkManager[8315]: <info>  [1483654670.8609] manager: sleep requested (sleeping: no  enabled: yes)
Jan 05 23:17:50 miraculix NetworkManager[8315]: <info>  [1483654670.8611] manager: sleeping...
Jan 05 23:17:50 miraculix NetworkManager[8315]: <debug> [1483654670.8617] device[0x563f66811d30] (eth0): unmanaged: flags set to [sleeping,!loopback,!platform-init,!user-settings=0x1/0x59/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 05 23:17:50 miraculix NetworkManager[8315]: <info>  [1483654670.8618] device (eth0): state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3416] manager: sleep: wait disconnection of device wlan0
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3417] device[0x563f6677e000] (wlan0): queued state change to deactivating due to sleeping (id 208432)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3417] device[0x563f66a21f30] (nlmon0): unmanaged: flags set to [sleeping,by-default,!loopback,!platform-init,!user-settings=0x101/0x159/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3417] device[0x563f6692f2e0] (cdc-wdm0): unmanaged: flags set to [sleeping,!loopback,!platform-init,!user-settings=0x1/0x59/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info>  [1483654671.3418] device (cdc-wdm0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info>  [1483654671.3434] device (wlan0): state change: activated -> deactivating (reason 'sleeping') [100 110 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3513] device[0x563f6677e000] (wlan0): queued state change to disconnected due to sleeping (id 208448)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info>  [1483654671.3513] device (wlan0): state change: deactivating -> disconnected (reason 'sleeping') [110 30 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.3523] device[0x563f6677e000] (wlan0): deactivating device (reason 'sleeping') [37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.4391] manager: sleep: unmanaging device wlan0
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.4392] device[0x563f6677e000] (wlan0): unmanaged: flags set to [sleeping,!loopback,!platform-init,!user-explicit,!user-settings=0x1/0x79/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.4392] device[0x563f6677e000] (wlan0): queued state change to unmanaged due to sleeping (id 208505)
Jan 05 23:17:51 miraculix NetworkManager[8315]: <info>  [1483654671.4638] device (wlan0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.5829] manager: sleep: device wlan0 is ready
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.5829] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0155] sleep-monitor-sd: received RESUME signal
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0156] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 23:52:08 miraculix NetworkManager[8315]: <info>  [1483656728.0158] manager: wake requested (sleeping: yes  enabled: yes)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0163] device[0x563f66811d30] (eth0): unmanaged: flags set to [!sleeping,!loopback,!platform-init,!user-settings=0x0/0x59/managed, set-managed [sleeping=0x1], reason managed, transition-state)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.2374] device[0x563f6677e000] (wlan0): unmanaged: flags set to [!sleeping,!loopback,!platform-init,!user-explicit,!user-settings=0x0/0x79/managed, set-managed [sleeping=0x1], reason managed, transition-state)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7797] device[0x563f66a21f30] (nlmon0): unmanaged: flags set to [by-default,!sleeping,!loopback,!platform-init,!user-settings=0x100/0x159/manageable, set-managed [sleeping=0x1], reason managed)
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7804] udev rfkill event: action 'remove' device 'rfkill26'
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7835] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7858] udev rfkill event: action 'add' device 'rfkill27'
Jan 05 23:52:17 miraculix NetworkManager[8315]: <debug> [1483656737.0046] platform-linux: UDEV event: action 'add' subsys 'net' device 'wwan0' (41); seqnum=4507
Jan 05 23:52:17 miraculix NetworkManager[8315]: <trace> [1483656737.0046] platform-linux: udev-add[wwan0,41]: device added

Note that 'cdc-wdm0' is going to unmanaged. 'wwan0' is not?

> Can you grep the NM journal output for "inhibit"?  Perhaps it's built
> for systemd power management but that power management isn't actually
> enabled or working?  You should get some hits for this in either case:
>
> _LOGW ("inhibit: failed (%s)", error->message);
> _LOGW ("inhibit: didn't get a single fd back");
> _LOGD ("inhibit: inhibitor fd is %d", self->inhibit_fd);
>
> would be possible messages.

Got the last one:

root at miraculix:/tmp# journalctl --unit=NetworkManager|egrep -i inhibit
Jan 04 18:10:22 miraculix NetworkManager[8315]: <debug> [1483549822.8534] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 04 18:10:31 miraculix NetworkManager[8315]: <debug> [1483549831.1536] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 04 18:10:31 miraculix NetworkManager[8315]: <debug> [1483549831.9598] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 04 18:37:17 miraculix NetworkManager[8315]: <debug> [1483551437.5307] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 04 18:54:53 miraculix NetworkManager[8315]: <debug> [1483552493.2074] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 04 18:54:53 miraculix NetworkManager[8315]: <debug> [1483552493.9648] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 04 19:33:06 miraculix NetworkManager[8315]: <debug> [1483554786.7031] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 04 20:04:01 miraculix NetworkManager[8315]: <debug> [1483556641.0917] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 04 20:04:01 miraculix NetworkManager[8315]: <debug> [1483556641.9009] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 20:46:16 miraculix NetworkManager[8315]: <debug> [1483645576.4266] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 20:46:22 miraculix NetworkManager[8315]: <debug> [1483645582.2054] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 20:46:23 miraculix NetworkManager[8315]: <debug> [1483645583.0393] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 20:57:21 miraculix NetworkManager[8315]: <debug> [1483646241.0498] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 20:57:31 miraculix NetworkManager[8315]: <debug> [1483646251.1373] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 20:57:31 miraculix NetworkManager[8315]: <debug> [1483646251.9211] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 20:58:00 miraculix NetworkManager[8315]: <debug> [1483646280.0683] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 22:03:36 miraculix NetworkManager[8315]: <debug> [1483650216.0202] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 22:03:36 miraculix NetworkManager[8315]: <debug> [1483650216.7939] sleep-monitor-sd: inhibit: inhibitor fd is 19
Jan 05 23:17:51 miraculix NetworkManager[8315]: <debug> [1483654671.5829] sleep-monitor-sd: inhibit: dropping sleep inhibitor 19
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.0156] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 05 23:52:08 miraculix NetworkManager[8315]: <debug> [1483656728.7835] sleep-monitor-sd: inhibit: inhibitor fd is 19

Bjørn