Created attachment 781787 [details]
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)