On Fri, 2016-05-27 at 09:59 +0200, Samuel Casa wrote: > On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller <thal...@redhat.com> > wrote: > > > The pppd connection is handled by the NM. > The problem with the connection setup seems to be related to the > 'secondaries' configuration element in the section 'connection'. > If I define the VPN connection as a 'secondary' for my Mobile0 > configuration, the NM can not bring up the connection [1] > > $ nmcli c up Mobile0 > > > If I bring up the network connection from the command line without > 'secondaries' using > > $ nmcli c up Mobile0 > $ nmcli c up VPN0 > > everything works fine! DNS is set as expected for the mobile link and > the VPN connection comes up. > > How to debug this easiest way? > Thank you in advance!
Hi Samuel, You can see that openvpn fails to resolve the name of your external gateway. nm-openvpn[5674]: RESOLVE: Cannot resolve host address: vpn.host.com: Temporary failure in name resolution As you are probably aware, setting a VPN connection as "secondaries" is similar to just activating both Mobile0 and VPN0 manually after each other. From the logfile, it is not clear why that happens. But obviously, at the time when openvpn wants to connect, DNS does not work yet. I would look at the logfile of NetworkManager with DEBUG logging enabled (see `man NetworkManager.conf`). Maybe it would help to replace /usr/sbin/openvpn by a wrapper script, that prints /etc/resolv.conf, ip addr, nmcli device, nmcli connection, Thomas > > > [1] trace for bad VPN connection using secondaries > > ... > May 26 14:18:18 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: disconnected -> prepare (reason 'none') [30 40 0] > May 26 14:18:18 MYHOST NetworkManager[4597]: <info> NetworkManager > state is now CONNECTING > May 26 14:18:18 MYHOST ModemManager[225]: <info> Simple connect > started... > May 26 14:18:18 MYHOST ModemManager[225]: <info> Simple connect > state > (4/8): Wait to get fully enabled > May 26 14:18:18 MYHOST ModemManager[225]: <info> Simple connect > state > (5/8): Register > May 26 14:18:18 MYHOST ModemManager[225]: <info> Simple connect > state > (6/8): Bearer > May 26 14:18:18 MYHOST ModemManager[225]: <info> Simple connect > state > (7/8): Connect > May 26 14:18:18 MYHOST ModemManager[225]: <info> Modem > /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> > connecting) > May 26 14:18:18 MYHOST NetworkManager[4597]: <info> (ttyUSB3): modem > state changed, 'registered' --> 'connecting' (reason: user-requested) > May 26 14:18:19 MYHOST ModemManager[225]: <info> Modem > /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> > connected) > May 26 14:18:19 MYHOST ModemManager[225]: <info> Simple connect > state > (8/8): All done > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> (ttyUSB3): modem > state changed, 'connecting' --> 'connected' (reason: user-requested) > May 26 14:18:19 MYHOST NetworkManager[4597]: <warn> (ttyUSB3): > failed > to look up interface index > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: prepare -> config (reason 'none') [40 50 0] > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: config -> ip-config (reason 'none') [50 70 0] > May 26 14:18:19 MYHOST NetworkManager[4597]: <warn> (ttyUSB3): > interface ttyUSB3 not up for IP configuration > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> (ttyUSB3): using > modem-specified IP timeout: 20 seconds > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> starting PPP > connection > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> pppd started > with pid 5647 > May 26 14:18:19 MYHOST pppd[5647]: Plugin > /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded. > May 26 14:18:19 MYHOST NetworkManager[4597]: Plugin > /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded. > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (plugin_init): initializing > May 26 14:18:19 MYHOST pppd[5647]: pppd 2.4.7 started by root, uid 0 > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection' > May 26 14:18:19 MYHOST pppd[5647]: Using interface ppp0 > May 26 14:18:19 MYHOST pppd[5647]: Connect: ppp0 <--> /dev/ttyUSB3 > May 26 14:18:19 MYHOST NetworkManager[4597]: <info> (ppp0): new > Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 97) > May 26 14:18:19 MYHOST NetworkManager[4597]: Using interface ppp0 > May 26 14:18:19 MYHOST NetworkManager[4597]: Connect: ppp0 <--> > /dev/ttyUSB3 > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish' > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate' > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (get_credentials): passwd-hook, requesting > credentials... > May 26 14:18:19 MYHOST pppd[5647]: CHAP authentication succeeded > May 26 14:18:19 MYHOST pppd[5647]: CHAP authentication succeeded > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (get_credentials): got credentials from NetworkManager > May 26 14:18:19 MYHOST NetworkManager[4597]: CHAP authentication > succeeded > May 26 14:18:19 MYHOST NetworkManager[4597]: CHAP authentication > succeeded > May 26 14:18:19 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network' > May 26 14:18:21 MYHOST pppd[5647]: Could not determine remote IP > address: defaulting to A.B.C.D > May 26 14:18:21 MYHOST pppd[5647]: local IP address A.B.C.D > May 26 14:18:21 MYHOST pppd[5647]: remote IP address A.B.C.D > May 26 14:18:21 MYHOST pppd[5647]: primary DNS address A.B.C.D > May 26 14:18:21 MYHOST pppd[5647]: secondary DNS address A.B.C.D > May 26 14:18:22 MYHOST NetworkManager[4597]: Could not determine > remote IP address: defaulting to A.B.C.D > May 26 14:18:22 MYHOST NetworkManager[4597]: local IP address > A.B.C.D > May 26 14:18:22 MYHOST NetworkManager[4597]: remote IP address > A.B.C.D > May 26 14:18:22 MYHOST NetworkManager[4597]: primary DNS address > A.B.C.D > May 26 14:18:22 MYHOST NetworkManager[4597]: secondary DNS address > A.B.C.D > May 26 14:18:22 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running' > May 26 14:18:22 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_ip_up): ip-up event > May 26 14:18:22 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_ip_up): sending IPv4 config to NetworkManager... > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> keyfile: add > connection in-memory (38365f22-b270-4b09-aa40-921d2210a099,"ppp0") > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: unmanaged -> unavailable (reason 'connection-assumed') > [10 20 41] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: unavailable -> disconnected (reason > 'connection-assumed') [20 30 41] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): > Activation: starting connection 'ppp0' > (38365f22-b270-4b09-aa40-921d2210a099) > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> PPP manager > (IPv4 > Config Get) reply received. > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: disconnected -> prepare (reason 'none') [30 40 0] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: ip-config -> ip-check (reason 'none') [70 80 0] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: prepare -> config (reason 'none') [40 50 0] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: config -> ip-config (reason 'none') [50 70 0] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: ip-check -> secondaries (reason 'none') [80 90 0] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> Policy set > 'ppp0' > (ppp0) as default for IPv4 routing and DNS. > May 26 14:18:22 MYHOST NetworkManager[4597]: <warn> (ppp0): arping > could not be found; no ARPs will be sent > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: ip-config -> ip-check (reason 'none') [70 80 0] > May 26 14:18:22 MYHOST NetworkManager[4597]: <info> (ppp0): device > state change: ip-check -> secondaries (reason 'none') [80 90 0] > May 26 14:18:23 MYHOST NetworkManager[2803]: > (nm-openvpn-service:4169): nm-openvpn-WARNING **: Directory > '/var/lib/openvpn/chroot' not usable for chroot by 'nm-openvpn', > openvpn will not be chrooted. > May 26 14:18:23 MYHOST NetworkManager[2803]: nm-openvpn-Message: > openvpn started with pid 5674 > May 26 14:18:23 MYHOST NetworkManager[2803]: > (nm-openvpn-service:4169): GLib-CRITICAL **: g_propagate_error: > assertion 'src != NULL' failed > May 26 14:18:23 MYHOST NetworkManager[4597]: <info> VPN plugin state > changed: starting (3) > May 26 14:18:23 MYHOST NetworkManager[4597]: <info> VPN connection > 'VPN0' (ConnectInteractive) reply received. > May 26 14:18:23 MYHOST nm-openvpn[5674]: OpenVPN 2.3.10 > i586-oe-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [MH] [IPv6] built on > Apr 6 2016 > May 26 14:18:23 MYHOST nm-openvpn[5674]: library versions: OpenSSL > 1.0.2d 9 Jul 2015, LZO 2.09 > May 26 14:18:23 MYHOST nm-openvpn[5674]: NOTE: the current > --script-security setting may allow this configuration to call > user-defined scripts > May 26 14:18:23 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:23 MYHOST nm-openvpn[5674]: NOTE: UID/GID downgrade will > be delayed because of --client, --pull, or --up-delay > May 26 14:18:23 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:25 MYHOST NetworkManager[4597]: <warn> (ppp0): arping > could not be found; no ARPs will be sent > May 26 14:18:28 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:33 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:38 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:43 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:48 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:49 MYHOST pppd[5647]: IPV6CP: timeout sending Config- > Requests > May 26 14:18:49 MYHOST NetworkManager[4597]: IPV6CP: timeout sending > Config-Requests > May 26 14:18:53 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:18:58 MYHOST nm-openvpn[5674]: RESOLVE: Cannot resolve host > address: vpn.host.com: Temporary failure in name resolution > May 26 14:19:03 MYHOST NetworkManager[4597]: <warn> VPN connection > 'VPN0' connect timeout exceeded. > May 26 14:19:03 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: secondaries -> failed (reason > 'secondary-connection-failed') [90 120 54] > May 26 14:19:03 MYHOST NetworkManager[4597]: <info> NetworkManager > state is now CONNECTED_LOCAL > May 26 14:19:03 MYHOST pppd[5647]: Terminating on signal 15 > May 26 14:19:03 MYHOST pppd[5647]: Connect time 0.7 minutes. > May 26 14:19:03 MYHOST pppd[5647]: Sent 126 bytes, received 0 bytes. > May 26 14:19:03 MYHOST NetworkManager[4597]: <warn> (ttyUSB3): > Activation: failed for connection 'Mobile0' > May 26 14:19:03 MYHOST ModemManager[225]: <info> Modem > /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> > disconnecting) > May 26 14:19:03 MYHOST pppd[5647]: Connection terminated. > May 26 14:19:03 MYHOST dbus[231]: [system] Rejected send message, 9 > matched rules; type="error", sender=":1.282" (uid=0 pid=4597 > comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" > member="(unset)" error > name="org.freedesktop.DBus.Error.UnknownMethod" > requested_reply="0" destination=":1.296" (uid=0 pid=5647 > comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,") > May 26 14:19:03 MYHOST NetworkManager[4597]: <info> (ttyUSB3): modem > state changed, 'connected' --> 'disconnecting' (reason: > user-requested) > May 26 14:19:03 MYHOST dbus[231]: [system] Rejected send message, 9 > matched rules; type="error", sender=":1.282" (uid=0 pid=4597 > comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" > member="(unset)" error > name="org.freedesktop.DBus.Error.UnknownMethod" > requested_reply="0" destination=":1.296" (uid=0 pid=5647 > comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,") > May 26 14:19:03 MYHOST dbus[231]: [system] Rejected send message, 9 > matched rules; type="error", sender=":1.282" (uid=0 pid=4597 > comm="/usr/sbin/NetworkManager --no-daemon ") interface="(unset)" > member="(unset)" error > name="org.freedesktop.DBus.Error.UnknownMethod" > requested_reply="0" destination=":1.296" (uid=0 pid=5647 > comm="/usr/sbin/pppd nodetach lock nodefaultroute ipv6 ,") > May 26 14:19:03 MYHOST NetworkManager[4597]: Terminating on signal 15 > May 26 14:19:03 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate' > May 26 14:19:03 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network' > May 26 14:19:03 MYHOST NetworkManager[4597]: Connect time 0.7 > minutes. > May 26 14:19:03 MYHOST NetworkManager[4597]: Sent 126 bytes, received > 0 bytes. > May 26 14:19:03 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish' > May 26 14:19:03 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect' > May 26 14:19:03 MYHOST NetworkManager[4597]: Connection terminated. > May 26 14:19:03 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead' > May 26 14:19:03 MYHOST NetworkManager[4597]: nm-pppd-plugin-Message: > nm-ppp-plugin: (nm_exit_notify): cleaning up > May 26 14:19:03 MYHOST NetworkManager[4597]: <info> (ttyUSB3): > device > state change: failed -> disconnected (reason 'none') [120 30 0] > May 26 14:19:03 MYHOST NetworkManager[2803]: nm-openvpn-Message: > Terminated openvpn daemon with PID 5674. > May 26 14:19:03 MYHOST dbus-daemon[231]: dbus[231]: [system] Rejected > send message, 9 matched rules; type="error", sender=":1.282" (uid=0 > pid=4597 comm="/usr/sbin/NetworkManager --no-daemon ") > interface="(unset)" member="(unset)" error > name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" > destination=":1.296" (uid=0 pid=5647 comm="/usr/sbin/pppd nodetach > lock nodefaultroute ipv6 ,") > May 26 14:19:03 MYHOST dbus-daemon[231]: dbus[231]: [system] Rejected > send message, 9 matched rules; type="error", sender=":1.282" (uid=0 > pid=4597 comm="/usr/sbin/NetworkManager --no-daemon ") > interface="(unset)" member="(unset)" error > name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" > destination=":1.296" (uid=0 pid=5647 comm="/usr/sbin/pppd nodetach > lock nodefaultroute ipv6 ,") > May 26 14:19:03 MYHOST dbus-daemon[231]: dbus[231]: [system] Rejected > send message, 9 matched rules; type="error", sender=":1.282" (uid=0 > pid=4597 comm="/usr/sbin/NetworkManager --no-daemon ") > interface="(unset)" member="(unset)" error > name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" > destination=":1.296" (uid=0 pid=5647 comm="/usr/sbin/pppd nodetach > lock nodefaultroute ipv6 ,") > May 26 14:19:03 MYHOST firewalld[218]: 2016-05-26 14:19:03 ERROR: > UNKNOWN_INTERFACE: 'ppp0' is not in any zone > May 26 14:19:03 MYHOST firewalld[218]: 2016-05-26 14:19:03 ERROR: > UNKNOWN_INTERFACE: 'ppp0' is not in any zone > May 26 14:19:04 MYHOST ModemManager[225]: <warn> (ttyUSB3): port > attributes not fully set > May 26 14:19:05 MYHOST ModemManager[225]: <info> Modem > /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting > -> registered) > May 26 14:19:05 MYHOST NetworkManager[4597]: <info> (ttyUSB3): modem > state changed, 'disconnecting' --> 'registered' (reason: > user-requested)
signature.asc
Description: This is a digitally signed message part
_______________________________________________ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
