Reconnecting after disconnect not possible

Wed Apr 29 11:26:37 PDT 2015

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.

Cheers,
Bernd