GNOME.org
 

Re: pppd DNS update issue in NM 1.0.12

On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller <thaller redhat com> wrote:

On Mon, 2016-04-18 at 19:42 +0200, Samuel Casa wrote:

Hi!
I am using NM 1.0.12 in combination with pppd and modemmanager 1.4.14
to get a GSM link up and running.
The mobile link comes up, but the DNS information from the provider
is
not updated correctly in /etc/resolv.conf by the NM.

I can see the GSM providers DNS information in /run/resolv.conf.
If i symlink /etc/resolv.conf -> /run/resolv.conf everything works
fine with the update and name resolution.

DNS information for Ethernet connections is updated correctly in
/etc/reslov.conf.
I am not using a resolver.

Any ideas?


Hi Samuel,


NetworkManager does not write to /run/resolv.conf. This is probably
written by pppd.

When you run pppd yourself (without using the wwan plugin of
NetworkManager), you have to care for resolv.conf yourself.


For example, disable NetworkManager writing /etc/resolv.conf
via

  [main]
  dns=none

in /etc/NetworkManager/NetworkManager.conf. After that, there is
nothing wrong with symlinking /etc/resolv.conf -> /run/resolv.conf, if
that is what you want.
(Sidenote: on newer version 1.2, NM would respect your symlink, and you
would not need to disable it via configuration).


A bit more tricky is, to combine the DNS information from pppd and
NetworkManager. Maybe you could use a dispatcher script for that...


Alternatively, let NetworkManager manage the GSM connection via the
wwan plugin.


Good luck,
Thomas



Hi Thomas
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!


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