Reconnecting after disconnect not possible

Wed Apr 29 09:47:08 PDT 2015

On Wed, 2015-04-29 at 18:26 +0000, Bernd Eggink wrote:
> On 29.04.2015 14:21, Aleksander Morgado wrote:
> > On Tue, Apr 28, 2015 at 9:17 PM, Bernd Eggink <monoped at sudrala.de> wrote:
> >> first of all, I'm happy that I got mobile broadband working under Linux on
> >> my Toshiba Portege, using ModemManager and mmcli. The notebook has a
> >> built-in SIM port with a Sierra mobile broadband device. On Linux (Crux) I
> >> get an interface "wwp0s20u4c2i12" and connecting with mmcli --simple-connect
> >> works well - at least the first time.
> >>
> >> However, when I disconnect, and then (after some time) try to re-connect, I
> >> frequently don't get a connection again. Whatever I do results in a timeout.
> >> Neither disabling and re-enabling the modem nor removing and reloading the
> >> kernel module helps; only after rebooting I can get a connection again.
> >> I append part of the debug output; when the problem arises, the log starts
> >> reporting "unexpected messages". Could anybody have a look into it?
> >>
> >> Thanks, Bernd
> >>
> >> -------------------------------
> >>
> >> ModemManager[2465]: <debug> [1430160272.228369]
> >> [mm-broadband-modem-mbim.c:1543] basic_connect_notification_signal_state():
> >> Signal state indication: 29 --> 93%
> >> ModemManager[2465]: <debug> [1430160272.228516] [mm-iface-modem.c:1165]
> >> update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0:
> >> signal quality updated (93)
> >> ModemManager[2465]: <info>  [1430160282.212883] [mm-iface-modem.c:1392]
> >> __iface_modem_update_state_internal(): Modem
> >> /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> disabled)
> >> ModemManager[2465]: <info>  [1430160282.251994]
> >> [mm-iface-modem-simple.c:641] connect_auth_ready(): Simple connect
> >> started...
> >> ModemManager[2465]: <debug> [1430160282.252078]
> >> [mm-iface-modem-simple.c:651] connect_auth_ready():    PIN: unspecified
> >> ModemManager[2465]: <debug> [1430160282.252109]
> >> [mm-iface-modem-simple.c:653] connect_auth_ready():    Operator ID:
> >> unspecified
> >> ModemManager[2465]: <debug> [1430160282.252137]
> >> [mm-iface-modem-simple.c:655] connect_auth_ready():    Allowed roaming: yes
> >> ModemManager[2465]: <debug> [1430160282.252164]
> >> [mm-iface-modem-simple.c:657] connect_auth_ready():    APN: internet.t-d1.de
> >> ModemManager[2465]: <debug> [1430160282.252199]
> >> [mm-iface-modem-simple.c:665] connect_auth_ready():    IP family:
> >> unspecified
> >> ModemManager[2465]: <debug> [1430160282.252227]
> >> [mm-iface-modem-simple.c:673] connect_auth_ready():    Allowed
> >> authentication: unspecified
> >> ModemManager[2465]: <debug> [1430160282.252254]
> >> [mm-iface-modem-simple.c:675] connect_auth_ready():    User: unspecified
> >> ModemManager[2465]: <debug> [1430160282.252351]
> >> [mm-iface-modem-simple.c:677] connect_auth_ready():    Password: unspecified
> >> ModemManager[2465]: <debug> [1430160282.252381]
> >> [mm-iface-modem-simple.c:679] connect_auth_ready():    Number: unspecified
> >> ModemManager[2465]: <info>  [1430160282.252405]
> >> [mm-iface-modem-simple.c:461] connection_step(): Simple connect state (3/8):
> >> Enable
> >> ModemManager[2465]: <info>  [1430160282.252520] [mm-iface-modem.c:1392]
> >> __iface_modem_update_state_internal(): Modem
> >> /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
> >> ModemManager[2465]: <debug> [1430160282.252958] [mm-broadband-modem.c:8003]
> >> enabling_started(): Skipping modem initialization: not required
> >> ModemManager[2465]: <debug> [1430160282.254681]
> >> [mm-broadband-modem-mbim.c:1216] parent_enabling_started_ready(): Couldn't
> >> start parent enabling: Couldn't open ports during modem enabling: Couldn't
> >> get primary port
> >> ModemManager[2465]: [/dev/cdc-wdm0] Sent message...
> >> <<<<<< RAW:
> >> <<<<<<   length = 48
> >> <<<<<<   data   =
> >> 03:00:00:00:30:00:00:00:20:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:03:00:00:00:00:00:00:00:00:00:00:00
> >> ModemManager[2465]: [/dev/cdc-wdm0] Sent message (translated)...
> >> <<<<<< Header:
> >> <<<<<<   length      = 48
> >> <<<<<<   type        = command (0x00000003)
> >> <<<<<<   transaction = 32
> >> <<<<<< Fragment header:
> >> <<<<<<   total   = 1
> >> <<<<<<   current = 0
> >> <<<<<< Contents:
> >> <<<<<<   service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
> >> <<<<<<   cid     = 'radio-state' (0x00000003)
> >> <<<<<<   type    = 'query' (0x00000000)
> >> ModemManager[2465]: [/dev/cdc-wdm0] Received message...
> >>>>>>>> RAW:
> >>>>>>>>    length = 56
> >>>>>>>>    data   =
> >>>>>>>> 03:00:00:80:38:00:00:00:1C:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:03:00:00:00:00:00:00:00:08:00:00:00:01:00:00:00:01:00:00:00
> >> ModemManager[2465]: [/dev/cdc-wdm0] No transaction matched in received
> >> message
> >> ModemManager[2465]: [/dev/cdc-wdm0] Received unexpected message
> >> (translated)...
> >>>>>>>> Header:
> >>>>>>>>    length      = 56
> >>>>>>>>    type        = command-done (0x80000003)
> >>>>>>>>    transaction = 28
> >>>>>>>> Fragment header:
> >>>>>>>>    total   = 1
> >>>>>>>>    current = 0
> >>>>>>>> Contents:
> >>>>>>>>    status error = 'None' (0x00000000)
> >>>>>>>>    service      = 'basic-connect'
> >>>>>>>> (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
> >>>>>>>>    cid          = 'radio-state' (0x00000003)
> >> ModemManager[2465]: Couldn't reload current power state: Transaction timed
> >> out
> >
> >
> > Oh, how weird is that; looks like transaction ids got mismatched
> > between request and response?
> >
> > What specific ModemManager and libmbim versions are you using? I'm
> > afraid this may be an issue with the mbim-proxy.
> 
> Aleksander,
> ModemManager is 1.4.8, libmbim is 1.12.2.
> 
> > Also, do you by any chance suspend/resume in between connection
> > attempts? If so, it may be a known issue which is partially fixed in
> > libmbim (latest stable) and in ModemManager (git master), and only if
> > systemd (or an old upowerd) is used.
> 
> Yes, I suspended/resumed sometimes. However, that can't be the main 
> reason, as I even had situations where the _first_ connection after a 
> fresh boot didn't work.
> 
> > Would you be able to install ModemManager git master compiled using
> > --with-suspend-resume=systemd and retry?
> 
> I'll try the git master tomorrow, but as I'm in the lucky position to 
> run a system _without_ systemd, I can't use that option. Anyway, it 
> seems that suspending/resuming isn't a problem as long as I keep the 
> connection open, so I can live with it for the time being.

There's also upower support IIRC, so if you have that, and can try with
--with-suspend-resume=upower, that would be great.  Basically,
ModemManager needs to know that the systems is going into suspend so
that it can clean stuff up and reset transactions and such.

Dan