Unnamed

Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Vodafone UK'
Sep 10 14:30:40 lucid NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Sep 10 14:30:40 lucid NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6 (reason 0)
Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Sep 10 14:30:40 lucid NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4 (reason 0)
Sep 10 14:30:40 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Sep 10 14:30:41 lucid NetworkManager: <WARN>  stage1_enable_done(): GSM modem enable failed: (32) org.freedesktop.ModemManager.Modem.Gsm.SimPinRequired: 
Sep 10 14:30:41 lucid NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6 (reason 0)
Sep 10 14:30:46 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 10 14:30:46 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Sep 10 14:30:46 lucid NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4 (reason 0)
Sep 10 14:30:46 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Sep 10 14:30:46 lucid NetworkManager: <WARN>  stage1_enable_done(): GSM modem enable failed: (32) org.freedesktop.ModemManager.Modem.Gsm.SimPinRequired: 
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Sep 10 14:30:56 lucid NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
Sep 10 14:30:56 lucid NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
Sep 10 14:30:56 lucid NetworkManager: <info>  Starting pppd connection
Sep 10 14:30:56 lucid NetworkManager: <debug> [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: <debug> [1284125456.412166] nm_ppp_manager_start(): ppp started with pid 4266
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
Sep 10 14:30:56 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
Sep 10 14:30:56 lucid NetworkManager: <info>  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: <info>  PPP manager(IP Config Get) reply received.
Sep 10 14:31:07 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Sep 10 14:31:07 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) started...
Sep 10 14:31:07 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
Sep 10 14:31:07 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) complete.
Sep 10 14:31:07 lucid NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
Sep 10 14:31:08 lucid NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for routing and DNS.
Sep 10 14:31:08 lucid NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8 (reason 0)
Sep 10 14:31:08 lucid NetworkManager: <info>  Activation (ttyUSB0) successful, device activated.
Sep 10 14:31:08 lucid NetworkManager: <info>  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 <HuaweiK3520 dport: /dev/ttyUSB0 cport: /dev/ttyUSB2> with opath /org/freedesktop/ModemManager/Devices/0

2010-09-10 14:30:28+0100 [-] wrapping plugin <HuaweiK3520 dport: /dev/ttyUSB0 cport: /dev/ttyUSB2> with class <class 'wader.plugins.huawei_k3520.HuaweiK3520Wrapper'>
2010-09-10 14:30:28+0100 [-] exporting <HuaweiK3520 dport: /dev/ttyUSB0 cport: /dev/ttyUSB2> methods with class <class 'wader.common.exported.WCDMAExporter'>
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',)]