Ubuntu
network-manager package

Network Manager fails to connect via Mobile Broadband if device takes longer than 16 seconds to connect

Bug #407519 reported by Vasya Pupkin
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
network-manager (Ubuntu)
Expired
Undecided
Unassigned

Bug Description

Binary package hint: network-manager

My mobile phone takes around 30 seconds to initialize GPRS connection. When I'm trying to connect via Network Manager, I see that mobile phone starts the connection but after 16 seconds Network Manager thinks it was timed out and kills pppd. I couldn't find any place to specify a connection timeout for Network Manager. With another mobile phone (and another mobile operator), that requires only 2-5 seconds to initialize GPRS connection, everything works fine. I will attach logs in comments.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

Unsuccessful attempt:

syslog:
Aug 1 01:33:59 vampirella-netbook NetworkManager: <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) complete.
Aug 1 01:33:59 vampirella-netbook pppd[3770]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Aug 1 01:33:59 vampirella-netbook pppd[3770]: pppd 2.4.5 started by root, uid 0
Aug 1 01:33:59 vampirella-netbook pppd[3770]: Using interface ppp0
Aug 1 01:33:59 vampirella-netbook pppd[3770]: Connect: ppp0 <--> /dev/ttyACM0
Aug 1 01:33:59 vampirella-netbook NetworkManager: <info> (ttyACM0): device state change: 5 -> 6
Aug 1 01:33:59 vampirella-netbook pppd[3770]: CHAP authentication succeeded: Congratulations!
Aug 1 01:33:59 vampirella-netbook pppd[3770]: CHAP authentication succeeded
Aug 1 01:33:59 vampirella-netbook NetworkManager: <info> (ttyACM0): device state change: 6 -> 7
Aug 1 01:34:15 vampirella-netbook NetworkManager: <WARN> pppd_timed_out(): Looks like pppd didn't initialize our dbus module
Aug 1 01:34:15 vampirella-netbook NetworkManager: <info> (ttyACM0): device state change: 7 -> 9
Aug 1 01:34:15 vampirella-netbook NetworkManager: <debug> [1249076055.002183] nm_serial_device_close(): Closing device 'ttyACM0'
Aug 1 01:34:15 vampirella-netbook pppd[3770]: Terminating on signal 15

messages:
Aug 1 01:33:59 vampirella-netbook pppd[3770]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Aug 1 01:33:59 vampirella-netbook pppd[3770]: pppd 2.4.5 started by root, uid 0
Aug 1 01:33:59 vampirella-netbook pppd[3770]: Using interface ppp0
Aug 1 01:33:59 vampirella-netbook pppd[3770]: Connect: ppp0 <--> /dev/ttyACM0
Aug 1 01:33:59 vampirella-netbook pppd[3770]: CHAP authentication succeeded: Congratulations!
Aug 1 01:33:59 vampirella-netbook pppd[3770]: CHAP authentication succeeded
Aug 1 01:34:15 vampirella-netbook pppd[3770]: Terminating on signal 15
Aug 1 01:34:15 vampirella-netbook pppd[3770]: Connection terminated.
Aug 1 01:34:16 vampirella-netbook pppd[3770]: Exit.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

Successful attempt (another phone):

syslog:
Jul 31 07:01:49 vampirella-netbook NetworkManager: <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) complete.
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Jul 31 07:01:49 vampirella-netbook pppd[22686]: pppd 2.4.5 started by root, uid 0
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Removed stale lock on ttyACM0 (pid 22253)
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Using interface ppp0
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Connect: ppp0 <--> /dev/ttyACM0
Jul 31 07:01:52 vampirella-netbook NetworkManager: <info> (ttyACM0): device state change: 5 -> 6
Jul 31 07:01:52 vampirella-netbook pppd[22686]: PAP authentication succeeded
Jul 31 07:01:52 vampirella-netbook NetworkManager: <info> (ttyACM0): device state change: 6 -> 7
Jul 31 07:01:53 vampirella-netbook pppd[22686]: Cannot determine ethernet address for proxy ARP
Jul 31 07:01:53 vampirella-netbook pppd[22686]: local IP address 90.143.253.208
Jul 31 07:01:53 vampirella-netbook pppd[22686]: remote IP address 10.6.6.6
Jul 31 07:01:53 vampirella-netbook pppd[22686]: primary DNS address 130.244.127.161
Jul 31 07:01:53 vampirella-netbook pppd[22686]: secondary DNS address 130.244.127.169
Jul 31 07:01:53 vampirella-netbook NetworkManager: <info> PPP manager(IP Config Get) reply received.
Jul 31 07:01:53 vampirella-netbook NetworkManager: <info> Activation (ttyACM0) Stage 4 of 5 (IP Configure Get) scheduled...
Jul 31 07:01:53 vampirella-netbook NetworkManager: <info> Activation (ttyACM0) Stage 4 of 5 (IP Configure Get) started...
Jul 31 07:01:53 vampirella-netbook NetworkManager: <info> Activation (ttyACM0) Stage 5 of 5 (IP Configure Commit) scheduled...
Jul 31 07:01:53 vampirella-netbook NetworkManager: <info> Activation (ttyACM0) Stage 4 of 5 (IP Configure Get) complete.

messages:
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Jul 31 07:01:49 vampirella-netbook pppd[22686]: pppd 2.4.5 started by root, uid 0
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Removed stale lock on ttyACM0 (pid 22253)
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Using interface ppp0
Jul 31 07:01:49 vampirella-netbook pppd[22686]: Connect: ppp0 <--> /dev/ttyACM0
Jul 31 07:01:52 vampirella-netbook pppd[22686]: PAP authentication succeeded
Jul 31 07:01:53 vampirella-netbook pppd[22686]: local IP address 90.143.253.208
Jul 31 07:01:53 vampirella-netbook pppd[22686]: remote IP address 10.6.6.6
Jul 31 07:01:53 vampirella-netbook pppd[22686]: primary DNS address 130.244.127.161
Jul 31 07:01:53 vampirella-netbook pppd[22686]: secondary DNS address 130.244.127.169
Jul 31 07:02:35 vampirella-netbook pppd[22686]: Terminating on signal 15
Jul 31 07:02:35 vampirella-netbook pppd[22686]: Connect time 0.7 minutes.
Jul 31 07:02:35 vampirella-netbook pppd[22686]: Sent 420 bytes, received 420 bytes.
Jul 31 07:02:35 vampirella-netbook pppd[22686]: Connection terminated.

Revision history for this message
madboy (mike-pie) wrote :
Download full text (6.4 KiB)

I have a very similar problem. Since upgrading to 9.04 when trying to connect using Mobile in NetworkManger. Sometimes it will work, and other times not. I can plug in the phone and it may connect successfully. Then I disconnect and unplug, then replug and try again and the Mobile connectrion may not even show up in NetworkManager. The following appears in syslog:

Successful:

Aug 3 09:45:34 mike-laptop kernel: [29596.728079] usb 2-1: new full speed USB device using uhci_hcd and address 8
Aug 3 09:45:35 mike-laptop kernel: [29596.911410] usb 2-1: configuration #1 chosen from 1 choice
Aug 3 09:45:35 mike-laptop kernel: [29596.921401] cdc_acm 2-1:1.0: ttyACM0: USB ACM device
Aug 3 09:45:36 mike-laptop nm-system-settings: SCPlugin-Ifupdown: device added (udi: /org/freedesktop/Hal/devices/usb_device_22b8_3002_noserial_if0_serial_unknown_0_1, iface: (null)): iface not found
Aug 3 09:45:36 mike-laptop NetworkManager: <info> (ttyACM0): found serial port (udev:GSM hal:GSM)
Aug 3 09:45:36 mike-laptop NetworkManager: <info> (ttyACM0): new Modem device (driver: 'cdc_acm')
Aug 3 09:45:36 mike-laptop NetworkManager: <info> (ttyACM0): exported as /org/freedesktop/Hal/devices/usb_device_22b8_3002_noserial_if0_serial_unknown_0_1
Aug 3 09:45:39 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 1 -> 2
Aug 3 09:45:40 mike-laptop NetworkManager: <info> (ttyACM0): deactivating device (reason: 2).
Aug 3 09:45:40 mike-laptop NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Aug 3 09:45:40 mike-laptop NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Aug 3 09:45:40 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 2 -> 3
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Activation (ttyACM0) starting connection 'Vodafone'
Aug 3 09:45:49 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 3 -> 4
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) started...
Aug 3 09:45:49 mike-laptop NetworkManager: <debug> [1249249549.061475] nm_serial_device_open(): (ttyACM0) opening device...
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) complete.
Aug 3 09:45:49 mike-laptop NetworkManager: <info> (ttyACM0): powering up...
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Registered on Home network
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Associated with network: +COPS: 0,0,"vodafone NZ"
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Connected, Woo!
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) scheduled...
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) starting...
Aug 3 09:45:49 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 4 -> 5
Aug 3 09:45:49 mike-laptop NetworkManager: <info> Starting pppd connection
Aug 3 09...

Read more...

Revision history for this message
madboy (mike-pie) wrote :

I forgot to mention that on further attempts when the phone is recognised, I get the same as entries in /var/log/messages and syslog as Vasya and the ppp connection is not established. After a system reboot NetworkManger will connect successfully.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

madboy, I think you are having a different issue. In my case everything works as expected and the problem is that Network Manager does not wait enough time for my mobile phone to establish a GPRS connection. An easy solution to my problem would be an option to manually specify a timeout for pppd to finish it's job. Currently it has only 16 seconds and there is no way to change it, at least I couldn't find where it can be changed.

Revision history for this message
madboy (mike-pie) wrote :

Vasya, I think I have 2 problems, one which is the same as yours and the other is where the hardware does not seem to be detected properly. I will do some more investigating.

Revision history for this message
madboy (mike-pie) wrote :
Download full text (6.5 KiB)

Ok, after trying to get it to fail again I finally managed it. This is the syslog:

Aug 4 07:48:59 mike-laptop kernel: [69033.385030] usb 2-1: new full speed USB device using uhci_hcd and address 7
Aug 4 07:48:59 mike-laptop kernel: [69033.559814] usb 2-1: configuration #1 chosen from 1 choice
Aug 4 07:48:59 mike-laptop kernel: [69033.567797] cdc_acm 2-1:1.0: ttyACM0: USB ACM device
Aug 4 07:49:00 mike-laptop nm-system-settings: SCPlugin-Ifupdown: device added (udi: /org/freedesktop/Hal/devices/usb_device_22b8_3002_noserial_if0_serial_unknown_0_3, iface: (null)): iface not found
Aug 4 07:49:00 mike-laptop NetworkManager: <info> (ttyACM0): found serial port (udev:GSM hal:GSM)
Aug 4 07:49:00 mike-laptop NetworkManager: <info> (ttyACM0): new Modem device (driver: 'cdc_acm')
Aug 4 07:49:00 mike-laptop NetworkManager: <info> (ttyACM0): exported as /org/freedesktop/Hal/devices/usb_device_22b8_3002_noserial_if0_serial_unknown_0_3
Aug 4 07:49:05 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 1 -> 2
Aug 4 07:49:05 mike-laptop NetworkManager: <info> (ttyACM0): deactivating device (reason: 2).
Aug 4 07:49:05 mike-laptop NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Aug 4 07:49:05 mike-laptop NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Aug 4 07:49:05 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 2 -> 3
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Activation (ttyACM0) starting connection 'Vodafone'
Aug 4 07:49:05 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 3 -> 4
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) started...
Aug 4 07:49:05 mike-laptop NetworkManager: <debug> [1249328945.012171] nm_serial_device_open(): (ttyACM0) opening device...
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) complete.
Aug 4 07:49:05 mike-laptop NetworkManager: <info> (ttyACM0): powering up...
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Registered on Home network
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Associated with network: +COPS: 0,0,"vodafone NZ"
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Connected, Woo!
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) scheduled...
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) starting...
Aug 4 07:49:05 mike-laptop NetworkManager: <info> (ttyACM0): device state change: 4 -> 5
Aug 4 07:49:05 mike-laptop NetworkManager: <info> Starting pppd connection
Aug 4 07:49:05 mike-laptop NetworkManager: <debug> [1249328945.937676] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute user web ttyACM0 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/6 plugin /usr/lib/pppd/...

Read more...

Revision history for this message
madboy (mike-pie) wrote :

OK having read through https://bugs.launchpad.net/bugs/371291 and done what was suggested, I have been able to connect successfully for the last week. So that could be the fix. :-) Give it a go and see if it works for you. If I run into problems again I will keep you posted.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

I have seen that bug before reporting this one. Not my case at all. In my case it's device itself takes too long to connect, I only need to increase time that NM waits for pppd to finish connection.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

Any update on this?

Revision history for this message
Thomas Hood (jdthood) wrote :

@Vasya: Has this bug been fixed in Ubuntu 12.04?

Changed in network-manager (Ubuntu):
status: New → Incomplete
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for network-manager (Ubuntu) because there has been no activity for 60 days.]

Changed in network-manager (Ubuntu):
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.