PIN handling problem on Connect automatically

[Sérgio Basto <sergio serjux com>]

Hi, on my HUAWEI E1550 HSDPA usb stick,

If I do automatically , I got always 
Oct 26 17:33:19 segulix modem-manager[1014]: <info>  (ttyUSB3) opening
serial port...
Oct 26 17:33:19 segulix modem-manager[1014]: Invalid error code: 500
Oct 26 17:33:19 segulix modem-manager[1014]: Invalid error code: 303

but now I checked, if I use PIN dialog that pop-up and go, very fast, to
nm-applet to connect broad band , I got same error.
If, I use PIN dialog  , to unlock modem , and wait a few seconds, I
connect without problems .
In short, we have to wait a few time (one or two seconds) after unlock
modem, to connect.

Thanks,

-- 
Sérgio M. B.

Oct 26 17:32:38 segulix kernel: [71589.982167] usb 2-1.3: new high speed USB device number 18 using ehci_hcd
Oct 26 17:32:38 segulix kernel: [71590.079105] usb 2-1.3: New USB device found, idVendor=12d1, idProduct=1446
Oct 26 17:32:38 segulix kernel: [71590.079110] usb 2-1.3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 26 17:32:38 segulix kernel: [71590.079114] usb 2-1.3: Product: HUAWEI Mobile
Oct 26 17:32:38 segulix kernel: [71590.079117] usb 2-1.3: Manufacturer: HUAWEI Technology
Oct 26 17:32:38 segulix kernel: [71590.083813] scsi21 : usb-storage 2-1.3:1.0
Oct 26 17:32:38 segulix kernel: [71590.084256] scsi22 : usb-storage 2-1.3:1.1
Oct 26 17:32:38 segulix mtp-probe: checking bus 2, device 18: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3"
Oct 26 17:32:38 segulix mtp-probe: bus: 2, device: 18 was not an MTP device
Oct 26 17:32:39 segulix usb_modeswitch: switching 12d1:1446 (HUAWEI Technology: HUAWEI Mobile)
Oct 26 17:32:39 segulix kernel: [71590.828025] usb 2-1.3: USB disconnect, device number 18
Oct 26 17:32:45 segulix kernel: [71596.883011] usb 2-1.3: new high speed USB device number 19 using ehci_hcd
Oct 26 17:32:45 segulix kernel: [71596.980084] usb 2-1.3: New USB device found, idVendor=12d1, idProduct=140c
Oct 26 17:32:45 segulix kernel: [71596.980089] usb 2-1.3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 26 17:32:45 segulix kernel: [71596.980093] usb 2-1.3: Product: HUAWEI Mobile
Oct 26 17:32:45 segulix kernel: [71596.980096] usb 2-1.3: Manufacturer: HUAWEI Technology
Oct 26 17:32:45 segulix kernel: [71596.985221] option 2-1.3:1.0: GSM modem (1-port) converter detected
Oct 26 17:32:45 segulix kernel: [71596.985393] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB0
Oct 26 17:32:45 segulix kernel: [71596.985775] option 2-1.3:1.1: GSM modem (1-port) converter detected
Oct 26 17:32:45 segulix kernel: [71596.985942] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB1
Oct 26 17:32:45 segulix kernel: [71596.986231] option 2-1.3:1.2: GSM modem (1-port) converter detected
Oct 26 17:32:45 segulix kernel: [71596.986372] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB2
Oct 26 17:32:45 segulix kernel: [71596.986623] option 2-1.3:1.3: GSM modem (1-port) converter detected
Oct 26 17:32:45 segulix kernel: [71596.986760] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB3
Oct 26 17:32:45 segulix kernel: [71596.987472] scsi27 : usb-storage 2-1.3:1.4
Oct 26 17:32:45 segulix kernel: [71596.988422] scsi28 : usb-storage 2-1.3:1.5
Oct 26 17:32:46 segulix usb_modeswitch: switched to 12d1:140c (HUAWEI Technology: HUAWEI Mobile)
Oct 26 17:32:46 segulix kernel: [71597.989212] scsi 27:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Oct 26 17:32:46 segulix kernel: [71597.991301] scsi 28:0:0:0: Direct-Access     HUAWEI   MMC Storage      2.31 PQ: 0 ANSI: 2
Oct 26 17:32:46 segulix kernel: [71598.127388] sr1: scsi-1 drive
Oct 26 17:32:46 segulix kernel: [71598.128099] sr 27:0:0:0: Attached scsi generic sg2 type 5
Oct 26 17:32:46 segulix kernel: [71598.128642] sd 28:0:0:0: Attached scsi generic sg3 type 0
Oct 26 17:32:46 segulix kernel: [71598.137265] sd 28:0:0:0: [sdb] Attached SCSI removable disk
Oct 26 17:32:46 segulix mtp-probe: checking bus 2, device 19: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3"
Oct 26 17:32:47 segulix mtp-probe: bus: 2, device: 19 was not an MTP device
Oct 26 17:32:47 segulix modem-manager[1014]: <info>  (ttyUSB0) opening serial port...
Oct 26 17:32:51 segulix modem-manager[1014]: <info>  (ttyUSB0) closing serial port...
Oct 26 17:32:51 segulix modem-manager[1014]: <info>  (ttyUSB0) serial port closed
Oct 26 17:32:51 segulix modem-manager[1014]: <info>  (ttyUSB0) opening serial port...
Oct 26 17:32:51 segulix modem-manager[1014]: <info>  (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3 claimed port
ttyUSB0
Oct 26 17:32:52 segulix modem-manager[1014]: <info>  (ttyUSB0) closing serial port...
Oct 26 17:32:52 segulix modem-manager[1014]: <info>  (ttyUSB0) serial port closed
Oct 26 17:32:53 segulix modem-manager[1014]: <info>  (ttyUSB1) opening serial port...
Oct 26 17:32:53 segulix modem-manager[1014]: <info>  (ttyUSB2) opening serial port...
Oct 26 17:32:53 segulix modem-manager[1014]: <info>  (ttyUSB3) opening serial port...
Oct 26 17:32:55 segulix modem-manager[1014]: <info>  (ttyUSB3) closing serial port...
Oct 26 17:32:55 segulix modem-manager[1014]: <info>  (ttyUSB3) serial port closed
Oct 26 17:32:55 segulix modem-manager[1014]: <info>  (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3 claimed port
ttyUSB3
Oct 26 17:33:02 segulix kernel: [71613.713971] sd 28:0:0:0: [sdb] 1888256 512-byte logical blocks: (966 MB/922 MiB)
Oct 26 17:33:02 segulix kernel: [71613.719978] sd 28:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Oct 26 17:33:02 segulix kernel: [71613.736688]  sdb:
Oct 26 17:33:05 segulix modem-manager[1014]: <info>  (ttyUSB1) closing serial port...
Oct 26 17:33:05 segulix modem-manager[1014]: <info>  (ttyUSB1) serial port closed
Oct 26 17:33:05 segulix modem-manager[1014]: <info>  (ttyUSB1) opening serial port...
Oct 26 17:33:05 segulix modem-manager[1014]: <info>  (ttyUSB2) closing serial port...
Oct 26 17:33:05 segulix modem-manager[1014]: <info>  (ttyUSB2) serial port closed
Oct 26 17:33:05 segulix modem-manager[1014]: <info>  (ttyUSB2) opening serial port...
Oct 26 17:33:08 segulix modem-manager[1014]: <info>  (ttyUSB2) closing serial port...
Oct 26 17:33:08 segulix modem-manager[1014]: <info>  (ttyUSB2) serial port closed
Oct 26 17:33:08 segulix modem-manager[1014]: <info>  (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3 claimed port
ttyUSB2
Oct 26 17:33:11 segulix modem-manager[1014]: <info>  (ttyUSB1) closing serial port...
Oct 26 17:33:11 segulix modem-manager[1014]: <info>  (ttyUSB1) serial port closed
Oct 26 17:33:11 segulix NetworkManager[19931]: <warn> (ttyUSB0): failed to look up interface index
Oct 26 17:33:11 segulix NetworkManager[19931]: <info> (ttyUSB0): new GSM/UMTS device (driver: 'option1' ifindex: -1)
Oct 26 17:33:11 segulix NetworkManager[19931]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/4
Oct 26 17:33:11 segulix NetworkManager[19931]: <info> (ttyUSB0): now managed
Oct 26 17:33:11 segulix NetworkManager[19931]: <info> (ttyUSB0): device state change: unmanaged -> unavailable (reason 'managed') [10 20
2]
Oct 26 17:33:11 segulix NetworkManager[19931]: <info> (ttyUSB0): deactivating device (reason 'managed') [2]
Oct 26 17:33:11 segulix NetworkManager[19931]: nm_system_iface_flush_routes: assertion `ifindex > 0' failed
Oct 26 17:33:11 segulix NetworkManager[19931]: nm_system_iface_flush_addresses: assertion `ifindex > 0' failed
Oct 26 17:33:11 segulix NetworkManager[19931]: <info> (ttyUSB0): device state change: unavailable -> disconnected (reason 'none') [20 30
0]
Oct 26 17:33:16 segulix modem-manager[1014]: <info>  (ttyUSB0) opening serial port...
Oct 26 17:33:16 segulix modem-manager[1014]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: unlock no longer required
Oct 26 17:33:16 segulix modem-manager[1014]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: # unlock retries is 0
Oct 26 17:33:16 segulix modem-manager[1014]: <info>  (ttyUSB0) closing serial port...
Oct 26 17:33:16 segulix modem-manager[1014]: <info>  (ttyUSB0) serial port closed
Oct 26 17:33:18 segulix NetworkManager[19931]: <info> Activation (ttyUSB0) starting connection 'cartao1'
Oct 26 17:33:18 segulix NetworkManager[19931]: <info> (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 26 17:33:18 segulix NetworkManager[19931]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 26 17:33:18 segulix NetworkManager[19931]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Oct 26 17:33:18 segulix NetworkManager[19931]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Oct 26 17:33:18 segulix modem-manager[1014]: <info>  (ttyUSB0) opening serial port...
Oct 26 17:33:18 segulix modem-manager[1014]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Oct 26 17:33:19 segulix modem-manager[1014]: <info>  (ttyUSB3) opening serial port...
Oct 26 17:33:19 segulix modem-manager[1014]: Invalid error code: 500
Oct 26 17:33:19 segulix modem-manager[1014]: Invalid error code: 303
Oct 26 17:33:19 segulix modem-manager[1014]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> enabled)
Oct 26 17:33:19 segulix NetworkManager[19931]: <info> WWAN now enabled by management service
Oct 26 17:33:20 segulix modem-manager[1014]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabled -> searching)
Oct 26 17:33:25 segulix kernel: [71636.407906] sdb: detected capacity change from 966787072 to 0
Oct 26 17:33:25 segulix kernel: [71636.452862] option: option_instat_callback: error -71
Oct 26 17:33:25 segulix kernel: [71636.453837] option: option_instat_callback: error -71
Oct 26 17:33:25 segulix kernel: [71636.573041] usb 2-1.3: USB disconnect, device number 19
Oct 26 17:33:25 segulix kernel: [71636.573244] option: option_instat_callback: error -108
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (ttyUSB0) closing serial port...
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (ttyUSB0) serial port closed
Oct 26 17:33:25 segulix kernel: [71636.573462] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Oct 26 17:33:25 segulix kernel: [71636.573485] option 2-1.3:1.0: device disconnected
Oct 26 17:33:25 segulix kernel: [71636.573725] option: option_instat_callback: error -108
Oct 26 17:33:25 segulix kernel: [71636.573856] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Oct 26 17:33:25 segulix kernel: [71636.573895] option 2-1.3:1.1: device disconnected
Oct 26 17:33:25 segulix kernel: [71636.574063] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Oct 26 17:33:25 segulix kernel: [71636.574088] option 2-1.3:1.2: device disconnected
Oct 26 17:33:25 segulix kernel: [71636.574301] option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
Oct 26 17:33:25 segulix kernel: [71636.574356] option 2-1.3:1.3: device disconnected
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (ttyUSB3) closing serial port...
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (ttyUSB3) serial port closed
Oct 26 17:33:25 segulix NetworkManager[19931]: <warn> GSM connection failed: (32) Serial port is now closed
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): device state change: prepare -> failed (reason 'unknown') [40 120 1]
Oct 26 17:33:25 segulix NetworkManager[19931]: <warn> Activation (ttyUSB0) failed.
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): deactivating device (reason 'none') [0]
Oct 26 17:33:25 segulix NetworkManager[19931]: nm_system_iface_flush_routes: assertion `ifindex > 0' failed
Oct 26 17:33:25 segulix NetworkManager[19931]: nm_system_iface_flush_addresses: assertion `ifindex > 0' failed
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> Policy set 'System eth0' (eth0) as default for IPv4 routing and DNS.
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> Policy set 'System eth0' (eth0) as default for IPv4 routing and DNS.
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (tty/ttyUSB3): released by modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (tty/ttyUSB2): released by modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  (tty/ttyUSB0): released by modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3
Oct 26 17:33:25 segulix modem-manager[1014]: <info>  Modem /org/freedesktop/ModemManager/Modems/2: state changed (searching -> disabled)
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): now unmanaged
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): device state change: disconnected -> unmanaged (reason 'removed') [30 10
36]
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): cleaning up...
Oct 26 17:33:25 segulix NetworkManager[19931]: <info> (ttyUSB0): taking down device.
Oct 26 17:33:25 segulix kernel: [71636.604641] sd 28:0:0:0: [sdb] Synchronizing SCSI cache
Oct 26 17:33:25 segulix kernel: [71636.604697] sd 28:0:0:0: [sdb]  Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Oct 26 17:33:25 segulix kernel: [71636.791209] usb 2-1.3: new high speed USB device number 20 using ehci_hcd
Oct 26 17:33:25 segulix kernel: [71636.892258] usb 2-1.3: New USB device found, idVendor=12d1, idProduct=1003
Oct 26 17:33:25 segulix kernel: [71636.892267] usb 2-1.3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 26 17:33:25 segulix kernel: [71636.892274] usb 2-1.3: Product: HUAWEI Mobile
Oct 26 17:33:25 segulix kernel: [71636.892280] usb 2-1.3: Manufacturer: HUAWEI Technology
Oct 26 17:33:25 segulix mtp-probe: checking bus 2, device 20: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3"
Oct 26 17:33:25 segulix mtp-probe: bus: 2, device: 20 was not an MTP device
Oct 26 17:33:25 segulix kernel: [71637.084742] usb 2-1.3: USB disconnect, device number 20
Oct 26 17:33:29 segulix kernel: [71640.839080] usb 2-1.3: new high speed USB device number 21 using ehci_hcd
Oct 26 17:33:29 segulix kernel: [71640.936194] usb 2-1.3: New USB device found, idVendor=12d1, idProduct=140c
Oct 26 17:33:29 segulix kernel: [71640.936200] usb 2-1.3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Oct 26 17:33:29 segulix kernel: [71640.936204] usb 2-1.3: Product: HUAWEI Mobile
Oct 26 17:33:29 segulix kernel: [71640.936207] usb 2-1.3: Manufacturer: HUAWEI Technology
Oct 26 17:33:29 segulix kernel: [71640.941182] option 2-1.3:1.0: GSM modem (1-port) converter detected
Oct 26 17:33:29 segulix kernel: [71640.941376] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB0
Oct 26 17:33:29 segulix kernel: [71640.941582] option 2-1.3:1.1: GSM modem (1-port) converter detected
Oct 26 17:33:29 segulix kernel: [71640.941661] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB1
Oct 26 17:33:29 segulix kernel: [71640.941855] option 2-1.3:1.2: GSM modem (1-port) converter detected
Oct 26 17:33:29 segulix kernel: [71640.941994] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB2
Oct 26 17:33:29 segulix kernel: [71640.942197] option 2-1.3:1.3: GSM modem (1-port) converter detected
Oct 26 17:33:29 segulix kernel: [71640.942266] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB3
Oct 26 17:33:29 segulix kernel: [71640.942913] scsi34 : usb-storage 2-1.3:1.4
Oct 26 17:33:29 segulix kernel: [71640.943925] scsi35 : usb-storage 2-1.3:1.5
Oct 26 17:33:29 segulix mtp-probe: checking bus 2, device 21: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3"
Oct 26 17:33:29 segulix mtp-probe: bus: 2, device: 21 was not an MTP device
Oct 26 17:33:29 segulix modem-manager[1014]: <info>  (ttyUSB0) opening serial port...
Oct 26 17:33:30 segulix kernel: [71641.944590] scsi 34:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Oct 26 17:33:30 segulix kernel: [71641.946583] scsi 35:0:0:0: Direct-Access     HUAWEI   MMC Storage      2.31 PQ: 0 ANSI: 2
Oct 26 17:33:30 segulix kernel: [71642.074342] sr1: scsi-1 drive
Oct 26 17:33:30 segulix kernel: [71642.074605] sr 34:0:0:0: Attached scsi generic sg2 type 5
Oct 26 17:33:30 segulix kernel: [71642.074876] sd 35:0:0:0: Attached scsi generic sg3 type 0
Oct 26 17:33:30 segulix kernel: [71642.086591] sd 35:0:0:0: [sdb] Attached SCSI removable disk