GNOME.org
 

Re: NM 0.7.1 rc3 oddness with 3G USB device

Hi,

On Mon, 2009-03-09 at 15:05 -0400, Dan Williams wrote:

> > The devices don't always get cleared from the list of Broadband devices when
> > the device is removed - these can keep mounting up.
> 
> That's quite odd; can you post some logs of this happening in NM?  I've
> heard of similar issues before but we could never nail them down to
> either NM or HAL.

I see the same behaviour with my Huawei e160g dongle: 

When the dongle is inserted, two ttyUSB devices appear. If it is removed
without making a connection, they both disappear again.

After connecting to and disconnecting from the network through the
nm-applet menu, the dongle is left registered to the network (according
to the dongle's LED code). If it is removed in this state, the
lower-numbered tty device remains. When it is reconnected, two tty
devices appear again, for a total of three. Also, the applet menu will
then have two identical entries for the 3g provider. (And it is still
possible to connect.)

NM debug output and syslog attached. (Tested in Ubuntu jaunty alpha 6
(USB stick). FTR, the behavior was the same in Fedora 10 + updates to
0.7.1.99 (live CD).)

Best regards,
Jacob Nielsen


NetworkManager: <info>  starting...
NetworkManager: <info>  (eth0): new Ethernet device (driver: 'r8169')
NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_1f_d0_ad_34_43
NetworkManager: <info>  Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
NetworkManager: <info>  Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
NetworkManager: <info>  (eth0): device state change: 1 -> 2
NetworkManager: <info>  (eth0): bringing up device.
NetworkManager: <info>  (eth0): preparing device.
NetworkManager: <info>  (eth0): deactivating device (reason: 2).
NetworkManager: <info>  (ttyUSB0): detected GSM modem via HAL capabilities
NetworkManager: <info>  (ttyUSB0): new Modem device (driver: 'option')
NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0
NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2
NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3
NetworkManager: <info>  (ttyUSB0): now unmanaged
NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 1
NetworkManager: <info>  (ttyUSB0): cleaning up...
NetworkManager: <info>  (ttyUSB0): taking down device.
NetworkManager: <info>  (ttyUSB0): detected GSM modem via HAL capabilities
NetworkManager: <info>  (ttyUSB0): new Modem device (driver: 'option')
NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0
NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2
NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3
NetworkManager: <info>  Activation (ttyUSB0) starting connection 'oister'
NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <debug> [1236955082.238117] nm_serial_device_open(): (ttyUSB0) opening device...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <debug> [1236955082.344984] nm_serial_debug(): Sending: 'ATZ E0 V1 X4 &C1 +FCLASS=0
'
NetworkManager: <debug> [1236955082.374032] nm_serial_debug(): Got: 'ATZ E0 V1 X4 &C1 +FCLASS=0'
NetworkManager: <debug> [1236955082.374208] nm_serial_debug(): Got: 'ATZ E0 V1 X4 &C1 +FCLASS=0
'
NetworkManager: <debug> [1236955082.381801] nm_serial_debug(): Got: 'ATZ E0 V1 X4 &C1 +FCLASS=0


OK

'
NetworkManager: <debug> [1236955082.381830] nm_serial_debug(): Sending: 'AT+CPIN?
'
NetworkManager: <debug> [1236955082.391706] nm_serial_debug(): Got: '

+CPIN: SIM PIN



OK

'
NetworkManager: <info>  (ttyUSB0): GSM pin secret required
NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4
NetworkManager: <debug> [1236955086.246913] nm_serial_device_open(): (ttyUSB0) opening device...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <debug> [1236955086.348101] nm_serial_debug(): Sending: 'ATZ E0 V1 X4 &C1 +FCLASS=0
'
NetworkManager: <debug> [1236955086.383323] nm_serial_debug(): Got: '

OK

'
NetworkManager: <debug> [1236955086.383363] nm_serial_debug(): Sending: 'AT+CPIN?
'
NetworkManager: <debug> [1236955086.393185] nm_serial_debug(): Got: '

+CPIN: SIM PIN



OK

'
NetworkManager: <debug> [1236955086.393223] nm_serial_debug(): Sending: 'AT+CPIN="1234"
'
NetworkManager: <debug> [1236955086.539307] nm_serial_debug(): Got: '

OK

'
NetworkManager: <debug> [1236955086.539341] nm_serial_debug(): Sending: 'ATZ E0 V1 X4 &C1 +FCLASS=0
'
NetworkManager: <debug> [1236955086.578288] nm_serial_debug(): Got: '

OK

'
NetworkManager: <info>  (ttyUSB0): powering up...
NetworkManager: <debug> [1236955086.578328] nm_serial_debug(): Sending: 'AT+CFUN=1
'
NetworkManager: <debug> [1236955087.727458] nm_serial_debug(): Got: '

OK

'
NetworkManager: <debug> [1236955087.727531] nm_serial_debug(): Sending: 'AT+CGMM
'
NetworkManager: <debug> [1236955087.736680] nm_serial_debug(): Got: '

E160G



OK

'
NetworkManager: <debug> [1236955087.736715] nm_serial_debug(): Sending: 'AT+CGREG?
'
NetworkManager: <debug> [1236955087.751928] nm_serial_debug(): Got: '

+CGREG: 0,2



OK

'
NetworkManager: <info>  Searching for a network...
NetworkManager: <debug> [1236955088.999526] nm_serial_debug(): Sending: 'AT+CGREG?
'
NetworkManager: <debug> [1236955089.014052] nm_serial_debug(): Got: '

+CGREG: 0,2



OK

'
NetworkManager: <info>  Searching for a network...
NetworkManager: <debug> [1236955090.000569] nm_serial_debug(): Sending: 'AT+CGREG?
'
NetworkManager: <debug> [1236955090.014201] nm_serial_debug(): Got: '

+CGREG: 0,2



OK

'
NetworkManager: <info>  Searching for a network...
NetworkManager: <debug> [1236955091.001323] nm_serial_debug(): Sending: 'AT+CGREG?
'
NetworkManager: <debug> [1236955091.013603] nm_serial_debug(): Got: '

+CGREG: 0,2



OK

'
NetworkManager: <info>  Searching for a network...
NetworkManager: <debug> [1236955092.001658] nm_serial_debug(): Sending: 'AT+CGREG?
'
NetworkManager: <debug> [1236955092.012335] nm_serial_debug(): Got: '

+CGREG: 0,1



OK

'
NetworkManager: <info>  Registered on Home network
NetworkManager: <debug> [1236955092.012370] nm_serial_debug(): Sending: 'AT+COPS?
'
NetworkManager: <debug> [1236955092.143122] nm_serial_debug(): Got: '

+COPS: 0,0,"Oister",2



OK

'
NetworkManager: <info>  Associated with network: +COPS: 0,0,"Oister",2
NetworkManager: <debug> [1236955092.143166] nm_serial_debug(): Sending: 'AT+CGDCONT=1,"IP","bredband.oister.dk"
'
NetworkManager: <debug> [1236955092.191741] nm_serial_debug(): Got: '

OK

'
NetworkManager: <debug> [1236955092.191780] nm_serial_debug(): Sending: 'ATD*99***1#
'
NetworkManager: <debug> [1236955092.212860] nm_serial_debug(): Got: '

CONNECT 3600000

'
NetworkManager: <info>  Connected, Woo!
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5
NetworkManager: <info>  Starting pppd connection
NetworkManager: <debug> [1236955092.215318] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute ttyUSB0 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/0 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
NetworkManager: <debug> [1236955092.217997] nm_ppp_manager_start(): ppp started with pid 8764
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB0
NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 6
CHAP authentication succeeded
CHAP authentication succeeded
NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 7
Could not determine remote IP address: defaulting to 10.64.64.64
Cannot determine ethernet address for proxy ARP
local  IP address 10.186.73.93
remote IP address 10.64.64.64
primary   DNS address 80.251.192.244
secondary DNS address 80.251.192.245
NetworkManager: <info>  PPP manager(IP Config Get) reply received.
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) started...
NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8
NetworkManager: <info>  Policy set 'oister' (ppp0) as default for routing and DNS.
NetworkManager: <info>  Activation (ttyUSB0) successful, device activated.
NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete.
NetworkManager: <info>  (ttyUSB0): device state change: 8 -> 3
NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 39).
NetworkManager: <debug> [1236955148.806260] nm_serial_device_close(): Closing device 'ttyUSB0'
Terminating on signal 15
Connect time 0.9 minutes.
Sent 466 bytes, received 744 bytes.
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Connection terminated.
NetworkManager: <debug> [1236955151.000795] ensure_killed(): waiting for ppp pid 8764 to exit
NetworkManager: <debug> [1236955151.000900] ensure_killed(): ppp pid 8764 cleaned up
NetworkManager: <info>  (ttyUSB1): detected GSM modem via HAL capabilities
NetworkManager: <info>  (ttyUSB1): new Modem device (driver: 'option')
NetworkManager: <info>  (ttyUSB1): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0_0
NetworkManager: <info>  (ttyUSB1): device state change: 1 -> 2
NetworkManager: <info>  (ttyUSB1): deactivating device (reason: 2).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
NetworkManager: <info>  (ttyUSB1): device state change: 2 -> 3
NetworkManager: <info>  (ttyUSB1): now unmanaged
NetworkManager: <info>  (ttyUSB1): device state change: 3 -> 1
NetworkManager: <info>  (ttyUSB1): cleaning up...
NetworkManager: <info>  (ttyUSB1): taking down device.

ubuntu ubuntu:~$ tail -f /var/log/syslog 
Mar 13 14:31:25 ubuntu NetworkManager: <info>  (eth0): new Ethernet device (driver: 'r8169') 
Mar 13 14:31:25 ubuntu NetworkManager: <info>  (eth0): exported as /org/freedesktop/Hal/devices/net_00_1f_d0_ad_34_43 
Mar 13 14:31:25 ubuntu NetworkManager: <info>  Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889) 
Mar 13 14:31:25 ubuntu NetworkManager: <info>  Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889) 
Mar 13 14:31:30 ubuntu NetworkManager: <info>  (eth0): device state change: 1 -> 2 
Mar 13 14:31:30 ubuntu NetworkManager: <info>  (eth0): bringing up device. 
Mar 13 14:31:30 ubuntu NetworkManager: <info>  (eth0): preparing device. 
Mar 13 14:31:30 ubuntu NetworkManager: <info>  (eth0): deactivating device (reason: 2). 
Mar 13 14:31:30 ubuntu kernel: [  332.648680] r8169: eth0: link down
Mar 13 14:31:30 ubuntu kernel: [  332.648850] ADDRCONF(NETDEV_UP): eth0: link is not ready

[dongle inserted here. /dev/ttyUSB{0,1} appear, 3g entry appears in nm-applet menu]
Mar 13 14:32:25 ubuntu kernel: [  388.112550] usb 2-4: new high speed USB device using ehci_hcd and address 4
Mar 13 14:32:25 ubuntu kernel: [  388.256703] usb 2-4: configuration #1 chosen from 1 choice
Mar 13 14:32:25 ubuntu kernel: [  388.272297] usb-storage: probe of 2-4:1.0 failed with error -1
Mar 13 14:32:25 ubuntu kernel: [  388.272452] usb 2-4: USB disconnect, address 4
Mar 13 14:32:32 ubuntu kernel: [  394.920536] usb 2-4: new high speed USB device using ehci_hcd and address 5
Mar 13 14:32:32 ubuntu kernel: [  395.063897] usb 2-4: configuration #1 chosen from 1 choice
Mar 13 14:32:32 ubuntu kernel: [  395.072062] usb-storage: probe of 2-4:1.0 failed with error -5
Mar 13 14:32:32 ubuntu kernel: [  395.074106] usb-storage: probe of 2-4:1.1 failed with error -5
Mar 13 14:32:32 ubuntu kernel: [  395.076598] usb-storage: probe of 2-4:1.2 failed with error -1
Mar 13 14:32:32 ubuntu kernel: [  395.079725] usb-storage: probe of 2-4:1.3 failed with error -1
Mar 13 14:32:32 ubuntu kernel: [  395.126965] USB Serial support registered for GSM modem (1-port)
Mar 13 14:32:32 ubuntu kernel: [  395.127005] option 2-4:1.0: GSM modem (1-port) converter detected
Mar 13 14:32:32 ubuntu kernel: [  395.127091] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB0
Mar 13 14:32:32 ubuntu kernel: [  395.127100] option 2-4:1.1: GSM modem (1-port) converter detected
Mar 13 14:32:32 ubuntu kernel: [  395.127132] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
Mar 13 14:32:32 ubuntu kernel: [  395.127146] usbcore: registered new interface driver option
Mar 13 14:32:32 ubuntu kernel: [  395.127148] option: v0.7.2:USB Driver for GSM modems
Mar 13 14:32:37 ubuntu nm-system-settings:    SCPlugin-Ifupdown: device added (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0, iface: (null)): iface not found
Mar 13 14:32:37 ubuntu NetworkManager: <info>  (ttyUSB0): detected GSM modem via HAL capabilities 
Mar 13 14:32:37 ubuntu NetworkManager: <info>  (ttyUSB0): new Modem device (driver: 'option') 
Mar 13 14:32:37 ubuntu NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0 
Mar 13 14:32:41 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2 
Mar 13 14:32:41 ubuntu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2). 
Mar 13 14:32:41 ubuntu NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:32:41 ubuntu NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:32:41 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3 

[dongle removed, no 3g connection was made. /dev/ttyUSB[0-1] disappear]
Mar 13 14:35:19 ubuntu kernel: [  562.532667] usb 2-4: USB disconnect, address 5
Mar 13 14:35:19 ubuntu kernel: [  562.534216] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Mar 13 14:35:19 ubuntu kernel: [  562.534229] option 2-4:1.0: device disconnected
Mar 13 14:35:19 ubuntu kernel: [  562.534363] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Mar 13 14:35:19 ubuntu kernel: [  562.534372] option 2-4:1.1: device disconnected
Mar 13 14:35:19 ubuntu NetworkManager: <info>  (ttyUSB0): now unmanaged 
Mar 13 14:35:19 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 1 
Mar 13 14:35:19 ubuntu NetworkManager: <info>  (ttyUSB0): cleaning up... 
Mar 13 14:35:19 ubuntu NetworkManager: <info>  (ttyUSB0): taking down device. 
Mar 13 14:35:19 ubuntu nm-system-settings:    SCPlugin-Ifupdown: devices removed (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0)

[dongle reinserted. /dev/ttyUSB{0,1} and nm-applet menu item reappear]
Mar 13 14:36:16 ubuntu kernel: [  619.572528] usb 2-4: new high speed USB device using ehci_hcd and address 6
Mar 13 14:36:17 ubuntu kernel: [  619.716253] usb 2-4: configuration #1 chosen from 1 choice
Mar 13 14:36:17 ubuntu kernel: [  619.728578] usb-storage: probe of 2-4:1.0 failed with error -1
Mar 13 14:36:17 ubuntu kernel: [  619.736159] usb 2-4: USB disconnect, address 6
Mar 13 14:36:23 ubuntu kernel: [  626.380023] usb 2-4: new high speed USB device using ehci_hcd and address 7
Mar 13 14:36:23 ubuntu kernel: [  626.524537] usb 2-4: configuration #1 chosen from 1 choice
Mar 13 14:36:23 ubuntu kernel: [  626.538854] usb-storage: probe of 2-4:1.0 failed with error -5
Mar 13 14:36:23 ubuntu kernel: [  626.538867] option 2-4:1.0: GSM modem (1-port) converter detected
Mar 13 14:36:23 ubuntu kernel: [  626.538960] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB0
Mar 13 14:36:23 ubuntu kernel: [  626.539123] usb-storage: probe of 2-4:1.1 failed with error -5
Mar 13 14:36:23 ubuntu kernel: [  626.539128] option 2-4:1.1: GSM modem (1-port) converter detected
Mar 13 14:36:23 ubuntu kernel: [  626.539163] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
Mar 13 14:36:23 ubuntu kernel: [  626.539954] usb-storage: probe of 2-4:1.2 failed with error -1
Mar 13 14:36:23 ubuntu kernel: [  626.542069] usb-storage: probe of 2-4:1.3 failed with error -1
Mar 13 14:36:28 ubuntu nm-system-settings:    SCPlugin-Ifupdown: device added (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0, iface: (null)): iface not found
Mar 13 14:36:28 ubuntu NetworkManager: <info>  (ttyUSB0): detected GSM modem via HAL capabilities 
Mar 13 14:36:28 ubuntu NetworkManager: <info>  (ttyUSB0): new Modem device (driver: 'option') 
Mar 13 14:36:28 ubuntu NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0 
Mar 13 14:36:32 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2 
Mar 13 14:36:32 ubuntu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2). 
Mar 13 14:36:32 ubuntu NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:36:32 ubuntu NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:36:32 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3 

[connect through nm-applet]
Mar 13 14:38:02 ubuntu NetworkManager: <info>  Activation (ttyUSB0) starting connection 'oister' 
Mar 13 14:38:02 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 
Mar 13 14:38:02 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... 
Mar 13 14:38:02 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.238117] nm_serial_device_open(): (ttyUSB0) opening device... 
Mar 13 14:38:02 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.344984] nm_serial_debug(): Sending: 'ATZ E0 V1 X4 &C1 +FCLASS=0 ' 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.374032] nm_serial_debug(): Got: 'ATZ E0 V1 X4 &C1 +FCLASS=0' 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.374208] nm_serial_debug(): Got: 'ATZ E0 V1 X4 &C1 +FCLASS=0 ' 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.381801] nm_serial_debug(): Got: 'ATZ E0 V1 X4 &C1 +FCLASS=0   OK  ' 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.381830] nm_serial_debug(): Sending: 'AT+CPIN? ' 
Mar 13 14:38:02 ubuntu NetworkManager: <debug> [1236955082.391706] nm_serial_debug(): Got: '  +CPIN: SIM PIN    OK  ' 
Mar 13 14:38:02 ubuntu NetworkManager: <info>  (ttyUSB0): GSM pin secret required 
Mar 13 14:38:02 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6 
Mar 13 14:38:06 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... 
Mar 13 14:38:06 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... 
Mar 13 14:38:06 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.246913] nm_serial_device_open(): (ttyUSB0) opening device... 
Mar 13 14:38:06 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.348101] nm_serial_debug(): Sending: 'ATZ E0 V1 X4 &C1 +FCLASS=0 ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.383323] nm_serial_debug(): Got: '  OK  ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.383363] nm_serial_debug(): Sending: 'AT+CPIN? ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.393185] nm_serial_debug(): Got: '  +CPIN: SIM PIN    OK  ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.393223] nm_serial_debug(): Sending: 'AT+CPIN="7240" ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.539307] nm_serial_debug(): Got: '  OK  ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.539341] nm_serial_debug(): Sending: 'ATZ E0 V1 X4 &C1 +FCLASS=0 ' 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.578288] nm_serial_debug(): Got: '  OK  ' 
Mar 13 14:38:06 ubuntu NetworkManager: <info>  (ttyUSB0): powering up... 
Mar 13 14:38:06 ubuntu NetworkManager: <debug> [1236955086.578328] nm_serial_debug(): Sending: 'AT+CFUN=1 ' 
Mar 13 14:38:07 ubuntu NetworkManager: <debug> [1236955087.727458] nm_serial_debug(): Got: '  OK  ' 
Mar 13 14:38:07 ubuntu NetworkManager: <debug> [1236955087.727531] nm_serial_debug(): Sending: 'AT+CGMM ' 
Mar 13 14:38:07 ubuntu NetworkManager: <debug> [1236955087.736680] nm_serial_debug(): Got: '  E160G    OK  ' 
Mar 13 14:38:07 ubuntu NetworkManager: <debug> [1236955087.736715] nm_serial_debug(): Sending: 'AT+CGREG? ' 
Mar 13 14:38:07 ubuntu NetworkManager: <debug> [1236955087.751928] nm_serial_debug(): Got: '  +CGREG: 0,2    OK  ' 
Mar 13 14:38:07 ubuntu NetworkManager: <info>  Searching for a network... 
Mar 13 14:38:08 ubuntu NetworkManager: <debug> [1236955088.999526] nm_serial_debug(): Sending: 'AT+CGREG? ' 
Mar 13 14:38:09 ubuntu NetworkManager: <debug> [1236955089.014052] nm_serial_debug(): Got: '  +CGREG: 0,2    OK  ' 
Mar 13 14:38:09 ubuntu NetworkManager: <info>  Searching for a network... 
Mar 13 14:38:09 ubuntu NetworkManager: <debug> [1236955090.000569] nm_serial_debug(): Sending: 'AT+CGREG? ' 
Mar 13 14:38:10 ubuntu NetworkManager: <debug> [1236955090.014201] nm_serial_debug(): Got: '  +CGREG: 0,2    OK  ' 
Mar 13 14:38:10 ubuntu NetworkManager: <info>  Searching for a network... 
Mar 13 14:38:11 ubuntu NetworkManager: <debug> [1236955091.001323] nm_serial_debug(): Sending: 'AT+CGREG? ' 
Mar 13 14:38:11 ubuntu NetworkManager: <debug> [1236955091.013603] nm_serial_debug(): Got: '  +CGREG: 0,2    OK  ' 
Mar 13 14:38:11 ubuntu NetworkManager: <info>  Searching for a network... 
Mar 13 14:38:11 ubuntu NetworkManager: <debug> [1236955092.001658] nm_serial_debug(): Sending: 'AT+CGREG? ' 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.012335] nm_serial_debug(): Got: '  +CGREG: 0,1    OK  ' 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Registered on Home network 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.012370] nm_serial_debug(): Sending: 'AT+COPS? ' 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.143122] nm_serial_debug(): Got: '  +COPS: 0,0,"Oister",2    OK  ' 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Associated with network: +COPS: 0,0,"Oister",2 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.143166] nm_serial_debug(): Sending: 'AT+CGDCONT=1,"IP","bredband.oister.dk" ' 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.191741] nm_serial_debug(): Got: '  OK  ' 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.191780] nm_serial_debug(): Sending: 'ATD*99***1# ' 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.212860] nm_serial_debug(): Got: '  CONNECT 3600000  ' 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Connected, Woo! 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled... 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting... 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Starting pppd connection 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.215318] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute ttyUSB0 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/0 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so 
Mar 13 14:38:12 ubuntu NetworkManager: <debug> [1236955092.217997] nm_ppp_manager_start(): ppp started with pid 8764 
Mar 13 14:38:12 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete. 
Mar 13 14:38:12 ubuntu pppd[8764]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Mar 13 14:38:12 ubuntu pppd[8764]: pppd 2.4.5 started by root, uid 0
Mar 13 14:38:12 ubuntu pppd[8764]: Using interface ppp0
Mar 13 14:38:12 ubuntu pppd[8764]: Connect: ppp0 <--> /dev/ttyUSB0
Mar 13 14:38:12 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 6 
Mar 13 14:38:12 ubuntu pppd[8764]: CHAP authentication succeeded
Mar 13 14:38:12 ubuntu pppd[8764]: CHAP authentication succeeded
Mar 13 14:38:12 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 7 
Mar 13 14:38:12 ubuntu kernel: [  734.956903] PPP BSD Compression module registered
Mar 13 14:38:12 ubuntu kernel: [  734.962163] PPP Deflate Compression module registered
Mar 13 14:38:16 ubuntu pppd[8764]: Could not determine remote IP address: defaulting to 10.64.64.64
Mar 13 14:38:16 ubuntu pppd[8764]: Cannot determine ethernet address for proxy ARP
Mar 13 14:38:16 ubuntu pppd[8764]: local  IP address 10.186.73.93
Mar 13 14:38:16 ubuntu pppd[8764]: remote IP address 10.64.64.64
Mar 13 14:38:16 ubuntu pppd[8764]: primary   DNS address 80.251.192.244
Mar 13 14:38:16 ubuntu pppd[8764]: secondary DNS address 80.251.192.245
Mar 13 14:38:16 ubuntu NetworkManager: <info>  PPP manager(IP Config Get) reply received. 
Mar 13 14:38:16 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) scheduled... 
Mar 13 14:38:16 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) started... 
Mar 13 14:38:16 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled... 
Mar 13 14:38:16 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) complete. 
Mar 13 14:38:16 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started... 
Mar 13 14:38:17 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8 
Mar 13 14:38:17 ubuntu NetworkManager: <info>  Policy set 'oister' (ppp0) as default for routing and DNS. 
Mar 13 14:38:17 ubuntu NetworkManager: <info>  Activation (ttyUSB0) successful, device activated. 
Mar 13 14:38:17 ubuntu NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete. 
Mar 13 14:38:18 ubuntu ntpdate[8849]: adjust time server 91.189.94.4 offset -0.021476 sec

[disconnect through nm-applet]
Mar 13 14:39:08 ubuntu NetworkManager: <info>  (ttyUSB0): device state change: 8 -> 3 
Mar 13 14:39:08 ubuntu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 39). 
Mar 13 14:39:08 ubuntu NetworkManager: <debug> [1236955148.806260] nm_serial_device_close(): Closing device 'ttyUSB0' 
Mar 13 14:39:08 ubuntu pppd[8764]: Terminating on signal 15
Mar 13 14:39:08 ubuntu pppd[8764]: Connect time 0.9 minutes.
Mar 13 14:39:08 ubuntu pppd[8764]: Sent 466 bytes, received 744 bytes.
Mar 13 14:39:08 ubuntu NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:39:08 ubuntu NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:39:08 ubuntu pppd[8764]: Connection terminated.
Mar 13 14:39:09 ubuntu pppd[8764]: Exit.
Mar 13 14:39:11 ubuntu NetworkManager: <debug> [1236955151.000795] ensure_killed(): waiting for ppp pid 8764 to exit 
Mar 13 14:39:11 ubuntu NetworkManager: <debug> [1236955151.000900] ensure_killed(): ppp pid 8764 cleaned up 

[dongle removed. /dev/ttyUSB1 disappear, /dev/ttyUSB0 remains]
Mar 13 14:40:01 ubuntu /USR/SBIN/CRON[8892]: (root) CMD ([ -x /usr/sbin/update-motd ] && /usr/sbin/update-motd 2>/dev/null)
Mar 13 14:40:15 ubuntu kernel: [  858.081510] usb 2-4: USB disconnect, address 7
Mar 13 14:40:15 ubuntu kernel: [  858.082146] option 2-4:1.0: device disconnected
Mar 13 14:40:15 ubuntu kernel: [  858.082386] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Mar 13 14:40:15 ubuntu kernel: [  858.083530] option 2-4:1.1: device disconnected

[dongle reinserted. /dev/ttyUSB[0-2] are now present. nm-applet menu shows two identical 3g items]
Mar 13 14:41:06 ubuntu kernel: [  908.960546] usb 2-4: new high speed USB device using ehci_hcd and address 8
Mar 13 14:41:06 ubuntu kernel: [  909.105162] usb 2-4: configuration #1 chosen from 1 choice
Mar 13 14:41:06 ubuntu kernel: [  909.131675] usb-storage: probe of 2-4:1.0 failed with error -1
Mar 13 14:41:06 ubuntu kernel: [  909.132655] usb 2-4: USB disconnect, address 8
Mar 13 14:41:13 ubuntu kernel: [  915.768534] usb 2-4: new high speed USB device using ehci_hcd and address 9
Mar 13 14:41:13 ubuntu kernel: [  915.912265] usb 2-4: configuration #1 chosen from 1 choice
Mar 13 14:41:13 ubuntu kernel: [  915.924064] usb-storage: probe of 2-4:1.0 failed with error -5
Mar 13 14:41:13 ubuntu kernel: [  915.924077] option 2-4:1.0: GSM modem (1-port) converter detected
Mar 13 14:41:13 ubuntu kernel: [  915.924164] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB1
Mar 13 14:41:13 ubuntu kernel: [  915.924316] usb-storage: probe of 2-4:1.1 failed with error -5
Mar 13 14:41:13 ubuntu kernel: [  915.924321] option 2-4:1.1: GSM modem (1-port) converter detected
Mar 13 14:41:13 ubuntu kernel: [  915.924356] usb 2-4: GSM modem (1-port) converter now attached to ttyUSB2
Mar 13 14:41:13 ubuntu kernel: [  915.924954] usb-storage: probe of 2-4:1.2 failed with error -1
Mar 13 14:41:13 ubuntu kernel: [  915.931723] usb-storage: probe of 2-4:1.3 failed with error -1
Mar 13 14:41:18 ubuntu nm-system-settings:    SCPlugin-Ifupdown: device added (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0_0, iface: (null)): iface not found
Mar 13 14:41:18 ubuntu NetworkManager: <info>  (ttyUSB1): detected GSM modem via HAL capabilities 
Mar 13 14:41:18 ubuntu NetworkManager: <info>  (ttyUSB1): new Modem device (driver: 'option') 
Mar 13 14:41:18 ubuntu NetworkManager: <info>  (ttyUSB1): exported as /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0_0 
Mar 13 14:41:22 ubuntu NetworkManager: <info>  (ttyUSB1): device state change: 1 -> 2 
Mar 13 14:41:22 ubuntu NetworkManager: <info>  (ttyUSB1): deactivating device (reason: 2). 
Mar 13 14:41:22 ubuntu NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:41:22 ubuntu NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Mar 13 14:41:22 ubuntu NetworkManager: <info>  (ttyUSB1): device state change: 2 -> 3 

[dongle removed, no 3g connection was made. /dev/ttyUSB[1-2] disappear, /dev/ttyUSB0 remains]
Mar 13 14:43:05 ubuntu kernel: [ 1028.176876] usb 2-4: USB disconnect, address 9
Mar 13 14:43:05 ubuntu kernel: [ 1028.178465] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Mar 13 14:43:05 ubuntu kernel: [ 1028.178478] option 2-4:1.0: device disconnected
Mar 13 14:43:05 ubuntu kernel: [ 1028.178619] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Mar 13 14:43:05 ubuntu kernel: [ 1028.178628] option 2-4:1.1: device disconnected
Mar 13 14:43:05 ubuntu NetworkManager: <info>  (ttyUSB1): now unmanaged 
Mar 13 14:43:05 ubuntu NetworkManager: <info>  (ttyUSB1): device state change: 3 -> 1 
Mar 13 14:43:05 ubuntu NetworkManager: <info>  (ttyUSB1): cleaning up... 
Mar 13 14:43:05 ubuntu NetworkManager: <info>  (ttyUSB1): taking down device. 
Mar 13 14:43:05 ubuntu nm-system-settings:    SCPlugin-Ifupdown: devices removed (udi: /org/freedesktop/Hal/devices/usb_device_12d1_1003_noserial_if0_serial_usb_0_0)
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]