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

Fri Jan 6 18:37:34 UTC 2017

Dan Williams <dcbw at redhat.com> writes:

> Can you give the attached NM patch a try?  It's diffed from the nm-1-4
> branch.

works for me.  A few selected log lines from a sleep+resume cycle:

Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.0645] sleep-monitor-sd: received SLEEP signal
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.0645] manager: Received sleeping signal
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.0646] manager: sleep requested (sleeping: no  enabled: yes)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.0646] manager: sleeping...
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.0647] device[0x556c4e4948d0] (eth0): unmanaged: flags set to [sleeping,!loopback,!platform-init,!user-settings=0x1/0x59/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.0648] device (eth0): state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.5585] manager: sleep: wait disconnection of device wlan0
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.5586] device[0x556c4e3fa000] (wlan0): queued state change to deactivating due to sleeping (id 1358)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.5586] device[0x556c4e4d7580] (nlmon0): unmanaged: flags set to [sleeping,by-default,!loopback,!platform-init,!user-settings=0x101/0x159/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.5587] device[0x556c4e52b220] (cdc-wdm0): unmanaged: flags set to [sleeping,!loopback,!platform-init,!user-settings=0x1/0x59/unmanaged, set-unmanaged [sleeping=0x1], reason sleeping, transition-state)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.5587] device (cdc-wdm0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.5611] device (wlan0): state change: activated -> deactivating (reason 'sleeping') [100 110 37]
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.5719] device[0x556c4e3fa000] (wlan0): queued state change to disconnected due to sleeping (id 1374)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.5720] device (wlan0): state change: deactivating -> disconnected (reason 'sleeping') [110 30 37]
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.5755] device[0x556c4e3fa000] (wlan0): deactivating device (reason 'sleeping') [37]
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.7103] manager: sleep: unmanaging device wlan0
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.7104] device[0x556c4e3fa000] (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 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.7105] device[0x556c4e3fa000] (wlan0): queued state change to unmanaged due to sleeping (id 1430)
Jan 06 19:24:44 miraculix NetworkManager[11115]: <info>  [1483727084.7405] device (wlan0): state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.8672] manager: sleep: device wlan0 is ready
Jan 06 19:24:44 miraculix NetworkManager[11115]: <debug> [1483727084.8673] sleep-monitor-sd: inhibit: dropping sleep inhibitor 17
Jan  6 19:24:50 miraculix NetworkManager[11115]: <trace> [1483727090.1662] platform-linux: event-notification: DELLINK, seq 0: 43
Jan  6 19:24:50 miraculix NetworkManager[11115]: <debug> [1483727090.1662] platform: signal: link removed: 43: wwan0 <NOARP,DOWN;broadcast,multicast,noarp> mtu 1500 arp 1 wwan? not-init addrgenmode eui64 addr 9E:20:EC:6F:E5:38 rx:0,0 tx:0,0
Jan 06 19:24:50 miraculix NetworkManager[11115]: <debug> [1483727090.2214] udev rfkill event: action 'remove' device 'rfkill29'
Jan 06 19:24:50 miraculix NetworkManager[11115]: <debug> [1483727090.2268] sleep-monitor-sd: received RESUME signal
Jan 06 19:24:50 miraculix NetworkManager[11115]: <debug> [1483727090.2268] sleep-monitor-sd: inhibit: taking sleep inhibitor...
Jan 06 19:24:50 miraculix NetworkManager[11115]: <info>  [1483727090.2270] manager: wake requested (sleeping: yes  enabled: yes)
Jan 06 19:24:50 miraculix NetworkManager[11115]: <debug> [1483727090.2273] device[0x556c4e4948d0] (eth0): unmanaged: flags set to [!sleeping,!loopback,!platform-init,!user-settings=0x0/0x59/managed, set-managed [sleeping=0x1], reason managed, transition-state)
Jan 06 19:24:50 miraculix NetworkManager[11115]: <debug> [1483727090.4485] device[0x556c4e3fa000] (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 06 19:24:51 miraculix NetworkManager[11115]: <debug> [1483727091.0842] device[0x556c4e4d7580] (nlmon0): unmanaged: flags set to [by-default,!sleeping,!loopback,!platform-init,!user-settings=0x100/0x159/manageable, set-managed [sleeping=0x1], reason managed)
Jan 06 19:24:51 miraculix NetworkManager[11115]: <debug> [1483727091.0850] udev rfkill event: action 'add' device 'rfkill30'
Jan 06 19:24:51 miraculix NetworkManager[11115]: <debug> [1483727091.0873] sleep-monitor-sd: inhibit: inhibitor fd is 19

..

Jan  6 19:24:59 miraculix NetworkManager[11115]: <trace> [1483727099.0318] platform-linux: event-notification: NEWLINK, seq 0: 46: wwan0 <NOARP,DOWN;broadcast,multicast,noarp> mtu 1500 arp 1 wwan? not-init addrgenmode eui64 addr 9E:20:EC:6F:E5:38 rx:0,0 tx:0,0
Jan  6 19:24:59 miraculix NetworkManager[11115]: <debug> [1483727099.0324] platform: signal: link   added: 46: wwan0 <NOARP,DOWN;broadcast,multicast,noarp> mtu 1500 arp 1 wwan? not-init addrgenmode eui64 addr 9E:20:EC:6F:E5:38 driver cdc_mbim rx:0,0 tx:0,0
Jan  6 19:24:59 miraculix NetworkManager[11115]: <debug> [1483727099.0329] manager: wwan0: factory failed to create device: Device factory NMWwanFactory ignores device wwan0
Jan  6 19:24:59 miraculix NetworkManager[11115]: <debug> [1483727099.1775] platform-linux: UDEV event: action 'add' subsys 'net' device 'wwan0' (46); seqnum=4944
Jan  6 19:24:59 miraculix NetworkManager[11115]: <trace> [1483727099.1775] platform-linux: udev-add[wwan0,46]: device added
Jan  6 19:24:59 miraculix NetworkManager[11115]: <debug> [1483727099.1779] platform: signal: link changed: 46: wwan0 <NOARP,DOWN;broadcast,multicast,noarp> mtu 1500 arp 1 wwan? init addrgenmode eui64 addr 9E:20:EC:6F:E5:38 driver cdc_mbim rx:0,0 tx:0,0
Jan  6 19:24:59 miraculix NetworkManager[11115]: <info>  [1483727099.1780] devices added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.12/net/wwan0, iface: wwan0)
Jan  6 19:24:59 miraculix NetworkManager[11115]: <info>  [1483727099.1780] device added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.12/net/wwan0, iface: wwan0): no ifupdown configuration found.
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4634] device[0x556c4e591080] (cdc-wdm0): constructed (NMDeviceModem)
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4637] device[0x556c4e591080] (cdc-wdm0): start setup of NMDeviceModem, kernel ifindex 0
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4641] device[0x556c4e591080] (cdc-wdm0): unmanaged: flags set to [platform-init,!loopback=0x10/0x18/unmanaged/unrealized, set-managed [loopback=0x8])
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4643] device[0x556c4e591080] (cdc-wdm0): unmanaged: flags set to [platform-init,!loopback,!user-settings=0x10/0x58/unmanaged/unrealized, set-managed [user-settings=0x40])
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4644] device[0x556c4e591080] (cdc-wdm0): unmanaged: flags set to [!loopback,!platform-init,!user-settings=0x0/0x58/managed/unrealized, set-managed [platform-init=0x10])
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4653] manager: WWAN hw-enabled 1 sw-enabled 1
Jan  6 19:25:14 miraculix NetworkManager[11115]: <warn>  [1483727114.4655] (cdc-wdm0): cannot enable/disable modem: locked
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4657] device[0x556c4e591080] (cdc-wdm0): unmanaged: flags set to [!sleeping,!loopback,!platform-init,!user-settings=0x0/0x59/managed/unrealized, set-managed [sleeping=0x1])
Jan  6 19:25:14 miraculix NetworkManager[11115]: <trace> [1483727114.4690] exported-object[0x556c4e591080]: export: "/org/freedesktop/NetworkManager/Devices/9"
Jan  6 19:25:14 miraculix NetworkManager[11115]: <info>  [1483727114.4705] manager: (cdc-wdm0): new Broadband device (/org/freedesktop/NetworkManager/Devices/9)
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4731] manager: (cdc-wdm0): can't assume; no connection
Jan  6 19:25:14 miraculix NetworkManager[11115]: <info>  [1483727114.4732] device (cdc-wdm0): state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4737] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4741] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_defrtr: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_defrtr': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4743] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_pinfo: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_pinfo': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4746] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_rtr_pref: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_rtr_pref': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4750] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/disable_ipv6: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/disable_ipv6': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4753] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/hop_limit: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/hop_limit': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4755] platform-linux: error reading /proc/sys/net/ipv6/conf/cdc-wdm0/use_tempaddr: Failed to open file '/proc/sys/net/ipv6/conf/cdc-wdm0/use_tempaddr': No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4759] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_defrtr': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4762] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_pinfo': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4764] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_rtr_pref': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4767] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/use_tempaddr': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4769] device[0x556c4e591080] (cdc-wdm0): bringing up device
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4770] device[0x556c4e591080] (cdc-wdm0): preparing device
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4858] device[0x556c4e591080] (cdc-wdm0): clearing queued IP4 config change
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4860] device[0x556c4e591080] (cdc-wdm0): clearing queued IP6 config change
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4862] device[0x556c4e591080] (cdc-wdm0): remove_pending_action (0): 'dhcp6' not pending (expected)
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4863] device[0x556c4e591080] (cdc-wdm0): remove_pending_action (0): 'autoconf6' not pending (expected)
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4866] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4876] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/use_tempaddr': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4879] device[0x556c4e591080] (cdc-wdm0): ip4-config: update (commit=1, routes-full-sync=1, new-config=(nil))
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4880] device[0x556c4e591080] (cdc-wdm0): ip6-config: update (commit=1, routes-full-sync=1, new-config=(nil))
Jan  6 19:25:14 miraculix NetworkManager[11115]: <info>  [1483727114.4893] device (cdc-wdm0): modem state 'locked'
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4911] device[0x556c4e591080] (cdc-wdm0): add_pending_action (1): 'queued state change to disconnected'
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4912] device[0x556c4e591080] (cdc-wdm0): queued state change to disconnected due to none (id 2743)
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4913] device[0x556c4e591080] (cdc-wdm0): is available, will transition to disconnected
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4914] device[0x556c4e591080] (cdc-wdm0): running queued state change to disconnected (id 2743)
Jan  6 19:25:14 miraculix NetworkManager[11115]: <info>  [1483727114.4915] device (cdc-wdm0): state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4919] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_defrtr': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4921] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_pinfo': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4922] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/accept_ra_rtr_pref': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4942] platform-linux: sysctl: failed to open '/proc/sys/net/ipv6/conf/cdc-wdm0/use_tempaddr': (2) No such file or directory
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4954] device[0x556c4e591080] (cdc-wdm0): add_pending_action (2): 'autoactivate'
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4956] device[0x556c4e591080] (cdc-wdm0): remove_pending_action (1): 'queued state change to disconnected'
Jan  6 19:25:14 miraculix NetworkManager[11115]: <debug> [1483727114.4980] device[0x556c4e591080] (cdc-wdm0): remove_pending_action (0): 'autoactivate'

Bjørn