Re: Differences between GSM modems
- From: Colin Helliwell <colin helliwell ln-systems com>
- To: networkmanager-list gnome org
- Subject: Re: Differences between GSM modems
- Date: Fri, 24 Mar 2017 13:53:53 +0000 (GMT)
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/archives/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).
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><LF>'
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>'
[
Date Prev][
Date Next] [
Thread Prev][
Thread Next]
[
Thread Index]
[
Date Index]
[
Author Index]
