Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) starting connection 'Vodafone UK' Sep 10 14:30:40 lucid NetworkManager: (ttyUSB0): device state change: 3 -> 4 (reason 0) Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... Sep 10 14:30:40 lucid NetworkManager: (ttyUSB0): device state change: 4 -> 6 (reason 0) Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... Sep 10 14:30:40 lucid NetworkManager: (ttyUSB0): device state change: 6 -> 4 (reason 0) Sep 10 14:30:40 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. Sep 10 14:30:41 lucid NetworkManager: stage1_enable_done(): GSM modem enable failed: (32) org.freedesktop.ModemManager.Modem.Gsm.SimPinRequired: Sep 10 14:30:41 lucid NetworkManager: (ttyUSB0): device state change: 4 -> 6 (reason 0) Sep 10 14:30:46 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... Sep 10 14:30:46 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... Sep 10 14:30:46 lucid NetworkManager: (ttyUSB0): device state change: 6 -> 4 (reason 0) Sep 10 14:30:46 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. Sep 10 14:30:46 lucid NetworkManager: stage1_enable_done(): GSM modem enable failed: (32) org.freedesktop.ModemManager.Modem.Gsm.SimPinRequired: Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled... Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting... Sep 10 14:30:56 lucid NetworkManager: (ttyUSB0): device state change: 4 -> 5 (reason 0) Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful. Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled. Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete. Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started... Sep 10 14:30:56 lucid NetworkManager: (ttyUSB0): device state change: 5 -> 7 (reason 0) Sep 10 14:30:56 lucid NetworkManager: Starting pppd connection Sep 10 14:30:56 lucid NetworkManager: [1284125456.409478] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute user web ttyUSB0 noipdefault noauth refuse-eap refuse-mschap refuse-mschap-v2 usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/10 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so Sep 10 14:30:56 lucid NetworkManager: [1284125456.412166] nm_ppp_manager_start(): ppp started with pid 4266 Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled... Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete. Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started... Sep 10 14:30:56 lucid NetworkManager: Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete. Sep 10 14:30:56 lucid NetworkManager: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0) Sep 10 14:30:56 lucid NetworkManager: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found. Sep 10 14:31:07 lucid NetworkManager: PPP manager(IP Config Get) reply received. Sep 10 14:31:07 lucid NetworkManager: Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) scheduled... Sep 10 14:31:07 lucid NetworkManager: Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) started... Sep 10 14:31:07 lucid NetworkManager: Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled... Sep 10 14:31:07 lucid NetworkManager: Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) complete. Sep 10 14:31:07 lucid NetworkManager: Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started... Sep 10 14:31:08 lucid NetworkManager: Policy set 'Auto eth0' (eth0) as default for routing and DNS. Sep 10 14:31:08 lucid NetworkManager: (ttyUSB0): device state change: 7 -> 8 (reason 0) Sep 10 14:31:08 lucid NetworkManager: Activation (ttyUSB0) successful, device activated. Sep 10 14:31:08 lucid NetworkManager: Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete. Sep 10 14:31:09 lucid ntpdate[4291]: adjust time server 91.189.94.4 offset 0.071252 sec ======================================= 2010-09-10 14:30:06+0100 [-] twistd 10.0.0 (/usr/bin/python 2.6.5) starting up. 2010-09-10 14:30:06+0100 [-] reactor class: twisted.internet.glib2reactor.Glib2Reactor. 2010-09-10 14:30:18+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.0 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.0 action: remove 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1 action: remove 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.3 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.1 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.2 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.2/ttyUSB2/tty/ttyUSB2 action: add 2010-09-10 14:30:19+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.1/ttyUSB1/tty/ttyUSB1 action: add 2010-09-10 14:30:20+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.0 action: add 2010-09-10 14:30:20+0100 [-] UEVENT device: /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1/4-1:1.0/ttyUSB0/tty/ttyUSB0 action: add 2010-09-10 14:30:26+0100 [-] get_plugin_by_id called with 0x12D1 and 0x1001 2010-09-10 14:30:26+0100 [-] /dev/ttyUSB0: ID_MM_PORT_TYPE_MODEM 2010-09-10 14:30:26+0100 [-] /dev/ttyUSB2: ID_MM_PORT_TYPE_AUX 2010-09-10 14:30:27+0100 [-] at+cgmm response: ['K3520'] 2010-09-10 14:30:28+0100 [-] registering plugin with opath /org/freedesktop/ModemManager/Devices/0 2010-09-10 14:30:28+0100 [-] wrapping plugin with class 2010-09-10 14:30:28+0100 [-] exporting methods with class 2010-09-10 14:30:28+0100 [-] emitting DeviceAdded('/org/freedesktop/ModemManager/Devices/0') 2010-09-10 14:30:41+0100 [-] starting AuthStateMachine ... 2010-09-10 14:30:41+0100 [-] authentication_sm: transition to get_pin_status mode.... 2010-09-10 14:30:41+0100 [ttyUSB2] idle: sending 'AT+CPIN?' 2010-09-10 14:30:41+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:41+0100 [ttyUSB2] waiting: callback = [('SIM PIN',)] 2010-09-10 14:30:41+0100 [ttyUSB2] authentication_sm: notifying auth failure org.freedesktop.ModemManager.Modem.Gsm.SimPinRequired: 2010-09-10 14:30:41+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:46+0100 [-] starting AuthStateMachine ... 2010-09-10 14:30:46+0100 [-] authentication_sm: transition to get_pin_status mode.... 2010-09-10 14:30:46+0100 [ttyUSB2] idle: sending 'AT+CPIN?' 2010-09-10 14:30:46+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:46+0100 [ttyUSB2] waiting: callback = [('SIM PIN',)] 2010-09-10 14:30:46+0100 [ttyUSB2] authentication_sm: notifying auth failure org.freedesktop.ModemManager.Modem.Gsm.SimPinRequired: 2010-09-10 14:30:46+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:46+0100 [ttyUSB2] idle: sending 'AT+CPIN="0000"' 2010-09-10 14:30:46+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:46+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:46+0100 [ttyUSB2] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem {'UnlockRequired': ''} 2010-09-10 14:30:46+0100 [ttyUSB2] giving the device 6 seconds to settle, waiting... 2010-09-10 14:30:46+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:51+0100 [ttyUSB2] idle: '\r\n^RSSI:1\r\n' 2010-09-10 14:30:51+0100 [ttyUSB2] emitting SignalQuality(3) 2010-09-10 14:30:52+0100 [ttyUSB2] idle: '\r\n^MODE:5,4\r\n' 2010-09-10 14:30:52+0100 [ttyUSB2] emitting NetworkMode(8) 2010-09-10 14:30:52+0100 [ttyUSB2] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem.Gsm.Network {'AccessTechnology': 5} 2010-09-10 14:30:52+0100 [ttyUSB2] idle: '\r\n^SIMST:1\r\n\r\n^SRVST:2\r\n' 2010-09-10 14:30:52+0100 [ttyUSB2] idle: '\r\n^MODE:3,2\r\n' 2010-09-10 14:30:52+0100 [ttyUSB2] emitting NetworkMode(2) 2010-09-10 14:30:52+0100 [ttyUSB2] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem.Gsm.Network {'AccessTechnology': 3} 2010-09-10 14:30:52+0100 [-] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem {'Enabled': False} 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CFUN?' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('1',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CMEE=1' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CSCS=?' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('IRA',), ('GSM',), ('UCS2',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CNMI=1,1,0,1,0' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CMGF=0' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CPBR=?' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting Traceback (most recent call last): Failure: wader.common.aterrors.SimBusy: org.freedesktop.ModemManager.Modem.Gsm.SimBusy: +CME ERROR: 14 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CSCS?' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('IRA',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:52+0100 [ttyUSB2] idle: sending 'AT+CSCS="UCS2"' 2010-09-10 14:30:52+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:52+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:52+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:55+0100 [ttyUSB2] idle: '\r\n^MODE:3,2\r\n' 2010-09-10 14:30:55+0100 [ttyUSB2] emitting NetworkMode(2) 2010-09-10 14:30:55+0100 [ttyUSB2] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem.Gsm.Network {'AccessTechnology': 3} 2010-09-10 14:30:55+0100 [ttyUSB2] idle: '\r\n^RSSI:17\r\n' 2010-09-10 14:30:55+0100 [ttyUSB2] emitting SignalQuality(54) 2010-09-10 14:30:55+0100 [ttyUSB2] idle: sending 'AT+CPBR=?' 2010-09-10 14:30:55+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:55+0100 [ttyUSB2] waiting: callback = [('200',)] 2010-09-10 14:30:55+0100 [ttyUSB2] Setting size to 200 2010-09-10 14:30:55+0100 [ttyUSB2] initialize returning 2010-09-10 14:30:55+0100 [ttyUSB2] daemon NetworkRegistrationDaemon started... 2010-09-10 14:30:55+0100 [ttyUSB2] executing NetworkRegistrationDaemon.function every 120 seconds 2010-09-10 14:30:55+0100 [ttyUSB2] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem {'UnlockRetries': 999} 2010-09-10 14:30:55+0100 [ttyUSB2] emitting MmPropertiesChanged: org.freedesktop.ModemManager.Modem.Gsm.Card {'SupportedBands': dbus.UInt32(62L)} 2010-09-10 14:30:55+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:55+0100 [ttyUSB2] idle: sending 'AT^CURC=1' 2010-09-10 14:30:55+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:55+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:55+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:55+0100 [ttyUSB2] idle: sending 'AT^SYSCFG?' 2010-09-10 14:30:55+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:55+0100 [ttyUSB2] waiting: callback = [('2', '0', '3FFFFFFF', '1', '2')] 2010-09-10 14:30:55+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:55+0100 [ttyUSB2] idle: sending 'AT+COPS=3,0' 2010-09-10 14:30:55+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:55+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:55+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:55+0100 [ttyUSB2] idle: sending 'AT+CPMS="SM","SM","SM"' 2010-09-10 14:30:55+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:55+0100 [ttyUSB2] waiting: callback = [('OK',)] 2010-09-10 14:30:55+0100 [ttyUSB2] state change: waiting -> idle 2010-09-10 14:30:55+0100 [ttyUSB2] idle: sending 'AT+CLCK="SC",2' 2010-09-10 14:30:55+0100 [ttyUSB2] state change: idle -> waiting 2010-09-10 14:30:56+0100 [ttyUSB2] waiting: callback = [('1',)]