Re: Differences between GSM modems

From: Dan Williams <dcbw redhat com>
To: Colin Helliwell <colin helliwell ln-systems com>, networkmanager-list gnome org
Subject: Re: Differences between GSM modems
Date: Sat, 25 Mar 2017 01:31:48 -0500

On Fri, 2017-03-24 at 13:53 +0000, Colin Helliwell wrote:

On 23 March 2017 at 19:43 Dan Williams <dcbw redhat com> wrote:

On Thu, 2017-03-23 at 18:26 +0000, colin helliwell ln-systems com
wrote:

NetworkManager[1398]:  [1490292215.0368] (ttyMux1): modem
state
changed, 'connected' --> 'registered' (reason: user-requested)
NetworkManager[1398]:  [1490292215.0371] device (ttyMux1):
state
change: activated -> failed (reason 'modem-no-carrier') [100 120
25]
NetworkManager[1398]:  [1490292215.0390]
active-connection[0x1f38140]: set state deactivated (was
activated)
NetworkManager[1398]:  [1490292215.0395]


We'll need ModemManager logs here; MM is saying the modem state
changed, possibly due to status changes on the secondary AT port.
NM
hears that and terminates the connection.


Log including MM below.

But I think I've spotted the cause - the AT+CGACT? is getting a
'deactivated' response (@ 09:28:54). Hence MM seeing it as being
disconnected.

As Aleksander commented before (https://lists.freedesktop.org/archive
s/modemmanager-devel/2017-March/004042.html), it doesn't make sense
to have different PDP's across multiple TTYs. And indeed their EHS5
appears to behave sensibly i.e. indicates the port 1 PDP as active
even if queried over [Primary] port 2.

However, on trawling through the BGS2 docs, I've found that that "PDP
contexts can be defined on any [mux] channel, but are visible and
usable only on the channel on which they are defined". 
And doing some manual tests seems to confirm that - they can indeed
be set up independantly on different ports. Nice 'feature'....  :S
(I'm wondering if that's also behind some of the other weird sh^t
I've been grappling with).


That is... interesting.  And unlike anything I've ever encountered
before :)  If there's a way to detect that it's a BGS2, then we'll need
to special-case that device and stop ModemManager from polling
bearer/connection status.  We might also need to somehow suppress the
MM disconnect behavior of sending CGACT=x,0 on the secondary port while
trying to ensure that PPP terminates and the data port returns to
command mode.

Dan



Mar 24 09:28:46 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.6780] agent-manager: req[0x1733b58, :1.15/nmcli-
connect/0]: requesting permissions
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.6780]
agent-manager: req[0x1733b58, :1.15/nmcli-connect/0]: requesting
permissions
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.6852]
agent-manager: req[0x1733b58, :1.15/nmcli-connect/0]: agent
registered
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.6941]
policy: re-enabling autoconnect for all connections with failed
secrets
Mar 24 09:28:46 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.6852] agent-manager: req[0x1733b58, :1.15/nmcli-
connect/0]: agent registered
Mar 24 09:28:46 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.6941] policy: re-enabling autoconnect for all
connections with failed secrets
Mar 24 09:28:46 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7106] active-connection[0x1713140]: set device
"ttyMux1" [0x1730368]
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7106]
active-connection[0x1713140]: set device "ttyMux1" [0x1730368]
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7202]
device[0x1730368] (ttyMux1): add_pending_action (1):
'activation::0x1713140'
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7206]
active-connection[0x1713140]: constructed (NMActRequest, version-id
2)
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7242]
device[0x1730368] (ttyMux1): add_pending_action (2): 'autoactivate'
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7248]
device[0x1730368] (ttyMux1): remove_pending_action (1):
'autoactivate'
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7252]
device[0x1730368] (ttyMux1): unmanaged: flags set to
[!sleeping,!loopback,!platform-init,!user-explicit,!user-
settings=0x0/0x79/managed, set-managed [user-explicit=0x20], reason
user-requested)
Mar 24 09:28:46 w2 NetworkManager[23563]: <info>  [1490347726.7456]
device (ttyMux1): Activation: starting connection 'Vodafone'
(e0f97177-2f8e-4ed4-9942-7b4e499397cc)
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7459]
device[0x1730368] (ttyMux1): activation-stage: schedule
activate_stage1_device_prepare,2 (id 179)
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7527]
create NMAuditManager singleton (0x16e63b0)
Mar 24 09:28:46 w2 NetworkManager[23563]: <info>  [1490347726.7530]
audit: op="connection-activate" uuid="e0f97177-2f8e-4ed4-9942-
7b4e499397cc" name="Vodafone" pid=23664 uid=0 result="success"
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7599]
device[0x1730368] (ttyMux1): activation-stage: invoke
activate_stage1_device_prepare,2 (id 179)
Mar 24 09:28:46 w2 NetworkManager[23563]: <info>  [1490347726.7605]
device (ttyMux1): state change: disconnected -> prepare (reason
'none') [30 40 0]
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7738]
active-connection[0x1713140]: set state activating (was unknown)
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7743]
active-connection[0x1713140]: check-master-ready: not signalling
(state activating, no master)
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7752]
modem-broadband[ttyMux1]: launching connection with ip type 'ipv4'
(try 1)
Mar 24 09:28:46 w2 ModemManager[1184]: <info>  [1490347726.783853]
[src/mm-iface-modem-simple.c:641] connect_auth_ready(): Simple
connect started...
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.784016]
[src/mm-iface-modem-simple.c:651] connect_auth_ready():    PIN:
unspecified
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.784119]
[src/mm-iface-modem-simple.c:653] connect_auth_ready():    Operator
ID: unspecified
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.784211]
[src/mm-iface-modem-simple.c:655] connect_auth_ready():    Allowed
roaming: yes
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.784303]
[src/mm-iface-modem-simple.c:657] connect_auth_ready():    APN:
wap.vodafone.co.uk
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.784396]
[src/mm-iface-modem-simple.c:662] connect_auth_ready():    IP family:
ipv4
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.784489]
[src/mm-iface-modem-simple.c:673] connect_auth_ready():    Allowed
authentication: unspecified
Mar 24 09:28:46 w2 NetworkManager[23563]: <debug> [1490347726.7847]
device[0x1730368] (ttyMux1): activation-stage: complete
activate_stage1_device_prepare,2 (id 179)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.786815]
[src/mm-iface-modem-simple.c:675] connect_auth_ready():    User:
unspecified
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.818138]
[src/mm-iface-modem-simple.c:677] connect_auth_ready():    Password:
unspecified
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.824426]
[src/mm-iface-modem-simple.c:679] connect_auth_ready():    Number:
unspecified
Mar 24 09:28:46 w2 ModemManager[1184]: <info>  [1490347726.832195]
[src/mm-iface-modem-simple.c:469] connection_step(): Simple connect
state (4/8): Wait to get fully enabled
Mar 24 09:28:46 w2 ModemManager[1184]: <info>  [1490347726.850635]
[src/mm-iface-modem-simple.c:478] connection_step(): Simple connect
state (5/8): Register
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.860832]
[src/mm-iface-modem-3gpp.c:437]
mm_iface_modem_3gpp_register_in_network(): Already registered in
network '23415', automatic registration not launched...
Mar 24 09:28:46 w2 ModemManager[1184]: <info>  [1490347726.874214]
[src/mm-iface-modem-simple.c:501] connection_step(): Simple connect
state (6/8): Bearer
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.879872]
[src/mm-iface-modem-simple.c:521] connection_step(): Creating new
bearer...
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.884392]
[src/mm-iface-modem-simple.c:545] connection_step(): Deleted
disconnected bearer at '/org/freedesktop/ModemManager1/Bearer/0'
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.890549]
[src/mm-base-bearer.c:1107] base_bearer_dbus_unexport(): Removing
from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/0'
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.894070]
[plugins/cinterion/mm-broadband-modem-cinterion.c:1671]
common_create_bearer(): ^SWWAN not supported, creating default
bearer...
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.898647]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux1) device
open count is 2 (open)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.902174]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device open
count is 1 (close)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.905768]
[plugins/cinterion/mm-broadband-modem-cinterion.c:1630]
cinterion_modem_create_bearer_finish(): New bearer created at DBus
path '/org/freedesktop/ModemManager1/Bearer/1'
Mar 24 09:28:46 w2 ModemManager[1184]: <info>  [1490347726.913254]
[src/mm-iface-modem-simple.c:583] connection_step(): Simple connect
state (7/8): Connect
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.916657]
[src/mm-base-bearer.c:801] mm_base_bearer_connect(): Connecting
bearer '/org/freedesktop/ModemManager1/Bearer/1'
Mar 24 09:28:46 w2 ModemManager[1184]: <info>  [1490347726.919897]
[src/mm-iface-modem.c:1433] __iface_modem_update_state_internal():
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(registered -> connecting)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.930455]
[src/mm-broadband-bearer.c:1342] connect(): Launching 3GPP connection
attempt with APN 'wap.vodafone.co.uk'
Mar 24 09:28:46 w2 NetworkManager[23563]: <info>  [1490347726.9311]
(ttyMux1): modem state changed, 'registered' --> 'connecting'
(reason: user-requested)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.934899]
[src/mm-broadband-bearer.c:951] cid_selection_3gpp(): Looking for
best CID...
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.941617]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux1) device
open count is 2 (open)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.945015]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CGDCONT?<CR>'
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.980618]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CGDCONT:
1,"IP","wap.vodafone.co.uk","",0,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.981396]
[src/mm-broadband-bearer.c:867] parse_pdp_list(): Found '1' PDP
contexts
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.981531]
[src/mm-broadband-bearer.c:876] parse_pdp_list():   PDP context
[cid=1] [type='ipv4'] [apn='wap.vodafone.co.uk']
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.981644]
[src/mm-broadband-bearer.c:901] parse_pdp_list(): Found PDP context
with CID 1 and PDP type ipv4 for APN 'wap.vodafone.co.uk'
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.981810]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux0) device
open count is 2 (open)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.981923]
[src/mm-broadband-bearer.c:222] common_get_at_data_port(): Connection
through a plain serial AT port (ttyMux0)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.982110]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux0) device
open count is 3 (open)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.982383]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device open
count is 1 (close)
Mar 24 09:28:46 w2 ModemManager[1184]: <debug> [1490347726.982645]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): -->
'ATD*99***1#<CR>'
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7202] device[0x1730368] (ttyMux1):
add_pending_action (1): 'activation::0x1713140'
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7206] active-connection[0x1713140]: constructed
(NMActRequest, version-id 2)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7242] device[0x1730368] (ttyMux1):
add_pending_action (2): 'autoactivate'
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7248] device[0x1730368] (ttyMux1):
remove_pending_action (1): 'autoactivate'
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7252] device[0x1730368] (ttyMux1): unmanaged:
flags set to [!sleeping,!loopback,!platform-init,!user-
explicit,!user-settings=0x0/0x79/managed, set-managed [user-
explicit=0x20], reason user-requested)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347726.7456] device (ttyMux1): Activation: starting
connection 'Vodafone' (e0f97177-2f8e-4ed4-9942-7b4e499397cc)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7459] device[0x1730368] (ttyMux1): activation-
stage: schedule activate_stage1_device_prepare,2 (id 179)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7527] create NMAuditManager singleton (0x16e63b0)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347726.7530] audit: op="connection-activate"
uuid="e0f97177-2f8e-4ed4-9942-7b4e499397cc" name="Vodafone" pid=23664
uid=0 result="success"
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7599] device[0x1730368] (ttyMux1): activation-
stage: invoke activate_stage1_device_prepare,2 (id 179)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347726.7605] device (ttyMux1): state change:
disconnected -> prepare (reason 'none') [30 40 0]
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7738] active-connection[0x1713140]: set state
activating (was unknown)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7743] active-connection[0x1713140]: check-master-
ready: not signalling (state activating, no master)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7752] modem-broadband[ttyMux1]: launching
connection with ip type 'ipv4' (try 1)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.022391]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CGREG: 2<CR><LF>'
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347726.7847] device[0x1730368] (ttyMux1): activation-
stage: complete activate_stage1_device_prepare,2 (id 179)
Mar 24 09:28:47 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347726.9311] (ttyMux1): modem state changed,
'registered' --> 'connecting' (reason: user-requested)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.261526]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux1) device
open count is 2 (open)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.261847]
[src/mm-broadband-modem.c:2077] modem_load_signal_quality(): loading
signal quality...
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.262042]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux1) device
open count is 3 (open)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.262319]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT^SMONG<CR>'
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.305847]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>GPRS Monitor<CR><LF><CR><LF>BCCH  G  PBCCH  PAT
MCC  MNC  NOM  TA      RAC                              # Cell
#<CR><LF>   2  1  -      -   234   15  -    -       -                
                             <CR><LF><CR><LF><CR><LF><CR><LF>OK<CR><L
F>'
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.306754]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device open
count is 2 (close)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.307072]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CIND?<CR>'
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.334240]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CIND: 5,99,1,0,0,0,0,0,3<CR><LF><CR><LF>OK<CR><LF>'
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.334982]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux1) device
open count is 3 (open)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.335247]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device open
count is 2 (close)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.335515]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CSQ<CR>'
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.359343]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CSQ: 16,99<CR><LF><CR><LF>OK<CR><LF>'
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.359954]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device open
count is 1 (close)
Mar 24 09:28:47 w2 ModemManager[1184]: <debug> [1490347727.360692]
[src/mm-iface-modem.c:1206] update_signal_quality(): Modem
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (51)
Mar 24 09:28:48 w2 ModemManager[1184]: <debug> [1490347728.381868]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CGREG: 1<CR><LF>'
Mar 24 09:28:48 w2 ModemManager[1184]: <debug> [1490347728.883635]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <--
'<CR><LF>CONNECT<CR><LF>~\255}#\192!}!}#} }9}"}&} }*} }
}'}"}(}"}%}&\207}.} \132}#}%\194#}%aL~'
Mar 24 09:28:48 w2 ModemManager[1184]: <debug> [1490347728.884052]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux0) device open
count is 2 (close)
Mar 24 09:28:48 w2 ModemManager[1184]: <debug> [1490347728.884432]
[src/mm-port.c:94] mm_port_set_connected(): (ttyMux0): port now
connected
Mar 24 09:28:48 w2 ModemManager[1184]: <debug> [1490347728.884674]
[src/mm-base-bearer.c:699] connect_ready(): Connected bearer
'/org/freedesktop/ModemManager1/Bearer/1'
Mar 24 09:28:48 w2 ModemManager[1184]: <info>  [1490347728.885886]
[src/mm-iface-modem.c:1433] __iface_modem_update_state_internal():
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(connecting -> connected)
Mar 24 09:28:48 w2 NetworkManager[23563]: <info>  [1490347728.8963]
(ttyMux1): modem state changed, 'connecting' --> 'connected' (reason:
user-requested)
Mar 24 09:28:48 w2 ModemManager[1184]: <info>  [1490347728.897254]
[src/mm-iface-modem-simple.c:602] connection_step(): Simple connect
state (8/8): All done
Mar 24 09:28:48 w2 NetworkManager[23563]: <warn>  [1490347728.9316]
device (ttyMux1): failed to look up interface index
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9322]
platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ttyMux0/disable_ipv6': (2) No such file or
directory
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9324]
device[0x1730368] (ttyMux1): activation-stage: schedule
activate_stage2_device_config,2 (id 210)
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9340]
device[0x1730368] (ttyMux1): activation-stage: invoke
activate_stage2_device_config,2 (id 210)
Mar 24 09:28:48 w2 NetworkManager[23563]: <info>  [1490347728.9341]
device (ttyMux1): state change: prepare -> config (reason 'none') [40
50 0]
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9358]
device[0x1730368] (ttyMux1): bringing up device
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9360]
device[0x1730368] (ttyMux1): Activation: setting firewall zone
'default'
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9362]
firewall: [0x1734380,change*:"ttyMux0"]: firewall zone change
ttyMux0:default (not running, simulate success)
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9363]
device[0x1730368] (ttyMux1): activation-stage: complete
activate_stage2_device_config,2 (id 210)
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9808]
firewall: [0x1734380,change*:"ttyMux0"]: complete: fake success
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9811]
device[0x1730368] (ttyMux1): activation-stage: schedule
activate_stage3_ip_config_start,2 (id 216)
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9814]
device[0x1730368] (ttyMux1): activation-stage: invoke
activate_stage3_ip_config_start,2 (id 216)
Mar 24 09:28:48 w2 NetworkManager[23563]: <info>  [1490347728.9815]
device (ttyMux1): state change: config -> ip-config (reason 'none')
[50 70 0]
Mar 24 09:28:48 w2 NetworkManager[23563]: <warn>  [1490347728.9940]
device (ttyMux1): interface ttyMux0 not up for IP configuration
Mar 24 09:28:48 w2 NetworkManager[23563]: <debug> [1490347728.9942]
ip4_config_start
Mar 24 09:28:48 w2 NetworkManager[23563]: <info>  [1490347728.9948]
(ttyMux1): using modem-specified IP timeout: 20 seconds
Mar 24 09:28:49 w2 NetworkManager[23563]: <info>  [1490347729.0059]
ppp-manager: starting PPP connection
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.0092]
ppp-manager: command line: /usr/sbin/pppd nodetach lock
nodefaultroute debug ttyMux0 noipdefault noauth usepeerdns lcp-echo-
failure 0 lcp-echo-interval 0 idle 0 ipparam
/org/freedesktop/NetworkManager/PPP plugin /usr/lib/pppd/2.4.5/nm-
pppd-plugin.so
Mar 24 09:28:49 w2 NetworkManager[23563]: <info>  [1490347729.0194]
ppp-manager: pppd started with pid 23672
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.0199]
device[0x1730368] (ttyMux1): activation-stage: complete
activate_stage3_ip_config_start,2 (id 216)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347728.8963] (ttyMux1): modem state changed,
'connecting' --> 'connected' (reason: user-requested)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<warn>  [1490347728.9316] device (ttyMux1): failed to look up
interface index
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9322] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ttyMux0/disable_ipv6': (2) No such file or
directory
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9324] device[0x1730368] (ttyMux1): activation-
stage: schedule activate_stage2_device_config,2 (id 210)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9340] device[0x1730368] (ttyMux1): activation-
stage: invoke activate_stage2_device_config,2 (id 210)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347728.9341] device (ttyMux1): state change: prepare ->
config (reason 'none') [40 50 0]
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9358] device[0x1730368] (ttyMux1): bringing up
device
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9360] device[0x1730368] (ttyMux1): Activation:
setting firewall zone 'default'
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9362] firewall: [0x1734380,change*:"ttyMux0"]:
firewall zone change ttyMux0:default (not running, simulate success)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9363] device[0x1730368] (ttyMux1): activation-
stage: complete activate_stage2_device_config,2 (id 210)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9808] firewall: [0x1734380,change*:"ttyMux0"]:
complete: fake success
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9811] device[0x1730368] (ttyMux1): activation-
stage: schedule activate_stage3_ip_config_start,2 (id 216)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9814] device[0x1730368] (ttyMux1): activation-
stage: invoke activate_stage3_ip_config_start,2 (id 216)
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347728.9815] device (ttyMux1): state change: config ->
ip-config (reason 'none') [50 70 0]
Mar 24 09:28:49 w2 NetworkManager[23563]: NetworkManager[23563]:
<warn>  [1490347728.9940] device (ttyMux1): interface ttyMux0 not up
for IP configuration
Mar 24 09:28:49 w2 pppd[23672]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-
plugin.so loaded.
Mar 24 09:28:49 w2 pppd[23672]: pppd 2.4.7 started by root, uid 0
Mar 24 09:28:49 w2 pppd[23672]: using channel 2
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2297]
ethtool: Request failed: Operation not supported
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2304]
ethtool: Request failed: Operation not supported
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2394]
platform: signal: link   added: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
not-init driver unknown rx:0,0 tx:0,0
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2402]
device[0x16f4578] (ppp0): unmanaged: flags set to [platform-init,by-
default=0x110/0x110/unmanaged/unrealized, set-unmanaged [by-
default=0x100])
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2405]
ethtool: Request failed: Operation not supported
Mar 24 09:28:49 w2 pppd[23672]: Using interface ppp0
Mar 24 09:28:49 w2 pppd[23672]: Connect: ppp0 <--> /dev/ttyMux0
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2427]
mii: SIOCGMIIPHY failed: Invalid argument (22) (ppp0)
Mar 24 09:28:49 w2 pppd[23672]: sent [LCP ConfReq id=0x1 <asyncmap
0x0> <magic 0x32ad9385> <pcomp> <accomp>]
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2501]
mii: MII not supported (ppp0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2734]
device[0x16f4578] (ppp0): constructed (NMDeviceGeneric)
Mar 24 09:28:49 w2 pppd[23672]: rcvd [LCP ConfNak id=0x1 <asyncmap
0xa0000>]
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.2995]
device[0x16f4578] (ppp0): start setup of NMDeviceGeneric, kernel
ifindex 4
Mar 24 09:28:49 w2 pppd[23672]: sent [LCP ConfReq id=0x2 <asyncmap
0xa0000> <magic 0x32ad9385> <pcomp> <accomp>]
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.3128]
platform-linux: error reading /sys/class/net/ppp0/phys_port_id:
Failed to read from file '/sys/class/net/ppp0/phys_port_id':
Operation not supported
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.3538]
platform-linux: sysctl: reading '/sys/class/net/ppp0/dev_id': '0x0'
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.3651]
ethtool: Request failed: Operation not supported
Mar 24 09:28:49 w2 pppd[23672]: rcvd [LCP ConfAck id=0x2 <asyncmap
0xa0000> <magic 0x32ad9385> <pcomp> <accomp>]
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.3746]
ethtool: Request failed: Operation not supported
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4073]
mii: SIOCGMIIPHY failed: Invalid argument (22) (ppp0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4131]
mii: MII not supported (ppp0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4249]
device[0x16f4578] (ppp0): hw-addr: failed reading current MAC address
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4394]
device[0x16f4578] (ppp0): hw-addr: failed reading current MAC address
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4462]
device[0x16f4578] (ppp0): unmanaged: flags set to [platform-init,by-
default,!loopback=0x110/0x118/unmanaged/unrealized, set-managed
[loopback=0x8])
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4586]
device[0x16f4578] (ppp0): unmanaged: flags set to [platform-init,by-
default,!loopback,!user-settings=0x110/0x158/unmanaged/unrealized,
set-managed [user-settings=0x40])
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.4654]
device[0x16f4578] (ppp0): unmanaged: flags set to [platform-init,by-
default,!sleeping,!loopback,!user-
settings=0x110/0x159/unmanaged/unrealized, set-managed
[sleeping=0x1])
Mar 24 09:28:49 w2 NetworkManager[23563]: <info>  [1490347729.5122]
manager: (ppp0): new Generic device
(/org/freedesktop/NetworkManager/Devices/3)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.5396]
device[0x16f4578] (ppp0): ip4-config: update (commit=0, routes-full-
sync=0, new-config=0x173e980)
Mar 24 09:28:49 w2 ModemManager[1184]: <debug> [1490347729.551973]
[src/mm-base-manager.c:263] device_added(): (net/ppp0): adding device
at sysfs path: /sys/devices/virtual/net/ppp0
Mar 24 09:28:49 w2 ModemManager[1184]: <debug> [1490347729.552508]
[src/kerneldevice/mm-kernel-device-udev.c:461]
kernel_device_is_candidate(): (net/ppp0): could not get port's parent
device
Mar 24 09:28:49 w2 ModemManager[1184]: <debug> [1490347729.552687]
[src/mm-base-manager.c:272] device_added(): (net/ppp0): port not
candidate
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.5687]
device[0x16f4578] (ppp0): ip4-config: set IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.5754]
dns-mgr: (device_ip4_config_changed): queueing DNS updates (1)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.5946]
dns-mgr: (device_ip4_config_changed): DNS configuration did not
change
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.6238]
dns-mgr: (device_ip4_config_changed): no DNS changes to commit (0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.6350]
device[0x16f4578] (ppp0): ip6-config: update (commit=0, routes-full-
sync=0, new-config=0x16b00e0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.6754]
device[0x16f4578] (ppp0): ip6-config: set IP6Config instance
(/org/freedesktop/NetworkManager/IP6Config/2)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.6840]
dns-mgr: (device_ip6_config_changed): queueing DNS updates (1)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.6899]
dns-mgr: (device_ip6_config_changed): DNS configuration did not
change
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.6956]
dns-mgr: (device_ip6_config_changed): no DNS changes to commit (0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.7073]
platform-linux: UDEV event: action 'add' subsys 'net' device 'ppp0'
(4); seqnum=28323
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.7298]
ethtool: Request failed: Operation not supported
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.7395]
platform: signal: link changed: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
init driver unknown rx:0,0 tx:0,0
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.7447]
device[0x16f4578] (ppp0): queued link change for ifindex 4
Mar 24 09:28:49 w2 NetworkManager[23563]: <info>  [1490347729.7508]
devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Mar 24 09:28:49 w2 NetworkManager[23563]: <info>  [1490347729.7559]
device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no
ifupdown configuration found.
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.7643]
device[0x16f4578] (ppp0): emit RECHECK_ASSUME signal
Mar 24 09:28:49 w2 ModemManager[1184]: <debug> [1490347729.788049]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CIEV: rssi,2<CR><LF>'
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.7961]
device[0x16f4578] (ppp0): hw-addr: failed reading current MAC address
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.8076]
device[0x16f4578] (ppp0): hw-addr: failed reading current MAC address
Mar 24 09:28:49 w2 NetworkManager[23563]: <debug> [1490347729.8133]
device[0x16f4578] (ppp0): unmanaged: flags set to [by-
default,!sleeping,!loopback,!platform-init,!user-
settings=0x100/0x159/manageable, set-managed [platform-init=0x10],
reason managed)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347728.9942] ip4_config_start
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347728.9948] (ttyMux1): using modem-specified IP
timeout: 20 seconds
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347729.0059] ppp-manager: starting PPP connection
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.0092] ppp-manager: command line: /usr/sbin/pppd
nodetach lock nodefaultroute debug ttyMux0 noipdefault noauth
usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 idle 0 ipparam
/org/freedesktop/NetworkManager/PPP plugin /usr/lib/pppd/2.4.5/nm-
pppd-plugin.so
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347729.0194] ppp-manager: pppd started with pid 23672
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.0199] device[0x1730368] (ttyMux1): activation-
stage: complete activate_stage3_ip_config_start,2 (id 216)
Mar 24 09:28:50 w2 NetworkManager[23563]: Plugin
/usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Mar 24 09:28:50 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (plugin_init): initializing
Mar 24 09:28:50 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Mar 24 09:28:50 w2 NetworkManager[23563]: using channel 2
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2297] ethtool: Request failed: Operation not
supported
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2304] ethtool: Request failed: Operation not
supported
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2394] platform: signal: link   added: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
not-init driver unknown rx:0,0 tx:0,0
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2402] device[0x16f4578] (ppp0): unmanaged: flags
set to [platform-init,by-default=0x110/0x110/unmanaged/unrealized,
set-unmanaged [by-default=0x100])
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2405] ethtool: Request failed: Operation not
supported
Mar 24 09:28:50 w2 NetworkManager[23563]: Using interface ppp0
Mar 24 09:28:50 w2 NetworkManager[23563]: Connect: ppp0 <-->
/dev/ttyMux0
Mar 24 09:28:50 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2427] mii: SIOCGMIIPHY failed: Invalid argument
(22) (ppp0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2501] mii: MII not supported (ppp0)
Mar 24 09:28:50 w2 NetworkManager[23563]: sent [LCP ConfReq id=0x1
<asyncmap 0x0> <magic 0x32ad9385> <pcomp> <accomp>]
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2734] device[0x16f4578] (ppp0): constructed
(NMDeviceGeneric)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.2995] device[0x16f4578] (ppp0): start setup of
NMDeviceGeneric, kernel ifindex 4
Mar 24 09:28:50 w2 NetworkManager[23563]: rcvd [LCP ConfNak id=0x1
<asyncmap 0xa0000>]
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.3128] platform-linux: error reading
/sys/class/net/ppp0/phys_port_id: Failed to read from file
'/sys/class/net/ppp0/phys_port_id': Operation not supported
Mar 24 09:28:50 w2 NetworkManager[23563]: sent [LCP ConfReq id=0x2
<asyncmap 0xa0000> <magic 0x32ad9385> <pcomp> <accomp>]
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.3538] platform-linux: sysctl: reading
'/sys/class/net/ppp0/dev_id': '0x0'
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.3651] ethtool: Request failed: Operation not
supported
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.3746] ethtool: Request failed: Operation not
supported
Mar 24 09:28:50 w2 NetworkManager[23563]: rcvd [LCP ConfAck id=0x2
<asyncmap 0xa0000> <magic 0x32ad9385> <pcomp> <accomp>]
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4073] mii: SIOCGMIIPHY failed: Invalid argument
(22) (ppp0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4131] mii: MII not supported (ppp0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4249] device[0x16f4578] (ppp0): hw-addr: failed
reading current MAC address
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4394] device[0x16f4578] (ppp0): hw-addr: failed
reading current MAC address
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4462] device[0x16f4578] (ppp0): unmanaged: flags
set to [platform-init,by-
default,!loopback=0x110/0x118/unmanaged/unrealized, set-managed
[loopback=0x8])
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4586] device[0x16f4578] (ppp0): unmanaged: flags
set to [platform-init,by-default,!loopback,!user-
settings=0x110/0x158/unmanaged/unrealized, set-managed [user-
settings=0x40])
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.4654] device[0x16f4578] (ppp0): unmanaged: flags
set to [platform-init,by-default,!sleeping,!loopback,!user-
settings=0x110/0x159/unmanaged/unrealized, set-managed
[sleeping=0x1])
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347729.5122] manager: (ppp0): new Generic device
(/org/freedesktop/NetworkManager/Devices/3)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.5396] device[0x16f4578] (ppp0): ip4-config:
update (commit=0, routes-full-sync=0, new-config=0x173e980)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.5687] device[0x16f4578] (ppp0): ip4-config: set
IP4Config instance (/org/freedesktop/NetworkManager/IP4Config/2)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.5754] dns-mgr: (device_ip4_config_changed):
queueing DNS updates (1)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.5946] dns-mgr: (device_ip4_config_changed): DNS
configuration did not change
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.6238] dns-mgr: (device_ip4_config_changed): no
DNS changes to commit (0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.6350] device[0x16f4578] (ppp0): ip6-config:
update (commit=0, routes-full-sync=0, new-config=0x16b00e0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.6754] device[0x16f4578] (ppp0): ip6-config: set
IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/2)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.6840] dns-mgr: (device_ip6_config_changed):
queueing DNS updates (1)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.6899] dns-mgr: (device_ip6_config_changed): DNS
configuration did not change
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.6956] dns-mgr: (device_ip6_config_changed): no
DNS changes to commit (0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.7073] platform-linux: UDEV event: action 'add'
subsys 'net' device 'ppp0' (4); seqnum=28323
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.7298] ethtool: Request failed: Operation not
supported
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.7395] platform: signal: link changed: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
init driver unknown rx:0,0 tx:0,0
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.7447] device[0x16f4578] (ppp0): queued link
change for ifindex 4
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347729.7508] devices added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0)
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347729.7559] device added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown
configuration found.
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.7643] device[0x16f4578] (ppp0): emit
RECHECK_ASSUME signal
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.7961] device[0x16f4578] (ppp0): hw-addr: failed
reading current MAC address
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.8076] device[0x16f4578] (ppp0): hw-addr: failed
reading current MAC address
Mar 24 09:28:50 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347729.8133] device[0x16f4578] (ppp0): unmanaged: flags
set to [by-default,!sleeping,!loopback,!platform-init,!user-
settings=0x100/0x159/manageable, set-managed [platform-init=0x10],
reason managed)
Mar 24 09:28:51 w2 pppd[23672]: rcvd [LCP ConfReq id=0x3 <asyncmap
0xa0000> <pcomp> <accomp> <magic 0xcf0e0084> <auth chap MD5>]
Mar 24 09:28:51 w2 pppd[23672]: sent [LCP ConfAck id=0x3 <asyncmap
0xa0000> <pcomp> <accomp> <magic 0xcf0e0084> <auth chap MD5>]
Mar 24 09:28:51 w2 NetworkManager[23563]: rcvd [LCP ConfReq id=0x3
<asyncmap 0xa0000> <pcomp> <accomp> <magic 0xcf0e0084> <auth chap
MD5>]
Mar 24 09:28:51 w2 NetworkManager[23563]: sent [LCP ConfAck id=0x3
<asyncmap 0xa0000> <pcomp> <accomp> <magic 0xcf0e0084> <auth chap
MD5>]
Mar 24 09:28:51 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
Mar 24 09:28:51 w2 pppd[23672]: rcvd [CHAP Challenge id=0x1
<c40f9ea96710dd05c148d298d2b77f639a5ce364>, name = ""]
Mar 24 09:28:51 w2 NetworkManager[23563]: rcvd [CHAP Challenge id=0x1
<c40f9ea96710dd05c148d298d2b77f639a5ce364>, name = ""]
Mar 24 09:28:51 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (get_credentials): passwd-hook, requesting credentials...
Mar 24 09:28:51 w2 pppd[23672]: sent [CHAP Response id=0x1
<1415d92201f6e26fb30c4767cf670cc1>, name = ""]
Mar 24 09:28:51 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (get_credentials): got credentials from NetworkManager
Mar 24 09:28:51 w2 NetworkManager[23563]: sent [CHAP Response id=0x1
<1415d92201f6e26fb30c4767cf670cc1>, name = ""]
Mar 24 09:28:51 w2 pppd[23672]: rcvd [CHAP Success id=0x1 ""]
Mar 24 09:28:51 w2 pppd[23672]: CHAP authentication succeeded
Mar 24 09:28:51 w2 pppd[23672]: CHAP authentication succeeded
Mar 24 09:28:51 w2 pppd[23672]: kernel does not support PPP filtering
Mar 24 09:28:51 w2 pppd[23672]: sent [CCP ConfReq id=0x1 <deflate 15>
<deflate(old#) 15> <bsd v1 15>]
Mar 24 09:28:51 w2 pppd[23672]: sent [IPCP ConfReq id=0x1 <compress
VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar 24 09:28:51 w2 pppd[23672]: rcvd [LCP ProtRej id=0x4 80 fd 01 01
00 0f 1a 04]
Mar 24 09:28:51 w2 pppd[23672]: Protocol-Reject for 'Compression
Control Protocol' (0x80fd) received
Mar 24 09:28:51 w2 NetworkManager[23563]: rcvd [CHAP Success id=0x1
""]
Mar 24 09:28:51 w2 NetworkManager[23563]: CHAP authentication
succeeded
Mar 24 09:28:51 w2 NetworkManager[23563]: CHAP authentication
succeeded
Mar 24 09:28:51 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Mar 24 09:28:51 w2 NetworkManager[23563]: kernel does not support PPP
filtering
Mar 24 09:28:51 w2 NetworkManager[23563]: sent [CCP ConfReq id=0x1
<deflate 15> <deflate(old#) 15> <bsd v1 15>]
Mar 24 09:28:51 w2 NetworkManager[23563]: sent [IPCP ConfReq id=0x1
<compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2
0.0.0.0>]
Mar 24 09:28:51 w2 NetworkManager[23563]: rcvd [LCP ProtRej id=0x4 80
fd 01 01 00 0f 1a 04]
Mar 24 09:28:51 w2 NetworkManager[23563]: Protocol-Reject for
'Compression Control Protocol' (0x80fd) received
Mar 24 09:28:52 w2 pppd[23672]: rcvd [IPCP ConfReq id=0x1 <addr
192.168.254.254>]
Mar 24 09:28:52 w2 pppd[23672]: sent [IPCP ConfAck id=0x1 <addr
192.168.254.254>]
Mar 24 09:28:52 w2 pppd[23672]: rcvd [IPCP ConfRej id=0x1 <compress
VJ 0f 01>]
Mar 24 09:28:52 w2 pppd[23672]: sent [IPCP ConfReq id=0x2 <addr
0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar 24 09:28:52 w2 NetworkManager[23563]: rcvd [IPCP ConfReq id=0x1
<addr 192.168.254.254>]
Mar 24 09:28:52 w2 NetworkManager[23563]: sent [IPCP ConfAck id=0x1
<addr 192.168.254.254>]
Mar 24 09:28:52 w2 NetworkManager[23563]: rcvd [IPCP ConfRej id=0x1
<compress VJ 0f 01>]
Mar 24 09:28:52 w2 NetworkManager[23563]: sent [IPCP ConfReq id=0x2
<addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar 24 09:28:52 w2 pppd[23672]: rcvd [IPCP ConfNak id=0x2 <addr
10.10.13.164> <ms-dns1 10.206.128.1> <ms-dns2 10.206.128.1>]
Mar 24 09:28:52 w2 pppd[23672]: sent [IPCP ConfReq id=0x3 <addr
10.10.13.164> <ms-dns1 10.206.128.1> <ms-dns2 10.206.128.1>]
Mar 24 09:28:52 w2 NetworkManager[23563]: rcvd [IPCP ConfNak id=0x2
<addr 10.10.13.164> <ms-dns1 10.206.128.1> <ms-dns2 10.206.128.1>]
Mar 24 09:28:52 w2 NetworkManager[23563]: sent [IPCP ConfReq id=0x3
<addr 10.10.13.164> <ms-dns1 10.206.128.1> <ms-dns2 10.206.128.1>]
Mar 24 09:28:52 w2 pppd[23672]: rcvd [IPCP ConfAck id=0x3 <addr
10.10.13.164> <ms-dns1 10.206.128.1> <ms-dns2 10.206.128.1>]
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1206]
platform: signal: address 4   added: 10.10.13.164/32 lft forever pref
forever lifetime 86-0[4294967295,4294967295] dev 4 flags permanent
src kernel
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1209]
default-route: resync: schedule on idle
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1211]
device[0x16f4578] (ppp0): queued IP4 config change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1219]
device[0x16f4578] (ppp0): ip4-config: update (commit=0, routes-full-
sync=0, new-config=0x173ea90)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1231]
device[0x16f4578] (ppp0): ip4-config: update IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1236]
dns-mgr: (device_ip4_config_changed): queueing DNS updates (1)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1238]
dns-mgr: (device_ip4_config_changed): DNS configuration did not
change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1239]
dns-mgr: (device_ip4_config_changed): no DNS changes to commit (0)
Mar 24 09:28:52 w2 pppd[23672]: local  IP address 10.10.13.164
Mar 24 09:28:52 w2 pppd[23672]: remote IP address 192.168.254.254
Mar 24 09:28:52 w2 pppd[23672]: primary   DNS address 10.206.128.1
Mar 24 09:28:52 w2 pppd[23672]: secondary DNS address 10.206.128.1
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1580]
platform: signal: address 4 removed: 10.10.13.164/32 lft forever pref
forever lifetime 86-0[4294967295,4294967295] dev 4 flags permanent
src kernel
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1704]
device[0x16f4578] (ppp0): queued IP4 config change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1799]
platform: signal: address 4   added: 10.10.13.164/32 lft forever pref
forever lifetime 86-0[4294967295,4294967295] ptp 192.168.254.254 dev
4 flags permanent src kernel
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1859]
ethtool: Request failed: Operation not supported
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1923]
ethtool: Request failed: Operation not supported
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.1982]
platform: signal: link changed: 4: ppp0
<NOARP,UP,LOWER_UP;pointopoint,multicast,noarp,up,running,lowerup>
mtu 1500 arp 512 unknown? init driver unknown rx:4,64 tx:5,97
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2039]
device[0x16f4578] (ppp0): queued link change for ifindex 4
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2098]
platform: signal: route   4   added: 192.168.254.254/32 via 0.0.0.0
dev 4 metric 0 mss 0 src rt-kernel scope link pref-src 10.10.13.164
Mar 24 09:28:52 w2 NetworkManager[23563]: <info>  [1490347732.2181]
ppp-manager: (IPv4 Config Get) reply received.
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2328]
manager: (ppp0): removing device (allow_unmanage 0, managed 0)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2395]
device[0x16f4578] (ppp0): ip4-config: update (commit=0, routes-full-
sync=0, new-config=(nil))
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2453]
device[0x16f4578] (ppp0): ip4-config: clear IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2514]
dns-mgr: (device_ip4_config_changed): queueing DNS updates (1)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2574]
dns-mgr: (device_ip4_config_changed): DNS configuration did not
change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2633]
dns-mgr: (device_ip4_config_changed): no DNS changes to commit (0)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2704]
device[0x16f4578] (ppp0): ip6-config: update (commit=0, routes-full-
sync=0, new-config=(nil))
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2771]
device[0x16f4578] (ppp0): ip6-config: clear IP6Config instance
(/org/freedesktop/NetworkManager/IP6Config/2)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2832]
dns-mgr: (device_ip6_config_changed): queueing DNS updates (1)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2892]
dns-mgr: (device_ip6_config_changed): DNS configuration did not
change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.2953]
dns-mgr: (device_ip6_config_changed): no DNS changes to commit (0)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3047]
device[0x16f4578] (ppp0): disposing
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3244]
device[0x16f4578] (ppp0): clearing queued IP4 config change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3357]
device[0x16f4578] (ppp0): remove_pending_action (0): 'dhcp6' not
pending (expected)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3413]
device[0x16f4578] (ppp0): remove_pending_action (0): 'autoconf6' not
pending (expected)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3471]
device[0x16f4578] (ppp0): ip4-config: update (commit=1, routes-full-
sync=1, new-config=(nil))
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3540]
device[0x16f4578] (ppp0): ip6-config: update (commit=1, routes-full-
sync=1, new-config=(nil))
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3634]
device[0x16f4578] (ppp0): finalize(): NMDeviceGeneric
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3695]
platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file or
directory
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3785]
device[0x1730368] (ttyMux1): ip4-config: update (commit=1, routes-
full-sync=1, new-config=0x173eba0)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3844]
platform: address: adding or updating IPv4 address: 10.10.13.164/32
lft forever pref forever lifetime 87-0[4294967295,4294967295] ptp
192.168.254.254 dev 4 src unknown
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3903]
platform-linux: do-add-ip4-address[4:
10.10.13.164/32,192.168.254.254]: success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.3983]
route-mgr4:   4: sync 1 IPv4 routes
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4183]
platform: route: deleting IPv4 route 192.168.254.254/32, metric=0,
ifindex 4 dev ppp0
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4243]
platform: signal: route   4 removed: 192.168.254.254/32 via 0.0.0.0
dev 4 metric 0 mss 0 src rt-kernel scope link pref-src 10.10.13.164
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4380]
device[0x1730368] (ttyMux1): queued IP4 config change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4657]
platform-linux: do-delete-ip4-route[4: 192.168.254.254/32 0]: success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4723]
platform: route: adding or updating IPv4 route: 192.168.254.254/32
via 0.0.0.0 dev 4 metric 700 mss 0 src kernel pref-src 10.10.13.164
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4854]
platform: signal: route   4   added: 192.168.254.254/32 via 0.0.0.0
dev 4 metric 700 mss 0 src rt-kernel scope link pref-src 10.10.13.164
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.4951]
platform-linux: do-add-ip4-route[4: 192.168.254.254/32 700]: success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5342]
device[0x1730368] (ttyMux1): ip4-config: set IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/3)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5398]
default-route: entry[1/dev:0x1730368:ttyMux1:1:+sync]:
record:add    0.0.0.0/0 via 192.168.254.254 dev 4 metric 700 mss 0
src user (700)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5454]
default-route: resync: cancelled (258)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5514]
default-route: entry[1/dev:0x1730368:ttyMux1:1:+sync]:
sync:add    0.0.0.0/0 via 192.168.254.254 dev 4 metric 700 mss 0 src
user (700)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5567]
platform: route: adding or updating IPv4 route: 0.0.0.0/0 via
192.168.254.254 dev 4 metric 700 mss 0 src user
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5764]
platform: signal: route   4   added: 0.0.0.0/0 via 192.168.254.254
dev 4 metric 700 mss 0 src rt-static scope global
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5833]
platform-linux: do-add-ip4-route[4: 0.0.0.0/0 700]: success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5949]
dns-mgr: (device_ip4_config_changed): queueing DNS updates (1)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.5999]
dns-mgr: (device_ip4_config_changed): DNS configuration did not
change
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.6268]
dns-mgr: (device_ip4_config_changed): no DNS changes to commit (0)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.6333]
device[0x1730368] (ttyMux1): activation-stage: schedule
activate_stage5_ip4_config_commit,2 (id 267)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.6473]
device[0x1730368] (ttyMux1): activation-stage: invoke
activate_stage5_ip4_config_commit,2 (id 267)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.6560]
device[0x1730368] (ttyMux1): ip4-config: update (commit=1, routes-
full-sync=0, new-config=0x173ea08)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7106]
platform: address: adding or updating IPv4 address: 10.10.13.164/32
lft forever pref forever lifetime 87-0[4294967295,4294967295] ptp
192.168.254.254 dev 4 src unknown
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7225]
platform-linux: do-add-ip4-address[4:
10.10.13.164/32,192.168.254.254]: success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7281]
route-mgr4:   4: sync 1 IPv4 routes
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7340]
platform: route: adding or updating IPv4 route: 192.168.254.254/32
via 0.0.0.0 dev 4 metric 700 mss 0 src kernel pref-src 10.10.13.164
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7403]
platform-linux: do-add-ip4-route[4: 192.168.254.254/32 700]: success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7463]
device[0x1730368] (ttyMux1): remove_pending_action (1): 'dhcp4' not
pending (expected)
Mar 24 09:28:52 w2 NetworkManager[23563]: <info>  [1490347732.7523]
device (ttyMux1): state change: ip-config -> ip-check (reason 'none')
[70 80 0]
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7665]
firewall: [0x1745500,change*:"ppp0"]: firewall zone change
ppp0:default (not running, simulate success)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.7742]
device[0x1730368] (ttyMux1): activation-stage: complete
activate_stage5_ip4_config_commit,2 (id 267)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.8101]
device[0x1730368] (ttyMux1): ip4-config: update (commit=0, routes-
full-sync=0, new-config=0x173ea90)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.8161]
default-route: entry[1/dev:0x1730368:ttyMux1:1:-sync]: record:update
0.0.0.0/0 via 192.168.254.254 dev 4 metric 700 mss 0 src rt-static
scope global (700)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.8417]
firewall: [0x1745500,change*:"ppp0"]: complete: fake success
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.8526]
device[0x1730368] (ttyMux1): add_pending_action (2): 'queued state
change to secondaries'
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.8833]
device[0x1730368] (ttyMux1): queued state change to secondaries due
to none (id 275)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.8954]
device[0x1730368] (ttyMux1): running queued state change to
secondaries (id 275)
Mar 24 09:28:52 w2 NetworkManager[23563]: <info>  [1490347732.9071]
device (ttyMux1): state change: ip-check -> secondaries (reason
'none') [80 90 0]
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9221]
device[0x1730368] (ttyMux1): add_pending_action (3): 'queued state
change to activated'
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9281]
device[0x1730368] (ttyMux1): queued state change to activated due to
none (id 280)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9338]
device[0x1730368] (ttyMux1): device entered SECONDARIES state
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9392]
device[0x1730368] (ttyMux1): remove_pending_action (2): 'queued state
change to secondaries'
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9699]
device[0x1730368] (ttyMux1): running queued state change to activated
(id 280)
Mar 24 09:28:52 w2 NetworkManager[23563]: <info>  [1490347732.9705]
device (ttyMux1): state change: secondaries -> activated (reason
'none') [90 100 0]
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9828]
active-connection[0x1713140]: set state activated (was activating)
Mar 24 09:28:52 w2 NetworkManager[23563]: <debug> [1490347732.9905]
active-connection[0x1713140]: check-master-ready: not signalling
(state activated, no master)
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0110]
device[0x1730368] (ttyMux1): remove_pending_action (1):
'activation::0x1713140'
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0139]
dns-mgr: (device_state_changed): queueing DNS updates (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0141]
dns-mgr: (update_routing_and_dns): queueing DNS updates (2)
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0144]
dns-mgr: (update_routing_and_dns): DNS configuration changed
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0190]
dns-mgr: (update_routing_and_dns): no DNS changes to commit (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0194]
dns-mgr: (device_state_changed): DNS configuration changed
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0228]
dns-mgr: (device_state_changed): committing DNS changes (0)
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0258]
dns-mgr: update-dns: updating resolv.conf
Mar 24 09:28:53 w2 NetworkManager[23563]: <info>  [1490347733.0296]
device (ttyMux1): Activation: successful, device activated.
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0329]
device[0x1730368] (ttyMux1): set metered value 3
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.0367]
device[0x1730368] (ttyMux1): remove_pending_action (0): 'queued state
change to activated'
Mar 24 09:28:53 w2 NetworkManager[23563]: rcvd [IPCP ConfAck id=0x3
<addr 10.10.13.164> <ms-dns1 10.206.128.1> <ms-dns2 10.206.128.1>]
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1206] platform: signal: address 4   added:
10.10.13.164/32 lft forever pref forever lifetime 86-
0[4294967295,4294967295] dev 4 flags permanent src kernel
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1209] default-route: resync: schedule on idle
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1211] device[0x16f4578] (ppp0): queued IP4 config
change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1219] device[0x16f4578] (ppp0): ip4-config:
update (commit=0, routes-full-sync=0, new-config=0x173ea90)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1231] device[0x16f4578] (ppp0): ip4-config:
update IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1236] dns-mgr: (device_ip4_config_changed):
queueing DNS updates (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1238] dns-mgr: (device_ip4_config_changed): DNS
configuration did not change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1239] dns-mgr: (device_ip4_config_changed): no
DNS changes to commit (0)
Mar 24 09:28:53 w2 NetworkManager[23563]: <debug> [1490347733.2041]
agent-manager: req[0x1733b58, :1.15/nmcli-connect/0]: agent
unregistered or disappeared
Mar 24 09:28:53 w2 NetworkManager[23563]: local  IP address
10.10.13.164
Mar 24 09:28:53 w2 NetworkManager[23563]: remote IP address
192.168.254.254
Mar 24 09:28:53 w2 NetworkManager[23563]: primary   DNS address
10.206.128.1
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1580] platform: signal: address 4 removed:
10.10.13.164/32 lft forever pref forever lifetime 86-
0[4294967295,4294967295] dev 4 flags permanent src kernel
Mar 24 09:28:53 w2 NetworkManager[23563]: secondary DNS address
10.206.128.1
Mar 24 09:28:53 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 9 / phase 'running'
Mar 24 09:28:53 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_ip_up): ip-up event
Mar 24 09:28:53 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_ip_up): sending IPv4 config to NetworkManager...
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1704] device[0x16f4578] (ppp0): queued IP4 config
change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1799] platform: signal: address 4   added:
10.10.13.164/32 lft forever pref forever lifetime 86-
0[4294967295,4294967295] ptp 192.168.254.254 dev 4 flags permanent
src kernel
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1859] ethtool: Request failed: Operation not
supported
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1923] ethtool: Request failed: Operation not
supported
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.1982] platform: signal: link changed: 4: ppp0
<NOARP,UP,LOWER_UP;pointopoint,multicast,noarp,up,running,lowerup>
mtu 1500 arp 512 unknown? init driver unknown rx:4,64 tx:5,97
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2039] device[0x16f4578] (ppp0): queued link
change for ifindex 4
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2098] platform: signal: route   4   added:
192.168.254.254/32 via 0.0.0.0 dev 4 metric 0 mss 0 src rt-kernel
scope link pref-src 10.10.13.164
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347732.2181] ppp-manager: (IPv4 Config Get) reply
received.
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2328] manager: (ppp0): removing device
(allow_unmanage 0, managed 0)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2395] device[0x16f4578] (ppp0): ip4-config:
update (commit=0, routes-full-sync=0, new-config=(nil))
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2453] device[0x16f4578] (ppp0): ip4-config: clear
IP4Config instance (/org/freedesktop/NetworkManager/IP4Config/2)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2514] dns-mgr: (device_ip4_config_changed):
queueing DNS updates (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2574] dns-mgr: (device_ip4_config_changed): DNS
configuration did not change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2633] dns-mgr: (device_ip4_config_changed): no
DNS changes to commit (0)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2704] device[0x16f4578] (ppp0): ip6-config:
update (commit=0, routes-full-sync=0, new-config=(nil))
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2771] device[0x16f4578] (ppp0): ip6-config: clear
IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/2)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2832] dns-mgr: (device_ip6_config_changed):
queueing DNS updates (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2892] dns-mgr: (device_ip6_config_changed): DNS
configuration did not change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.2953] dns-mgr: (device_ip6_config_changed): no
DNS changes to commit (0)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3047] device[0x16f4578] (ppp0): disposing
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3244] device[0x16f4578] (ppp0): clearing queued
IP4 config change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3357] device[0x16f4578] (ppp0):
remove_pending_action (0): 'dhcp6' not pending (expected)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3413] device[0x16f4578] (ppp0):
remove_pending_action (0): 'autoconf6' not pending (expected)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3471] device[0x16f4578] (ppp0): ip4-config:
update (commit=1, routes-full-sync=1, new-config=(nil))
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3540] device[0x16f4578] (ppp0): ip6-config:
update (commit=1, routes-full-sync=1, new-config=(nil))
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3634] device[0x16f4578] (ppp0): finalize():
NMDeviceGeneric
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3695] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file or
directory
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3785] device[0x1730368] (ttyMux1): ip4-config:
update (commit=1, routes-full-sync=1, new-config=0x173eba0)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3844] platform: address: adding or updating IPv4
address: 10.10.13.164/32 lft forever pref forever lifetime 87-
0[4294967295,4294967295] ptp 192.168.254.254 dev 4 src unknown
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3903] platform-linux: do-add-ip4-address[4:
10.10.13.164/32,192.168.254.254]: success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.3983] route-mgr4:   4: sync 1 IPv4 routes
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4183] platform: route: deleting IPv4 route
192.168.254.254/32, metric=0, ifindex 4 dev ppp0
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4243] platform: signal: route   4 removed:
192.168.254.254/32 via 0.0.0.0 dev 4 metric 0 mss 0 src rt-kernel
scope link pref-src 10.10.13.164
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4380] device[0x1730368] (ttyMux1): queued IP4
config change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4657] platform-linux: do-delete-ip4-route[4:
192.168.254.254/32 0]: success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4723] platform: route: adding or updating IPv4
route: 192.168.254.254/32 via 0.0.0.0 dev 4 metric 700 mss 0 src
kernel pref-src 10.10.13.164
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4854] platform: signal: route   4   added:
192.168.254.254/32 via 0.0.0.0 dev 4 metric 700 mss 0 src rt-kernel
scope link pref-src 10.10.13.164
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.4951] platform-linux: do-add-ip4-route[4:
192.168.254.254/32 700]: success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5342] device[0x1730368] (ttyMux1): ip4-config:
set IP4Config instance (/org/freedesktop/NetworkManager/IP4Config/3)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5398] default-route:
entry[1/dev:0x1730368:ttyMux1:1:+sync]: record:add    0.0.0.0/0 via
192.168.254.254 dev 4 metric 700 mss 0 src user (700)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5454] default-route: resync: cancelled (258)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5514] default-route:
entry[1/dev:0x1730368:ttyMux1:1:+sync]: sync:add    0.0.0.0/0 via
192.168.254.254 dev 4 metric 700 mss 0 src user (700)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5567] platform: route: adding or updating IPv4
route: 0.0.0.0/0 via 192.168.254.254 dev 4 metric 700 mss 0 src user
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5764] platform: signal: route   4   added:
0.0.0.0/0 via 192.168.254.254 dev 4 metric 700 mss 0 src rt-static
scope global
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5833] platform-linux: do-add-ip4-route[4:
0.0.0.0/0 700]: success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5949] dns-mgr: (device_ip4_config_changed):
queueing DNS updates (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.5999] dns-mgr: (device_ip4_config_changed): DNS
configuration did not change
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.6268] dns-mgr: (device_ip4_config_changed): no
DNS changes to commit (0)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.6333] device[0x1730368] (ttyMux1): activation-
stage: schedule activate_stage5_ip4_config_commit,2 (id 267)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.6473] device[0x1730368] (ttyMux1): activation-
stage: invoke activate_stage5_ip4_config_commit,2 (id 267)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.6560] device[0x1730368] (ttyMux1): ip4-config:
update (commit=1, routes-full-sync=0, new-config=0x173ea08)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7106] platform: address: adding or updating IPv4
address: 10.10.13.164/32 lft forever pref forever lifetime 87-
0[4294967295,4294967295] ptp 192.168.254.254 dev 4 src unknown
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7225] platform-linux: do-add-ip4-address[4:
10.10.13.164/32,192.168.254.254]: success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7281] route-mgr4:   4: sync 1 IPv4 routes
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7340] platform: route: adding or updating IPv4
route: 192.168.254.254/32 via 0.0.0.0 dev 4 metric 700 mss 0 src
kernel pref-src 10.10.13.164
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7403] platform-linux: do-add-ip4-route[4:
192.168.254.254/32 700]: success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7463] device[0x1730368] (ttyMux1):
remove_pending_action (1): 'dhcp4' not pending (expected)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347732.7523] device (ttyMux1): state change: ip-config
-> ip-check (reason 'none') [70 80 0]
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7665] firewall: [0x1745500,change*:"ppp0"]:
firewall zone change ppp0:default (not running, simulate success)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.7742] device[0x1730368] (ttyMux1): activation-
stage: complete activate_stage5_ip4_config_commit,2 (id 267)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.8101] device[0x1730368] (ttyMux1): ip4-config:
update (commit=0, routes-full-sync=0, new-config=0x173ea90)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.8161] default-route:
entry[1/dev:0x1730368:ttyMux1:1:-sync]: record:update 0.0.0.0/0 via
192.168.254.254 dev 4 metric 700 mss 0 src rt-static scope global
(700)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.8417] firewall: [0x1745500,change*:"ppp0"]:
complete: fake success
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.8526] device[0x1730368] (ttyMux1):
add_pending_action (2): 'queued state change to secondaries'
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.8833] device[0x1730368] (ttyMux1): queued state
change to secondaries due to none (id 275)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.8954] device[0x1730368] (ttyMux1): running queued
state change to secondaries (id 275)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347732.9071] device (ttyMux1): state change: ip-check ->
secondaries (reason 'none') [80 90 0]
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9221] device[0x1730368] (ttyMux1):
add_pending_action (3): 'queued state change to activated'
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9281] device[0x1730368] (ttyMux1): queued state
change to activated due to none (id 280)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9338] device[0x1730368] (ttyMux1): device entered
SECONDARIES state
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9392] device[0x1730368] (ttyMux1):
remove_pending_action (2): 'queued state change to secondaries'
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9699] device[0x1730368] (ttyMux1): running queued
state change to activated (id 280)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347732.9705] device (ttyMux1): state change: secondaries
-> activated (reason 'none') [90 100 0]
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9828] active-connection[0x1713140]: set state
activated (was activating)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347732.9905] active-connection[0x1713140]: check-master-
ready: not signalling (state activated, no master)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0110] device[0x1730368] (ttyMux1):
remove_pending_action (1): 'activation::0x1713140'
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0139] dns-mgr: (device_state_changed): queueing
DNS updates (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0141] dns-mgr: (update_routing_and_dns): queueing
DNS updates (2)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0144] dns-mgr: (update_routing_and_dns): DNS
configuration changed
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0190] dns-mgr: (update_routing_and_dns): no DNS
changes to commit (1)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0194] dns-mgr: (device_state_changed): DNS
configuration changed
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0228] dns-mgr: (device_state_changed): committing
DNS changes (0)
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0258] dns-mgr: update-dns: updating resolv.conf
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347733.0296] device (ttyMux1): Activation: successful,
device activated.
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0329] device[0x1730368] (ttyMux1): set metered
value 3
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.0367] device[0x1730368] (ttyMux1):
remove_pending_action (0): 'queued state change to activated'
Mar 24 09:28:53 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347733.2041] agent-manager: req[0x1733b58, :1.15/nmcli-
connect/0]: agent unregistered or disappeared
Mar 24 09:28:54 w2 ModemManager[1184]: <debug> [1490347734.265786]
[src/mm-port-serial.c:1222] mm_port_serial_open(): (ttyMux1) device
open count is 2 (open)
Mar 24 09:28:54 w2 ModemManager[1184]: <debug> [1490347734.266166]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CGACT?<CR>'
Mar 24 09:28:54 w2 ModemManager[1184]: <debug> [1490347734.293967]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar 24 09:28:54 w2 ModemManager[1184]: <debug> [1490347734.294617]
[src/mm-base-bearer.c:172] load_connection_status_ready(): connection
status loaded: disconnected
Mar 24 09:28:54 w2 ModemManager[1184]: <debug> [1490347734.294870]
[src/mm-port.c:94] mm_port_set_connected(): (ttyMux0): port now
disconnected
Mar 24 09:28:54 w2 ModemManager[1184]: <info>  [1490347734.295107]
[src/mm-iface-modem.c:1433] __iface_modem_update_state_internal():
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(connected -> registered)
Mar 24 09:28:54 w2 NetworkManager[23563]: <info>  [1490347734.3055]
(ttyMux1): modem state changed, 'connected' --> 'registered' (reason:
user-requested)
Mar 24 09:28:54 w2 NetworkManager[23563]: <info>  [1490347734.3057]
device (ttyMux1): state change: activated -> failed (reason 'modem-
no-carrier') [100 120 25]
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.3077]
active-connection[0x1713140]: set state deactivated (was activated)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.3082]
active-connection[0x1713140]: check-master-ready: not signalling
(state deactivated, no master)
Mar 24 09:28:54 w2 ModemManager[1184]: <debug> [1490347734.313842]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device open
count is 1 (close)
Mar 24 09:28:54 w2 pppd[23672]: Terminating on signal 15
Mar 24 09:28:54 w2 pppd[23672]: Connect time 0.1 minutes.
Mar 24 09:28:54 w2 pppd[23672]: Sent 0 bytes, received 0 bytes.
Mar 24 09:28:54 w2 pppd[23672]: sent [LCP TermReq id=0x3 "User
request"]
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.3903]
kill child process 'pppd' (23672): wait for process to terminate
after sending SIGTERM (15) (send SIGKILL in 2000 milliseconds)...
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.3954]
modem-broadband[ttyMux1]: notifying ModemManager about the modem
disconnection
Mar 24 09:28:54 w2 pppd[23672]: rcvd [LCP TermAck id=0x3 "User
request"]
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.4193]
policy: connection 'Vodafone' failed to autoconnect; 4 tries left
Mar 24 09:28:54 w2 pppd[23672]: Connection terminated.
Mar 24 09:28:54 w2 NetworkManager[23563]: <warn>  [1490347734.4728]
device (ttyMux1): Activation: failed for connection 'Vodafone'
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5005]
device[0x1730368] (ttyMux1): add_pending_action (1): 'queued state
change to disconnected'
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5135]
device[0x1730368] (ttyMux1): queued state change to disconnected due
to none (id 305)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5222]
platform: signal: link changed: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
init driver unknown rx:4,64 tx:5,97
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5291]
device[0x1730368] (ttyMux1): queued link change for ip-ifindex 4
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5354]
platform: signal: address 4 removed: 10.10.13.164/32 lft forever pref
forever lifetime 89-0[4294967295,4294967295] ptp 192.168.254.254 dev
4 flags permanent src kernel
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5418]
default-route: resync: schedule on idle
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5462]
device[0x1730368] (ttyMux1): queued IP4 config change
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5525]
platform: signal: link removed: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
not-init rx:4,64 tx:5,97
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5600]
platform: signal: address 4 changed: 192.168.10.133/24 lft 75024sec
pref 75024sec lifetime 89-32[75081,75081] dev 2 src kernel
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5685]
device[0x16fc3a8] (eth0): queued IP4 config change
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5737]
platform: signal: address 4 changed: 192.168.10.125/24 lft 86344sec
pref 86344sec lifetime 89-32[86401,86401] dev 2 flags secondary src
kernel
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5816]
platform: signal: route   4 removed: 0.0.0.0/0 via 192.168.254.254
dev 4 metric 700 mss 0 src rt-static scope global
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.5876]
platform: signal: route   4 removed: 192.168.254.254/32 via 0.0.0.0
dev 4 metric 700 mss 0 src rt-kernel scope link pref-src 10.10.13.164
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6126]
device[0x1730368] (ttyMux1): running queued state change to
disconnected (id 305)
Mar 24 09:28:54 w2 NetworkManager[23563]: <info>  [1490347734.6128]
device (ttyMux1): state change: failed -> disconnected (reason
'none') [120 30 0]
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6184]
device[0x1730368] (ttyMux1): deactivating device (reason 'none') [0]
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6241]
firewall: [0x173e260,remove*:"ppp0"]: firewall zone remove
ppp0:default (not running, simulate success)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6300]
firewall: [0x173e260,remove*:"ppp0"]: complete: drop request
simulating success
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6366]
device[0x1730368] (ttyMux1): clearing queued IP4 config change
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6423]
device[0x1730368] (ttyMux1): remove_pending_action (1): 'dhcp6' not
pending (expected)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6478]
device[0x1730368] (ttyMux1): remove_pending_action (1): 'autoconf6'
not pending (expected)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6545]
platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file or
directory
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6604]
platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/accept_ra': (2) No such file or
directory
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6669]
platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/use_tempaddr': (2) No such file or
directory
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6727]
modem-broadband[ttyMux1]: notifying ModemManager about the modem
disconnection
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.6814]
route-mgr4:   4: sync 0 IPv4 routes
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.7072]
route-mgr6:   4: sync 0 IPv6 routes
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.7192]
device[0x1730368] (ttyMux1): set metered value 0
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.7457]
default-route: entry[1/dev:0x1730368:ttyMux1:0:+sync]: record:update
0.0.0.0/0 via 0.0.0.0 dev 4 metric 4294967295 mss 0 src unknown (700)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.7759]
default-route: resync: cancelled (313)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.7882]
default-route: entry[0/dev:0x1730368:ttyMux1:0:+sync]:
record:add    ::/0 via :: dev 4 metric 4294967295 mss 0 src unknown
(4294967295)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8195]
default-route: entry[1/dev:0x1730368:ttyMux1:0:+sync]: record:remove
0.0.0.0/0 via 0.0.0.0 dev 4 metric 4294967295 mss 0 src unknown (700)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8276]
default-route: entry[0/dev:0x1730368:ttyMux1:0:+sync]: record:remove
::/0 via :: dev 4 metric 4294967295 mss 0 src unknown (4294967295)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8381]
device[0x1730368] (ttyMux1): ip4-config: update (commit=1, routes-
full-sync=1, new-config=(nil))
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8431]
device[0x1730368] (ttyMux1): ip4-config: clear IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/3)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8484]
dns-mgr: (device_ip4_config_changed): queueing DNS updates (1)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8543]
dns-mgr: (device_ip4_config_changed): DNS configuration changed
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8597]
dns-mgr: (device_ip4_config_changed): committing DNS changes (0)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8658]
dns-mgr: update-dns: updating resolv.conf
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8722]
device[0x1730368] (ttyMux1): ip6-config: update (commit=1, routes-
full-sync=1, new-config=(nil))
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8804]
dns-mgr: (update_routing_and_dns): queueing DNS updates (1)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8856]
dns-mgr: (update_routing_and_dns): DNS configuration did not change
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8901]
dns-mgr: (update_routing_and_dns): no DNS changes to commit (0)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.8958]
device[0x1730368] (ttyMux1): add_pending_action (2): 'autoactivate'
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.9245]
active-connection[0x1713140]: disposing
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.9324]
device[0x1730368] (ttyMux1): remove_pending_action (1): 'queued state
change to disconnected'
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.9400]
device[0x16fc3a8] (eth0): ip4-config: update (commit=0, routes-full-
sync=0, new-config=0x173e870)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.9531]
platform-linux: UDEV event: action 'remove' subsys 'net' device
'ppp0' (4); seqnum=28331
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.9613]
platform-linux: udev-remove: IFINDEX=4
Mar 24 09:28:54 w2 NetworkManager[23563]: <info>  [1490347734.9673]
devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Mar 24 09:28:54 w2 NetworkManager[23563]: <debug> [1490347734.9838]
device[0x1730368] (ttyMux1): remove_pending_action (0):
'autoactivate'
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347734.3055] (ttyMux1): modem state changed, 'connected'
--> 'registered' (reason: user-requested)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347734.3057] device (ttyMux1): state change: activated
-> failed (reason 'modem-no-carrier') [100 120 25]
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.3077] active-connection[0x1713140]: set state
deactivated (was activated)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.3082] active-connection[0x1713140]: check-master-
ready: not signalling (state deactivated, no master)
Mar 24 09:28:55 w2 NetworkManager[23563]: Terminating on signal 15
Mar 24 09:28:55 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
Mar 24 09:28:55 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Mar 24 09:28:55 w2 NetworkManager[23563]: Connect time 0.1 minutes.
Mar 24 09:28:55 w2 NetworkManager[23563]: Sent 0 bytes, received 0
bytes.
Mar 24 09:28:55 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Mar 24 09:28:55 w2 NetworkManager[23563]: sent [LCP TermReq id=0x3
"User request"]
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.3903] kill child process 'pppd' (23672): wait for
process to terminate after sending SIGTERM (15) (send SIGKILL in 2000
milliseconds)...
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.3954] modem-broadband[ttyMux1]: notifying
ModemManager about the modem disconnection
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.4193] policy: connection 'Vodafone' failed to
autoconnect; 4 tries left
Mar 24 09:28:55 w2 NetworkManager[23563]: rcvd [LCP TermAck id=0x3
"User request"]
Mar 24 09:28:55 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<warn>  [1490347734.4728] device (ttyMux1): Activation: failed for
connection 'Vodafone'
Mar 24 09:28:55 w2 NetworkManager[23563]: Connection terminated.
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5005] device[0x1730368] (ttyMux1):
add_pending_action (1): 'queued state change to disconnected'
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5135] device[0x1730368] (ttyMux1): queued state
change to disconnected due to none (id 305)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5222] platform: signal: link changed: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
init driver unknown rx:4,64 tx:5,97
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5291] device[0x1730368] (ttyMux1): queued link
change for ip-ifindex 4
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5354] platform: signal: address 4 removed:
10.10.13.164/32 lft forever pref forever lifetime 89-
0[4294967295,4294967295] ptp 192.168.254.254 dev 4 flags permanent
src kernel
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5418] default-route: resync: schedule on idle
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5462] device[0x1730368] (ttyMux1): queued IP4
config change
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5525] platform: signal: link removed: 4: ppp0
<NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512 unknown?
not-init rx:4,64 tx:5,97
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5600] platform: signal: address 4 changed:
192.168.10.133/24 lft 75024sec pref 75024sec lifetime 89-
32[75081,75081] dev 2 src kernel
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5685] device[0x16fc3a8] (eth0): queued IP4 config
change
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5737] platform: signal: address 4 changed:
192.168.10.125/24 lft 86344sec pref 86344sec lifetime 89-
32[86401,86401] dev 2 flags secondary src kernel
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5816] platform: signal: route   4 removed:
0.0.0.0/0 via 192.168.254.254 dev 4 metric 700 mss 0 src rt-static
scope global
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.5876] platform: signal: route   4 removed:
192.168.254.254/32 via 0.0.0.0 dev 4 metric 700 mss 0 src rt-kernel
scope link pref-src 10.10.13.164
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6126] device[0x1730368] (ttyMux1): running queued
state change to disconnected (id 305)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347734.6128] device (ttyMux1): state change: failed ->
disconnected (reason 'none') [120 30 0]
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6184] device[0x1730368] (ttyMux1): deactivating
device (reason 'none') [0]
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6241] firewall: [0x173e260,remove*:"ppp0"]:
firewall zone remove ppp0:default (not running, simulate success)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6300] firewall: [0x173e260,remove*:"ppp0"]:
complete: drop request simulating success
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6366] device[0x1730368] (ttyMux1): clearing
queued IP4 config change
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6423] device[0x1730368] (ttyMux1):
remove_pending_action (1): 'dhcp6' not pending (expected)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6478] device[0x1730368] (ttyMux1):
remove_pending_action (1): 'autoconf6' not pending (expected)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6545] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file or
directory
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6604] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/accept_ra': (2) No such file or
directory
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6669] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/ppp0/use_tempaddr': (2) No such file or
directory
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6727] modem-broadband[ttyMux1]: notifying
ModemManager about the modem disconnection
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.6814] route-mgr4:   4: sync 0 IPv4 routes
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.7072] route-mgr6:   4: sync 0 IPv6 routes
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.7192] device[0x1730368] (ttyMux1): set metered
value 0
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.7457] default-route:
entry[1/dev:0x1730368:ttyMux1:0:+sync]: record:update 0.0.0.0/0 via
0.0.0.0 dev 4 metric 4294967295 mss 0 src unknown (700)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.7759] default-route: resync: cancelled (313)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.7882] default-route:
entry[0/dev:0x1730368:ttyMux1:0:+sync]: record:add    ::/0 via :: dev
4 metric 4294967295 mss 0 src unknown (4294967295)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8195] default-route:
entry[1/dev:0x1730368:ttyMux1:0:+sync]: record:remove 0.0.0.0/0 via
0.0.0.0 dev 4 metric 4294967295 mss 0 src unknown (700)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8276] default-route:
entry[0/dev:0x1730368:ttyMux1:0:+sync]: record:remove ::/0 via :: dev
4 metric 4294967295 mss 0 src unknown (4294967295)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8381] device[0x1730368] (ttyMux1): ip4-config:
update (commit=1, routes-full-sync=1, new-config=(nil))
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8431] device[0x1730368] (ttyMux1): ip4-config:
clear IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/3)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8484] dns-mgr: (device_ip4_config_changed):
queueing DNS updates (1)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8543] dns-mgr: (device_ip4_config_changed): DNS
configuration changed
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8597] dns-mgr: (device_ip4_config_changed):
committing DNS changes (0)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8658] dns-mgr: update-dns: updating resolv.conf
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8722] device[0x1730368] (ttyMux1): ip6-config:
update (commit=1, routes-full-sync=1, new-config=(nil))
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8804] dns-mgr: (update_routing_and_dns): queueing
DNS updates (1)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8856] dns-mgr: (update_routing_and_dns): DNS
configuration did not change
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8901] dns-mgr: (update_routing_and_dns): no DNS
changes to commit (0)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.8958] device[0x1730368] (ttyMux1):
add_pending_action (2): 'autoactivate'
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.9245] active-connection[0x1713140]: disposing
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.9324] device[0x1730368] (ttyMux1):
remove_pending_action (1): 'queued state change to disconnected'
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.9400] device[0x16fc3a8] (eth0): ip4-config:
update (commit=0, routes-full-sync=0, new-config=0x173e870)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.9531] platform-linux: UDEV event: action 'remove'
subsys 'net' device 'ppp0' (4); seqnum=28331
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.9613] platform-linux: udev-remove: IFINDEX=4
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<info>  [1490347734.9673] devices removed (path:
/sys/devices/virtual/net/ppp0, iface: ppp0)
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347734.9838] device[0x1730368] (ttyMux1):
remove_pending_action (0): 'autoactivate'
Mar 24 09:28:55 w2 NetworkManager[23563]: <debug> [1490347735.5103]
kill child process 'pppd' (23672): terminated normally with status 5
(1120051 usec elapsed)
Mar 24 09:28:55 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Mar 24 09:28:55 w2 NetworkManager[23563]: nm-pppd-plugin-Message: nm-
ppp-plugin: (nm_exit_notify): cleaning up
Mar 24 09:28:55 w2 NetworkManager[23563]: NetworkManager[23563]:
<debug> [1490347735.5103] kill child process 'pppd' (23672):
terminated normally with status 5 (1120051 usec elapsed)
Mar 24 09:28:57 w2 ModemManager[1184]: <debug> [1490347737.817498]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>NO
CARRIER<CR><LF>'
Mar 24 09:28:57 w2 ModemManager[1184]: <debug> [1490347737.817835]
[src/mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got
failure code 1: No carrier
Mar 24 09:28:59 w2 ModemManager[1184]: <debug> [1490347739.778336]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
'<CR><LF>+CIEV: rssi,3<CR><LF>'
_______________________________________________
networkmanager-list mailing list
networkmanager-list gnome org
https://mail.gnome.org/mailman/listinfo/networkmanager-list

Follow-Ups:
- Re: Differences between GSM modems
  - From: Colin Helliwell

References:
- Differences between GSM modems
  - From: colin.helliwell
- Re: Differences between GSM modems
  - From: Dan Williams
- Re: Differences between GSM modems
  - From: Colin Helliwell

[Date Prev][Date Next] [Thread Prev][Thread Next] [Thread Index] [Date Index] [Author Index]