|
On 10/04/2013 14:11, Dan Williams
wrote:
Hmm, try putting "noccp" into /etc/ppp/options, does that help with anything? It seems NM doesn't support changing that option (but does support flipping vjcomp, bsdcomp, etc) but I think putting it into /etc/ppp/options is a quick check. DanTried... the protocol reject lines disappeared, but the behavior remains the same. I've also tried to playing a bit with the settings in /etc/ppp/options, but nothing. I don't understand why the module simply "hangs up", and why only the first time... On Mon, 2013-04-08 at 10:39 +0200, Enrico Murador - Research & Development - CET wrote: I was finally able to make the module "hang", but I don't know how. After the issue happened, I tried to disconnect and reconnect the USB cable, but "hang" remained.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. Finally, I cycled the power of the module, and then I was able to connect (apart from the first try...). Following is the log. On this log the comm port used by the manager was USB4, and also after the failed attempts of disconnecting/reconnecting the cable, port was still USB4. Only after I cycled the module power supply, used port was USB2, and connection worked again. In the various logs I've done, I've found another connection attempt in which the comm port choosed was not USB2 (it was USB3), and I found the same "sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]" repeated attempts, until timeout happened. I suppose that USB port assignments can vary from time to time... could it be that the manager chooses the wrong USB port to communicate? If useful, I have the corresponding MM logs available. Thank you very much Here is the log: First (failed) connection attempt: NetworkManager[10648]: <info> Activation (ttyUSB4) starting connection 'gsm1' NetworkManager[10648]: <info> (ttyUSB4): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) started... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) complete. NetworkManager[10648]: <info> (ttyUSB4) state changed, 'disabled' --> 'enabling' (reason: user-requested) NetworkManager[10648]: <info> (ttyUSB4) state changed, 'enabling' --> 'registered' (reason: user-requested) NetworkManager[10648]: <info> (ttyUSB4) state changed, 'registered' --> 'connecting' (reason: user-requested) NetworkManager[10648]: <info> (ttyUSB4) state changed, 'connecting' --> 'connected' (reason: user-requested) NetworkManager[10648]: <warn> (ttyUSB4): failed to look up interface index NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device Configure) scheduled... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device Configure) starting... NetworkManager[10648]: <info> (ttyUSB4): device state change: prepare -> config (reason 'none') [40 50 0] NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device Configure) successful. NetworkManager[10648]: <debug> [1365603731.639957] [nm-device.c:3085] nm_device_activate_schedule_stage3_ip_config_start(): Activation (ttyUSB4) setting firewall zone 'default' NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 3 of 5 (IP Configure Start) scheduled. NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 2 of 5 (Device Configure) complete. NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 3 of 5 (IP Configure Start) started... NetworkManager[10648]: <info> (ttyUSB4): device state change: config -> ip-config (reason 'none') [50 70 0] NetworkManager[10648]: <info> using modem-specified IP timeout: 20 seconds NetworkManager[10648]: <info> starting PPP connection NetworkManager[10648]: <debug> [1365603731.641587] [nm-ppp-manager.c:1067] nm_ppp_manager_start(): command line: /usr/sbin/pppd nodetach lock nodefaultroute ipv6 , debug ttyUSB4 noipdefault noauth usepeerdns lcp-echo-failure 5 lcp-echo-interval 30 ipparam /org/freedesktop/NetworkManager/PPP/17 plugin /usr/lib/i386-linux-gnu/pppd/2.4.5/nm-pppd-plugin.so NetworkManager[10648]: <info> pppd started with pid 12276 NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv6 Configure Timeout) scheduled... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 3 of 5 (IP Configure Start) 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' Removed stale lock on ttyUSB4 (pid 12181) NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv6 Configure Timeout) started... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv6 Configure Timeout) complete. using channel 57 NetworkManager[10648]: <debug> [1365603731.651022] [nm-ip6-manager.c:1340] netlink_notification(): netlink event type 16 NetworkManager[10648]: <debug> [1365603731.652138] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 48 flags 0x1090 NetworkManager[10648]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0) Using interface ppp0 Connect: ppp0 <--> /dev/ttyUSB4NetworkManager[10648]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found. NetworkManager[10648]: <debug> [1365603731.652400] [nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'ppp0' ** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish' sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>]NetworkManager[10648]: <warn> /sys/devices/virtual/net/ppp0: couldn't determine device driver; ignoring... sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>] sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>] sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>] sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>] sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>] sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x87e350df> <pcomp> <accomp>] NetworkManager[10648]: <warn> pppd timed out or didn't initialize our dbus module NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv4 Configure Timeout) scheduled... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv4 Configure Timeout) started... NetworkManager[10648]: <info> (ttyUSB4): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5] Terminating on signal 15 ** Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate' sent [LCP TermReq id=0x2 "User request"] NetworkManager[10648]: <warn> Activation (ttyUSB4) failed for connection 'gsm1' NetworkManager[10648]: <debug> [1365603751.808564] [nm-device.c:5256] nm_device_queue_state(): (ttyUSB4): queued state change to disconnected (id 2917) NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 4 of 5 (IPv4 Configure Timeout) complete. NetworkManager[10648]: <debug> [1365603751.808893] [nm-device.c:5214] queued_set_state(): (ttyUSB4): running queued state change to disconnected (id 2917) NetworkManager[10648]: <info> (ttyUSB4): device state change: failed -> disconnected (reason 'none') [120 30 0] NetworkManager[10648]: <info> (ttyUSB4): deactivating device (reason 'none') [0] NetworkManager[10648]: <info> (ttyUSB4) state changed, 'connected' --> 'disconnecting' (reason: user-requested) NetworkManager[10648]: <debug> [1365603753.789508] [nm-ppp-manager.c:1103] ensure_killed(): waiting for pppd pid 12276 to exit NetworkManager[10648]: <debug> [1365603753.794918] [nm-ppp-manager.c:1105] ensure_killed(): pppd pid 12276 cleaned up NetworkManager[10648]: <debug> [1365603753.795013] [nm-ip6-manager.c:1340] netlink_notification(): netlink event type 17 NetworkManager[10648]: <debug> [1365603753.795055] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 48 flags 0x1090 NetworkManager[10648]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0) NetworkManager[10648]: <debug> [1365603753.795234] [nm-udev-manager.c:573] handle_uevent(): UDEV event: action 'remove' subsys 'net' device 'ppp0' Second (failed) attempt: NetworkManager[10648]: <info> Activation (ttyUSB4) starting connection 'gsm1' NetworkManager[10648]: <info> (ttyUSB4): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) started... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) complete. NetworkManager[10648]: <warn> (ttyUSB4) failed to connect modem: Bearer currently being disconnected NetworkManager[10648]: <debug> [1365603765.579840] [nm-modem-broadband.c:102] translate_mm_error(): unmapped error detected: 'Bearer currently being disconnected' NetworkManager[10648]: <info> (ttyUSB4): device state change: prepare -> failed (reason 'unknown') [40 120 1] NetworkManager[10648]: <warn> Activation (ttyUSB4) failed for connection 'gsm1' NetworkManager[10648]: <debug> [1365603765.580106] [nm-device.c:5256] nm_device_queue_state(): (ttyUSB4): queued state change to disconnected (id 2952) NetworkManager[10648]: <debug> [1365603765.583728] [nm-device.c:5214] queued_set_state(): (ttyUSB4): running queued state change to disconnected (id 2952) NetworkManager[10648]: <info> (ttyUSB4): device state change: failed -> disconnected (reason 'none') [120 30 0] NetworkManager[10648]: <info> (ttyUSB4): deactivating device (reason 'none') [0] NetworkManager[10648]: <info> (ttyUSB4) state changed, 'disconnecting' --> 'registered' (reason: user-requested) NetworkManager[10648]: <info> Activation (ttyUSB4) starting connection 'gsm1' NetworkManager[10648]: <info> (ttyUSB4): device state change: disconnected -> prepare (reason 'none') [30 40 0] NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) started... NetworkManager[10648]: <info> Activation (ttyUSB4) Stage 1 of 5 (Device Prepare) complete. NetworkManager[10648]: <info> (ttyUSB4) state changed, 'registered' --> 'connecting' (reason: user-requested) NetworkManager[10648]: <info> (ttyUSB4) state changed, 'connecting' --> 'registered' (reason: user-requested) NetworkManager[10648]: <warn> (ttyUSB4) failed to connect modem: Sending command failed: 'Resource temporarily unavailable' NetworkManager[10648]: <debug> [1365603791.534050] [nm-modem-broadband.c:102] translate_mm_error(): unmapped error detected: 'Sending command failed: 'Resource temporarily unavailable'' NetworkManager[10648]: <info> (ttyUSB4): device state change: prepare -> failed (reason 'unknown') [40 120 1] NetworkManager[10648]: <warn> Activation (ttyUSB4) failed for connection 'gsm1' NetworkManager[10648]: <debug> [1365603791.534589] [nm-device.c:5256] nm_device_queue_state(): (ttyUSB4): queued state change to disconnected (id 3003) NetworkManager[10648]: <debug> [1365603791.534852] [nm-device.c:5214] queued_set_state(): (ttyUSB4): running queued state change to disconnected (id 3003) NetworkManager[10648]: <info> (ttyUSB4): device state change: failed -> disconnected (reason 'none') [120 30 0] NetworkManager[10648]: <info> (ttyUSB4): deactivating device (reason 'none') [0] |