NETWORK-MANAGER + UMTS (with intrepid, Simyo-Spain and Huawei e220) FAILING TO CONNECT randomly. WVDIAL WORKING

[trueno]

Binary package hint: network-manager

Hi,

I have been experiencing weird behavior when it comes to connecting to Simyo (Spain) using Ubuntu intrepid (fresh install) and the network-manager. I am using a Huawei e220 and the SIM has PIN disabled.

Sometimes it connects, sometimes it doesn't. However, I have been unable to find the exact problem, and since sudo wvdial works always, it can't be a problem related to the kernel (2.6.27-7) or permissions (it would fail always).

Here you have my package info:
 #dpkg -l
 ii network-manager 0.7~~svn20081018t105859-0ubuntu1 network management framework daemon
ii network-manager-gnome 0.7~~svn20081020t000444-0ubuntu1 network management framework (GNOME frontend

network-manager:
  Instalados: 0.7~~svn20081018t105859-0ubuntu1
  Candidato: 0.7~~svn20081018t105859-0ubuntu1
  Tabla de versión:
 *** 0.7~~svn20081018t105859-0ubuntu1 0
        500 http://es.archive.ubuntu.com intrepid/main Packages
        100 /var/lib/dpkg/status

network-manager-gnome:
  Instalados: 0.7~~svn20081020t000444-0ubuntu1
  Candidato: 0.7~~svn20081020t000444-0ubuntu1
  Tabla de versión:
 *** 0.7~~svn20081020t000444-0ubuntu1 0
        500 http://es.archive.ubuntu.com intrepid/main Packages
        100 /var/lib/dpkg/status

Ubuntu:
Description: Ubuntu 8.10
Release: 8.10

And here you have the logs:
(syslog)

===============================
A.- This log corresponds to the "WORKING" situation:
===============================

Nov 4 14:16:59 peque kernel: [ 551.308081] usb 3-1: new full speed USB device using uhci_hcd and address 2
Nov 4 14:16:59 peque kernel: [ 551.474516] usb 3-1: configuration #1 chosen from 1 choice
Nov 4 14:16:59 peque kernel: [ 551.706643] usbcore: registered new interface driver libusual
Nov 4 14:16:59 peque kernel: [ 551.739098] Initializing USB Mass Storage driver...
Nov 4 14:16:59 peque kernel: [ 551.742389] scsi2 : SCSI emulation for USB Mass Storage devices
Nov 4 14:16:59 peque kernel: [ 551.751810] usbcore: registered new interface driver usb-storage
Nov 4 14:16:59 peque kernel: [ 551.752247] USB Mass Storage support registered.
Nov 4 14:16:59 peque kernel: [ 551.752684] usb-storage: device found at 2
Nov 4 14:16:59 peque kernel: [ 551.752689] usb-storage: waiting for device to settle before scanning
Nov 4 14:17:00 peque kernel: [ 552.191215] usb 3-1: USB disconnect, address 2
Nov 4 14:17:00 peque kernel: [ 552.432062] usb 3-1: new full speed USB device using uhci_hcd and address 3
Nov 4 14:17:00 peque kernel: [ 552.626847] usb 3-1: configuration #1 chosen from 1 choice
Nov 4 14:17:00 peque kernel: [ 552.650052] usb-storage: probe of 3-1:1.0 failed with error -5
Nov 4 14:17:00 peque kernel: [ 552.669988] usb-storage: probe of 3-1:1.1 failed with error -5
Nov 4 14:17:00 peque kernel: [ 552.710006] scsi5 : SCSI emulation for USB Mass Storage devices
Nov 4 14:17:00 peque kernel: [ 552.716673] usb-storage: device found at 3
Nov 4 14:17:00 peque kernel: [ 552.716690] usb-storage: waiting for device to settle before scanning
Nov 4 14:17:00 peque kernel: [ 552.960319] usbcore: registered new interface driver usbserial
Nov 4 14:17:00 peque kernel: [ 552.962160] usbserial: USB Serial support registered for generic
Nov 4 14:17:00 peque kernel: [ 552.963058] usbcore: registered new interface driver usbserial_generic
Nov 4 14:17:00 peque kernel: [ 552.963064] usbserial: USB Serial Driver core
Nov 4 14:17:00 peque kernel: [ 552.998490] usbserial: USB Serial support registered for GSM modem (1-port)
Nov 4 14:17:00 peque kernel: [ 552.999643] option 3-1:1.0: GSM modem (1-port) converter detected
Nov 4 14:17:00 peque kernel: [ 553.001886] usb 3-1: GSM modem (1-port) converter now attached to ttyUSB0
Nov 4 14:17:00 peque kernel: [ 553.002881] option 3-1:1.1: GSM modem (1-port) converter detected
Nov 4 14:17:00 peque kernel: [ 553.003847] usb 3-1: GSM modem (1-port) converter now attached to ttyUSB1
Nov 4 14:17:00 peque kernel: [ 553.005910] usbcore: registered new interface driver option
Nov 4 14:17:00 peque kernel: [ 553.005917] option: USB Driver for GSM modems: v0.7.2
Nov 4 14:17:00 peque nm-system-settings: SCPlugin-Ifupdown: devices added (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0, iface: (null))
Nov 4 14:17:00 peque NetworkManager: <info> ttyUSB0: driver is 'option'.
Nov 4 14:17:00 peque NetworkManager: <debug> [1225804620.946921] setup_monitor_device(): No monitoring udi provided
Nov 4 14:17:00 peque NetworkManager: <info> Found new Modem device 'ttyUSB0'.
Nov 4 14:17:00 peque NetworkManager: <info> (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0
Nov 4 14:17:01 peque CRON[6384]: Sigfile not found
Nov 4 14:17:01 peque /USR/SBIN/CRON[6391]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Nov 4 14:17:01 peque CRON[6384]: Sigfile not found
Nov 4 14:17:04 peque NetworkManager: <info> (ttyUSB0): device state change: 1 -> 2
Nov 4 14:17:05 peque NetworkManager: <info> (ttyUSB0): deactivating device (reason: 2).
Nov 4 14:17:05 peque NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Nov 4 14:17:05 peque NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Nov 4 14:17:05 peque NetworkManager: <info> (ttyUSB0): device state change: 2 -> 3
Nov 4 14:17:05 peque kernel: [ 557.717651] usb-storage: device scan complete
Nov 4 14:17:05 peque kernel: [ 557.720659] scsi 5:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
Nov 4 14:17:05 peque kernel: [ 557.756591] sr1: scsi-1 drive
Nov 4 14:17:05 peque kernel: [ 557.758390] sr 5:0:0:0: Attached scsi CD-ROM sr1
Nov 4 14:17:05 peque kernel: [ 557.760469] sr 5:0:0:0: Attached scsi generic sg2 type 5
Nov 4 14:17:06 peque kernel: [ 558.808075] ACPI: EC: non-query interrupt received, switching to interrupt mode
Nov 4 14:17:11 peque kernel: [ 563.196079] ACPI: EC: non-query interrupt received, switching to interrupt mode
Nov 4 14:17:13 peque kernel: [ 565.396076] ACPI: EC: non-query interrupt received, switching to interrupt mode
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) starting connection 'Simyo'
Nov 4 14:17:17 peque NetworkManager: <info> (ttyUSB0): device state change: 3 -> 4
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Nov 4 14:17:17 peque NetworkManager: <debug> [1225804637.477073] nm_serial_device_open(): (ttyUSB0) opening device...
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Nov 4 14:17:17 peque NetworkManager: <info> (ttyUSB0): powering up...
Nov 4 14:17:17 peque NetworkManager: <info> Registered on Roaming network
Nov 4 14:17:17 peque NetworkManager: <info> Associated with network: +COPS: 0,0,"Orange@",2
Nov 4 14:17:17 peque NetworkManager: <info> Connected, Woo!
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Nov 4 14:17:17 peque NetworkManager: <info> (ttyUSB0): device state change: 4 -> 5
Nov 4 14:17:17 peque NetworkManager: <info> Starting pppd connection
Nov 4 14:17:17 peque NetworkManager: <debug> [1225804637.972887] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock ttyUSB0 noipdefault usepeerdns ipparam /org/freedesktop/NetworkManager/PPP/0 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
Nov 4 14:17:17 peque NetworkManager: <debug> [1225804637.983033] nm_ppp_manager_start(): ppp started with pid 6489
Nov 4 14:17:17 peque NetworkManager: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Nov 4 14:17:18 peque pppd[6489]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Nov 4 14:17:18 peque kernel: [ 570.425669] PPP generic driver version 2.4.2
Nov 4 14:17:18 peque pppd[6489]: pppd 2.4.4 started by root, uid 0
Nov 4 14:17:18 peque pppd[6489]: Using interface ppp0
Nov 4 14:17:18 peque pppd[6489]: Connect: ppp0 <--> /dev/ttyUSB0
Nov 4 14:17:18 peque NetworkManager: <info> (ttyUSB0): device state change: 5 -> 6
Nov 4 14:17:18 peque pppd[6489]: CHAP authentication succeeded
Nov 4 14:17:18 peque pppd[6489]: CHAP authentication succeeded
Nov 4 14:17:18 peque NetworkManager: <info> (ttyUSB0): device state change: 6 -> 7
Nov 4 14:17:18 peque kernel: [ 570.630404] PPP BSD Compression module registered
Nov 4 14:17:18 peque kernel: [ 570.709567] PPP Deflate Compression module registered
Nov 4 14:17:21 peque pppd[6489]: Could not determine remote IP address: defaulting to 10.64.64.64
Nov 4 14:17:21 peque pppd[6489]: Cannot determine ethernet address for proxy ARP
Nov 4 14:17:21 peque pppd[6489]: local IP address 10.2.2.199
Nov 4 14:17:21 peque pppd[6489]: remote IP address 10.64.64.64
Nov 4 14:17:21 peque pppd[6489]: primary DNS address 217.18.32.170
Nov 4 14:17:21 peque pppd[6489]: secondary DNS address 217.18.32.171
Nov 4 14:17:21 peque NetworkManager: <info> PPP manager(IP Config Get) reply received.
Nov 4 14:17:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) scheduled...
Nov 4 14:17:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) started...
Nov 4 14:17:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
Nov 4 14:17:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) complete.
Nov 4 14:17:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
Nov 4 14:17:22 peque NetworkManager: <info> (ttyUSB0): device state change: 7 -> 8
Nov 4 14:17:22 peque NetworkManager: <info> Policy set 'Simyo' (ppp0) as default for routing and DNS.
Nov 4 14:17:22 peque NetworkManager: <info> Activation (ttyUSB0) successful, device activated.
Nov 4 14:17:22 peque NetworkManager: <info> Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 4 14:17:24 peque ntpdate[6591]: adjust time server 91.189.94.4 offset 0.021601 sec
Nov 4 14:17:24 peque kernel: [ 576.404096] ACPI: EC: non-query interrupt received, switching to interrupt mode
Nov 4 14:18:12 peque NetworkManager: <info> (ttyUSB0): device state change: 8 -> 3
Nov 4 14:18:12 peque NetworkManager: <info> (ttyUSB0): deactivating device (reason: 39).
Nov 4 14:18:12 peque pppd[6489]: Terminating on signal 15
Nov 4 14:18:12 peque pppd[6489]: Connect time 0.9 minutes.
Nov 4 14:18:12 peque pppd[6489]: Sent 19651 bytes, received 37581 bytes.
Nov 4 14:18:12 peque NetworkManager: <debug> [1225804692.056142] nm_serial_device_close(): Closing device 'ttyUSB0'
Nov 4 14:18:12 peque NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Nov 4 14:18:12 peque NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Nov 4 14:18:12 peque pppd[6489]: Connection terminated.
Nov 4 14:18:12 peque pppd[6489]: Exit.

==================================
B.- This log corresponds to the "NOT WORKING" situation:
=================================
Nov 4 13:09:11 peque kernel: [ 626.092073] usb 2-1: new full speed USB device using uhci_hcd and address 4
Nov 4 13:09:12 peque kernel: [ 626.258462] usb 2-1: configuration #1 chosen from 1 choice
Nov 4 13:09:12 peque kernel: [ 626.271366] usb-storage: probe of 2-1:1.0 failed with error -5
Nov 4 13:09:12 peque kernel: [ 626.271897] option 2-1:1.0: GSM modem (1-port) converter detected
Nov 4 13:09:12 peque kernel: [ 626.273066] usb 2-1: GSM modem (1-port) converter now attached to ttyUSB0
Nov 4 13:09:12 peque kernel: [ 626.300172] usb-storage: probe of 2-1:1.1 failed with error -5
Nov 4 13:09:12 peque kernel: [ 626.300840] option 2-1:1.1: GSM modem (1-port) converter detected
Nov 4 13:09:12 peque kernel: [ 626.301785] usb 2-1: GSM modem (1-port) converter now attached to ttyUSB1
Nov 4 13:09:12 peque kernel: [ 626.345964] scsi7 : SCSI emulation for USB Mass Storage devices
Nov 4 13:09:12 peque kernel: [ 626.348964] usb-storage: device found at 4
Nov 4 13:09:12 peque kernel: [ 626.348972] usb-storage: waiting for device to settle before scanning
Nov 4 13:09:12 peque nm-system-settings: SCPlugin-Ifupdown: devices added (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0, iface: (null))
Nov 4 13:09:12 peque NetworkManager: <info> ttyUSB0: driver is 'option'.
Nov 4 13:09:12 peque NetworkManager: <debug> [1225800552.772520] setup_monitor_device(): No monitoring udi provided
Nov 4 13:09:12 peque NetworkManager: <info> Found new Modem device 'ttyUSB0'.
Nov 4 13:09:12 peque NetworkManager: <info> (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0
Nov 4 13:09:16 peque NetworkManager: <info> (ttyUSB0): device state change: 1 -> 2
Nov 4 13:09:16 peque NetworkManager: <info> (ttyUSB0): deactivating device (reason: 2).
Nov 4 13:09:16 peque NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Nov 4 13:09:16 peque NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Nov 4 13:09:16 peque NetworkManager: <info> (ttyUSB0): device state change: 2 -> 3
Nov 4 13:09:17 peque kernel: [ 631.349594] usb-storage: device scan complete
Nov 4 13:09:17 peque kernel: [ 631.352613] scsi 7:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
Nov 4 13:09:17 peque kernel: [ 631.386542] sr1: scsi-1 drive
Nov 4 13:09:17 peque kernel: [ 631.387167] sr 7:0:0:0: Attached scsi CD-ROM sr1
Nov 4 13:09:17 peque kernel: [ 631.387892] sr 7:0:0:0: Attached scsi generic sg2 type 5
Nov 4 13:09:21 peque NetworkManager: <info> Activation (ttyUSB0) starting connection 'Simyo'
Nov 4 13:09:21 peque NetworkManager: <info> (ttyUSB0): device state change: 3 -> 4
Nov 4 13:09:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 4 13:09:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Nov 4 13:09:21 peque NetworkManager: <debug> [1225800561.446078] nm_serial_device_open(): (ttyUSB0) opening device...
Nov 4 13:09:21 peque NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Nov 4 13:09:21 peque NetworkManager: <info> (ttyUSB0): powering up...
Nov 4 13:09:21 peque NetworkManager: <info> Registered on Roaming network
Nov 4 13:09:22 peque kernel: [ 637.044102] ACPI: EC: non-query interrupt received, switching to interrupt mode
Nov 4 13:09:32 peque NetworkManager: <info> Associated with network: +COPS: 0,0,"Orange
Nov 4 13:09:32 peque NetworkManager: Invalid byte sequence in conversion input
Nov 4 13:09:40 peque NetworkManager: <WARN> set_apn_done(): Setting APN failed
Nov 4 13:09:40 peque NetworkManager: <info> (ttyUSB0): device state change: 4 -> 9
Nov 4 13:09:40 peque NetworkManager: <debug> [1225800580.002771] nm_serial_device_close(): Closing device 'ttyUSB0'
Nov 4 13:09:40 peque NetworkManager: <info> Marking connection 'Simyo' invalid.
Nov 4 13:09:40 peque NetworkManager: <info> Activation (ttyUSB0) failed.
Nov 4 13:09:40 peque NetworkManager: <info> (ttyUSB0): device state change: 9 -> 3
Nov 4 13:09:40 peque NetworkManager: <info> (ttyUSB0): deactivating device (reason: 0).
============================
C.- My wvdial.conf is here:
============================
[Dialer Defaults]
Init1 = ATZ
Init2 = ATQ0 V1 E1 S0=0 &C1 &D2 +FCLASS=0
Modem Type = Analog Modem
Baud = 9600
New PPPD = yes
Modem = /dev/ttyUSB0
ISDN = 0
Stupid Mode = 1
Phone = *99#
Password = dummy
Username = dummy

It might be related to the parsing of the string data by network-manager. The line:
Associated with network: +COPS: 0,0,"Orange
in the not-working log seems to lack the end of the string:
Associated with network: +COPS: 0,0,"Orange@",2
that appears in the working section.

Hope it helps,

Thanks for following.

[Alexander Sack (asac)]

marking as duplicate of bug 290177 ... there is a suggested patch. also Bug #268667 might also cause issues once you have that patch.

[trueno (wasteandcrap)]

Alex, please note that the behavior posted above is experienced with the PIN DISABLED.

Thus, I don't think this bug is a duplicate of bug 290177.

Thanks,

[Alexander Sack (asac)]

trueno wrote:
> *** This bug is a duplicate of bug 290177 ***
> https://bugs.launchpad.net/bugs/290177
>
> Alex, please note that the behavior posted above is experienced with the
> PIN DISABLED.
>
> Thus, I don't think this bug is a duplicate of bug 290177.
>
>

feel free to undupe this bug then. Can you reproduce with latest
intrepid-updates packages? If so, you could also test that this issue is
in the bits available in network-manager team PPA
(https://edge.launchpad.net/~network-manager/+archive)

Thanks!

> Thanks,
>
>

[trueno (wasteandcrap)]

Hi, Alex!!

I've been testing the packages you proposed, and there is maybe a slight increase in the number of successful connections, but still far from 100% (achieved using "sudo wvdial" and the wvdial.conf above).

The connection settings for the Spanish Simyo connection are the default ones provided in the packages.

My opinion is that there must be a problem related to nm since there's no point in wvdial connecting 100% of the times and nm only 50-60%.

Cheers and thanks,

[Sam Lown (samlown)]

Hi,

I too am having the same problems and I do not believe this to a duplicate with the other issues mentioned.

I have exactly the same situation as the original poster except I'm using Bankinter as opposed to Simyo (which uses the same setup). I've also disabled the PIN and the modem flashes Blue rather than Green to show its found a connection.

wvdial works perfectly, were-as I have only managed to get NM to work once.

With NetworkManager in debug mode, I have exactly the same output as originally mentioned where the specific place things start to go wrong is the following:

NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info> (ttyUSB0): powering up...
NetworkManager: <info> Registered on Roaming network
NetworkManager: <info> Associated with network: +COPS: 0,0,"Orange
NetworkManager: Invalid byte sequence in conversion input
NetworkManager: <WARN> set_apn_done(): Setting APN failed

I've added the PPA repository as suggested, but the upgrade did not appear to change the network-manager applications version, only a few other related libraries. Is there something else I need to do to get NM itself to upgrade?

I should also mention that I am having problems with hal detecting the modem. I need to restart hal for the modem to be found and consequently be shown in NM. This should be unrelated, but perhaps there is a relation...

Let me know if I can provide any further information!

Cheers, sam