On Tue, Jun 7, 2016 at 11:02 AM, Samuel Casa <samuelca...@gmail.com> wrote:
> 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)
I could workaround the issue with this patch:
diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index 1171473..d111926 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -6118,6 +6118,9 @@ _update_ip4_address (NMDevice *self)
if (addr != priv->ip4_address) {
priv->ip4_address = addr;
g_object_notify (G_OBJECT (self), NM_DEVICE_IP4_ADDRESS);
+
+ _LOGD (LOGD_DEVICE, "update_ip4_address: delay return
from IPv4 address update to workaround problem with pppd
configuration");
+ g_usleep (1000000);
}
}
}
I have no idea what kind of factors affect this behaviour on my
platform, but this works for me (for now).
Thaks for helping!
_______________________________________________
networkmanager-list mailing list
networkmanager-list@gnome.org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
