Reconnecting after disconnect not possible

Wed Apr 29 07:21:55 PDT 2015

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.

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.

Would you be able to install ModemManager git master compiled using
--with-suspend-resume=systemd and retry?

-- 
Aleksander
https://aleksander.es