> On 23 March 2017 at 19:43 Dan Williams <[email protected]> wrote: > > On Thu, 2017-03-23 at 18:26 +0000, [email protected] > 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>' _______________________________________________ networkmanager-list mailing list [email protected] https://mail.gnome.org/mailman/listinfo/networkmanager-list
