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