You are not logged in.

#1 2013-04-07 09:47:51

goofy
Member
Registered: 2011-10-02
Posts: 22

Analyzing ModemManager/NetworkManager logs

Hello,

I'm using 3G network connection (Polish ISP called "Aero2") with modem Huawei e173-u2. Despite poor signal quality in my neighborhood on Windows I successfully connect to network, let's say 8 on 10 times. On my Arch Linux it's definitely less often. Id' like to ask you to help my analyzing NetworkManager and/or ModemManager logs, because they're a bit to complicated for me:

First log from successful connection:

NetworkManager[3734]: <warn> (ttyUSB0): failed to look up interface index
NetworkManager[3734]: <info> WWAN now disabled by management service
NetworkManager[3734]: <info> (ttyUSB0): new GSM/UMTS device (driver: 'option1' ifindex: 0)
NetworkManager[3734]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/4
NetworkManager[3734]: <info> (ttyUSB0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
NetworkManager[3734]: <info> (ttyUSB0): deactivating device (reason 'managed') [2]
NetworkManager[3734]: <info> (ttyUSB0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) starting connection 'Aero 2'
NetworkManager[3734]: <info> (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager[3734]: <info> WWAN now enabled by management service
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
NetworkManager[3734]: <info> (ttyUSB0): device state change: prepare -> config (reason 'none') [40 50 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[3734]: <info> (ttyUSB0): device state change: config -> ip-config (reason 'none') [50 70 0]
NetworkManager[3734]: <info> starting PPP connection
NetworkManager[3734]: <info> pppd started with pid 5868
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) started...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
** Message: nm-ppp-plugin: (plugin_init): initializing
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Removed stale lock on ttyUSB0 (pid 5088)
using channel 18
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB0
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd4729> <pcomp> <accomp>]
NetworkManager[3734]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x10549cc> <pcomp> <accomp>]
sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x10549cc> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xd4729> <pcomp> <accomp>]
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
rcvd [LCP DiscReq id=0x1 magic=0x10549cc]
rcvd [CHAP Challenge id=0x1 <9848081674fed57928b034d0e27c1933>, 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 <4eeaad4f63ffa3c782937a64f309664d>, name = ""]
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 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
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> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
rcvd [IPCP ConfNak id=0x2 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x3 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
rcvd [IPCP ConfReq id=0x0]
sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
rcvd [IPCP ConfRej id=0x3 <compress VJ 0f 01> <ms-wins 10.11.12.13> <ms-wins 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 ConfReq id=0x1]
sent [IPCP ConfAck id=0x1]
rcvd [IPCP ConfNak id=0x4 <addr 78.30.95.180> <ms-dns1 193.41.112.14> <ms-dns2 193.41.112.18>]
sent [IPCP ConfReq id=0x5 <addr 78.30.95.180> <ms-dns1 193.41.112.14> <ms-dns2 193.41.112.18>]
rcvd [IPCP ConfAck id=0x5 <addr 78.30.95.180> <ms-dns1 193.41.112.14> <ms-dns2 193.41.112.18>]
Could not determine remote IP address: defaulting to 10.64.64.64
Cannot determine ethernet address for proxy ARP
local  IP address 78.30.95.180
remote IP address 10.64.64.64
primary   DNS address 193.41.112.14
secondary DNS address 193.41.112.18
** 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...
NetworkManager[3734]: <info> PPP manager(IP Config Get) reply received.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 5 of 5 (IPv4 Commit) started...
Script /etc/ppp/ip-up started (pid 5872)
Script /etc/ppp/ip-up finished (pid 5872), status = 0x0
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
NetworkManager[3734]: <info> (ttyUSB0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 5 of 5 (IPv4 Commit) complete.
NetworkManager[3734]: <info> (ttyUSB0): device state change: secondaries -> activated (reason 'none') [90 100 0]
NetworkManager[3734]: <info> Policy set 'Aero 2' (ppp0) as default for IPv4 routing and DNS.
NetworkManager[3734]: <info> Activation (ttyUSB0) successful, device activated.
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::9c8e:4560:c4a4:d177>]
IPV6CP: timeout sending Config-Requests

And from failed attempt

NetworkManager[3734]: <warn> (ttyUSB0): failed to look up interface index
NetworkManager[3734]: <info> WWAN now disabled by management service
NetworkManager[3734]: <info> (ttyUSB0): new GSM/UMTS device (driver: 'option1' ifindex: 0)
NetworkManager[3734]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/3
NetworkManager[3734]: <info> (ttyUSB0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
NetworkManager[3734]: <info> (ttyUSB0): deactivating device (reason 'managed') [2]
NetworkManager[3734]: <info> (ttyUSB0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
NetworkManager[3734]: <info> WWAN now enabled by management service
NetworkManager[3734]: <info> Activation (ttyUSB0) starting connection 'Aero 2'
NetworkManager[3734]: <info> (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
NetworkManager[3734]: <info> (ttyUSB0): device state change: prepare -> config (reason 'none') [40 50 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[3734]: <info> (ttyUSB0): device state change: config -> ip-config (reason 'none') [50 70 0]
NetworkManager[3734]: <info> starting PPP connection
NetworkManager[3734]: <info> pppd started with pid 5075
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) started...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
** Message: nm-ppp-plugin: (plugin_init): initializing
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Removed stale lock on ttyUSB0 (pid 4296)
using channel 15
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB0
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x20e71c21> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x1057e27> <pcomp> <accomp>]
sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x1057e27> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x20e71c21> <pcomp> <accomp>]
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
NetworkManager[3734]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
rcvd [LCP DiscReq id=0x1 magic=0x1057e27]
rcvd [CHAP Challenge id=0x1 <28b034d0e27c1933a2f355ce827aee6c>, 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 <45bb132fc774c217b303fcc1ee52fe28>, name = ""]
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 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::340c:fc76:7cae:7bb0>]
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> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
Modem hangup
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
** Message: nm-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Connection terminated.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv4 Configure Timeout) started...
NetworkManager[3734]: <info> (ttyUSB0): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
NetworkManager[3734]: <info> Marking connection 'Aero 2' invalid.
NetworkManager[3734]: <warn> Activation (ttyUSB0) failed for connection 'Aero 2'
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv4 Configure Timeout) complete.
NetworkManager[3734]: <info> (ttyUSB0): device state change: failed -> disconnected (reason 'none') [120 30 0]
NetworkManager[3734]: <info> (ttyUSB0): deactivating device (reason 'none') [0]
** Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
** Message: nm-ppp-plugin: (nm_exit_notify): cleaning up
NetworkManager[3734]: <info> Activation (ttyUSB0) starting connection 'Aero 2'
NetworkManager[3734]: <info> (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
NetworkManager[3734]: <info> (ttyUSB0): device state change: prepare -> config (reason 'none') [40 50 0]
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[3734]: <info> (ttyUSB0): device state change: config -> ip-config (reason 'none') [50 70 0]
NetworkManager[3734]: <info> starting PPP connection
NetworkManager[3734]: <info> pppd started with pid 5088
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) started...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
** Message: nm-ppp-plugin: (plugin_init): initializing
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
using channel 17
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB0
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
NetworkManager[3734]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring...
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x86742c66> <pcomp> <accomp>]
NetworkManager[3734]: <warn> pppd timed out or didn't initialize our dbus module
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv4 Configure Timeout) started...
NetworkManager[3734]: <info> (ttyUSB0): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
NetworkManager[3734]: <info> Marking connection 'Aero 2' invalid.
NetworkManager[3734]: <warn> Activation (ttyUSB0) failed for connection 'Aero 2'
NetworkManager[3734]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv4 Configure Timeout) complete.
NetworkManager[3734]: <info> (ttyUSB0): device state change: failed -> disconnected (reason 'none') [120 30 0]
NetworkManager[3734]: <info> (ttyUSB0): deactivating device (reason 'none') [0]
Terminating on signal 15
** Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
sent [LCP TermReq id=0x2 "User request"]
NetworkManager[3734]: <info> (ttyUSB0): device state change: disconnected -> unmanaged (reason 'removed') [30 10 36]
NetworkManager[3734]: <info> (ttyUSB0): cleaning up...
NetworkManager[3734]: <info> (ttyUSB0): taking down device.
NetworkManager[3734]: nm_system_iface_set_up: assertion `ifindex > 0' failed

Any hints?

Offline

Board footer

Powered by FluxBB