GNOME.org
 

Re: pppd DNS update issue in NM 1.0.12

On Tue, Jun 7, 2016 at 11:02 AM, Samuel Casa <samuelcasa9 gmail com> wrote:

On Sun, May 29, 2016 at 3:14 PM, Thomas Haller <thaller 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 <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,



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!
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]