On Sun, May 29, 2016 at 3:14 PM, Thomas Haller <thal...@redhat.com> wrote: > 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, >
Hi Thomas > > 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. There seems to be a timing issue on my system... If I enable the DEBUG logging in the NM configuration file, the mobile connection comes successfully up. So it works if I bring the mobile connection up manually (without secondaries configured) and with the DEBUG logging. If i grep the NM log for 'state' changes, the output is quiet interesting and as well strange for me. state changes _without_ DEBUG logging, no connection establishment (nmcli c up Mobile0): NetworkManager[]: <info> (ttyUSB3): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[]: <info> NetworkManager state is now CONNECTING ModemManager[]: <info> Simple connect state (4/8): Wait to get fully enabled ModemManager[]: <info> Simple connect state (5/8): Register ModemManager[]: <info> Simple connect state (6/8): Bearer ModemManager[]: <info> Simple connect state (7/8): Connect ModemManager[]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting) NetworkManager[]: <info> (ttyUSB3): modem state changed, 'registered' --> 'connecting' (reason: user-requested) ModemManager[]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected) NetworkManager[]: <info> (ttyUSB3): modem state changed, 'connecting' --> 'connected' (reason: user-requested) ModemManager[]: <info> Simple connect state (8/8): All done NetworkManager[]: <info> (ttyUSB3): device state change: prepare -> config (reason 'none') [40 50 0] NetworkManager[]: <info> (ttyUSB3): device state change: config -> ip-config (reason 'none') [50 70 0] NetworkManager[]: <info> (ppp0): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41] NetworkManager[]: <info> (ppp0): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41] NetworkManager[]: <info> (ppp0): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[]: <info> (ttyUSB3): device state change: ip-config -> ip-check (reason 'none') [70 80 0] NetworkManager[]: <info> (ppp0): device state change: prepare -> config (reason 'none') [40 50 0] NetworkManager[]: <info> (ppp0): device state change: config -> ip-config (reason 'none') [50 70 0] NetworkManager[]: <info> (ttyUSB3): device state change: ip-check -> secondaries (reason 'none') [80 90 0] NetworkManager[]: <info> (ppp0): device state change: ip-config -> ip-check (reason 'none') [70 80 0] NetworkManager[]: <info> (ppp0): device state change: ip-check -> secondaries (reason 'none') [80 90 0] NetworkManager[]: <info> VPN plugin state changed: starting (3) NetworkManager[]: <info> (ttyUSB3): device state change: secondaries -> failed (reason 'secondary-connection-failed') [90 120 54] NetworkManager[]: <info> NetworkManager state is now CONNECTED_LOCAL ModemManager[]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting) NetworkManager[]: <info> (ttyUSB3): modem state changed, 'connected' --> 'disconnecting' (reason: user-requested) NetworkManager[]: <info> (ttyUSB3): device state change: failed -> disconnected (reason 'none') [120 30 0] ModemManager[]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> registered) NetworkManager[]: <info> (ttyUSB3): modem state changed, 'disconnecting' --> 'registered' (reason: user-requested) state changes _with_ DEBUG logging, connection establishment (nmcli c up Mobile0): NetworkManager[]: <info> (ttyUSB3): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[]: <debug> [1465288862.903379] [NetworkManager-1.0.12/src/nm-connectivity.c:108] update_state(): connectivity: state changed from FULL to NONE NetworkManager[]: <info> NetworkManager state is now CONNECTING ModemManager[]: <info> Simple connect state (4/8): Wait to get fully enabled ModemManager[]: <info> Simple connect state (5/8): Register ModemManager[]: <info> Simple connect state (6/8): Bearer ModemManager[]: <info> Simple connect state (7/8): Connect ModemManager[]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting) NetworkManager[]: <info> (ttyUSB3): modem state changed, 'registered' --> 'connecting' (reason: user-requested) ModemManager[]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected) NetworkManager[]: <info> (ttyUSB3): modem state changed, 'connecting' --> 'connected' (reason: user-requested) ModemManager[]: <info> Simple connect state (8/8): All done NetworkManager[]: <info> (ttyUSB3): device state change: prepare -> config (reason 'none') [40 50 0] NetworkManager[]: <info> (ttyUSB3): device state change: config -> ip-config (reason 'none') [50 70 0] NetworkManager[]: <info> (ttyUSB3): device state change: ip-config -> ip-check (reason 'none') [70 80 0] NetworkManager[]: <debug> [1465288867.188249] [NetworkManager-1.0.12/src/devices/nm-device.c:7978] nm_device_add_pending_action(): [0x8312280] (ttyUSB3): add_pending_action (2): 'queued state change to secondaries' NetworkManager[]: <debug> [1465288867.188532] [NetworkManager-1.0.12/src/devices/nm-device.c:8836] nm_device_queue_state(): [0x8312280] (ttyUSB3): queued state change to secondaries due to none (id 476) NetworkManager[]: <debug> [1465288867.188832] [NetworkManager-1.0.12/src/devices/nm-device.c:8785] queued_set_state(): [0x8312280] (ttyUSB3): running queued state change to secondaries (id 476) NetworkManager[]: <info> (ttyUSB3): device state change: ip-check -> secondaries (reason 'none') [80 90 0] NetworkManager[]: <debug> [1465288867.354869] [NetworkManager-1.0.12/src/devices/nm-device.c:8736] _set_state_full(): [0x8312280] (ttyUSB3): device entered SECONDARIES state NetworkManager[]: <debug> [1465288867.375690] [NetworkManager-1.0.12/src/devices/nm-device.c:8011] nm_device_remove_pending_action(): [0x8312280] (ttyUSB3): remove_pending_action (2): 'queued state change to secondaries' NetworkManager[]: <info> VPN plugin state changed: starting (3) NetworkManager[]: <info> VPN plugin state changed: started (4) NetworkManager[]: <info> (ttyUSB3): device state change: secondaries -> activated (reason 'none') [90 100 0] NetworkManager[]: <debug> [1465288873.864054] [NetworkManager-1.0.12/src/nm-connectivity.c:108] update_state(): connectivity: state changed from NONE to FULL NetworkManager[]: <info> NetworkManager state is now CONNECTED_GLOBAL NetworkManager[]: <info> NetworkManager state is now CONNECTED_SITE NetworkManager[]: <info> NetworkManager state is now CONNECTED_GLOBAL NetworkManager[]: <debug> [1465288873.930678] [NetworkManager-1.0.12/src/dns-manager/nm-dns-manager.c:1040] nm_dns_manager_begin_updates(): (device_state_changed): queueing DNS updates (1) NetworkManager[]: <debug> [1465288873.947978] [NetworkManager-1.0.12/src/dns-manager/nm-dns-manager.c:1062] nm_dns_manager_end_updates(): (device_state_changed): no DNS changes to commit (0) NetworkManager[]: <info> (tun0): device state change: ip-config -> ip-check (reason 'none') [70 80 0] NetworkManager[]: <debug> [1465288875.308909] [NetworkManager-1.0.12/src/devices/nm-device.c:7978] nm_device_add_pending_action(): [0x833e310] (tun0): add_pending_action (1): 'queued state change to secondaries' NetworkManager[]: <debug> [1465288875.309301] [NetworkManager-1.0.12/src/devices/nm-device.c:8836] nm_device_queue_state(): [0x833e310] (tun0): queued state change to secondaries due to none (id 558) NetworkManager[]: <debug> [1465288875.309722] [NetworkManager-1.0.12/src/devices/nm-device.c:8785] queued_set_state(): [0x833e310] (tun0): running queued state change to secondaries (id 558) NetworkManager[]: <info> (tun0): device state change: ip-check -> secondaries (reason 'none') [80 90 0] NetworkManager[]: <debug> [1465288875.340766] [NetworkManager-1.0.12/src/devices/nm-device.c:7978] nm_device_add_pending_action(): [0x833e310] (tun0): add_pending_action (2): 'queued state change to activated' NetworkManager[]: <debug> [1465288875.350281] [NetworkManager-1.0.12/src/devices/nm-device.c:8836] nm_device_queue_state(): [0x833e310] (tun0): queued state change to activated due to none (id 560) NetworkManager[]: <debug> [1465288875.370014] [NetworkManager-1.0.12/src/devices/nm-device.c:8736] _set_state_full(): [0x833e310] (tun0): device entered SECONDARIES state NetworkManager[]: <debug> [1465288875.382154] [NetworkManager-1.0.12/src/devices/nm-device.c:8011] nm_device_remove_pending_action(): [0x833e310] (tun0): remove_pending_action (1): 'queued state change to secondaries' NetworkManager[]: <debug> [1465288875.412113] [NetworkManager-1.0.12/src/devices/nm-device.c:8785] queued_set_state(): [0x833e310] (tun0): running queued state change to activated (id 560) NetworkManager[]: <info> (tun0): device state change: secondaries -> activated (reason 'none') [90 100 0] NetworkManager[]: <debug> [1465288875.463440] [NetworkManager-1.0.12/src/dns-manager/nm-dns-manager.c:1040] nm_dns_manager_begin_updates(): (device_state_changed): queueing DNS updates (1) NetworkManager[]: <debug> [1465288875.522163] [NetworkManager-1.0.12/src/dns-manager/nm-dns-manager.c:1062] nm_dns_manager_end_updates(): (device_state_changed): no DNS changes to commit (0) NetworkManager[]: <debug> [1465288875.634534] [NetworkManager-1.0.12/src/devices/nm-device.c:8011] nm_device_remove_pending_action(): [0x833e310] (tun0): remove_pending_action (0): 'queued state change to activated' What I dont get is why the non DEBUG trace shows after this state change device state change: config -> ip-config (reason 'none') [50 70 0] state changes for ppp0. Best regards Samuel > > 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) _______________________________________________ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
