Reconnecting after disconnect not possible

Thu Apr 30 09:30:30 PDT 2015

On 29.04.2015 16:47, Dan Williams wrote:
> 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.

I tried that, didn't help. Actually I think the whole suspend-resume 
thing is a red herring. All tests I made showed that suspending and 
resuming does _not_ harm the connection, but _disconnecting_ does. In 
most cases after disconnecting the device I couldn't get a connection 
again, until the next boot. So the problem might be that after a 
disconnection the device is not properly reset to initial state.
Also weird is the fact that when connecting times out, disabling (-d) 
also times out, resetting (-r) is not possible ("Cannot reset the modem: 
operation not supported") and simple-status says "state: connected" (!)

Cheers, Bernd