modem-manager fails to reconnect

[José Queiroz <zekkerj gmail com>]

Hi,

I've noticed a strange behavior with my 3g dongle (Onda MSA405 HS / 19d2:0037). When I plug it, it connects with ease. After some time, if I disconnect it and try to reconnect, it fails, and I have to unplug/plug again the device or restart modem-manager process to get the connection back.

I've turned on loggin on modem-manager, and I saw that when it states that the connection transitioned from "connected -> disconnecting" and from "disconnecting -> registered", I can reconnect it. But sometimes, it transitions from "connected -> disconnecting" and then "disconnecting -> connect". When this happens, I cannot reconnect unless unplug or restart modem-manager.

This sometimes happens in the first reconnection, sometimes it takes some reconnections to happen, but sooner or later will happen.

I'm using:
Kubuntu Lucid 10.04, 
NetworkManager 0.8.1+git.20100810t184654.ab580f4-0ubuntu3~nmt3~lucid

modem-manager 0.4+git.20100922t210758.618dc06-0ubuntu1~nmt1~lucid

I also saw that in a normal disconnect, ttyUSB2 (data port) and ttyUSB1 send a "NO CARRIER" message; when the disconnection fails, only ttyUSB1 says "NO CARRIER".

This is a piece of modem-manager debug. I can consistently reproduce the symptom, if needed.

** (modem-manager:11224): DEBUG: <1285364689.581337> (ttyUSB2): network_mode => 8
** (modem-manager:11224): DEBUG: <1285364689.581337> (ttyUSB2): username => "tim"
** (modem-manager:11224): DEBUG: <1285364689.581337> (ttyUSB2): number => "*99#"
** (modem-manager:11224): DEBUG: <1285364689.581337> (ttyUSB2): apn => "www.tim.com.br"
** (modem-manager:11224): DEBUG: <1285364689.581337> (ttyUSB2): allowed_mode => 4
** (modem-manager:11224): DEBUG: <1285364689.581337> (ttyUSB2): password => "tim"
** (modem-manager:11224): DEBUG: <1285364689.581451> (ttyUSB2): simple connect state 0
** (modem-manager:11224): DEBUG: <1285364689.581492> (ttyUSB2): simple connect state 2
** (modem-manager:11224): DEBUG: <1285364689.581541> (ttyUSB2): --> 'AT+CREG?<CR>'
** (modem-manager:11224): DEBUG: <1285364689.591677> (ttyUSB2): <-- '<CR><LF>+CREG: 1,1<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364689.591776> (ttyUSB2): simple connect state 4
** (modem-manager:11224): DEBUG: <1285364689.591821> (ttyUSB2): --> 'AT+CGDCONT?<CR>'
** (modem-manager:11224): DEBUG: <1285364689.613745> (ttyUSB2): <-- '<CR><LF>+CGDCONT: 1,"IP","www.tim.com.br","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IP","www.tim.com.br","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IP","bandalarga.claro.com.br","0.0.0.0",0,0<CR><LF>+CGDCONT: 4,"IP","tim.br","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364689.613907> (ttyUSB2): simple connect state 5
** (modem-manager:11224): DEBUG: <1285364689.613961> Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
** (modem-manager:11224): DEBUG: <1285364689.614001> (ttyUSB2): --> 'ATD*99***1#<CR>'
** (modem-manager:11224): DEBUG: <1285364689.634906> (ttyUSB2): <-- '<CR><LF>CONNECT 115200<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364689.635012> (ttyUSB2): port now connected
** (modem-manager:11224): DEBUG: <1285364689.635055> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
** (modem-manager:11224): DEBUG: <1285364689.635098> (ttyUSB2): simple connect state 6
** (modem-manager:11224): DEBUG: (net/ppp0): could not get port's parent device
** (modem-manager:11224): DEBUG: <1285364691.463726> (ttyUSB1): <-- '<CR><LF>+ZPASR: "HSDPA"<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364701.3719> (ttyUSB1): --> 'AT+CSQ<CR>'
** (modem-manager:11224): DEBUG: <1285364701.13901> (ttyUSB1): <-- '<CR><LF>+CSQ: 16,99<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364701.14020> (ttyUSB1): --> 'AT+ZPAS?<CR>'
** (modem-manager:11224): DEBUG: <1285364701.34469> (ttyUSB1): <-- '<CR><LF>+ZPAS: "HSDPA","CS_PS"<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364708.9169> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285364708.9302> (ttyUSB1): --> 'AT+CGACT=0,1<CR>'
** (modem-manager:11224): DEBUG: <1285364708.42966> (ttyUSB2): network_mode => 8
** (modem-manager:11224): DEBUG: <1285364708.42966> (ttyUSB2): username => "tim"
** (modem-manager:11224): DEBUG: <1285364708.42966> (ttyUSB2): number => "*99#"
** (modem-manager:11224): DEBUG: <1285364708.42966> (ttyUSB2): apn => "www.tim.com.br"
** (modem-manager:11224): DEBUG: <1285364708.42966> (ttyUSB2): allowed_mode => 4
** (modem-manager:11224): DEBUG: <1285364708.42966> (ttyUSB2): password => "tim"
** (modem-manager:11224): DEBUG: <1285364708.43083> (ttyUSB2): simple connect state 0
** (modem-manager:11224): DEBUG: <1285364708.43126> (ttyUSB2): simple connect state 2
** (modem-manager:11224): DEBUG: <1285364710.903746> (ttyUSB2): <-- '<CR><LF>+ZPASR: "UMTS"<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364710.903941> (ttyUSB1): <-- '<CR><LF>+ZPASR: "UMTS"<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364710.925500> (ttyUSB1): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364710.927614> (ttyUSB2): <-- '<CR><LF>NO CARRIER<CR><LF>'
** (modem-manager:11224): DEBUG: Got failure code 3: No carrier
** (modem-manager:11224): DEBUG: <1285364710.927688> (ttyUSB1): <-- '<CR><LF>NO CARRIER<CR><LF>'
** (modem-manager:11224): DEBUG: Got failure code 3: No carrier
** (modem-manager:11224): DEBUG: <1285364711.929529> (ttyUSB2): port now disconnected
** (modem-manager:11224): DEBUG: <1285364711.929625> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> registered)
** (modem-manager:11224): DEBUG: <1285364722.888300> (ttyUSB2): network_mode => 8
** (modem-manager:11224): DEBUG: <1285364722.888300> (ttyUSB2): username => "tim"
** (modem-manager:11224): DEBUG: <1285364722.888300> (ttyUSB2): number => "*99#"
** (modem-manager:11224): DEBUG: <1285364722.888300> (ttyUSB2): apn => "www.tim.com.br"
** (modem-manager:11224): DEBUG: <1285364722.888300> (ttyUSB2): allowed_mode => 4
** (modem-manager:11224): DEBUG: <1285364722.888300> (ttyUSB2): password => "tim"
** (modem-manager:11224): DEBUG: <1285364722.888419> (ttyUSB2): simple connect state 0
** (modem-manager:11224): DEBUG: <1285364722.888461> (ttyUSB2): simple connect state 2
** (modem-manager:11224): DEBUG: <1285364722.888510> (ttyUSB2): --> 'AT+CREG?<CR>'
** (modem-manager:11224): DEBUG: <1285364722.898315> (ttyUSB2): <-- '<CR><LF>+CREG: 1,1<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364722.898425> (ttyUSB2): simple connect state 4
** (modem-manager:11224): DEBUG: <1285364722.898474> (ttyUSB2): --> 'AT+CGDCONT?<CR>'
** (modem-manager:11224): DEBUG: <1285364722.916703> (ttyUSB2): <-- '<CR><LF>+CGDCONT: 1,"IP","www.tim.com.br","0.0.0.0",0,0<CR><LF>+CGDCONT: 2,"IP","www.tim.com.br","0.0.0.0",0,0<CR><LF>+CGDCONT: 3,"IP","bandalarga.claro.com.br","0.0.0.0",0,0<CR><LF>+CGDCONT: 4,"IP","tim.br","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364722.916884> (ttyUSB2): simple connect state 5
** (modem-manager:11224): DEBUG: <1285364722.916944> Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
** (modem-manager:11224): DEBUG: <1285364722.916992> (ttyUSB2): --> 'ATD*99***1#<CR>'
** (modem-manager:11224): DEBUG: <1285364722.934074> (ttyUSB2): <-- '<CR><LF>CONNECT 115200<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364722.934185> (ttyUSB2): port now connected
** (modem-manager:11224): DEBUG: <1285364722.934230> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
** (modem-manager:11224): DEBUG: <1285364722.934272> (ttyUSB2): simple connect state 6
** (modem-manager:11224): DEBUG: (net/ppp0): could not get port's parent device
** (modem-manager:11224): DEBUG: <1285364724.943747> (ttyUSB1): <-- '<CR><LF>+ZPASR: "HSDPA"<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364731.3764> (ttyUSB1): --> 'AT+CSQ<CR>'
** (modem-manager:11224): DEBUG: <1285364731.11634> (ttyUSB1): <-- '<CR><LF>+CSQ: 16,99<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364731.11722> (ttyUSB1): --> 'AT+ZPAS?<CR>'
** (modem-manager:11224): DEBUG: <1285364731.25168> (ttyUSB1): <-- '<CR><LF>+ZPAS: "HSDPA","CS_PS"<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364761.1288> (ttyUSB1): --> 'AT+CSQ<CR>'
** (modem-manager:11224): DEBUG: <1285364761.14051> (ttyUSB1): <-- '<CR><LF>+CSQ: 16,99<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364761.14195> (ttyUSB1): --> 'AT+ZPAS?<CR>'
** (modem-manager:11224): DEBUG: <1285364761.24892> (ttyUSB1): <-- '<CR><LF>+ZPAS: "HSDPA","CS_PS"<CR><LF><CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364766.326255> (ttyUSB1): <-- '<CR><LF>+ZPASR: "UMTS"<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364789.101554> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285364789.101679> (ttyUSB1): --> 'AT+CGACT=0,1<CR>'
** (modem-manager:11224): DEBUG: <1285364789.152932> (ttyUSB2): network_mode => 8
** (modem-manager:11224): DEBUG: <1285364789.152932> (ttyUSB2): username => "tim"
** (modem-manager:11224): DEBUG: <1285364789.152932> (ttyUSB2): number => "*99#"
** (modem-manager:11224): DEBUG: <1285364789.152932> (ttyUSB2): apn => "www.tim.com.br"
** (modem-manager:11224): DEBUG: <1285364789.152932> (ttyUSB2): allowed_mode => 4
** (modem-manager:11224): DEBUG: <1285364789.152932> (ttyUSB2): password => "tim"
** (modem-manager:11224): DEBUG: <1285364789.153054> (ttyUSB2): simple connect state 0
** (modem-manager:11224): DEBUG: <1285364789.153096> (ttyUSB2): simple connect state 2
** (modem-manager:11224): DEBUG: <1285364789.934226> (ttyUSB2) device open count is 0 (close)
** Message: (ttyUSB2) closing serial device...
** (modem-manager:11224): DEBUG: <1285364789.934313> (ttyUSB2): port now disconnected
** (modem-manager:11224): DEBUG: <1285364789.934350> (ttyUSB1): <-- '<CR><LF>OK<CR><LF>'
** (modem-manager:11224): DEBUG: <1285364789.934448> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
** (modem-manager:11224): DEBUG: <1285364789.934809> (ttyUSB1): <-- '<CR><LF>NO CARRIER<CR><LF>'
** (modem-manager:11224): DEBUG: Got failure code 3: No carrier
** (modem-manager:11224): DEBUG: <1285364812.393781> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285364812.393866> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
** (modem-manager:11224): DEBUG: <1285364812.403096> (ttyUSB2): network_mode => 8
** (modem-manager:11224): DEBUG: <1285364812.403096> (ttyUSB2): username => "tim"
** (modem-manager:11224): DEBUG: <1285364812.403096> (ttyUSB2): number => "*99#"
** (modem-manager:11224): DEBUG: <1285364812.403096> (ttyUSB2): apn => "www.tim.com.br"
** (modem-manager:11224): DEBUG: <1285364812.403096> (ttyUSB2): allowed_mode => 4
** (modem-manager:11224): DEBUG: <1285364812.403096> (ttyUSB2): password => "tim"
** (modem-manager:11224): DEBUG: <1285364812.403213> (ttyUSB2): simple connect state 0
** (modem-manager:11224): DEBUG: <1285364812.403252> (ttyUSB2): simple connect state 2
** (modem-manager:11224): DEBUG: <1285364812.405497> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285364812.405579> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
** (modem-manager:11224): DEBUG: <1285366267.558723> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285366267.558809> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
** (modem-manager:11224): DEBUG: <1285366267.565280> (ttyUSB2): network_mode => 8
** (modem-manager:11224): DEBUG: <1285366267.565280> (ttyUSB2): username => "tim"
** (modem-manager:11224): DEBUG: <1285366267.565280> (ttyUSB2): number => "*99#"
** (modem-manager:11224): DEBUG: <1285366267.565280> (ttyUSB2): apn => "www.tim.com.br"
** (modem-manager:11224): DEBUG: <1285366267.565280> (ttyUSB2): allowed_mode => 4
** (modem-manager:11224): DEBUG: <1285366267.565280> (ttyUSB2): password => "tim"
** (modem-manager:11224): DEBUG: <1285366267.565398> (ttyUSB2): simple connect state 0
** (modem-manager:11224): DEBUG: <1285366267.565438> (ttyUSB2): simple connect state 2
** (modem-manager:11224): DEBUG: <1285366267.568561> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285366267.568642> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
^C** Message: Caught signal 2, shutting down...
** (modem-manager:11224): DEBUG: <1285367598.686325> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:11224): DEBUG: <1285367598.686387> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)

** (modem-manager:11224): WARNING **: disable_disconnect_done: (/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-2): error disconnecting the modem while disabling: (5) The serial port is not open.

** (modem-manager:11224): WARNING **: (mm-generic-gsm.c:1210):disable: runtime check failed: (priv->cid == -1)
** (modem-manager:11224): DEBUG: <1285367598.686668> (ttyUSB1) device open count is 0 (close)
** Message: (ttyUSB1) closing serial device...
** (modem-manager:11224): DEBUG: <1285367598.687661> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disabling)

** (modem-manager:11224): CRITICAL **: mm_serial_port_close_force: assertion `priv->open_count > 0' failed
** (modem-manager:11224): DEBUG: <1285367598.687724> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabling -> disabled)
** (modem-manager:11224): DEBUG: Removed modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-2