Re: modem-manager fails to reconnect
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?' > ** (modem-manager:11224): DEBUG: <1285364689.591677> (ttyUSB2): <-- > '+CREG: 1,1OK' > ** (modem-manager:11224): DEBUG: <1285364689.591776> (ttyUSB2): simple > connect state 4 > ** (modem-manager:11224): DEBUG: <1285364689.591821> (ttyUSB2): --> > 'AT+CGDCONT?' > ** (modem-manager:11224): DEBUG: <1285364689.613745> (ttyUSB2): <-- > '+CGDCONT: > 1,"IP","www.tim.com.br","0.0.0.0",0,0+CGDCONT: > 2,"IP","www.tim.com.br","0.0.0.0",0,0+CGDCONT: > 3,"IP","bandalarga.claro.com.br","0.0.0.0",0,0+CGDCONT: > 4,"IP","tim.br","0.0.0.0",0,0OK' > ** (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#' > ** (modem-manager:11224): DEBUG: <1285364689.634906> (ttyUSB2): <-- > 'CONNECT 115200' > ** (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): <-- > '+ZPASR: "HSDPA"' > ** (modem-manager:11224): DEBUG: <1285364701.3719> (ttyUSB1): --> 'AT > +CSQ' > ** (modem-manager:11224): DEBUG: <1285364701.13901> (ttyUSB1): <-- > '+CSQ: 16,99OK' > ** (modem-manager:11224): DEBUG: <1285364701.14020> (ttyUSB1): --> 'AT > +ZPAS?' > ** (modem-manager:11224): DEBUG: <1285364701.34469> (ttyUSB1): <-- > '+ZPAS: "HSDPA","CS_PS"OK' > ** (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' > ** (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): num
modem-manager fails to reconnect
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?' ** (modem-manager:11224): DEBUG: <1285364689.591677> (ttyUSB2): <-- '+CREG: 1,1OK' ** (modem-manager:11224): DEBUG: <1285364689.591776> (ttyUSB2): simple connect state 4 ** (modem-manager:11224): DEBUG: <1285364689.591821> (ttyUSB2): --> 'AT+CGDCONT?' ** (modem-manager:11224): DEBUG: <1285364689.613745> (ttyUSB2): <-- '+CGDCONT: 1,"IP","www.tim.com.br","0.0.0.0",0,0+CGDCONT: 2,"IP","www.tim.com.br","0.0.0.0",0,0+CGDCONT: 3,"IP"," bandalarga.claro.com.br","0.0.0.0",0,0+CGDCONT: 4,"IP","tim.br ","0.0.0.0",0,0OK' ** (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#' ** (modem-manager:11224): DEBUG: <1285364689.634906> (ttyUSB2): <-- 'CONNECT 115200' ** (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): <-- '+ZPASR: "HSDPA"' ** (modem-manager:11224): DEBUG: <1285364701.3719> (ttyUSB1): --> 'AT+CSQ' ** (modem-manager:11224): DEBUG: <1285364701.13901> (ttyUSB1): <-- '+CSQ: 16,99OK' ** (modem-manager:11224): DEBUG: <1285364701.14020> (ttyUSB1): --> 'AT+ZPAS?' ** (modem-manager:11224): DEBUG: <1285364701.34469> (ttyUSB1): <-- '+ZPAS: "HSDPA","CS_PS"OK' ** (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' ** (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): <-- '+ZPASR: "UMTS"' ** (modem-manager:11224): DEBUG: <1285364710.903941> (ttyUSB1): <-- '+ZPASR: "UMTS"' ** (modem-manager:11224): DEBUG: <1285364710.925500> (ttyUSB1): <-- 'OK' ** (modem-manager:11224): DEBUG: <1285364710.927614> (ttyUSB2): <-- 'NO CARRIER' ** (modem-manager:11224): DEBUG: Got failure code 3: No carrier ** (modem-manager:11224): D
