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
