Re: system-connection for WWAN not working

[van Schelve <public van-schelve de>]

Dan, Eugene.

I have captured the debug from this connection while not available as
system-connection. It works in this case as you can see:

NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: <info>  (ttyUSB2): new GSM device (driver: 'sierra')
NetworkManager: <info>  (ttyUSB2): exported as
/org/freedesktop/NetworkManager/Devices/3
NetworkManager: <info>  (ttyUSB2): now managed
NetworkManager: <info>  (ttyUSB2): device state change: 1 -> 2 (reason 2)
NetworkManager: <info>  (ttyUSB2): deactivating device (reason: 2).
NetworkManager: flush_routes: assertion `iface_idx >= 0' failed
NetworkManager: flush_addresses: assertion `iface_idx >= 0' failed
NetworkManager: <info>  (ttyUSB2): device state change: 2 -> 3 (reason 0)
NetworkManager: <info>  Activation (ttyUSB2) starting connection 'MyWWAN'
NetworkManager: <info>  (ttyUSB2): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (ttyUSB2) Stage 1 of 5 (Device Prepare)
scheduled...
NetworkManager: <info>  Activation (ttyUSB2) Stage 1 of 5 (Device Prepare)
started...
NetworkManager: <info>  (ttyUSB2): device state change: 4 -> 6 (reason 0)
NetworkManager: <info>  Activation (ttyUSB2) Stage 1 of 5 (Device Prepare)
complete.
NetworkManager: <info>  Activation (ttyUSB2) Stage 1 of 5 (Device Prepare)
scheduled...
NetworkManager: <info>  Activation (ttyUSB2) Stage 1 of 5 (Device Prepare)
started...
NetworkManager: <info>  (ttyUSB2): device state change: 6 -> 4 (reason 0)
NetworkManager: <info>  Activation (ttyUSB2) Stage 1 of 5 (Device Prepare)
complete.
NetworkManager: <info>  Activation (ttyUSB2) Stage 2 of 5 (Device
Configure) scheduled...
NetworkManager: <info>  Activation (ttyUSB2) Stage 2 of 5 (Device
Configure) starting...
NetworkManager: <info>  (ttyUSB2): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (ttyUSB2) Stage 2 of 5 (Device
Configure) successful.
NetworkManager: <info>  Activation (ttyUSB2) Stage 3 of 5 (IP Configure
Start) scheduled.
NetworkManager: <info>  Activation (ttyUSB2) Stage 2 of 5 (Device
Configure) complete.
NetworkManager: <info>  Activation (ttyUSB2) Stage 3 of 5 (IP Configure
Start) started...
NetworkManager: <info>  (ttyUSB2): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Starting pppd connection
NetworkManager: <debug> [1258531195.240804] nm_ppp_manager_start():
Command line: /usr/sbin/pppd nodetach lock nodefaultroute debug user
username ttyUSB2 noipdefault noauth usepeerdns lcp-echo-failure 0
lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/0 plugin
/usr/lib/pppd/2.4.4/nm-pppd-plugin.so
Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
** Message: nm-ppp-plugin: (plugin_init): initializing
NetworkManager: <debug> [1258531195.258102] nm_ppp_manager_start(): ppp
started with pid 9331
NetworkManager: <info>  Activation (ttyUSB2) Stage 4 of 5 (IP6 Configure
Get) scheduled...
NetworkManager: <info>  Activation (ttyUSB2) Stage 3 of 5 (IP Configure
Start) complete.
NetworkManager: <info>  Activation (ttyUSB2) Stage 4 of 5 (IP6 Configure
Get) started...
NetworkManager: <info>  Activation (ttyUSB2) Stage 4 of 5 (IP6 Configure
Get) complete.
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial
connection'
Removed stale lock on ttyUSB2 (pid 9216)
using channel 7
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB2
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd8437790> <pcomp>
<accomp>]
NetworkManager:    SCPlugin-Ifupdown: devices added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0)
NetworkManager:    SCPlugin-Ifupdown: device added (path:
/sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration
found.
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xc4897c>
<pcomp> <accomp>]
sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xc4897c>
<pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xd8437790> <pcomp>
<accomp>]
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase
'authenticate'
rcvd [LCP DiscReq id=0x1 magic=0xc4897c]
rcvd [CHAP Challenge id=0x1 <7e969b37b646b5c728bd354e34b515aa>, name =
"UMTS_CHAP_SRVR"]
** Message: nm-ppp-plugin: (get_credentials): passwd-hook, requesting
credentials...
** Message: nm-ppp-plugin: (get_credentials): got credentials from
NetworkManager
sent [CHAP Response id=0x1 <332d24b44f6834bd0ecc62af3b7fd0d6>, name =
"username"]
rcvd [CHAP Success id=0x1 ""]
CHAP authentication succeeded
CHAP authentication succeeded
** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2
0.0.0.0>]
rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03
2f]
Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
rcvd [IPCP ConfNak id=0x1 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2
10.11.12.14>]
rcvd [IPCP ConfNak id=0x2 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x3 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2
10.11.12.14>]
rcvd [IPCP ConfNak id=0x3 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x4 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2
10.11.12.14>]
rcvd [IPCP ConfNak id=0x4 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x5 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2
10.11.12.14>]
rcvd [IPCP ConfNak id=0x5 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x6 <addr 0.0.0.0>]
rcvd [IPCP ConfNak id=0x6 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x7 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2
10.11.12.14>]
rcvd [IPCP ConfNak id=0x7 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
sent [IPCP ConfReq id=0x8 <addr 0.0.0.0>]
rcvd [IPCP ConfReq id=0x0]
sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
rcvd [IPCP ConfNak id=0x8 <addr 10.33.145.106>]
sent [IPCP ConfReq id=0x9]
rcvd [IPCP ConfNak id=0x9 <addr 10.33.145.106>]
sent [IPCP ConfReq id=0xa <addr 10.33.145.106>]
rcvd [IPCP ConfAck id=0xa <addr 10.33.145.106>]
rcvd [IPCP ConfReq id=0x1]
sent [IPCP ConfAck id=0x1]
Could not determine remote IP address: defaulting to 10.64.64.64
Cannot determine ethernet address for proxy ARP
local  IP address 10.33.145.106
remote IP address 10.64.64.64
** Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
** Message: nm-ppp-plugin: (nm_ip_up): ip-up event
** Message: nm-ppp-plugin: (nm_ip_up): sending Ip4Config to
NetworkManager...
Script /etc/ppp/ip-up started (pid 9334)
NetworkManager: <info>  PPP manager(IP Config Get) reply received.
NetworkManager: <info>  Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure
Get) scheduled...
NetworkManager: <info>  Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure
Get) started...
NetworkManager: <info>  Activation (ttyUSB2) Stage 5 of 5 (IP Configure
Commit) scheduled...
NetworkManager: <info>  Activation (ttyUSB2) Stage 4 of 5 (IP4 Configure
Get) complete.
NetworkManager: <info>  Activation (ttyUSB2) Stage 5 of 5 (IP Configure
Commit) started...
Script /etc/ppp/ip-up finished (pid 9334), status = 0x0
NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for
routing and DNS.
NetworkManager: <info>  (ttyUSB2): device state change: 7 -> 8 (reason 0)
NetworkManager: <info>  Activation (ttyUSB2) successful, device activated.
NetworkManager: <info>  Activation (ttyUSB2) Stage 5 of 5 (IP Configure
Commit) complete.
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: Tried to set deprecated property gsm/band
NetworkManager: <WARN>  nm_signal_handler(): Caught signal 2, shutting
down normally.
NetworkManager: <info>  (wlan0): taking down device.
NetworkManager: <info>  (ttyUSB2): now unmanaged
NetworkManager: <info>  (ttyUSB2): device state change: 8 -> 1 (reason 36)
NetworkManager: <info>  (ttyUSB2): deactivating device (reason: 36).
NetworkManager: <info>  (ttyUSB2): cleaning up...
NetworkManager: <info>  (ttyUSB2): taking down device.
Terminating on signal 15
** Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Connect time 0.6 minutes.
Sent 0 bytes, received 0 bytes.

(NetworkManager:9221): GLib-GObject-CRITICAL **: g_object_unref: assertion
`G_IS_OBJECT (object)' failed
NetworkManager: <info>  exiting (success)
Script /etc/ppp/ip-down started (pid 9405)
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP TermReq id=0x2 "User request"]
rcvd [LCP TermAck id=0x2]
** Message: nm-ppp-plugin: (nm_phasechange): status 11 / phase
'disconnect'
Connection terminated.
** Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Script /etc/ppp/ip-down finished (pid 9405), status = 0x0
** Message: nm-ppp-plugin: (nm_exit_notify): cleaning up


I tried again the system-connection with -vj option in /etc/ppp/options
but it's still not working.

-- Hans-Gerd