[Pkg-utopia-maintainers] Bug#755202: network-manager: keeps creating and using new connection "eth0" that does not work

Fri Feb 23 16:10:37 UTC 2018

Package: network-manager
Version: 1.10.4-1+b1
Followup-For: Bug #755202

Hi folks,

I've also been seeing this bug on my system for quite some while now,
and decided to investigate today. I haven't quite figured it out, but
I'll share my findings here.

>From the previous discussion on this bug, most notably the IRC log
posted, I understand that the problem is somewhat like this:
 - On boot, something brings up the ethernet interface (or are network
   interfaces up by default?)
 - The interface gets a link-local ipv6 and/or statelessly
   autoconfigured global ipv6 address (handled by the kernel, I
   believe?).
 - NetworkManager starts, and finds a (partially configured interface).
 - NetworkManager starts managing the interface (with reason
   'connection-assumed') and creates a new (temporary) connection
   profile called 'eth0' that copies the current settings from the
   interface.
 - NetworkManager does *not* activate the normal default connection
   profile for the interface.

I haven't been able to confirm the above is exactly what happens, but my
observations do seem to match the above theory.

I have been trying to pinpoint the code path that handles it, without
much succes. I enabled trace logging (see NetworkManager.conf below) and
that caused debug and trace log entries to appear, but nothing I could
completely correlate with the source.

Here's the relevant bit of the log, where it apparently decides to
create a new connection. This is from 1.6.2, but with the output is
pretty much the same with 1.10.4.

  device (eth0): link connected
  manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
  manager: (eth0.10): new VLAN device (/org/freedesktop/NetworkManager/Devices/3)
  manager: (eth0.253): new VLAN device (/org/freedesktop/NetworkManager/Devices/4)
  keyfile: add connection in-memory (056caea2-6833-42cc-bdc5-bd8c5744c8a9,"eth0")
  device (eth0): state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
  device (eth0): state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
  device (eth0): Activation: starting connection 'eth0' (056caea2-6833-42cc-bdc5-bd8c5744c8a9)

Looking at the source, I would expect these lines to come from:

  keyfile: add connection in-memory (056caea2-6833-42cc-bdc5-bd8c5744c8a9,"eth0")
    https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1846
    https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1762
  device (eth0): state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
    https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1853-L1860
  device (eth0): state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
    https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1860
    https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1793-L1797

However, in that case I would also expect to see these messages:

  https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1758-L1760
  https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L1789-L1791

I've looked at other code paths that could lead to these
connection-assumed state changes, but each path I could find would also
log additional messages that I'm not seeing here.

It doesn't seem that debug messages for the device domain, or
nm-manager.c are broken, since I *do* see this message:

  manager: setup NMManager singleton (0x559e10330041)
  https://github.com/NetworkManager/NetworkManager/blob/1.6.2/src/nm-manager.c#L5688

All this looks at 1.6.2, but I've had a similar (but not as thorough)
look at 1.10.4 which looks pretty much the same.

Another observation I made is that:
 - With 1.6.2, if I set two (out of two) VLAN connections I had to
   autostart=false, the problem would disappear.
 - With 1.10.4, if I set both VLAN connections to autostart=false, the
   problem would remain. Also if I completely removed them.
 - With 1.6.2, if I removed the VLAN connections, but added
   `ExecStartPre=/bin/sh -c "sleep 5"` to the systemd service file, the
   problem would appear again.

Given that, the link-up message from the kernel in my log is only
shortly before NM starts (within the same second), I suspect that there
is a race condition with NM looking at the interface and the kernel
configuring it, and the VLAN connections I have subtly influence the
timing.

I've also disabled avahi, which does not seem to influence the problem
at all (with avahi enabled, it generates log output about registering
addresses, but I believe it does this *in response to* the addresses
being added by the kernel, not the other way around.

-- System Information:
Debian Release: 9.3
  APT prefers stable
  APT policy: (990, 'stable'), (500, 'unstable-debug'), (500, 'testing-debug'), (500, 'stable-debug'), (500, 'testing'), (500, 'oldstable'), (50, 'unstable'), (1, 'experimental-debug'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.11.0-1-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages network-manager depends on:
ii  adduser                3.115
ii  dbus                   1.10.24-0+deb9u1
ii  init-system-helpers    1.48
ii  libaudit1              1:2.6.7-2
ii  libbluetooth3          5.43-2+deb9u1
ii  libc6                  2.26-4
ii  libglib2.0-0           2.50.3-2
ii  libgnutls30            3.5.8-5+deb9u3
ii  libgudev-1.0-0         230-3
ii  libjansson4            2.9-1
ii  libmm-glib0            1.6.4-1
ii  libndp0                1.6-1+b1
ii  libnewt0.52            0.52.19-1+b1
ii  libnl-3-200            3.2.27-2
ii  libnm0                 1.6.2-3
ii  libpam-systemd         232-25+deb9u1
ii  libpolkit-agent-1-0    0.105-18
ii  libpolkit-gobject-1-0  0.105-18
ii  libreadline7           7.0-3
ii  libselinux1            2.6-3+b3
ii  libsoup2.4-1           2.56.0-2+deb9u1
ii  libsystemd0            232-25+deb9u1
ii  libteamdctl0           1.26-1+b1
ii  libuuid1               2.29.2-1
ii  lsb-base               9.20161125
ii  policykit-1            0.105-18
ii  udev                   232-25+deb9u1
ii  wpasupplicant          2:2.4-1+deb9u1

Versions of packages network-manager recommends:
ii  crda             3.18-1
ii  dnsmasq-base     2.76-5+deb9u1
ii  iptables         1.6.0+snapshot20161117-6
ii  iputils-arping   3:20161105-1
ii  isc-dhcp-client  4.3.5-3
ii  modemmanager     1.6.4-1
pn  ppp              <none>

Versions of packages network-manager suggests:
pn  libteam-utils  <none>

-- Configuration Files:
/etc/NetworkManager/NetworkManager.conf changed:
[main]
plugins=ifupdown,keyfile

[ifupdown]
managed=false

[logging]
level=TRACE
domains=ALL:TRACE,DEVICE:TRACE

-- no debconf information