On Fri, 2016-05-27 at 09:59 +0200, Samuel Casa wrote:
On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller <thaller 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)
Attachment:
signature.asc
Description: This is a digitally signed message part