Re: pppd DNS update issue in NM 1.0.12

[Samuel Casa]

On Tue, Jun 7, 2016 at 11:02 AM, Samuel Casa  wrote:
> On Sun, May 29, 2016 at 3:14 PM, Thomas Haller  wrote:
>> On Fri, 2016-05-27 at 09:59 +0200, Samuel Casa wrote:
>>> On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller 
>>> 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[]:   (ttyUSB3): device state change: disconnected
> -> prepare (reason 'none') [30 40 0]
> NetworkManager[]:   NetworkManager state is now CONNECTING
> ModemManager[]:   Simple connect state (4/8): Wait to get fully enabled
> ModemManager[]:   Simple connect state (5/8): Register
> ModemManager[]:   Simple connect state (6/8): Bearer
> ModemManager[]:   Simple connect state (7/8): Connect
> ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
> state changed (registered -> connecting)
> NetworkManager[]:   (ttyUSB3): modem state changed, 'registered'
> --> 'connecting' (reason: user-requested)
> ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
> state changed (connecting -> connected)
> NetworkManager[]:   (ttyUSB3): modem state changed, 'connecting'
> --> 'connected' (reason: user-requested)
> ModemManager[]:   Simple connect state (8/8): All done
> NetworkManager[]:   (ttyUSB3): device state change: prepare ->
> config (reason 'none') [40 50 0]
> NetworkManager[]:   (ttyUSB3): device state change: config ->
> ip-config (reason 'none') [50 70 0]
> NetworkManager[]:   (ppp0): device state change: unmanaged ->
> unavailable (reason 'connection-assumed') [10 20 41]
> NetworkManager[]:   (ppp0): device state change: unavailable ->
> disconnected (reason 'connection-assumed') [20 30 41]
> NetworkManager[]:   (ppp0): device state change: disconnected ->
> prepare (reason 'none') [30 40 0]
> NetworkManager[]:   (ttyUSB3): device state change: ip-config ->
> ip-check (reason 'none') [70 80 0]
> NetworkManager[]:   (ppp0): device state change: prepare ->
> config (reason 'none') [40 50 0]
> NetworkManager[]:   (ppp0): device state change: config ->
> ip-config (reason 'none') [50 70 0]
> NetworkManager[]:   (ttyUSB3): device state change: ip-check ->
> secondaries (reason 'none') [80 90 0]
> NetworkManager[]:   (ppp0): device state change: ip-config ->
> ip-check (reason 'none') [70 80 0]
> NetworkManager[]:   (ppp0): device state change: ip-check ->
> secondaries (reason 'none') [80 90 0]
> NetworkManager[]:   VPN plugin state changed: starting (3)
> NetworkManager[]:   (ttyUSB3): device state change: secondaries
> -> failed (reason 'secondary-connection-failed') [90 120 54]
> NetworkManager[]:   NetworkManager state is now CONNECTED_LOCAL
> ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
> state changed (connected -> disconnecting)
> NetworkManager[]:   (ttyUSB3): modem state changed, 'connected'
> --> 'disconnecting' (reason: user-requested)
> NetworkManager[]:   (ttyUSB3): device state change: failed ->
> disconnected (reason 'none') [120 30 0]
> ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
> state changed (disconnecting -> registered)
> NetworkManager[]:   (ttyUSB3): modem state changed,
> 'disconnecting' --> 'registered' (reason: user-requested)
>
> state changes _with_ DEBUG logging, connection establishment (nmcli c
> up  Mobile0):
> NetworkManager[]:   (ttyUSB3): device state change: disconnected
> -> prepare (reason 'none') [30 40 0]
> NetworkManager[]:  [1465288862.903379]
> 

Re: pppd DNS update issue in NM 1.0.12

[Samuel Casa]

On Sun, May 29, 2016 at 3:14 PM, Thomas Haller  wrote:
> On Fri, 2016-05-27 at 09:59 +0200, Samuel Casa wrote:
>> On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller 
>> 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[]:   (ttyUSB3): device state change: disconnected
-> prepare (reason 'none') [30 40 0]
NetworkManager[]:   NetworkManager state is now CONNECTING
ModemManager[]:   Simple connect state (4/8): Wait to get fully enabled
ModemManager[]:   Simple connect state (5/8): Register
ModemManager[]:   Simple connect state (6/8): Bearer
ModemManager[]:   Simple connect state (7/8): Connect
ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
state changed (registered -> connecting)
NetworkManager[]:   (ttyUSB3): modem state changed, 'registered'
--> 'connecting' (reason: user-requested)
ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
state changed (connecting -> connected)
NetworkManager[]:   (ttyUSB3): modem state changed, 'connecting'
--> 'connected' (reason: user-requested)
ModemManager[]:   Simple connect state (8/8): All done
NetworkManager[]:   (ttyUSB3): device state change: prepare ->
config (reason 'none') [40 50 0]
NetworkManager[]:   (ttyUSB3): device state change: config ->
ip-config (reason 'none') [50 70 0]
NetworkManager[]:   (ppp0): device state change: unmanaged ->
unavailable (reason 'connection-assumed') [10 20 41]
NetworkManager[]:   (ppp0): device state change: unavailable ->
disconnected (reason 'connection-assumed') [20 30 41]
NetworkManager[]:   (ppp0): device state change: disconnected ->
prepare (reason 'none') [30 40 0]
NetworkManager[]:   (ttyUSB3): device state change: ip-config ->
ip-check (reason 'none') [70 80 0]
NetworkManager[]:   (ppp0): device state change: prepare ->
config (reason 'none') [40 50 0]
NetworkManager[]:   (ppp0): device state change: config ->
ip-config (reason 'none') [50 70 0]
NetworkManager[]:   (ttyUSB3): device state change: ip-check ->
secondaries (reason 'none') [80 90 0]
NetworkManager[]:   (ppp0): device state change: ip-config ->
ip-check (reason 'none') [70 80 0]
NetworkManager[]:   (ppp0): device state change: ip-check ->
secondaries (reason 'none') [80 90 0]
NetworkManager[]:   VPN plugin state changed: starting (3)
NetworkManager[]:   (ttyUSB3): device state change: secondaries
-> failed (reason 'secondary-connection-failed') [90 120 54]
NetworkManager[]:   NetworkManager state is now CONNECTED_LOCAL
ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
state changed (connected -> disconnecting)
NetworkManager[]:   (ttyUSB3): modem state changed, 'connected'
--> 'disconnecting' (reason: user-requested)
NetworkManager[]:   (ttyUSB3): device state change: failed ->
disconnected (reason 'none') [120 30 0]
ModemManager[]:   Modem /org/freedesktop/ModemManager1/Modem/0:
state changed (disconnecting -> registered)
NetworkManager[]:   (ttyUSB3): modem state changed,
'disconnecting' --> 'registered' (reason: user-requested)

state changes _with_ DEBUG logging, connection establishment (nmcli c
up  Mobile0):
NetworkManager[]:   (ttyUSB3): device state change: disconnected
-> prepare (reason 'none') [30 40 0]
NetworkManager[]:  [1465288862.903379]
[NetworkManager-1.0.12/src/nm-connectivity.c:108] update_state():
connectivity: state changed from FULL to NONE
NetworkManager[]:   NetworkManager state is now CONNECTING
ModemManager[]:   Simple connect state (4/8): Wait to get fully enabled
ModemManager[]:   Simple connect 

Re: pppd DNS update issue in NM 1.0.12

[Thomas Haller]

On Fri, 2016-05-27 at 09:59 +0200, Samuel Casa wrote:
> On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller 
> wrote:
> > 
> The pppd connection is handled by the NM.
> The problem with the connection setup seems to be related to the
> 'secondaries' configuration element in the section 'connection'.
> If I define the VPN connection as a 'secondary' for my Mobile0
> configuration, the NM can not bring up the connection [1]
> 
>   $ nmcli c up Mobile0
> 
> 
> If I bring up the network connection from the command line without
> 'secondaries' using
> 
>   $ nmcli c up Mobile0
>   $ nmcli c up VPN0
> 
> everything works fine! DNS is set as expected for the mobile link and
> the VPN connection comes up.
> 
> How to debug this easiest way?
> Thank you in advance!

Hi Samuel,


You can see that openvpn fails to resolve the name of your external
gateway. 
  nm-openvpn[5674]: RESOLVE: Cannot resolve host address: vpn.host.com: 
Temporary failure in name resolution

As you are probably aware, setting a VPN connection as "secondaries" is
similar to just activating both Mobile0 and VPN0 manually after each
other.

From the logfile, it is not clear why that happens. But obviously, at
the time when openvpn wants to connect, DNS does not work yet.

I would look at the logfile of NetworkManager with DEBUG logging
enabled (see `man NetworkManager.conf`).
Maybe it would help to replace /usr/sbin/openvpn by a wrapper script,
that prints /etc/resolv.conf, ip addr, nmcli device, nmcli connection, 



Thomas


> 
> 
> [1] trace for bad VPN connection using secondaries
> 
> ...
> May 26 14:18:18 MYHOST NetworkManager[4597]:   (ttyUSB3):
> device
> state change: disconnected -> prepare (reason 'none') [30 40 0]
> May 26 14:18:18 MYHOST NetworkManager[4597]:   NetworkManager
> state is now CONNECTING
> May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect
> started...
> May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect
> state
> (4/8): Wait to get fully enabled
> May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect
> state
> (5/8): Register
> May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect
> state
> (6/8): Bearer
> May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect
> state
> (7/8): Connect
> May 26 14:18:18 MYHOST ModemManager[225]:   Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
> connecting)
> May 26 14:18:18 MYHOST NetworkManager[4597]:   (ttyUSB3): modem
> state changed, 'registered' --> 'connecting' (reason: user-requested)
> May 26 14:18:19 MYHOST ModemManager[225]:   Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> connected)
> May 26 14:18:19 MYHOST ModemManager[225]:   Simple connect
> state
> (8/8): All done
> May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): modem
> state changed, 'connecting' --> 'connected' (reason: user-requested)
> May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3):
> failed
> to look up interface index
> May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3):
> device
> state change: prepare -> config (reason 'none') [40 50 0]
> May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3):
> device
> state change: config -> ip-config (reason 'none') [50 70 0]
> May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3):
> interface ttyUSB3 not up for IP configuration
> May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): using
> modem-specified IP timeout: 20 seconds
> May 26 14:18:19 MYHOST NetworkManager[4597]:   starting PPP
> connection
> May 26 14:18:19 MYHOST NetworkManager[4597]:   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]:   (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 

Re: pppd DNS update issue in NM 1.0.12

[Samuel Casa]

On Mon, Apr 18, 2016 at 8:02 PM, Thomas Haller  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]:   (ttyUSB3): device
state change: disconnected -> prepare (reason 'none') [30 40 0]
May 26 14:18:18 MYHOST NetworkManager[4597]:   NetworkManager
state is now CONNECTING
May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect started...
May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect state
(4/8): Wait to get fully enabled
May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect state
(5/8): Register
May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect state
(6/8): Bearer
May 26 14:18:18 MYHOST ModemManager[225]:   Simple connect state
(7/8): Connect
May 26 14:18:18 MYHOST ModemManager[225]:   Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
May 26 14:18:18 MYHOST NetworkManager[4597]:   (ttyUSB3): modem
state changed, 'registered' --> 'connecting' (reason: user-requested)
May 26 14:18:19 MYHOST ModemManager[225]:   Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
connected)
May 26 14:18:19 MYHOST ModemManager[225]:   Simple connect state
(8/8): All done
May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): modem
state changed, 'connecting' --> 'connected' (reason: user-requested)
May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): failed
to look up interface index
May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): device
state change: prepare -> config (reason 'none') [40 50 0]
May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): device
state change: config -> ip-config (reason 'none') [50 70 0]
May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3):
interface ttyUSB3 not up for IP configuration
May 26 14:18:19 MYHOST NetworkManager[4597]:   (ttyUSB3): using
modem-specified IP timeout: 20 seconds
May 26 14:18:19 MYHOST NetworkManager[4597]:   starting PPP connection
May 26 14:18:19 MYHOST NetworkManager[4597]:   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]:   (ppp0): new
Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 97)
May 26 14:18:19 MYHOST NetworkManager[4597]: Using 

Re: pppd DNS update issue in NM 1.0.12

[Thomas Haller]

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

signature.asc
Description: This is a digitally signed message part
___
networkmanager-list mailing list
networkmanager-list@gnome.org
https://mail.gnome.org/mailman/listinfo/networkmanager-list