[Bug 1106993] New: NetworkManager 1.12.2: "Connection activation failed: Could not find source connection." when starting VPN
http://bugzilla.suse.com/show_bug.cgi?id=1106993 Bug ID: 1106993 Summary: NetworkManager 1.12.2: "Connection activation failed: Could not find source connection." when starting VPN Classification: openSUSE Product: openSUSE Tumbleweed Version: Current Hardware: x86-64 OS: Other Status: NEW Severity: Major Priority: P5 - None Component: Network Assignee: bnc-team-screening@forge.provo.novell.com Reporter: martin.wilck@suse.com QA Contact: qa-bugs@suse.de Found By: --- Blocker: --- Created attachment 781787 --> http://bugzilla.suse.com/attachment.cgi?id=781787&action=edit NetworkManager journal with logging level=DEBUG I'm seeing the following behavior recently when I try to start openVPN via NetworkManager. I haven't observed this behavior until I updated to NetworkManager 1.12.2 a few days ago:
2018-08-31 09:13:52|install|NetworkManager|1.12.2-1.2|x86_64||repo-oss|08f9fee5f82bcc8b1bc47d6117712ce86715000a41dbafab35fc71d18f8c3b58|
If I click on the VPN connection in the nm-applet GUI as I used to, simply nothing happens, that was the starting point. The system is connected to my home network via ethernet (enp0s31f6). 2 VLAN interfaces are set up via this interface. Routing and connectivity are OK. nmcli sees the enp0s31f6 connection and shows full connectivity. apollon:/etc/NetworkManager/system-connections # ip route show default via 192.168.1.4 dev enp0s31f6 proto dhcp metric 100 192.168.1.0/24 dev enp0s31f6 proto kernel scope link src 192.168.1.40 metric 100 mtu 1500 192.168.10.0/24 dev vlan10 proto kernel scope link src 192.168.10.40 metric 400 192.168.10.40 dev vlan10 proto kernel scope link src 192.168.10.40 metric 400 192.168.20.0/24 dev vlan20 proto kernel scope link src 192.168.20.40 metric 401 192.168.100.0/24 dev virbr0 proto kernel scope link src 192.168.100.1 linkdown 192.168.110.0/24 dev virbr1 proto kernel scope link src 192.168.110.1 linkdown apollon:/etc/NetworkManager/system-connections # ping -c 1 www.suse.com PING www.suse.com (130.57.66.10) 56(84) bytes of data. 64 bytes from www.suse.com (130.57.66.10): icmp_seq=1 ttl=44 time=170 ms --- www.suse.com ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 169.895/169.895/169.895/0.000 ms mwilck@apollon:~> nmcli general status STATE CONNECTIVITY WIFI-HW WIFI WWAN-HW WWAN connected full enabled disabled enabled enabled mwilck@apollon:~> nmcli con show NAME UUID TYPE DEVICE enp0s31f6 feef26e5-468f-4b11-8e12-5735d06903cd ethernet enp0s31f6 virbr0 3b0b4d63-187c-440c-8e6b-c1e8347ccb49 bridge virbr0 virbr1 6f4366ba-5b08-4283-8da1-8662993edb85 bridge virbr1 vlan10 71e3ae6d-68f4-4175-9d9c-913490b03229 vlan vlan10 vlan20 c1d43bbb-3404-4d74-a056-e1a6a58344db vlan vlan20 ... suse_de 061fd5ed-d901-4553-99be-36fd1551c46f vpn -- ... wired_dhcp b99bd77c-b92a-453d-a714-fef71dfd5586 ethernet -- Yet if I try to activate the VPN, I get: mwilck@apollon:~> nmcli -a con up suse_de Error: Connection activation failed: Could not find source connection. The NM log shows not much, despite full debugging:
Sep 04 08:57:42 apollon.suse.de NetworkManager[3290]: <debug> [1536044262.0527] agent-manager: req[0x7fc0e80049c0, :1.101/nmcli-connect/17326]: requesting permissions Sep 04 08:57:42 apollon.suse.de NetworkManager[3290]: <debug> [1536044262.0874] agent-manager: req[0x7fc0e80049c0, :1.101/nmcli-connect/17326]: agent registered Sep 04 08:57:42 apollon.suse.de NetworkManager[3290]: <debug> [1536044262.0875] policy: re-enabling autoconnect for all connections (only clear no-secrets flag) Sep 04 08:57:42 apollon.suse.de NetworkManager[3290]: <info> [1536044262.0889] audit: op="connection-activate" uuid="061fd5ed-d901-4553-99be-36fd1551c46f" name="suse_de" pid=7861 uid=17326 result="fail" reason="Could not find source connection." Sep 04 08:57:42 apollon.suse.de NetworkManager[3290]: <debug> [1536044262.0910] agent-manager: req[0x7fc0e80049c0, :1.101/nmcli-connect/17326]: agent unregistered or disappeared
It appears that NetworkManager doesn't take the fully functional enp0s31f6 connection into account when looking for a source connection for the VPN. There is no configuration file for connection "enp0s31f6" under /etc/NetworkManager/system-connections. I observed there is a config file apollon:/etc/NetworkManager/system-connections # ls -l /etc/sysconfig/network/ifcfg* -rw------- 1 root root 141 Jun 20 09:54 /etc/sysconfig/network/ifcfg-br0 -rw------- 1 root root 96 Jun 20 09:54 /etc/sysconfig/network/ifcfg-enp0s31f6 -rw------- 1 root root 147 Jun 9 19:36 /etc/sysconfig/network/ifcfg-lo It's not unlikely that I don't recall having created these files. Interestingly, the modification time corresponds to the last update of wicked to 0.6.48-1.2:
2018-06-20 09:53:58|install|wicked|0.6.48-1.2|x86_64||repo-oss|4371c193d743f1076297f052ed9ad4ed06989645b60809175106b5da24e3e71b| 2018-06-20 09:54:18|install|wicked-service|0.6.48-1.2|x86_64||repo-oss|45a30c9534a22319f64ccaca0139a821ae0c3eb7b5a942343e6f8e4d1e0fc668
But wicked services are off on this system: systemctl status wicked wickedd wickedd-nanny wickedd-dhcp4 ● wicked.service - wicked managed network interfaces Loaded: loaded (/usr/lib/systemd/system/wicked.service; disabled; vendor preset: disabled) Active: inactive (dead) ● wickedd.service - wicked network management service daemon Loaded: loaded (/usr/lib/systemd/system/wickedd.service; indirect; vendor preset: disabled) Active: inactive (dead) ● wickedd-nanny.service - wicked network nanny service Loaded: loaded (/usr/lib/systemd/system/wickedd-nanny.service; disabled; vendor preset: disabled) Active: inactive (dead) ● wickedd-dhcp4.service - wicked DHCPv4 supplicant service Loaded: loaded (/usr/lib/systemd/system/wickedd-dhcp4.service; disabled; vendor preset: disabled) Active: inactive (dead) -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.suse.com/show_bug.cgi?id=1106993
http://bugzilla.suse.com/show_bug.cgi?id=1106993#c1
--- Comment #1 from Martin Wilck
It appears that NetworkManager doesn't take the fully functional enp0s31f6 connection into account when looking for a source connection for the VPN.
This is supported by the fact that stopping NM doesn't kill this connection, nor the dnsmasq and dhcp processes associated with it: apollon:/etc/NetworkManager/system-connections # systemctl stop NetworkManager apollon:/etc/NetworkManager/system-connections # systemctl status NetworkManager ● NetworkManager.service - Network Manager Loaded: loaded (/usr/lib/systemd/system/NetworkManager.service; enabled; vendor preset: disabled) Drop-In: /usr/lib/systemd/system/NetworkManager.service.d └─NetworkManager-ovs.conf /etc/systemd/system/NetworkManager.service.d └─suse.conf Active: inactive (dead) since Tue 2018-09-04 09:28:34 CEST; 1s ago Docs: man:NetworkManager(8) Process: 3290 ExecStart=/usr/sbin/NetworkManager --no-daemon (code=exited, status=0/SUCCESS) Process: 3289 ExecStartPre=/usr/bin/rm -f /etc/NetworkManager/dnsmasq.d/suse-vpn.conf (code=exited, status=0/SUCCESS) Main PID: 3290 (code=exited, status=0/SUCCESS) Tasks: 2 (limit: 4915) CGroup: /system.slice/NetworkManager.service ├─2763 /usr/sbin/dnsmasq --no-resolv --keep-in-foreground --no-hosts --bind-interfaces --pid-file=/run/NetworkManager/dnsma> └─3204 /sbin/dhclient -d -q -sf /usr/lib/nm-dhcp-helper -pf /var/run/dhclient-enp0s31f6.pid -lf /var/lib/NetworkManager/dhc> -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.suse.com/show_bug.cgi?id=1106993
http://bugzilla.suse.com/show_bug.cgi?id=1106993#c2
--- Comment #2 from Martin Wilck
From the previous findings, I thought it might help to remove /etc/sysconfig/network/ifcfg-enp0s31f6. But it didn't. After reboot, the situation was exactly as shown before. It's necessary to run "nmcli down enp0s31f6" to be able to activate the VPN, as shown in comment 2. Note that
http://bugzilla.suse.com/show_bug.cgi?id=1106993
http://bugzilla.suse.com/show_bug.cgi?id=1106993#c3
--- Comment #3 from Martin Wilck
http://bugzilla.suse.com/show_bug.cgi?id=1106993
http://bugzilla.suse.com/show_bug.cgi?id=1106993#c4
--- Comment #4 from Martin Wilck
apollon: # ip link show vlan10 4: vlan10@enp0s31f6:
mtu 8990 qdisc noqueue state UP mode DEFAULT group default qlen 1000 link/ether 84:7b:eb:44:25:03 brd ff:ff:ff:ff:ff:ff
The connection names of format "vlan-vlan$ID" were created automatically when I run "nmcli con add type vlan", this still behaves the same way:
# nmcli con add type vlan ifname vlan30 dev enp0s31f6 id 30 Connection 'vlan-vlan30' (2a1f4f84-07bc-49a3-bfa6-2535aa4d9517) successfully added.
The logs show e.g. for vlan10 that NM creates an interface with id "vlan-vlan10", and then gets woken up with an event for "vlan10", which it apparently doesn't recognize as the one it just set up as "vlan-vlan10":
Sep 04 09:38:28 apollon NetworkManager[1666]: <debug> [1536046708.9996] keyfile: loading from file "/etc/NetworkManager/system-connections/vlan-vlan10"... Sep 04 09:38:29 apollon NetworkManager[1666]: <info> [1536046709.0019] keyfile: new connection /etc/NetworkManager/system-connections/vlan-vlan10 (9fdf61c7-a18c-415e-a02a-e9d804ef08a6,"vlan-vlan10") Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.1099] ++ connection.id = 'vlan-vlan10' Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.1100] ++ connection.interface-name = 'vlan10' Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4066] device[0x55d192029f90] (vlan10): constructed (NMDeviceVlan) Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4067] manager: (vlan-vlan10) create virtual device vlan10 Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4067] device[0x55d192029f90] (vlan10): unmanaged: flags set to [platform-init,!sleeping=0x10/0x11/unmanaged/unrealized], set-managed [sleeping=0x1]) Sep 04 09:38:29 apollon NetworkManager[1666]: <info> [1536046709.4069] manager: (vlan10): new VLAN device (/org/freedesktop/NetworkManager/Devices/3) Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4071] device[0x55d192029f90] (vlan10): create (is nm-owned) Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4072] platform: link: adding vlan 'vlan10' parent 2 vlanid 10 vlanflags 1 Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4072] platform-linux: link: add vlan 'vlan10', parent 2, vlan id 10, flags 1 Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4511] platform: signal: link added: 4: vlan10@2
mtu 1500 arp 1 vlan* not-init addrgenmode eui64 addr 84:7B:EB:44:25:03 driver vlan rx:0,0 tx:0,0 Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4511] platform-linux: do-add-link[vlan10/vlan]: success Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4513] device[0x55d192029f90] (vlan10): parent: ifindex 2, device 0x55d19200c920, enp0s31f6 Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4513] device[0x55d192029f90] (vlan10): unmanaged: flags set to [platform-init,!sleeping,!parent=0x10/0x15/unmanaged/unrealized], set-managed [parent=0x4]) Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4513] device[0x55d192029f90] (vlan10): add_pending_action (1): 'recheck-available' Sep 04 09:38:29 apollon NetworkManager[1666]: <debug> [1536046709.4514] device[0x55d192029f90] (vlan10): start setup of NMDeviceVlan, k
-- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.suse.com/show_bug.cgi?id=1106993
Chenzi Cao
participants (1)
-
bugzilla_noreply@novell.com