GNOME.org
 

Re: SMS sending error with Telit module

Obviously, with debug logs active, module doesn't hang anymore... Yesterday it stopped working only one time, and when I started NM without logging, as a daemon. Aargh!
There is something strange, anyway. Every time I reboot the module, first connection (and only first) fails. Following is part of the log that shows first (failed) connection attempt after module reboot, followed by a successful connection.
I've noted also that the number of "IPCP ConfReq/IPCP ConfNak" handshakes varies from time to time. I'm guessing what would happen if module keeps NAKing until manager goes (maybe) in timeout, and then module goes online anyway... is it possible? 

First attempt:
NetworkManager[5238]: <info> Activation (ttyUSB2) starting connection 'gsm1'
NetworkManager[5238]: <info> (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete. NetworkManager[5238]: <info> (ttyUSB2) state changed, 'disabled' --> 'enabling' (reason: user-requested) NetworkManager[5238]: <info> (ttyUSB2) state changed, 'enabling' --> 'registered' (reason: user-requested) 
NetworkManager[5238]: <info> WWAN now enabled by management service
NetworkManager[5238]: <debug> [1365521991.254632] [nm-manager.c:1667] manager_rfkill_update_one_type(): WWAN hw-enabled 1 sw-enabled 1 daemon-enabled 1 NetworkManager[5238]: <debug> [1365521991.254658] [nm-manager.c:1522] manager_update_radio_enabled(): (ttyUSB2): setting radio enabled NetworkManager[5238]: <info> (ttyUSB2) state changed, 'registered' --> 'connecting' (reason: user-requested) NetworkManager[5238]: <info> (ttyUSB2) state changed, 'connecting' --> 'connected' (reason: user-requested) 
NetworkManager[5238]: <warn> (ttyUSB2): failed to look up interface index
NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) starting... NetworkManager[5238]: <info> (ttyUSB2): device state change: prepare -> config (reason 'none') [40 50 0] NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) successful. NetworkManager[5238]: <debug> [1365521991.362312] [nm-device.c:3085] nm_device_activate_schedule_stage3_ip_config_start(): Activation (ttyUSB2) setting firewall zone 'default' NetworkManager[5238]: <debug> [1365521991.362331] [nm-firewall-manager.c:107] nm_firewall_manager_add_or_change_zone(): (ttyUSB2) firewall zone add/change skipped (not running) NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) scheduled. NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) complete. NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) started... NetworkManager[5238]: <info> (ttyUSB2): device state change: config -> ip-config (reason 'none') [50 70 0] 
NetworkManager[5238]: <info> using modem-specified IP timeout: 20 seconds
NetworkManager[5238]: <info> starting PPP connection
NetworkManager[5238]: <debug> [1365521991.368757] [nm-ppp-manager.c:1067] nm_ppp_manager_start(): command line: /usr/sbin/pppd nodetach lock nodefaultroute ipv6 , debug ttyUSB2 noipdefault noauth usepeerdns lcp-echo-failure 5 lcp-echo-interval 30 ipparam /org/freedesktop/NetworkManager/PPP/0 plugin /usr/lib/i386-linux-gnu/pppd/2.4.5/nm-pppd-plugin.so 
NetworkManager[5238]: <info> pppd started with pid 5369
NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) complete. NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) started... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) complete. 
Plugin /usr/lib/i386-linux-gnu/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' 
using channel 8
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 0x8ef8210> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xdab098c9> <pcomp> <accomp>] sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xdab098c9> <pcomp> <accomp>] NetworkManager[5238]: <debug> [1365521991.381391] [nm-ip6-manager.c:1340] netlink_notification(): netlink event type 16 NetworkManager[5238]: <debug> [1365521991.381460] [nm-ip6-manager.c:1301] process_newlink(): ignoring netlink message family 0 NetworkManager[5238]: <debug> [1365521991.381525] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 9 flags 0x1090 NetworkManager[5238]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0) NetworkManager[5238]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found. NetworkManager[5238]: <debug> [1365521991.381761] [nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'ppp0' NetworkManager[5238]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring... 
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x8ef8210> <pcomp> <accomp>]
sent [LCP EchoReq id=0x0 magic=0x8ef8210]
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
rcvd [LCP DiscReq id=0x1 magic=0xdab098c9]
rcvd [CHAP Challenge id=0x1 <1c1a6caf3c7e26e222092a4dc2bebd02>, 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 <345d59e276bafd14f080f80554b1d52f>, 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::f52c:7808:83d3:8875>]
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
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[5238]: <debug> [1365521991.630740] [nm-ip6-manager.c:1340] netlink_notification(): netlink event type 17 NetworkManager[5238]: <debug> [1365521991.630792] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 9 flags 0x1090 NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv4 Configure Timeout) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv4 Configure Timeout) started... NetworkManager[5238]: <info> (ttyUSB2): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5] NetworkManager[5238]: <warn> Activation (ttyUSB2) failed for connection 'gsm1' NetworkManager[5238]: <debug> [1365521991.631506] [nm-device.c:5256] nm_device_queue_state(): (ttyUSB2): queued state change to disconnected (id 203) NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv4 Configure Timeout) complete. NetworkManager[5238]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0) NetworkManager[5238]: <debug> [1365521991.631601] [nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'remove' subsys 'net' device 'ppp0' NetworkManager[5238]: <debug> [1365521991.631784] [nm-device.c:5214] queued_set_state(): (ttyUSB2): running queued state change to disconnected (id 203) NetworkManager[5238]: <info> (ttyUSB2): device state change: failed -> disconnected (reason 'none') [120 30 0] NetworkManager[5238]: <info> (ttyUSB2): deactivating device (reason 'none') [0] NetworkManager[5238]: <debug> [1365521991.631816] [nm-firewall-manager.c:157] nm_firewall_manager_remove_from_zone(): (ttyUSB2) firewall zone remove skipped (not running) NetworkManager[5238]: <debug> [1365521991.636507] [nm-dns-manager.c:1017] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS updates (1) NetworkManager[5238]: <debug> [1365521991.636583] [nm-dns-manager.c:1035] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration did not change NetworkManager[5238]: <debug> [1365521991.636604] [nm-dns-manager.c:1039] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to commit (0) NetworkManager[5238]: <info> (ttyUSB2) state changed, 'connected' --> 'disconnecting' (reason: user-requested) 
** Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
** Message: nm-ppp-plugin: (nm_exit_notify): cleaning up
NetworkManager[5238]: <info> (ttyUSB2) state changed, 'disconnecting' --> 'registered' (reason: user-requested) NetworkManager[5238]: <debug> [1365521993.807023] [nm-ppp-manager.c:1103] ensure_killed(): waiting for pppd pid 5369 to exit NetworkManager[5238]: <debug> [1365521993.807105] [nm-ppp-manager.c:1105] ensure_killed(): pppd pid 5369 cleaned up 

Second attempt:
NetworkManager[5238]: <info> Activation (ttyUSB2) starting connection 'gsm1'
NetworkManager[5238]: <info> (ttyUSB2): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) started... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 1 of 5 (Device Prepare) complete. NetworkManager[5238]: <info> (ttyUSB2) state changed, 'registered' --> 'connecting' (reason: user-requested) NetworkManager[5238]: <info> (ttyUSB2) state changed, 'connecting' --> 'connected' (reason: user-requested) 
NetworkManager[5238]: <warn> (ttyUSB2): failed to look up interface index
NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) starting... NetworkManager[5238]: <info> (ttyUSB2): device state change: prepare -> config (reason 'none') [40 50 0] NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) successful. NetworkManager[5238]: <debug> [1365522002.479468] [nm-device.c:3085] nm_device_activate_schedule_stage3_ip_config_start(): Activation (ttyUSB2) setting firewall zone 'default' NetworkManager[5238]: <debug> [1365522002.479484] [nm-firewall-manager.c:107] nm_firewall_manager_add_or_change_zone(): (ttyUSB2) firewall zone add/change skipped (not running) NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) scheduled. NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 2 of 5 (Device Configure) complete. NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) started... NetworkManager[5238]: <info> (ttyUSB2): device state change: config -> ip-config (reason 'none') [50 70 0] 
NetworkManager[5238]: <info> using modem-specified IP timeout: 20 seconds
NetworkManager[5238]: <info> starting PPP connection
NetworkManager[5238]: <debug> [1365522002.484264] [nm-ppp-manager.c:1067] nm_ppp_manager_start(): command line: /usr/sbin/pppd nodetach lock nodefaultroute ipv6 , debug ttyUSB2 noipdefault noauth usepeerdns lcp-echo-failure 5 lcp-echo-interval 30 ipparam /org/freedesktop/NetworkManager/PPP/1 plugin /usr/lib/i386-linux-gnu/pppd/2.4.5/nm-pppd-plugin.so 
NetworkManager[5238]: <info> pppd started with pid 5382
NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 3 of 5 (IP Configure Start) complete. NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) started... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 4 of 5 (IPv6 Configure Timeout) complete. 
Plugin /usr/lib/i386-linux-gnu/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' 
using channel 10
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 0x7d08c008> <pcomp> <accomp>]
NetworkManager[5238]: <debug> [1365522002.498429] [nm-ip6-manager.c:1340] netlink_notification(): netlink event type 16 NetworkManager[5238]: <debug> [1365522002.498449] [nm-ip6-manager.c:1301] process_newlink(): ignoring netlink message family 0 NetworkManager[5238]: <debug> [1365522002.498469] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 10 flags 0x1090 NetworkManager[5238]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0) NetworkManager[5238]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found. NetworkManager[5238]: <debug> [1365522002.498572] [nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'ppp0' NetworkManager[5238]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring... rcvd [LCP ConfReq id=0x3 <asyncmap 0x0> <auth chap MD5> <magic 0xdab0c439> <pcomp> <accomp>] sent [LCP ConfAck id=0x3 <asyncmap 0x0> <auth chap MD5> <magic 0xdab0c439> <pcomp> <accomp>] 
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x7d08c008> <pcomp> <accomp>]
sent [LCP EchoReq id=0x0 magic=0x7d08c008]
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
rcvd [LCP DiscReq id=0x4 magic=0xdab0c439]
rcvd [CHAP Challenge id=0x1 <7c48c1edd63e7e2c6c6a4f14dee2d369>, 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 <babd30c521e2416285ea882a64f2b476>, 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::8d5f:8455:3bee:4ead>]
rcvd [LCP ProtRej id=0x5 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>] 
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
rcvd [IPCP ConfNak id=0x3 <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=0x4 <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=0x4 <compress VJ 0f 01> <ms-wins 10.11.12.13> <ms-wins 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 <addr 10.82.49.80> <ms-dns1 62.13.173.92> <ms-dns2 62.13.173.93>] sent [IPCP ConfReq id=0x6 <addr 10.82.49.80> <ms-dns1 62.13.173.92> <ms-dns2 62.13.173.93>] rcvd [IPCP ConfAck id=0x6 <addr 10.82.49.80> <ms-dns1 62.13.173.92> <ms-dns2 62.13.173.93>] 
rcvd [IPCP ConfReq id=0x1]
sent [IPCP ConfAck id=0x1]
Could not determine remote IP address: defaulting to 10.64.64.64
NetworkManager[5238]: <debug> [1365522007.493185] [nm-ip6-manager.c:1340] netlink_notification(): netlink event type 16 NetworkManager[5238]: <debug> [1365522007.493226] [nm-ip6-manager.c:1301] process_newlink(): ignoring netlink message family 0 NetworkManager[5238]: <debug> [1365522007.493255] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 10 flags 0x110D1 
local  IP address 10.82.49.80
remote IP address 10.64.64.64
primary   DNS address 62.13.173.92
secondary DNS address 62.13.173.93
** 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[5238]: <info> PPP manager(IP Config Get) reply received.
Script /etc/ppp/ip-up started (pid 5385)
NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 5 of 5 (IPv4 Configure Commit) scheduled... NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 5 of 5 (IPv4 Commit) started... NetworkManager[5238]: <debug> [1365522007.494514] [nm-system.c:194] sync_addresses(): (ppp0): syncing addresses (family 2) NetworkManager[5238]: <debug> [1365522007.494544] [nm-system.c:247] sync_addresses(): (ppp0): removing address '10.82.49.80/32' NetworkManager[5238]: <debug> [1365522007.494733] [nm-system.c:280] sync_addresses(): (ppp0): adding address '10.82.49.80/0' 
Script /etc/ppp/ip-up finished (pid 5385), status = 0x0
NetworkManager[5238]: <debug> [1365522008.495064] [nm-netlink-utils.c:356] dump_route(): route idx 2 family INET (2) addr 41.0.0.0/0 NetworkManager[5238]: <debug> [1365522008.495106] [nm-netlink-utils.c:356] dump_route(): route idx 10 family INET (2) addr 10.64.64.64/32 NetworkManager[5238]: <debug> [1365522008.495126] [nm-netlink-utils.c:356] dump_route(): route idx 2 family INET (2) addr 169.254.0.0/16 NetworkManager[5238]: <debug> [1365522008.495139] [nm-netlink-utils.c:356] dump_route(): route idx 2 family INET (2) addr 192.168.4.0/24 NetworkManager[5238]: <debug> [1365522008.495152] [nm-netlink-utils.c:356] dump_route(): route idx 10 family INET (2) addr 10.82.49.80/32 NetworkManager[5238]: <debug> [1365522008.495165] [nm-netlink-utils.c:356] dump_route(): route idx 10 family INET (2) addr 10.82.49.80/32 NetworkManager[5238]: <debug> [1365522008.495331] [nm-dns-manager.c:1017] nm_dns_manager_begin_updates(): (device_ip4_config_changed): queueing DNS updates (1) NetworkManager[5238]: <debug> [1365522008.495364] [nm-dns-manager.c:1035] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration did not change NetworkManager[5238]: <debug> [1365522008.495382] [nm-dns-manager.c:1039] nm_dns_manager_end_updates(): (device_ip4_config_changed): no DNS changes to commit (0) NetworkManager[5238]: <info> (ttyUSB2): device state change: ip-config -> secondaries (reason 'none') [70 90 0] NetworkManager[5238]: <debug> [1365522008.495545] [nm-device.c:5256] nm_device_queue_state(): (ttyUSB2): queued state change to activated (id 266) NetworkManager[5238]: <debug> [1365522008.495570] [nm-device.c:5186] nm_device_state_changed(): (ttyUSB2): device entered SECONDARIES state NetworkManager[5238]: <info> Activation (ttyUSB2) Stage 5 of 5 (IPv4 Commit) complete. NetworkManager[5238]: <debug> [1365522008.495698] [nm-device.c:5214] queued_set_state(): (ttyUSB2): running queued state change to activated (id 266) NetworkManager[5238]: <info> (ttyUSB2): device state change: secondaries -> activated (reason 'none') [90 100 0] NetworkManager[5238]: <debug> [1365522008.502547] [nm-manager.c:596] manager_device_state_changed(): (ttyUSB2): triggered connectivity check due to state change NetworkManager[5238]: <debug> [1365522008.502785] [nm-dns-manager.c:1017] nm_dns_manager_begin_updates(): (device_state_changed): queueing DNS updates (1) NetworkManager[5238]: <debug> [1365522008.502816] [nm-dns-manager.c:1017] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS updates (2) NetworkManager[5238]: <debug> [1365522008.502868] [nm-dns-manager.c:1035] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration changed NetworkManager[5238]: <debug> [1365522008.502886] [nm-dns-manager.c:1039] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to commit (1) NetworkManager[5238]: <debug> [1365522008.502906] [nm-dns-manager.c:1035] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration changed NetworkManager[5238]: <debug> [1365522008.502918] [nm-dns-manager.c:1044] nm_dns_manager_end_updates(): (device_state_changed): committing DNS changes (0) NetworkManager[5238]: <debug> [1365522008.502930] [nm-dns-manager.c:592] update_dns(): updating resolv.conf NetworkManager[5238]: <debug> [1365522008.502960] [nm-dns-manager.c:714] update_dns(): DNS: updating plugin dnsmasq 
NetworkManager[5238]: <info> Writing DNS information to /sbin/resolvconf
NetworkManager[5238]: <info> Activation (ttyUSB2) successful, device activated. 
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
sent [IPV6CP ConfReq id=0x1 <addr fe80::8d5f:8455:3bee:4ead>]
IPV6CP: timeout sending Config-Requests

On 09/04/2013 18:09, Dan Williams wrote:

On Tue, 2013-04-09 at 10:35 +0200, Enrico Murador - Research &
Development - CET wrote:

On 08/04/2013 17:28, Dan Williams wrote:

On Mon, 2013-04-08 at 10:39 +0200, Enrico Murador - Research &
Development - CET wrote:

I'm trying the packages I updated friday from PPA, but now I'm facing
another problem: after I start the gsm data connection, most of the time
connection drops automatically... sometimes immediately after
connection, sometimes after some seconds (and in the meantime, I see the
modem status icon on top right of the screen in "searching" state).
After the connection drops, the modem seems to become "unreachable" from
the manager. I can get it working by disconnect and reconnect the
module's USB cable, without powering it off.

Side effect: one time, after some retries, I was able to completely
"lock" the applet with both LAN and mobile connections disabled, and
clicking on the connection names didn't make any effect, apart from this
message repeatedly popping up: "(4) Did not receive a reply. Possible
causes include: the remote application did not send a reply, the message
bus security policy blocked the reply, the reply timeout expired, or the
network connection was broken.".

Attached is the log of a failed attempt, where connection drops (line
755) some seconds after going up, and subsequent (failed?) attempts to
check module's state.
Is there a way to show in log also the cause of the disconnection?

If NetworkManager is being used here, what does the PPP exchange look
like?  Does ppp0 get an IP address from pppd before the disconnection,
or does the PPP negotiation just fail?  You'll see that wherever syslog
gets dumped to, sometimes /var/log/messages,
sometimes /var/log/daemon.log, etc.  Clearly the modem isn't completely
wedged because the QCDM port still works.  But getting the pppd output
might help diagnose.

Some theories are:

1) double-check the APN

2) perhaps PPP fails for some reason, but when pppd quits on the local
machine the module doesn't actually leave data mode; we don't have
multiple AT ports so there's no way to force the device to leave data
mode with AT+CGACT.  The device might require other mechanisms like
serial HUP or dropping DTR or +++.

Dan


To check PPP, I suppose I must enable NetworkManager logs (maybe using
--no-daemon option?)... What is the best way do it?

Yeah, best is to stop NetworkManager, then run manually with:

NetworkManager --no-daemon --log-level=debug --log-domains=core,hw,device,mb,ppp

and the pppd debug output will get printed in-line with the
NetworkManager log output.

Dan
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]