[PATCH] Hardening PORTCFG parse reply
Carlo Lobrano
c.lobrano at gmail.com
Thu Jun 30 14:23:09 UTC 2016
Hi Aleksander,
> Adding some code change to support a situation that shouldn't happen
> doesn't seem a good thing, we should fix the root cause! :)
> Do you have debug logs while this is being reproduced?
I agree with that, even if just providing a default behavior in case
of errors didn't look to bad to me :)
I'll try to get the same system again and provide some logs. On my
desktop is not reproducible because when connected to the usb the
modem is not de-enumerated when going in suspend mode.
> A long shot maybe, but did you see this issue while you were testing the SIM hotplug thing? Remember that there's an extra port open reference in that case.
No no :), I wouldn't have signaled such an error in a "corrupted"
ModemManager :D
Carlo
On 30 June 2016 at 16:12, Aleksander Morgado <aleksander at aleksander.es> wrote:
> Hey Carlo,
>
>>
>> I'm using a standard Ubuntu 16.06. I tested with both GUI interface
>> and rtcwake, but the "problem" is that the system I was working with
>> detaches the modem when it goes in stand by, so there's a full
>> de-enumeration/re-enumeration of the ports when passing from S0 to S3
>> and back. When the system wakes up I saw both messages for disposing
>> the modem and the ones that probe the "new" modem connected and they
>> goes to the same ports.
>>
>> When I debugged the problem I saw that the parser of PORTCFG response
>> (mm-common-telit.c:cache_port_mode) receives an empty string as reply,
>> so that the statement at line 138
>>
>> if (!g_regex_match_full (r, reply, strlen (reply), 0, 0,
>> &match_info, &error))
>>
>> returns FALSE
>>
>> I do not know how, but it seemed that the logic behind the AT
>> communication in MM mistakenly gets this message as reply of my AT
>> command, while the correct reply from the modem is shown in the logs,
>> so it is not modem's fault.
>>
>> The best solution would be to provide for each AT command the expected
>> response's prefix (PORTCFG in this case) to be checked in order to be
>> sure that the reply is the one expected, but this change is really too
>> much for this problem (also because I never observed other cases where
>> this is really necessary)
>>
>> However, I saw that this patch does not apply to the current master
>> branch, where the modified functions are in a different file. If you
>> think that this change could be applied, I will provide the updated
>> patch.
>>
>
> I tend to agree with Dan here; if after the suspend/resume cycle the
> device is re-enumerated, we should first cleanup the old modem object,
> forcing-close all TTYs, and only then start re-creating the new
> object.
>
> I'm assuming that we do get the udev events for the port removals
> before the udev events for the port additions, so if you're seeing
> some issue, it could very well be because there's some open port
> reference being left around without getting it closed when the udev
> port removal event arrives. A long shot maybe, but did you see this
> issue while you were testing the SIM hotplug thing? Remember that
> there's an extra port open reference in that case.
>
> Adding some code change to support a situation that shouldn't happen
> doesn't seem a good thing, we should fix the root cause! :)
>
> Do you have debug logs while this is being reproduced? It would be
> very interesting to see the sequence of events w.r.t. the TTYs being
> open after the udev removal event has arrived.
>
>
>>
>>
>>
>> On 10 June 2016 at 19:27, Dan Williams <dcbw at redhat.com> wrote:
>>> On Wed, 2016-06-01 at 14:51 +0200, Carlo Lobrano wrote:
>>>> A brief explaination of the issue that this patch solves.
>>>> I observed a probing failure at resume from memory (S3), caused by a
>>>> missing or wrong reply to #PORTCFG? AT command sent during port
>>>> probing.
>>>> This error is probably due to the overposition of multiple messages
>>>> and replies,
>>>> since at the same time the ModemManager is trying and close the last
>>>> connection,
>>>> and probing a new modem device, and the PORTCFG parser receive an
>>>> empty string to
>>>> parse, causing the failure.
>>>> Therefore the fix consists in the hardening of the reply to this
>>>> command and
>>>> in providing a default port configuration in case of the retries are
>>>> not enough.
>>>
>>> Hmm, this seems like a hackish workaround... What suspend/resume
>>> manager are you using? Ideally MM would either block suspend until it
>>> had cleaned up and disposed the modem, or on resume it would just
>>> force-close everything, dispose the modem, and reprobe.
>>>
>>> Dan
>>>
>>>> ---
>>>>
>>>> - Increase PORTCFG retries during initialization from 3 to 5 retries.
>>>> - Provide a default PORTCFG configuration in case of missing or wrong
>>>> reply.
>>>> ---
>>>> plugins/telit/mm-plugin-telit.c | 44 +++++++++++++++++++++++++++--
>>>> ------------
>>>> 1 file changed, 29 insertions(+), 15 deletions(-)
>>>>
>>>> diff --git a/plugins/telit/mm-plugin-telit.c b/plugins/telit/mm-
>>>> plugin-telit.c
>>>> index a3620e7..19eed8f 100644
>>>> --- a/plugins/telit/mm-plugin-telit.c
>>>> +++ b/plugins/telit/mm-plugin-telit.c
>>>> @@ -165,8 +165,10 @@ cache_port_mode (MMDevice *device,
>>>> r = g_regex_new ("#PORTCFG:\\s*(\\d+),(\\d+)", flags, 0, NULL);
>>>> g_assert (r != NULL);
>>>>
>>>> - if (!g_regex_match_full (r, reply, strlen (reply), 0, 0,
>>>> &match_info, &error))
>>>> + if (!g_regex_match_full (r, reply, strlen (reply), 0, 0,
>>>> &match_info, &error)) {
>>>> + mm_dbg ("Unexpected PORTCFG reply '%s'. Could not parse
>>>> it.", reply);
>>>> goto out;
>>>> + }
>>>>
>>>> if (!mm_get_uint_from_match_info (match_info, 2,
>>>> &portcfg_current)) {
>>>> mm_dbg ("telit: unrecognized #PORTCFG <active> value");
>>>> @@ -201,6 +203,7 @@ cache_port_mode (MMDevice *device,
>>>> break;
>>>> default:
>>>> /* portcfg value not supported */
>>>> + mm_err ("Invalid portcfg value from reply '%s'", reply);
>>>> goto out;
>>>> }
>>>> ret = TRUE;
>>>> @@ -222,29 +225,40 @@ getportcfg_ready (MMPortSerialAt *port,
>>>> {
>>>> const gchar *response;
>>>> GError *error = NULL;
>>>> + MMDevice *device;
>>>>
>>>> + device = mm_port_probe_peek_device (ctx->probe);
>>>> response = mm_port_serial_at_command_finish (port, res, &error);
>>>> - if (error) {
>>>> - mm_dbg ("telit: couldn't get port mode: '%s'",
>>>> - error->message);
>>>>
>>>> - /* If ERROR or COMMAND NOT SUPPORT occur then do not retry
>>>> the
>>>> - * command.
>>>> - */
>>>> - if (g_error_matches (error,
>>>> - MM_MOBILE_EQUIPMENT_ERROR,
>>>> - MM_MOBILE_EQUIPMENT_ERROR_UNKNOWN))
>>>> - ctx->getportcfg_done = TRUE;
>>>> + if (error) {
>>>> + mm_dbg ("telit: couldn't get port mode: '%s' (retries left
>>>> %d)",
>>>> + error->message,
>>>> + ctx->getportcfg_retries);
>>>> +
>>>> + if (ctx->getportcfg_retries == 0) {
>>>> + mm_dbg ("telit: getportcfg last retry failed. Try and
>>>> setting default port config.");
>>>> + if (g_object_get_data (G_OBJECT (device),
>>>> TAG_GETPORTCFG_SUPPORTED) == NULL) {
>>>> + mm_dbg ("telit: Defaulting to 00 and 06 for modem
>>>> and aux");
>>>> + g_object_set_data (G_OBJECT (device),
>>>> TAG_TELIT_MODEM_PORT, "00");
>>>> + g_object_set_data (G_OBJECT (device),
>>>> TAG_TELIT_AUX_PORT, "06");
>>>> + g_object_set_data (G_OBJECT (device),
>>>> TAG_GETPORTCFG_SUPPORTED, GUINT_TO_POINTER (TRUE));
>>>> + ctx->getportcfg_done = TRUE;
>>>> + }
>>>> + }
>>>> } else {
>>>> - MMDevice *device;
>>>> - device = mm_port_probe_peek_device (ctx->probe);
>>>> -
>>>> /* Results are cached in the parent device object */
>>>> if (g_object_get_data (G_OBJECT (device),
>>>> TAG_GETPORTCFG_SUPPORTED) == NULL) {
>>>> mm_dbg ("telit: retrieving port mode layout");
>>>> if (cache_port_mode (device, response)) {
>>>> g_object_set_data (G_OBJECT (device),
>>>> TAG_GETPORTCFG_SUPPORTED, GUINT_TO_POINTER (TRUE));
>>>> ctx->getportcfg_done = TRUE;
>>>> + } else {
>>>> + mm_dbg ("telit: Error in cache port mode");
>>>> + mm_dbg ("telit: Defaulting to 00 and 06 for modem
>>>> and aux");
>>>> + g_object_set_data (G_OBJECT (device),
>>>> TAG_TELIT_MODEM_PORT, "00");
>>>> + g_object_set_data (G_OBJECT (device),
>>>> TAG_TELIT_AUX_PORT, "06");
>>>> + g_object_set_data (G_OBJECT (device),
>>>> TAG_GETPORTCFG_SUPPORTED, GUINT_TO_POINTER (TRUE));
>>>> + ctx->getportcfg_done = TRUE;
>>>> }
>>>> }
>>>>
>>>> @@ -334,7 +348,7 @@ telit_custom_init (MMPortProbe *probe,
>>>> ctx->port = g_object_ref (port);
>>>> ctx->cancellable = cancellable ? g_object_ref (cancellable) :
>>>> NULL;
>>>> ctx->getportcfg_done = FALSE;
>>>> - ctx->getportcfg_retries = 3;
>>>> + ctx->getportcfg_retries = 5;
>>>>
>>>> /* If the device is tagged for supporting #PORTCFG do the custom
>>>> init */
>>>> if (g_udev_device_get_property_as_boolean (udevDevice,
>>>> "ID_MM_TELIT_PORTS_TAGGED")) {
>> _______________________________________________
>> ModemManager-devel mailing list
>> ModemManager-devel at lists.freedesktop.org
>> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
>
>
>
> --
> Aleksander
> https://aleksander.es
More information about the ModemManager-devel
mailing list