NM fails with 'config-failed' despite successful MM connection
Dan Williams
dcbw at redhat.com
Fri Jan 6 17:34:34 UTC 2017
On Fri, 2017-01-06 at 00:04 +0100, Bjørn Mork wrote:
> 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 :)
Yeah, sorry about that.
> 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?
NM knows to treat wwan0 as a child of cdc-wdm0, since wwan0 is useless
without setting it up via cdc-wdm0 first. So wwan0 isn't a real NM
device, and is only tracked via an "IP interface ifindex" in cdc-wdm0's
private data.
So anyway, we've confirmed that the problem is not actually with
systemd suspend/resume functionality, and that the bug really is in NM
itself.
Can you give the attached NM patch a try? It's diffed from the nm-1-4
branch.
Dan
diff --git a/src/devices/nm-device-private.h b/src/devices/nm-device-private.h
index c85cb96..d8f5c9e 100644
--- a/src/devices/nm-device-private.h
+++ b/src/devices/nm-device-private.h
@@ -42,7 +42,7 @@ enum NMActStageReturn {
NMSettings *nm_device_get_settings (NMDevice *self);
-void nm_device_set_ip_iface (NMDevice *self, const char *iface);
+gboolean nm_device_set_ip_iface (NMDevice *self, const char *iface);
void nm_device_activate_schedule_stage3_ip_config_start (NMDevice *device);
diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index ac840ab..f55868b 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -738,19 +738,25 @@ nm_device_get_ip_ifindex (NMDevice *self)
return priv->ip_iface ? priv->ip_ifindex : priv->ifindex;
}
-void
+gboolean
nm_device_set_ip_iface (NMDevice *self, const char *iface)
{
NMDevicePrivate *priv;
- char *old_ip_iface;
+ gs_free char *old_ip_iface = NULL;
+ int old_ip_ifindex;
+ gboolean changed = FALSE;
- g_return_if_fail (NM_IS_DEVICE (self));
+ g_return_val_if_fail (NM_IS_DEVICE (self), FALSE);
priv = NM_DEVICE_GET_PRIVATE (self);
- if (!g_strcmp0 (iface, priv->ip_iface))
- return;
+
+ /* Always update ip_iface and ip_ifindex since even if the name didn't
+ * change, the ip_ifindex may have if the devce was re-created with the
+ * same name after a suspend/resume cycle.
+ */
old_ip_iface = priv->ip_iface;
+ old_ip_ifindex = priv->ip_ifindex;
priv->ip_ifindex = 0;
priv->ip_iface = g_strdup (iface);
@@ -772,9 +778,12 @@ nm_device_set_ip_iface (NMDevice *self, const char *iface)
g_hash_table_remove_all (priv->ip6_saved_properties);
/* Emit change notification */
- if (g_strcmp0 (old_ip_iface, priv->ip_iface))
+ if (g_strcmp0 (old_ip_iface, priv->ip_iface) || old_ip_ifindex != priv->ip_ifindex) {
+ changed = TRUE;
_notify (self, PROP_IP_IFACE);
- g_free (old_ip_iface);
+ }
+
+ return changed;
}
/*****************************************************************************/
diff --git a/src/devices/wwan/nm-device-modem.c b/src/devices/wwan/nm-device-modem.c
index b277b15..fb09e14 100644
--- a/src/devices/wwan/nm-device-modem.c
+++ b/src/devices/wwan/nm-device-modem.c
@@ -249,16 +249,11 @@ static void
data_port_changed_cb (NMModem *modem, GParamSpec *pspec, gpointer user_data)
{
NMDevice *self = NM_DEVICE (user_data);
- const char *old = nm_device_get_ip_iface (self);
- const char *new = nm_modem_get_data_port (modem);
gboolean changed = FALSE;
- if (new && g_strcmp0 (new, old))
- changed = TRUE;
-
/* We set the IP iface in the device as soon as we know it, so that we
* properly ifup it if needed */
- nm_device_set_ip_iface (self, new);
+ changed = nm_device_set_ip_iface (self, nm_modem_get_data_port (modem));
/* Disable IPv6 immediately on the interface since NM handles IPv6
* internally, and leaving it enabled could allow the kernel's IPv6
More information about the ModemManager-devel
mailing list