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

[Dan Williams]

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.

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.

> Is this the reason it fails?  A cached entry is not expired because
> we
> miss the udev 'remove' event and/or suspend?

It's certainly one reason it would fail.  NM will typically unmanage
devices when it goes down and thus throw away any of the cached info.

That said, I would call it a bug that NM doesn't update the ifindex
when it gets a netlink ADD message for an interface that's already in
the cache by name.

Dan