Differences between GSM modems

[<colin helliwell ln-systems com>]

At the risk of sounding like a broken record, I'm getting problems with NM +
ModemManager with different GSM modems.
The rootfs and SIM is the same between the two, and I'm running the same
test, from boot-up:

systemctl stop NetworkManager    [because the service is enabled in systemd]
NM_PPP_DEBUG=1 NetworkManager --no-daemon --debug --log-level=DEBUG   [in
order to easily catch the debug output]

nmcli con up Vodafone


On one modem (Cinterion EHS5), all is fine and the ppp comes up. On the
other (Cinterion BGS2) it appears to negotiate the ppp ok but then something
goes awry and it gets taken down. Although nmcli reports "Connection
successfully activated (D-Bus active path:
/org/freedesktop/NetworkManager/ActiveConnection/1) " nonetheless; but no
ppp0 in 'ifconfig'.
I have no /etc/ppp/options, nor /etc/ppp/ip-up or /etc/ppp/ip-down.

Without NM, I *can* start the ppp successfully on the BGS2 with
systemctl stop NetworkManager   
mmcli -m 0 --enable
mmcli -m 0 --simple-connect="apn=wap.vodafone.co.uk"
pppd nodetach call provider 

Any thoughts on where to dig into next in order to get to the bottom of
this?

NM logs are as follows -

Working EHS5:

NetworkManager[1635]: <debug> [1490291827.9051] agent-manager:
req[0x1d93ee0, :1.12/nmcli-connect/0]: requesting permissions
NetworkManager[1635]: <debug> [1490291827.9086] agent-manager:
req[0x1d93ee0, :1.12/nmcli-connect/0]: agent registered
NetworkManager[1635]: <debug> [1490291827.9171] policy: re-enabling
autoconnect for all connections with failed secrets
NetworkManager[1635]: <debug> [1490291827.9335]
active-connection[0x1dd3140]: set device "ttyMux1" [0x1df6340]
NetworkManager[1635]: <debug> [1490291827.9366] device[0x1df6340] (ttyMux1):
add_pending_action (1): 'activation::0x1dd3140'
NetworkManager[1635]: <debug> [1490291827.9396]
active-connection[0x1dd3140]: constructed (NMActRequest, version-id 2)
NetworkManager[1635]: <debug> [1490291827.9408] device[0x1df6340] (ttyMux1):
add_pending_action (2): 'autoactivate'
NetworkManager[1635]: <debug> [1490291827.9443] device[0x1df6340] (ttyMux1):
remove_pending_action (1): 'autoactivate'
NetworkManager[1635]: <debug> [1490291827.9452] device[0x1df6340] (ttyMux1):
unmanaged: flags set to
[!sleeping,!loopback,!platform-init,!user-explicit,!user-settings=0x0/0x79/m
anaged, set-managed [user-explicit=0x20], reason user-requested)
NetworkManager[1635]: <info>  [1490291827.9734] device (ttyMux1):
Activation: starting connection 'Vodafone'
(e0f97177-2f8e-4ed4-9942-7b4e499397cc)
NetworkManager[1635]: <debug> [1490291827.9742] device[0x1df6340] (ttyMux1):
activation-stage: schedule activate_stage1_device_prepare,2 (id 185)
NetworkManager[1635]: <debug> [1490291827.9803] create NMAuditManager
singleton (0x1d9fc80)
NetworkManager[1635]: <info>  [1490291827.9812] audit:
op="connection-activate" uuid="e0f97177-2f8e-4ed4-9942-7b4e499397cc"
name="Vodafone" pid=1708 uid=0 result="success"
NetworkManager[1635]: <debug> [1490291827.9883] device[0x1df6340] (ttyMux1):
activation-stage: invoke activate_stage1_device_prepare,2 (id 185)
NetworkManager[1635]: <info>  [1490291827.9895] device (ttyMux1): state
change: disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[1635]: <debug> [1490291828.0017]
active-connection[0x1dd3140]: set state activating (was unknown)
NetworkManager[1635]: <debug> [1490291828.0050]
active-connection[0x1dd3140]: check-master-ready: not signalling (state
activating, no master)
NetworkManager[1635]: <debug> [1490291828.0067] modem-broadband[ttyMux1]:
launching connection with ip type 'ipv4' (try 1)
NetworkManager[1635]: <debug> [1490291828.0142] device[0x1df6340] (ttyMux1):
activation-stage: complete activate_stage1_device_prepare,2 (id 185)
NetworkManager[1635]: <info>  [1490291828.2627] (ttyMux1): modem state
changed, 'registered' --> 'connecting' (reason: user-requested)
NetworkManager[1635]: <info>  [1490291828.5662] (ttyMux1): modem state
changed, 'connecting' --> 'connected' (reason: user-requested)
NetworkManager[1635]: <warn>  [1490291828.5998] device (ttyMux1): failed to
look up interface index
NetworkManager[1635]: <debug> [1490291828.6010] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ttyMux0/disable_ipv6': (2) No such
file or directory
NetworkManager[1635]: <debug> [1490291828.6021] device[0x1df6340] (ttyMux1):
activation-stage: schedule activate_stage2_device_config,2 (id 215)
NetworkManager[1635]: <debug> [1490291828.6086] device[0x1df6340] (ttyMux1):
activation-stage: invoke activate_stage2_device_config,2 (id 215)
NetworkManager[1635]: <info>  [1490291828.6093] device (ttyMux1): state
change: prepare -> config (reason 'none') [40 50 0]
NetworkManager[1635]: <debug> [1490291828.6213] device[0x1df6340] (ttyMux1):
bringing up device
NetworkManager[1635]: <debug> [1490291828.6222] device[0x1df6340] (ttyMux1):
Activation: setting firewall zone 'default'
NetworkManager[1635]: <debug> [1490291828.6252] firewall:
[0x1ddafa0,change*:"ttyMux0"]: firewall zone change ttyMux0:default (not
running, simulate success)
NetworkManager[1635]: <debug> [1490291828.6260] device[0x1df6340] (ttyMux1):
activation-stage: complete activate_stage2_device_config,2 (id 215)
NetworkManager[1635]: <debug> [1490291828.6517] firewall:
[0x1ddafa0,change*:"ttyMux0"]: complete: fake success
NetworkManager[1635]: <debug> [1490291828.6525] device[0x1df6340] (ttyMux1):
activation-stage: schedule activate_stage3_ip_config_start,2 (id 221)
NetworkManager[1635]: <debug> [1490291828.6533] device[0x1df6340] (ttyMux1):
activation-stage: invoke activate_stage3_ip_config_start,2 (id 221)
NetworkManager[1635]: <info>  [1490291828.6539] device (ttyMux1): state
change: config -> ip-config (reason 'none') [50 70 0]
NetworkManager[1635]: <warn>  [1490291828.6664] device (ttyMux1): interface
ttyMux0 not up for IP configuration
NetworkManager[1635]: <debug> [1490291828.6693] ip4_config_start
NetworkManager[1635]: <info>  [1490291828.6700] (ttyMux1): using
modem-specified IP timeout: 20 seconds
NetworkManager[1635]: <info>  [1490291828.6798] ppp-manager: starting PPP
connection
NetworkManager[1635]: <debug> [1490291828.6805] 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
NetworkManager[1635]: <info>  [1490291828.7082] ppp-manager: pppd started
with pid 1716
NetworkManager[1635]: <debug> [1490291828.7088] device[0x1df6340] (ttyMux1):
activation-stage: complete activate_stage3_ip_config_start,2 (id 221)
Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase
'serial connection'
using channel 1
NetworkManager[1635]: <debug> [1490291828.9278] ethtool: Request failed:
Operation not supported
NetworkManager[1635]: <debug> [1490291828.9291] ethtool: Request failed:
Operation not supported
NetworkManager[1635]: <debug> [1490291828.9298] platform: signal: link
added: 3: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512
unknown? not-init driver unknown rx:0,0 tx:0,0
NetworkManager[1635]: <debug> [1490291828.9311] device[0x1db4578] (ppp0):
unmanaged: flags set to
[platform-init,by-default=0x110/0x110/unmanaged/unrealized, set-unmanaged
[by-default=0x100])Using interface ppp0
Connect: ppp0 <--> /dev/ttyMux0
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase
'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x633523af> <pcomp> <accomp>]

NetworkManager[1635]: <debug> [1490291828.9469] ethtool: Request failed:
Operation not supported
NetworkManager[1635]: <debug> [1490291828.9476] mii: SIOCGMIIPHY failed:
Invalid argument (22) (ppp0)
NetworkManager[1635]: <debug> [1490291828.9480] mii: MII not supported
(ppp0)
NetworkManager[1635]: <debug> [1490291828.9539] device[0x1db4578] (ppp0):
constructed (NMDeviceGeneric)
NetworkManager[1635]: <debug> [1490291828.9573] device[0x1db4578] (ppp0):
start setup of NMDeviceGeneric, kernel ifindex 3
NetworkManager[1635]: <debug> [1490291828.9719] 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
rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x6b7e4a17> <pcomp> <accomp>]
NetworkManager[1635]: <debug> [1490291828.9854] platform-linux: sysctl:
reading '/sys/class/net/ppp0/dev_id': '0x0'
sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x6b7e4a17> <pcomp> <accomp>]
NetworkManager[1635]: <debug> [1490291829.0047] ethtool: Request failed:
Operation not supported
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x633523af> <pcomp> <accomp>]
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase
'authenticate'
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase
'network'
NetworkManager[1635]: <debug> [1490291829.0218] ethtool: Request failed:
Operation not supported
kernel does not support PPP filtering
NetworkManager[1635]: <debug> [1490291829.0374] mii: SIOCGMIIPHY failed:
Invalid argument (22) (ppp0)
NetworkManager[1635]: <debug> [1490291829.0479] mii: MII not supported
(ppp0)
NetworkManager[1635]: <debug> [1490291829.0771] device[0x1db4578] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1635]: <debug> [1490291829.0910] device[0x1db4578] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1635]: <debug> [1490291829.1016] device[0x1db4578] (ppp0):
unmanaged: flags set to
[platform-init,by-default,!loopback=0x110/0x118/unmanaged/unrealized,
set-managed [loopback=0x8])
sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
NetworkManager[1635]: <debug> [1490291829.1162] device[0x1db4578] (ppp0):
unmanaged: flags set to
[platform-init,by-default,!loopback,!user-settings=0x110/0x158/unmanaged/unr
ealized, set-managed [user-settings=0x40])
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>]
NetworkManager[1635]: <debug> [1490291829.1404] device[0x1db4578] (ppp0):
unmanaged: flags set to
[platform-init,by-default,!sleeping,!loopback,!user-settings=0x110/0x159/unm
anaged/unrealized, set-managed [sleeping=0x1])
rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15]
Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
NetworkManager[1635]: <info>  [1490291829.2032] manager: (ppp0): new Generic
device (/org/freedesktop/NetworkManager/Devices/3)
NetworkManager[1635]: <debug> [1490291829.2367] device[0x1db4578] (ppp0):
ip4-config: update (commit=0, routes-full-sync=0, new-config=0x1dfc9a0)
NetworkManager[1635]: <debug> [1490291829.2910] device[0x1db4578] (ppp0):
ip4-config: set IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
NetworkManager[1635]: <debug> [1490291829.2966] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291829.3020] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1635]: <debug> [1490291829.3070] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
NetworkManager[1635]: <debug> [1490291829.3129] device[0x1db4578] (ppp0):
ip6-config: update (commit=0, routes-full-sync=0, new-config=0x1d71460)
NetworkManager[1635]: <debug> [1490291829.3292] device[0x1db4578] (ppp0):
ip6-config: set IP6Config instance
(/org/freedesktop/NetworkManager/IP6Config/2)
NetworkManager[1635]: <debug> [1490291829.3304] dns-mgr:
(device_ip6_config_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291829.3361] dns-mgr:
(device_ip6_config_changed): DNS configuration did not change
NetworkManager[1635]: <debug> [1490291829.3414] dns-mgr:
(device_ip6_config_changed): no DNS changes to commit (0)
NetworkManager[1635]: <debug> [1490291829.3496] device[0x1db4578] (ppp0):
emit RECHECK_ASSUME signal
NetworkManager[1635]: <debug> [1490291829.5655] platform-linux: UDEV event:
action 'add' subsys 'net' device 'ppp0' (3); seqnum=1240
NetworkManager[1635]: <debug> [1490291829.5665] ethtool: Request failed:
Operation not supported
NetworkManager[1635]: <debug> [1490291829.5668] platform: signal: link
changed: 3: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512
unknown? init driver unknown rx:0,0 tx:0,0
NetworkManager[1635]: <debug> [1490291829.5670] device[0x1db4578] (ppp0):
queued link change for ifindex 3
NetworkManager[1635]: <info>  [1490291829.5675] devices added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0)
NetworkManager[1635]: <info>  [1490291829.5677] device added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration
found.
NetworkManager[1635]: <debug> [1490291829.5685] device[0x1db4578] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1635]: <debug> [1490291829.5686] device[0x1db4578] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1635]: <debug> [1490291829.5688] device[0x1db4578] (ppp0):
unmanaged: flags set to
[by-default,!sleeping,!loopback,!platform-init,!user-settings=0x100/0x159/ma
nageable, set-managed [platform-init=0x10], reason managed)
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>]
rcvd [IPCP ConfReq id=0x1]
sent [IPCP ConfNak id=0x1 <addr 0.0.0.0>]
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2
0.0.0.0>]
rcvd [IPCP ConfReq id=0x2 <addr 10.8.49.163>]
sent [IPCP ConfAck id=0x2 <addr 10.8.49.163>]
rcvd [IPCP ConfNak id=0x2 <addr 10.8.49.163> <ms-dns1 10.206.128.1> <ms-dns2
10.206.128.1>]
sent [IPCP ConfReq id=0x3 <addr 10.8.49.163> <ms-dns1 10.206.128.1> <ms-dns2
10.206.128.1>]
rcvd [IPCP ConfAck id=0x3 <addr 10.8.49.163> <ms-dns1 10.206.128.1> <ms-dns2
10.206.128.1>]
NetworkManager[1635]: <debug> [1490291832.1579] platform: signal: address 4
added: 10.8.49.163/32 lft forever pref forever lifetime
47-0[4294967295,4294967295] dev 3 flags permanent src kernel
NetworkManager[1635]: <debug> [1490291832.1582] default-route: resync:
schedule on idle
NetworkManager[1635]: <debug> [1490291832.1584] device[0x1db4578] (ppp0):
queued IP4 config change
NetworkManager[1635]: <debug> [1490291832.1592] device[0x1db4578] (ppp0):
ip4-config: update (commit=0, routes-full-sync=0, new-config=0x1dfcab0)
NetworkManager[1635]: <debug> [1490291832.1604] device[0x1db4578] (ppp0):
ip4-config: update IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
NetworkManager[1635]: <debug> [1490291832.1609] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291832.1612] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1635]: <debug> [1490291832.1613] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
local  IP address 10.8.49.163
remote IP address 10.8.49.163
primary   DNS address 10.206.128.1
secondary DNS address 10.206.128.1
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase
'running'
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): ip-up event
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): sending IPv4 config to
NetworkManager...
NetworkManager[1635]: <debug> [1490291832.2001] ethtool: Request failed:
Operation not supported
NetworkManager[1635]: <debug> [1490291832.2064] ethtool: Request failed:
Operation not supported
NetworkManager[1635]: <debug> [1490291832.2111] platform: signal: link
changed: 3: ppp0
<NOARP,UP,LOWER_UP;pointopoint,multicast,noarp,up,running,lowerup> mtu 1500
arp 512 unknown? init driver unknown rx:5,68 tx:7,135
NetworkManager[1635]: <debug> [1490291832.2156] device[0x1db4578] (ppp0):
queued link change for ifindex 3
NetworkManager[1635]: <info>  [1490291832.2213] ppp-manager: (IPv4 Config
Get) reply received.
NetworkManager[1635]: <debug> [1490291832.2341] manager: (ppp0): removing
device (allow_unmanage 0, managed 0)
NetworkManager[1635]: <debug> [1490291832.2392] device[0x1db4578] (ppp0):
ip4-config: update (commit=0, routes-full-sync=0, new-config=(nil))
NetworkManager[1635]: <debug> [1490291832.2438] device[0x1db4578] (ppp0):
ip4-config: clear IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
NetworkManager[1635]: <debug> [1490291832.2490] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291832.2537] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1635]: <debug> [1490291832.2585] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
NetworkManager[1635]: <debug> [1490291832.2624] device[0x1db4578] (ppp0):
ip6-config: update (commit=0, routes-full-sync=0, new-config=(nil))
NetworkManager[1635]: <debug> [1490291832.2665] device[0x1db4578] (ppp0):
ip6-config: clear IP6Config instance
(/org/freedesktop/NetworkManager/IP6Config/2)
NetworkManager[1635]: <debug> [1490291832.2694] dns-mgr:
(device_ip6_config_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291832.2721] dns-mgr:
(device_ip6_config_changed): DNS configuration did not change
NetworkManager[1635]: <debug> [1490291832.2746] dns-mgr:
(device_ip6_config_changed): no DNS changes to commit (0)
NetworkManager[1635]: <debug> [1490291832.2816] device[0x1db4578] (ppp0):
disposing
NetworkManager[1635]: <debug> [1490291832.2880] device[0x1db4578] (ppp0):
remove_pending_action (0): 'dhcp6' not pending (expected)
NetworkManager[1635]: <debug> [1490291832.2905] device[0x1db4578] (ppp0):
remove_pending_action (0): 'autoconf6' not pending (expected)
NetworkManager[1635]: <debug> [1490291832.2935] device[0x1db4578] (ppp0):
ip4-config: update (commit=1, routes-full-sync=1, new-config=(nil))
NetworkManager[1635]: <debug> [1490291832.2961] device[0x1db4578] (ppp0):
ip6-config: update (commit=1, routes-full-sync=1, new-config=(nil))
NetworkManager[1635]: <debug> [1490291832.2988] device[0x1db4578] (ppp0):
finalize(): NMDeviceGeneric
NetworkManager[1635]: <debug> [1490291832.3017] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file
or directory
NetworkManager[1635]: <debug> [1490291832.3048] device[0x1df6340] (ttyMux1):
ip4-config: update (commit=1, routes-full-sync=1, new-config=0x1dfcbc0)
NetworkManager[1635]: <debug> [1490291832.3076] platform: address: adding or
updating IPv4 address: 10.8.49.163/32 lft forever pref forever lifetime
48-0[4294967295,4294967295] dev 3 src unknown
NetworkManager[1635]: <debug> [1490291832.3105] platform-linux:
do-add-ip4-address[3: 10.8.49.163/32]: success
NetworkManager[1635]: <debug> [1490291832.3139] route-mgr4:   3: sync 1 IPv4
routes
NetworkManager[1635]: <debug> [1490291832.3191] platform: route: adding or
updating IPv4 route: 10.8.49.163/32 via 0.0.0.0 dev 3 metric 700 mss 0 src
kernel pref-src 10.8.49.163
NetworkManager[1635]: <debug> [1490291832.3220] platform: signal: route   4
added: 10.8.49.163/32 via 0.0.0.0 dev 3 metric 700 mss 0 src rt-kernel scope
link pref-src 10.8.49.163
NetworkManager[1635]: <debug> [1490291832.3247] device[0x1df6340] (ttyMux1):
queued IP4 config change
NetworkManager[1635]: <debug> [1490291832.3275] platform-linux:
do-add-ip4-route[3: 10.8.49.163/32 700]: success
NetworkManager[1635]: <debug> [1490291832.3409] device[0x1df6340] (ttyMux1):
ip4-config: set IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/3)
NetworkManager[1635]: <debug> [1490291832.3418] default-route:
entry[1/dev:0x1df6340:ttyMux1:1:+sync]: record:add    0.0.0.0/0 via
10.8.49.163 dev 3 metric 700 mss 0 src user (700)
NetworkManager[1635]: <debug> [1490291832.3424] default-route: resync:
cancelled (251)
NetworkManager[1635]: <debug> [1490291832.3454] default-route:
entry[1/dev:0x1df6340:ttyMux1:1:+sync]: sync:add    0.0.0.0/0 via
10.8.49.163 dev 3 metric 700 mss 0 src user (700)
NetworkManager[1635]: <debug> [1490291832.3483] platform: route: adding or
updating IPv4 route: 0.0.0.0/0 via 10.8.49.163 dev 3 metric 700 mss 0 src
user
NetworkManager[1635]: <debug> [1490291832.3512] platform: signal: route   4
added: 0.0.0.0/0 via 10.8.49.163 dev 3 metric 700 mss 0 src rt-static scope
global
NetworkManager[1635]: <debug> [1490291832.3540] platform-linux:
do-add-ip4-route[3: 0.0.0.0/0 700]: success
NetworkManager[1635]: <debug> [1490291832.3570] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291832.3596] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1635]: <debug> [1490291832.3620] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
NetworkManager[1635]: <debug> [1490291832.3645] device[0x1df6340] (ttyMux1):
activation-stage: schedule activate_stage5_ip4_config_commit,2 (id 268)
NetworkManager[1635]: <debug> [1490291832.3712] device[0x1df6340] (ttyMux1):
activation-stage: invoke activate_stage5_ip4_config_commit,2 (id 268)
NetworkManager[1635]: <debug> [1490291832.3994] device[0x1df6340] (ttyMux1):
ip4-config: update (commit=1, routes-full-sync=0, new-config=0x1dfca28)
NetworkManager[1635]: <debug> [1490291832.4021] platform: address: adding or
updating IPv4 address: 10.8.49.163/32 lft forever pref forever lifetime
48-0[4294967295,4294967295] dev 3 src unknown
NetworkManager[1635]: <debug> [1490291832.4050] platform-linux:
do-add-ip4-address[3: 10.8.49.163/32]: success
NetworkManager[1635]: <debug> [1490291832.4085] route-mgr4:   3: sync 1 IPv4
routes
NetworkManager[1635]: <debug> [1490291832.4130] platform: route: adding or
updating IPv4 route: 10.8.49.163/32 via 0.0.0.0 dev 3 metric 700 mss 0 src
kernel pref-src 10.8.49.163
NetworkManager[1635]: <debug> [1490291832.4156] platform-linux:
do-add-ip4-route[3: 10.8.49.163/32 700]: success
NetworkManager[1635]: <debug> [1490291832.4194] device[0x1df6340] (ttyMux1):
remove_pending_action (1): 'dhcp4' not pending (expected)
NetworkManager[1635]: <info>  [1490291832.4227] device (ttyMux1): state
change: ip-config -> ip-check (reason 'none') [70 80 0]
NetworkManager[1635]: <debug> [1490291832.4355] firewall:
[0x1e06d60,change*:"ppp0"]: firewall zone change ppp0:default (not running,
simulate success)
NetworkManager[1635]: <debug> [1490291832.4401] device[0x1df6340] (ttyMux1):
activation-stage: complete activate_stage5_ip4_config_commit,2 (id 268)
NetworkManager[1635]: <debug> [1490291832.4745] device[0x1df6340] (ttyMux1):
ip4-config: update (commit=0, routes-full-sync=0, new-config=0x1dfcab0)
NetworkManager[1635]: <debug> [1490291832.4763] default-route:
entry[1/dev:0x1df6340:ttyMux1:1:-sync]: record:update 0.0.0.0/0 via
10.8.49.163 dev 3 metric 700 mss 0 src rt-static scope global (700)
NetworkManager[1635]: <debug> [1490291832.4901] firewall:
[0x1e06d60,change*:"ppp0"]: complete: fake success
NetworkManager[1635]: <debug> [1490291832.4955] dispatcher: (4) (ttyMux1)
dispatching action 'pre-up' (with callback)
NetworkManager[1635]: <debug> [1490291832.5002] dispatcher: (4) simulate
request; no scripts in /etc/NetworkManager/dispatcher.d/pre-up.d
NetworkManager[1635]: <debug> [1490291832.5110] device[0x1df6340] (ttyMux1):
add_pending_action (2): 'queued state change to secondaries'
NetworkManager[1635]: <debug> [1490291832.5163] device[0x1df6340] (ttyMux1):
queued state change to secondaries due to none (id 277)
NetworkManager[1635]: <debug> [1490291832.5211] device[0x1df6340] (ttyMux1):
running queued state change to secondaries (id 277)
NetworkManager[1635]: <info>  [1490291832.5256] device (ttyMux1): state
change: ip-check -> secondaries (reason 'none') [80 90 0]
NetworkManager[1635]: <debug> [1490291832.5405] device[0x1df6340] (ttyMux1):
add_pending_action (3): 'queued state change to activated'
NetworkManager[1635]: <debug> [1490291832.5455] device[0x1df6340] (ttyMux1):
queued state change to activated due to none (id 282)
NetworkManager[1635]: <debug> [1490291832.5504] device[0x1df6340] (ttyMux1):
device entered SECONDARIES state
NetworkManager[1635]: <debug> [1490291832.5550] device[0x1df6340] (ttyMux1):
remove_pending_action (2): 'queued state change to secondaries'
NetworkManager[1635]: <debug> [1490291832.5984] device[0x1df6340] (ttyMux1):
running queued state change to activated (id 282)
NetworkManager[1635]: <info>  [1490291832.6033] device (ttyMux1): state
change: secondaries -> activated (reason 'none') [90 100 0]
NetworkManager[1635]: <debug> [1490291832.6171]
active-connection[0x1dd3140]: set state activated (was activating)
NetworkManager[1635]: <debug> [1490291832.6264]
active-connection[0x1dd3140]: check-master-ready: not signalling (state
activated, no master)
NetworkManager[1635]: <debug> [1490291832.6478] device[0x1df6340] (ttyMux1):
remove_pending_action (1): 'activation::0x1dd3140'
NetworkManager[1635]: <debug> [1490291832.6511] dns-mgr:
(device_state_changed): queueing DNS updates (1)
NetworkManager[1635]: <debug> [1490291832.6513] dns-mgr:
(update_routing_and_dns): queueing DNS updates (2)
NetworkManager[1635]: <debug> [1490291832.6546] dns-mgr:
(update_routing_and_dns): DNS configuration changed
NetworkManager[1635]: <debug> [1490291832.6603] dns-mgr:
(update_routing_and_dns): no DNS changes to commit (1)
NetworkManager[1635]: <debug> [1490291832.6647] dns-mgr:
(device_state_changed): DNS configuration changed
NetworkManager[1635]: <debug> [1490291832.6693] dns-mgr:
(device_state_changed): committing DNS changes (0)
NetworkManager[1635]: <debug> [1490291832.6736] dns-mgr: update-dns:
updating resolv.conf
NetworkManager[1635]: <info>  [1490291832.6785] device (ttyMux1):
Activation: successful, device activated.
NetworkManager[1635]: <debug> [1490291832.6832] device[0x1df6340] (ttyMux1):
set metered value 3
NetworkManager[1635]: <debug> [1490291832.6885] dispatcher: (5) (ttyMux1)
dispatching action 'up'
NetworkManager[1635]: <debug> [1490291832.7045] device[0x1df6340] (ttyMux1):
remove_pending_action (0): 'queued state change to activated'
NetworkManager[1635]: <debug> [1490291832.9171] agent-manager:
req[0x1d93ee0, :1.12/nmcli-connect/0]: agent unregistered or disappeared
NetworkManager[1635]: <debug> [1490291833.1990] dispatcher: (5) ppp-vnstat
succeeded


Non-working BGS2:

NetworkManager[1398]: <debug> [1490292207.1432] agent-manager:
req[0x1f582e0, :1.12/nmcli-connect/0]: requesting permissions
NetworkManager[1398]: <debug> [1490292207.1468] agent-manager:
req[0x1f582e0, :1.12/nmcli-connect/0]: agent registered
NetworkManager[1398]: <debug> [1490292207.1554] policy: re-enabling
autoconnect for all connections with failed secrets
NetworkManager[1398]: <debug> [1490292207.1716]
active-connection[0x1f38140]: set device "ttyMux1" [0x1f54320]
NetworkManager[1398]: <debug> [1490292207.1746] device[0x1f54320] (ttyMux1):
add_pending_action (1): 'activation::0x1f38140'
NetworkManager[1398]: <debug> [1490292207.1777]
active-connection[0x1f38140]: constructed (NMActRequest, version-id 2)
NetworkManager[1398]: <debug> [1490292207.1789] device[0x1f54320] (ttyMux1):
add_pending_action (2): 'autoactivate'
NetworkManager[1398]: <debug> [1490292207.1825] device[0x1f54320] (ttyMux1):
remove_pending_action (1): 'autoactivate'
NetworkManager[1398]: <debug> [1490292207.1834] device[0x1f54320] (ttyMux1):
unmanaged: flags set to
[!sleeping,!loopback,!platform-init,!user-explicit,!user-settings=0x0/0x79/m
anaged, set-managed [user-explicit=0x20], reason user-requested)
NetworkManager[1398]: <info>  [1490292207.1984] device (ttyMux1):
Activation: starting connection 'Vodafone'
(e0f97177-2f8e-4ed4-9942-7b4e499397cc)
NetworkManager[1398]: <debug> [1490292207.2013] device[0x1f54320] (ttyMux1):
activation-stage: schedule activate_stage1_device_prepare,2 (id 186)
NetworkManager[1398]: <debug> [1490292207.2072] create NMAuditManager
singleton (0x1ed8270)
NetworkManager[1398]: <info>  [1490292207.2086] audit:
op="connection-activate" uuid="e0f97177-2f8e-4ed4-9942-7b4e499397cc"
name="Vodafone" pid=1495 uid=0 result="success"
NetworkManager[1398]: <debug> [1490292207.2160] device[0x1f54320] (ttyMux1):
activation-stage: invoke activate_stage1_device_prepare,2 (id 186)
NetworkManager[1398]: <info>  [1490292207.2172] device (ttyMux1): state
change: disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[1398]: <debug> [1490292207.2296]
active-connection[0x1f38140]: set state activating (was unknown)
NetworkManager[1398]: <debug> [1490292207.2328]
active-connection[0x1f38140]: check-master-ready: not signalling (state
activating, no master)
NetworkManager[1398]: <debug> [1490292207.2343] modem-broadband[ttyMux1]:
launching connection with ip type 'ipv4' (try 1)
NetworkManager[1398]: <debug> [1490292207.2423] device[0x1f54320] (ttyMux1):
activation-stage: complete activate_stage1_device_prepare,2 (id 186)
NetworkManager[1398]: <info>  [1490292207.3585] (ttyMux1): modem state
changed, 'registered' --> 'connecting' (reason: user-requested)
NetworkManager[1398]: <info>  [1490292210.0810] (ttyMux1): modem state
changed, 'connecting' --> 'connected' (reason: user-requested)
NetworkManager[1398]: <warn>  [1490292210.1150] device (ttyMux1): failed to
look up interface index
NetworkManager[1398]: <debug> [1490292210.1163] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ttyMux0/disable_ipv6': (2) No such
file or directory
NetworkManager[1398]: <debug> [1490292210.1174] device[0x1f54320] (ttyMux1):
activation-stage: schedule activate_stage2_device_config,2 (id 216)
NetworkManager[1398]: <debug> [1490292210.1238] device[0x1f54320] (ttyMux1):
activation-stage: invoke activate_stage2_device_config,2 (id 216)
NetworkManager[1398]: <info>  [1490292210.1245] device (ttyMux1): state
change: prepare -> config (reason 'none') [40 50 0]
NetworkManager[1398]: <debug> [1490292210.1367] device[0x1f54320] (ttyMux1):
bringing up device
NetworkManager[1398]: <debug> [1490292210.1377] device[0x1f54320] (ttyMux1):
Activation: setting firewall zone 'default'
NetworkManager[1398]: <debug> [1490292210.1385] firewall:
[0x1f58c00,change*:"ttyMux0"]: firewall zone change ttyMux0:default (not
running, simulate success)
NetworkManager[1398]: <debug> [1490292210.1392] device[0x1f54320] (ttyMux1):
activation-stage: complete activate_stage2_device_config,2 (id 216)
NetworkManager[1398]: <debug> [1490292210.1671] firewall:
[0x1f58c00,change*:"ttyMux0"]: complete: fake success
NetworkManager[1398]: <debug> [1490292210.1679] device[0x1f54320] (ttyMux1):
activation-stage: schedule activate_stage3_ip_config_start,2 (id 222)
NetworkManager[1398]: <debug> [1490292210.1687] device[0x1f54320] (ttyMux1):
activation-stage: invoke activate_stage3_ip_config_start,2 (id 222)
NetworkManager[1398]: <info>  [1490292210.1693] device (ttyMux1): state
change: config -> ip-config (reason 'none') [50 70 0]
NetworkManager[1398]: <warn>  [1490292210.1817] device (ttyMux1): interface
ttyMux0 not up for IP configuration
NetworkManager[1398]: <debug> [1490292210.1824] ip4_config_start
NetworkManager[1398]: <info>  [1490292210.1831] (ttyMux1): using
modem-specified IP timeout: 20 seconds
NetworkManager[1398]: <info>  [1490292210.1932] ppp-manager: starting PPP
connection
NetworkManager[1398]: <debug> [1490292210.1952] 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
NetworkManager[1398]: <info>  [1490292210.2229] ppp-manager: pppd started
with pid 1504
NetworkManager[1398]: <debug> [1490292210.2234] device[0x1f54320] (ttyMux1):
activation-stage: complete activate_stage3_ip_config_start,2 (id 222)
Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase
'serial connection'
using channel 1
NetworkManager[1398]: <debug> [1490292210.4535] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292210.4543] ethtool: Request failed:
Operation not supported
Using interface ppp0
Connect: ppp0 <--> /dev/ttyMux0
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase
'establish'
NetworkManager[1398]: <debug> [1490292210.4583] platform: signal: link
added: 3: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512
unknown? not-init driver unknown rx:0,0 tx:0,0
NetworkManager[1398]: <debug> [1490292210.4592] device[0x1f18698] (ppp0):
unmanaged: flags set to
[platform-init,by-default=0x110/0x110/unmanaged/unrealized, set-unmanaged
[by-default=0x100])
NetworkManager[1398]: <debug> [1490292210.4602] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292210.4611] mii: SIOCGMIIPHY failed:
Invalid argument (22) (ppp0)
NetworkManager[1398]: <debug> [1490292210.4620] mii: MII not supported
(ppp0)sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xe1c5e623> <pcomp>
<accomp>]

NetworkManager[1398]: <debug> [1490292210.4687] device[0x1f18698] (ppp0):
constructed (NMDeviceGeneric)
NetworkManager[1398]: <debug> [1490292210.4734] device[0x1f18698] (ppp0):
start setup of NMDeviceGeneric, kernel ifindex 3
NetworkManager[1398]: <debug> [1490292210.4887] 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
rcvd [LCP ConfNak id=0x1 <asyncmap 0xa0000>]
NetworkManager[1398]: <debug> [1490292210.5026] platform-linux: sysctl:
reading '/sys/class/net/ppp0/dev_id': '0x0'
sent [LCP ConfReq id=0x2 <asyncmap 0xa0000> <magic 0xe1c5e623> <pcomp>
<accomp>]
NetworkManager[1398]: <debug> [1490292210.5148] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292210.5250] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292210.5445] mii: SIOCGMIIPHY failed:
Invalid argument (22) (ppp0)
rcvd [LCP ConfAck id=0x2 <asyncmap 0xa0000> <magic 0xe1c5e623> <pcomp>
<accomp>]
NetworkManager[1398]: <debug> [1490292210.5655] mii: MII not supported
(ppp0)
NetworkManager[1398]: <debug> [1490292210.5764] device[0x1f18698] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1398]: <debug> [1490292210.6000] device[0x1f18698] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1398]: <debug> [1490292210.6073] device[0x1f18698] (ppp0):
unmanaged: flags set to
[platform-init,by-default,!loopback=0x110/0x118/unmanaged/unrealized,
set-managed [loopback=0x8])
NetworkManager[1398]: <debug> [1490292210.6241] device[0x1f18698] (ppp0):
unmanaged: flags set to
[platform-init,by-default,!loopback,!user-settings=0x110/0x158/unmanaged/unr
ealized, set-managed [user-settings=0x40])
NetworkManager[1398]: <debug> [1490292210.6500] device[0x1f18698] (ppp0):
unmanaged: flags set to
[platform-init,by-default,!sleeping,!loopback,!user-settings=0x110/0x159/unm
anaged/unrealized, set-managed [sleeping=0x1])
NetworkManager[1398]: <info>  [1490292210.6878] manager: (ppp0): new Generic
device (/org/freedesktop/NetworkManager/Devices/3)
NetworkManager[1398]: <debug> [1490292210.7363] device[0x1f18698] (ppp0):
ip4-config: update (commit=0, routes-full-sync=0, new-config=0x1ef91a0)
NetworkManager[1398]: <debug> [1490292210.7498] device[0x1f18698] (ppp0):
ip4-config: set IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
NetworkManager[1398]: <debug> [1490292210.7511] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292210.7543] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292210.7592] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
NetworkManager[1398]: <debug> [1490292210.7648] device[0x1f18698] (ppp0):
ip6-config: update (commit=0, routes-full-sync=0, new-config=0x1ed6460)
NetworkManager[1398]: <debug> [1490292210.7814] device[0x1f18698] (ppp0):
ip6-config: set IP6Config instance
(/org/freedesktop/NetworkManager/IP6Config/2)
NetworkManager[1398]: <debug> [1490292210.7826] dns-mgr:
(device_ip6_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292210.7887] dns-mgr:
(device_ip6_config_changed): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292210.7940] dns-mgr:
(device_ip6_config_changed): no DNS changes to commit (0)
NetworkManager[1398]: <debug> [1490292210.8030] device[0x1f18698] (ppp0):
emit RECHECK_ASSUME signal
NetworkManager[1398]: <debug> [1490292210.9502] platform-linux: UDEV event:
action 'add' subsys 'net' device 'ppp0' (3); seqnum=1132
NetworkManager[1398]: <debug> [1490292210.9510] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292210.9513] platform: signal: link
changed: 3: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512
unknown? init driver unknown rx:0,0 tx:0,0
NetworkManager[1398]: <debug> [1490292210.9516] device[0x1f18698] (ppp0):
queued link change for ifindex 3
NetworkManager[1398]: <info>  [1490292210.9521] devices added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0)
NetworkManager[1398]: <info>  [1490292210.9522] device added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration
found.
NetworkManager[1398]: <debug> [1490292210.9530] device[0x1f18698] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1398]: <debug> [1490292210.9532] device[0x1f18698] (ppp0):
hw-addr: failed reading current MAC address
NetworkManager[1398]: <debug> [1490292210.9629] device[0x1f18698] (ppp0):
unmanaged: flags set to
[by-default,!sleeping,!loopback,!platform-init,!user-settings=0x100/0x159/ma
nageable, set-managed [platform-init=0x10], reason managed)
rcvd [LCP ConfReq id=0x3 <asyncmap 0xa0000> <pcomp> <accomp> <magic
0x22dadf9b> <auth chap MD5>]
sent [LCP ConfAck id=0x3 <asyncmap 0xa0000> <pcomp> <accomp> <magic
0x22dadf9b> <auth chap MD5>]
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase
'authenticate'
rcvd [CHAP Challenge id=0x1 <6ca6fd2be8ebeca4ca174204142aff4ac4242378>, name
= ""]
nm-pppd-plugin-Message: nm-ppp-plugin: (get_credentials): passwd-hook,
requesting credentials...
nm-pppd-plugin-Message: nm-ppp-plugin: (get_credentials): got credentials
from NetworkManager
sent [CHAP Response id=0x1 <10bcdacd0495260c675db85a9677f7d2>, name = ""]
rcvd [CHAP Success id=0x1 ""]
CHAP authentication succeeded
CHAP authentication succeeded
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase
'network'
kernel does not support PPP filtering
sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
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>]
rcvd [LCP ProtRej id=0x4 80 fd 01 01 00 0f 1a 04]
Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
rcvd [IPCP ConfReq id=0x1 <addr 192.168.254.254>]
sent [IPCP ConfAck id=0x1 <addr 192.168.254.254>]
rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2
0.0.0.0>]
rcvd [IPCP ConfNak id=0x2 <addr 10.8.49.163> <ms-dns1 10.206.128.1> <ms-dns2
10.206.128.1>]
sent [IPCP ConfReq id=0x3 <addr 10.8.49.163> <ms-dns1 10.206.128.1> <ms-dns2
10.206.128.1>]
rcvd [IPCP ConfAck id=0x3 <addr 10.8.49.163> <ms-dns1 10.206.128.1> <ms-dns2
10.206.128.1>]
NetworkManager[1398]: <debug> [1490292213.4744] platform: signal: address 4
added: 10.8.49.163/32 lft forever pref forever lifetime
73-0[4294967295,4294967295] dev 3 flags permanent src kernel
NetworkManager[1398]: <debug> [1490292213.4747] default-route: resync:
schedule on idle
NetworkManager[1398]: <debug> [1490292213.4749] device[0x1f18698] (ppp0):
queued IP4 config change
NetworkManager[1398]: <debug> [1490292213.4758] device[0x1f18698] (ppp0):
ip4-config: update (commit=0, routes-full-sync=0, new-config=0x1ef92b0)
NetworkManager[1398]: <debug> [1490292213.4769] device[0x1f18698] (ppp0):
ip4-config: update IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
NetworkManager[1398]: <debug> [1490292213.4775] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292213.4777] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292213.4779] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
local  IP address 10.8.49.163
NetworkManager[1398]: <debug> [1490292213.5134] platform: signal: address 4
removed: 10.8.49.163/32 lft forever pref forever lifetime
73-0[4294967295,4294967295] dev 3 flags permanent src kernel
remote IP address 192.168.254.254
NetworkManager[1398]: <debug> [1490292213.5319] device[0x1f18698] (ppp0):
queued IP4 config change
primary   DNS address 10.206.128.1
NetworkManager[1398]: <debug> [1490292213.5456] platform: signal: address 4
added: 10.8.49.163/32 lft forever pref forever lifetime
73-0[4294967295,4294967295] ptp 192.168.254.254 dev 3 flags permanent src
kernel
secondary DNS address 10.206.128.1
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase
'running'
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): ip-up event
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): sending IPv4 config to
NetworkManager...
NetworkManager[1398]: <debug> [1490292213.5654] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292213.5703] ethtool: Request failed:
Operation not supported
NetworkManager[1398]: <debug> [1490292213.5754] platform: signal: link
changed: 3: 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
NetworkManager[1398]: <debug> [1490292213.5799] device[0x1f18698] (ppp0):
queued link change for ifindex 3
NetworkManager[1398]: <debug> [1490292213.5848] platform: signal: route   4
added: 192.168.254.254/32 via 0.0.0.0 dev 3 metric 0 mss 0 src rt-kernel
scope link pref-src 10.8.49.163
NetworkManager[1398]: <info>  [1490292213.5898] ppp-manager: (IPv4 Config
Get) reply received.
NetworkManager[1398]: <debug> [1490292213.5978] manager: (ppp0): removing
device (allow_unmanage 0, managed 0)
NetworkManager[1398]: <debug> [1490292213.6006] device[0x1f18698] (ppp0):
ip4-config: update (commit=0, routes-full-sync=0, new-config=(nil))
NetworkManager[1398]: <debug> [1490292213.6035] device[0x1f18698] (ppp0):
ip4-config: clear IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/2)
NetworkManager[1398]: <debug> [1490292213.6067] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292213.6095] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292213.6120] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
NetworkManager[1398]: <debug> [1490292213.6160] device[0x1f18698] (ppp0):
ip6-config: update (commit=0, routes-full-sync=0, new-config=(nil))
NetworkManager[1398]: <debug> [1490292213.6196] device[0x1f18698] (ppp0):
ip6-config: clear IP6Config instance
(/org/freedesktop/NetworkManager/IP6Config/2)
NetworkManager[1398]: <debug> [1490292213.6226] dns-mgr:
(device_ip6_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292213.6254] dns-mgr:
(device_ip6_config_changed): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292213.6282] dns-mgr:
(device_ip6_config_changed): no DNS changes to commit (0)
NetworkManager[1398]: <debug> [1490292213.6408] device[0x1f18698] (ppp0):
disposing
NetworkManager[1398]: <debug> [1490292213.6417] device[0x1f18698] (ppp0):
clearing queued IP4 config change
NetworkManager[1398]: <debug> [1490292213.6445] device[0x1f18698] (ppp0):
remove_pending_action (0): 'dhcp6' not pending (expected)
NetworkManager[1398]: <debug> [1490292213.6471] device[0x1f18698] (ppp0):
remove_pending_action (0): 'autoconf6' not pending (expected)
NetworkManager[1398]: <debug> [1490292213.6496] device[0x1f18698] (ppp0):
ip4-config: update (commit=1, routes-full-sync=1, new-config=(nil))
NetworkManager[1398]: <debug> [1490292213.6520] device[0x1f18698] (ppp0):
ip6-config: update (commit=1, routes-full-sync=1, new-config=(nil))
NetworkManager[1398]: <debug> [1490292213.6552] device[0x1f18698] (ppp0):
finalize(): NMDeviceGeneric
NetworkManager[1398]: <debug> [1490292213.6582] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file
or directory
NetworkManager[1398]: <debug> [1490292213.6614] device[0x1f54320] (ttyMux1):
ip4-config: update (commit=1, routes-full-sync=1, new-config=0x1ef93c0)
NetworkManager[1398]: <debug> [1490292213.6641] platform: address: adding or
updating IPv4 address: 10.8.49.163/32 lft forever pref forever lifetime
73-0[4294967295,4294967295] ptp 192.168.254.254 dev 3 src unknown
NetworkManager[1398]: <debug> [1490292213.6672] platform-linux:
do-add-ip4-address[3: 10.8.49.163/32,192.168.254.254]: success
NetworkManager[1398]: <debug> [1490292213.6707] route-mgr4:   3: sync 1 IPv4
routes
NetworkManager[1398]: <debug> [1490292213.6756] platform: route: deleting
IPv4 route 192.168.254.254/32, metric=0, ifindex 3 dev ppp0
NetworkManager[1398]: <debug> [1490292213.6785] platform: signal: route   4
removed: 192.168.254.254/32 via 0.0.0.0 dev 3 metric 0 mss 0 src rt-kernel
scope link pref-src 10.8.49.163
NetworkManager[1398]: <debug> [1490292213.6818] device[0x1f54320] (ttyMux1):
queued IP4 config change
NetworkManager[1398]: <debug> [1490292213.6845] platform-linux:
do-delete-ip4-route[3: 192.168.254.254/32 0]: success
NetworkManager[1398]: <debug> [1490292213.6872] platform: route: adding or
updating IPv4 route: 192.168.254.254/32 via 0.0.0.0 dev 3 metric 700 mss 0
src kernel pref-src 10.8.49.163
NetworkManager[1398]: <debug> [1490292213.6901] platform: signal: route   4
added: 192.168.254.254/32 via 0.0.0.0 dev 3 metric 700 mss 0 src rt-kernel
scope link pref-src 10.8.49.163
NetworkManager[1398]: <debug> [1490292213.6931] platform-linux:
do-add-ip4-route[3: 192.168.254.254/32 700]: success
NetworkManager[1398]: <debug> [1490292213.7059] device[0x1f54320] (ttyMux1):
ip4-config: set IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/3)
NetworkManager[1398]: <debug> [1490292213.7080] default-route:
entry[1/dev:0x1f54320:ttyMux1:1:+sync]: record:add    0.0.0.0/0 via
192.168.254.254 dev 3 metric 700 mss 0 src user (700)
NetworkManager[1398]: <debug> [1490292213.7088] default-route: resync:
cancelled (264)
NetworkManager[1398]: <debug> [1490292213.7123] default-route:
entry[1/dev:0x1f54320:ttyMux1:1:+sync]: sync:add    0.0.0.0/0 via
192.168.254.254 dev 3 metric 700 mss 0 src user (700)
NetworkManager[1398]: <debug> [1490292213.7151] platform: route: adding or
updating IPv4 route: 0.0.0.0/0 via 192.168.254.254 dev 3 metric 700 mss 0
src user
NetworkManager[1398]: <debug> [1490292213.7181] platform: signal: route   4
added: 0.0.0.0/0 via 192.168.254.254 dev 3 metric 700 mss 0 src rt-static
scope global
NetworkManager[1398]: <debug> [1490292213.7211] platform-linux:
do-add-ip4-route[3: 0.0.0.0/0 700]: success
NetworkManager[1398]: <debug> [1490292213.7241] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292213.7296] dns-mgr:
(device_ip4_config_changed): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292213.7390] dns-mgr:
(device_ip4_config_changed): no DNS changes to commit (0)
NetworkManager[1398]: <debug> [1490292213.7481] device[0x1f54320] (ttyMux1):
activation-stage: schedule activate_stage5_ip4_config_commit,2 (id 273)
NetworkManager[1398]: <debug> [1490292213.7577] device[0x1f54320] (ttyMux1):
activation-stage: invoke activate_stage5_ip4_config_commit,2 (id 273)
NetworkManager[1398]: <debug> [1490292213.7880] device[0x1f54320] (ttyMux1):
ip4-config: update (commit=1, routes-full-sync=0, new-config=0x1ef9228)
NetworkManager[1398]: <debug> [1490292213.7939] platform: address: adding or
updating IPv4 address: 10.8.49.163/32 lft forever pref forever lifetime
73-0[4294967295,4294967295] ptp 192.168.254.254 dev 3 src unknown
NetworkManager[1398]: <debug> [1490292213.7981] platform-linux:
do-add-ip4-address[3: 10.8.49.163/32,192.168.254.254]: success
NetworkManager[1398]: <debug> [1490292213.8036] route-mgr4:   3: sync 1 IPv4
routes
NetworkManager[1398]: <debug> [1490292213.8077] platform: route: adding or
updating IPv4 route: 192.168.254.254/32 via 0.0.0.0 dev 3 metric 700 mss 0
src kernel pref-src 10.8.49.163
NetworkManager[1398]: <debug> [1490292213.8115] platform-linux:
do-add-ip4-route[3: 192.168.254.254/32 700]: success
NetworkManager[1398]: <debug> [1490292213.8165] device[0x1f54320] (ttyMux1):
remove_pending_action (1): 'dhcp4' not pending (expected)
NetworkManager[1398]: <info>  [1490292213.8212] device (ttyMux1): state
change: ip-config -> ip-check (reason 'none') [70 80 0]
NetworkManager[1398]: <debug> [1490292213.8351] firewall:
[0x1f6afc0,change*:"ppp0"]: firewall zone change ppp0:default (not running,
simulate success)
NetworkManager[1398]: <debug> [1490292213.8419] device[0x1f54320] (ttyMux1):
activation-stage: complete activate_stage5_ip4_config_commit,2 (id 273)
NetworkManager[1398]: <debug> [1490292213.8759] device[0x1f54320] (ttyMux1):
ip4-config: update (commit=0, routes-full-sync=0, new-config=0x1ef92b0)
NetworkManager[1398]: <debug> [1490292213.8790] default-route:
entry[1/dev:0x1f54320:ttyMux1:1:-sync]: record:update 0.0.0.0/0 via
192.168.254.254 dev 3 metric 700 mss 0 src rt-static scope global (700)
NetworkManager[1398]: <debug> [1490292213.8922] firewall:
[0x1f6afc0,change*:"ppp0"]: complete: fake success
NetworkManager[1398]: <debug> [1490292213.8975] dispatcher: (4) (ttyMux1)
dispatching action 'pre-up' (with callback)
NetworkManager[1398]: <debug> [1490292213.9023] dispatcher: (4) simulate
request; no scripts in /etc/NetworkManager/dispatcher.d/pre-up.d
NetworkManager[1398]: <debug> [1490292213.9134] device[0x1f54320] (ttyMux1):
add_pending_action (2): 'queued state change to secondaries'
NetworkManager[1398]: <debug> [1490292213.9186] device[0x1f54320] (ttyMux1):
queued state change to secondaries due to none (id 282)
NetworkManager[1398]: <debug> [1490292213.9238] device[0x1f54320] (ttyMux1):
running queued state change to secondaries (id 282)
NetworkManager[1398]: <info>  [1490292213.9286] device (ttyMux1): state
change: ip-check -> secondaries (reason 'none') [80 90 0]
NetworkManager[1398]: <debug> [1490292213.9424] device[0x1f54320] (ttyMux1):
add_pending_action (3): 'queued state change to activated'
NetworkManager[1398]: <debug> [1490292213.9478] device[0x1f54320] (ttyMux1):
queued state change to activated due to none (id 287)
NetworkManager[1398]: <debug> [1490292213.9532] device[0x1f54320] (ttyMux1):
device entered SECONDARIES state
NetworkManager[1398]: <debug> [1490292213.9715] device[0x1f54320] (ttyMux1):
remove_pending_action (2): 'queued state change to secondaries'
NetworkManager[1398]: <debug> [1490292214.0025] device[0x1f54320] (ttyMux1):
running queued state change to activated (id 287)
NetworkManager[1398]: <info>  [1490292214.0097] device (ttyMux1): state
change: secondaries -> activated (reason 'none') [90 100 0]
NetworkManager[1398]: <debug> [1490292214.0234]
active-connection[0x1f38140]: set state activated (was activating)
NetworkManager[1398]: <debug> [1490292214.0288]
active-connection[0x1f38140]: check-master-ready: not signalling (state
activated, no master)
NetworkManager[1398]: <debug> [1490292214.2163] device[0x1f54320] (ttyMux1):
remove_pending_action (1): 'activation::0x1f38140'
NetworkManager[1398]: <debug> [1490292214.2193] dns-mgr:
(device_state_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292214.2196] dns-mgr:
(update_routing_and_dns): queueing DNS updates (2)
NetworkManager[1398]: <debug> [1490292214.2198] dns-mgr:
(update_routing_and_dns): DNS configuration changed
NetworkManager[1398]: <debug> [1490292214.2199] dns-mgr:
(update_routing_and_dns): no DNS changes to commit (1)
NetworkManager[1398]: <debug> [1490292214.2201] dns-mgr:
(device_state_changed): DNS configuration changed
NetworkManager[1398]: <debug> [1490292214.2202] dns-mgr:
(device_state_changed): committing DNS changes (0)
NetworkManager[1398]: <debug> [1490292214.2203] dns-mgr: update-dns:
updating resolv.conf
NetworkManager[1398]: <info>  [1490292214.2211] device (ttyMux1):
Activation: successful, device activated.
NetworkManager[1398]: <debug> [1490292214.2213] device[0x1f54320] (ttyMux1):
set metered value 3
NetworkManager[1398]: <debug> [1490292214.2218] dispatcher: (5) (ttyMux1)
dispatching action 'up'
NetworkManager[1398]: <debug> [1490292214.2443] device[0x1f54320] (ttyMux1):
remove_pending_action (0): 'queued state change to activated'
NetworkManager[1398]: <debug> [1490292214.4507] agent-manager:
req[0x1f582e0, :1.12/nmcli-connect/0]: agent unregistered or disappeared
NetworkManager[1398]: <debug> [1490292214.7115] dispatcher: (5) ppp-vnstat
succeeded

{**** this seems to be the point at which the logs start to differ ****}

NetworkManager[1398]: <info>  [1490292215.0368] (ttyMux1): modem state
changed, 'connected' --> 'registered' (reason: user-requested)
NetworkManager[1398]: <info>  [1490292215.0371] device (ttyMux1): state
change: activated -> failed (reason 'modem-no-carrier') [100 120 25]
NetworkManager[1398]: <debug> [1490292215.0390]
active-connection[0x1f38140]: set state deactivated (was activated)
NetworkManager[1398]: <debug> [1490292215.0395]
active-connection[0x1f38140]: check-master-ready: not signalling (state
deactivated, no master)
Terminating on signal 15
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase
'terminate'
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase
'network'
Connect time 0.1 minutes.
Sent 0 bytes, received 0 bytes.
NetworkManager[1398]: <debug> [1490292215.0872] kill child process 'pppd'
(1504): wait for process to terminate after sending SIGTERM (15) (send
SIGKILL in 2000 milliseconds)...nm-pppd-plugin-Message: nm-ppp-plugin:
(nm_phasechange): status 5 / phase 'establish'

NetworkManager[1398]: <debug> [1490292215.1059] modem-broadband[ttyMux1]:
notifying ModemManager about the modem disconnection
sent [LCP TermReq id=0x3 "User request"]
NetworkManager[1398]: <debug> [1490292215.1241] policy: connection
'Vodafone' failed to autoconnect; 4 tries left
NetworkManager[1398]: <warn>  [1490292215.1421] device (ttyMux1):
Activation: failed for connection 'Vodafone'
rcvd [LCP TermAck id=0x3 "User request"]
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 11 / phase
'disconnect'
NetworkManager[1398]: <debug> [1490292215.1559] device[0x1f54320] (ttyMux1):
add_pending_action (1): 'queued state change to disconnected'
Connection terminated.
NetworkManager[1398]: <debug> [1490292215.1860] device[0x1f54320] (ttyMux1):
queued state change to disconnected due to none (id 315)
NetworkManager[1398]: <debug> [1490292215.1962] dispatcher: (6) (ttyMux1)
dispatching action 'down'
NetworkManager[1398]: <debug> [1490292215.2176] platform: signal: link
changed: 3: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512
unknown? init driver unknown rx:4,64 tx:5,97
NetworkManager[1398]: <debug> [1490292215.2305] device[0x1f54320] (ttyMux1):
queued link change for ip-ifindex 3
NetworkManager[1398]: <debug> [1490292215.2427] platform: signal: address 4
removed: 10.8.49.163/32 lft forever pref forever lifetime
75-0[4294967295,4294967295] ptp 192.168.254.254 dev 3 flags permanent src
kernel
NetworkManager[1398]: <debug> [1490292215.2673] default-route: resync:
schedule on idle
NetworkManager[1398]: <debug> [1490292215.2893] device[0x1f54320] (ttyMux1):
queued IP4 config change
NetworkManager[1398]: <debug> [1490292215.3128] platform: signal: link
removed: 3: ppp0 <NOARP,DOWN;pointopoint,multicast,noarp> mtu 1500 arp 512
unknown? not-init rx:4,64 tx:5,97
NetworkManager[1398]: <debug> [1490292215.3427] platform: signal: route   4
removed: 0.0.0.0/0 via 192.168.254.254 dev 3 metric 700 mss 0 src rt-static
scope global
NetworkManager[1398]: <debug> [1490292215.3741] platform: signal: route   4
removed: 192.168.254.254/32 via 0.0.0.0 dev 3 metric 700 mss 0 src rt-kernel
scope link pref-src 10.8.49.163
NetworkManager[1398]: <debug> [1490292215.3890] platform-linux: UDEV event:
action 'remove' subsys 'net' device 'ppp0' (3); seqnum=1141
NetworkManager[1398]: <debug> [1490292215.4176] platform-linux: udev-remove:
IFINDEX=3
NetworkManager[1398]: <info>  [1490292215.4227] devices removed (path:
/sys/devices/virtual/net/ppp0, iface: ppp0)
NetworkManager[1398]: <debug> [1490292215.4400] device[0x1f54320] (ttyMux1):
running queued state change to disconnected (id 315)
NetworkManager[1398]: <info>  [1490292215.4547] device (ttyMux1): state
change: failed -> disconnected (reason 'none') [120 30 0]
NetworkManager[1398]: <debug> [1490292215.4594] device[0x1f54320] (ttyMux1):
deactivating device (reason 'none') [0]
NetworkManager[1398]: <debug> [1490292215.4639] firewall:
[0x1f407a0,remove*:"ppp0"]: firewall zone remove ppp0:default (not running,
simulate success)
NetworkManager[1398]: <debug> [1490292215.4688] firewall:
[0x1f407a0,remove*:"ppp0"]: complete: drop request simulating success
NetworkManager[1398]: <debug> [1490292215.4736] device[0x1f54320] (ttyMux1):
clearing queued IP4 config change
NetworkManager[1398]: <debug> [1490292215.4786] device[0x1f54320] (ttyMux1):
remove_pending_action (1): 'dhcp6' not pending (expected)
NetworkManager[1398]: <debug> [1490292215.4831] device[0x1f54320] (ttyMux1):
remove_pending_action (1): 'autoconf6' not pending (expected)
NetworkManager[1398]: <debug> [1490292215.4880] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ppp0/disable_ipv6': (2) No such file
or directory
NetworkManager[1398]: <debug> [1490292215.4926] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ppp0/accept_ra': (2) No such file or
directory
NetworkManager[1398]: <debug> [1490292215.4976] platform-linux: sysctl:
failed to open '/proc/sys/net/ipv6/conf/ppp0/use_tempaddr': (2) No such file
or directory
NetworkManager[1398]: <debug> [1490292215.5021] modem-broadband[ttyMux1]:
notifying ModemManager about the modem disconnection
NetworkManager[1398]: <debug> [1490292215.5094] route-mgr4:   3: sync 0 IPv4
routes
NetworkManager[1398]: <debug> [1490292215.5332] route-mgr6:   3: sync 0 IPv6
routes
NetworkManager[1398]: <debug> [1490292215.5389] device[0x1f54320] (ttyMux1):
set metered value 0
NetworkManager[1398]: <debug> [1490292215.5520] default-route:
entry[1/dev:0x1f54320:ttyMux1:0:+sync]: record:update 0.0.0.0/0 via 0.0.0.0
dev 3 metric 4294967295 mss 0 src unknown (700)
NetworkManager[1398]: <debug> [1490292215.5568] default-route: resync:
cancelled (321)
NetworkManager[1398]: <debug> [1490292215.5613] default-route:
entry[0/dev:0x1f54320:ttyMux1:0:+sync]: record:add    ::/0 via :: dev 3
metric 4294967295 mss 0 src unknown (4294967295)
NetworkManager[1398]: <debug> [1490292215.5661] default-route:
entry[1/dev:0x1f54320:ttyMux1:0:+sync]: record:remove 0.0.0.0/0 via 0.0.0.0
dev 3 metric 4294967295 mss 0 src unknown (700)
NetworkManager[1398]: <debug> [1490292215.5707] default-route:
entry[0/dev:0x1f54320:ttyMux1:0:+sync]: record:remove ::/0 via :: dev 3
metric 4294967295 mss 0 src unknown (4294967295)
NetworkManager[1398]: <debug> [1490292215.5753] device[0x1f54320] (ttyMux1):
ip4-config: update (commit=1, routes-full-sync=1, new-config=(nil))
NetworkManager[1398]: <debug> [1490292215.5801] device[0x1f54320] (ttyMux1):
ip4-config: clear IP4Config instance
(/org/freedesktop/NetworkManager/IP4Config/3)
NetworkManager[1398]: <debug> [1490292215.5852] dns-mgr:
(device_ip4_config_changed): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292215.5900] dns-mgr:
(device_ip4_config_changed): DNS configuration changed
NetworkManager[1398]: <debug> [1490292215.5944] dns-mgr:
(device_ip4_config_changed): committing DNS changes (0)
NetworkManager[1398]: <debug> [1490292215.5990] dns-mgr: update-dns:
updating resolv.conf
NetworkManager[1398]: <debug> [1490292215.6060] device[0x1f54320] (ttyMux1):
ip6-config: update (commit=1, routes-full-sync=1, new-config=(nil))
NetworkManager[1398]: <debug> [1490292215.6124] dns-mgr:
(update_routing_and_dns): queueing DNS updates (1)
NetworkManager[1398]: <debug> [1490292215.6158] dns-mgr:
(update_routing_and_dns): DNS configuration did not change
NetworkManager[1398]: <debug> [1490292215.6189] dns-mgr:
(update_routing_and_dns): no DNS changes to commit (0)
NetworkManager[1398]: <debug> [1490292215.6214] device[0x1f54320] (ttyMux1):
add_pending_action (2): 'autoactivate'
NetworkManager[1398]: <debug> [1490292215.6240]
active-connection[0x1f38140]: disposing
NetworkManager[1398]: <debug> [1490292215.6286] device[0x1f54320] (ttyMux1):
remove_pending_action (1): 'queued state change to disconnected'
NetworkManager[1398]: <debug> [1490292215.6333] dispatcher: (6) ppp-vnstat
succeeded
NetworkManager[1398]: <debug> [1490292215.6448] device[0x1f54320] (ttyMux1):
remove_pending_action (0): 'autoactivate'
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase
'dead'
nm-pppd-plugin-Message: nm-ppp-plugin: (nm_exit_notify): cleaning up
NetworkManager[1398]: <debug> [1490292216.2145] kill child process 'pppd'
(1504): terminated normally with status 5 (1127309 usec elapsed)