Re: modem-manager fails to reconnect

[Dan Williams <dcbw redhat com>]

On Fri, 2010-09-24 at 20:14 -0300, José Queiroz wrote:
> 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.

That's interesting, and something we should probably handle.  We should
detect NO CARRIER on secondary ports and then tell NetworkManager that
we've terminated the connection so that it disconnects PPP.

> 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.

Should fix that too.  What's happening here is that ModemManager tries
to disconnect the port by breaking into the serial stream, but clearly
that's not working.  Since that wasn't successful (it didn't get a
response) it reverts to the previous state (which is connected).  We'd
need to put some more debugging in to detect where exactly it fails and
try to figure out what to do about that.

Dan

> 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
> 
> _______________________________________________
> networkmanager-list mailing list
> networkmanager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list