ModemManager crash with more than one call with Huawei E3131 Modem

[Enrico Mioso]

Thank you very very much for your great work, as always Aleksander.


BTW- maybe something interesting is happening here:
[mrkiko at mStation ~]$ mmcli -o 44 --start
error: couldn't start the call: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Failed: Couldn't start the call: Unhandled response '^CCALLSTATE: 1,4''

but in reality call started anyway, without MM knowing it.
Thank you for all Aleksander.

enrico


On Thu, 21 May 2020, Aleksander Morgado wrote:

> Date: Thu, 21 May 2020 15:12:57
> From: Aleksander Morgado <aleksander at aleksander.es>
> To: Enrico Mioso <mrkiko.rs at gmail.com>
> Cc: "ModemManager (development)" <modemmanager-devel at lists.freedesktop.org>,
>     marco.perini1993 at gmail.com
> Subject: Re: ModemManager crash with more than one call with Huawei E3131
>     Modem
> 
> Hey Enrico,
>
>>> I am experiencing a crash in Modemmanager, triggered by the following scenario:
>>> 1 - Start a voice call from mmcli to my mobile phone.
>>> 2 - Answer the call there.
>>> 3 - From the mobile phone, call back my Huawei E3131 device.
>>>
>>> This results in the following crash: let me know if I can help out more.
>>>
>>
>> While I could write a quick fix for this issue, just replacing a
>> g_assert() by a if() check, I do need to understand fully how the
>> situation happened, because I did really expect the g_assert() to
>> always succeed. Will let you know.
>>
>
> I've understood how it happened, and the fix is indeed just to change
> the assert with an if(), because it really is an expected usecase.
>
> The problem happened because in load_call_list_ready() we call
> mm_iface_modem_voice_report_all_calls() before the assert() was
> checked, and in that report_all_calls() method we may be detecting new
> incoming calls that would trigger setting the call polling timeout as
> well.
>
> I've pushed a new fix for this already that will get to git master
> soon and then I'll backport it to the 1.12.x branch:
> https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/merge_requests/284
>
> These are the relevant commits from your log:
>
> ModemManager[417212]: <debug> [1589977056.106485] 1 calls being
> established: call list polling required
>
>    ctx->polling_ongoing = TRUE;
>    load_call_list()
>    load_call_list_ready()
>    ctx->polling_ongoing = FALSE;
>
> ModemManager[417212]: <debug> [1589977056.106550] (ttyUSB2) device
> open count is 3 (open)
> ModemManager[417212]: <debug> [1589977056.106624] (ttyUSB2): --> 'AT+CLCC<CR>'
> ModemManager[417212]: <debug> [1589977056.116273] (ttyUSB2): <--
> '<CR><LF>+CLCC: 1,0,0,0,0,"39XXXX",145,"",<CR><LF>+CLCC:
> 2,1,5,0,0,"39XXXX",145,"",<CR><LF><CR><LF>OK<CR><LF>'
>
>    mm_iface_modem_voice_report_all_calls()
>
>        New call added, setup_call_list_polling() is executed, which
> ends up setting up the call_list_poll() timeout.
>
> ModemManager[417212]: <debug> [1589977056.116495] Reported 2 ongoing calls
> ModemManager[417212]: <debug> [1589977056.116516] call at index 1:
> direction outgoing, state active, number 39XXXX
> ModemManager[417212]: <debug> [1589977056.116525] call at index 2:
> direction incoming, state waiting, number 39XXXX
> ModemManager[417212]: <debug> [1589977056.116550] call info matched
> (matched direction/state no, matched number yes, matched index no,
> matched terminated no) with call at
> '/org/freedesktop/ModemManager1/Call/1'
> ModemManager[417212]: <debug> [1589977056.116566]   index set: 1
> ModemManager[417212]: <debug> [1589977056.116578]   state updated: active
> ModemManager[417212]: <info>  [1589977056.116590] Call state changed:
> waiting -> active (unknown)
> ModemManager[417212]: <debug> [1589977056.116727]   incoming refreshed
> ModemManager[417212]: <debug> [1589977056.116750] Call
> '/org/freedesktop/ModemManager1/Call/0' with direction outgoing, state
> active, number '+39XXXX', index 1 not found in list, terminating
> ModemManager[417212]: <info>  [1589977056.116767] Call state changed:
> active -> terminated (unknown)
>
> ModemManager[417212]: <debug> [1589977056.116868] Creating new incoming call...
> ModemManager[417212]: <info>  [1589977056.116972] Call state changed:
> unknown -> waiting (incoming-new)
> ModemManager[417212]: <debug> [1589977056.117054] Added call at
> '/org/freedesktop/ModemManager1/Call/2'
> **
> ERROR:mm-iface-modem-voice.c:2376:load_call_list_ready: assertion
> failed: (!ctx->polling_id)
> Bail out! ERROR:mm-iface-modem-voice.c:2376:load_call_list_ready:
> assertion failed: (!ctx->polling_id)
>
>
> -- 
> Aleksander
> https://aleksander.es
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
>