[PATCH] Hardening PORTCFG parse reply

[Aleksander Morgado]

On Thu, Jul 7, 2016 at 5:45 PM, Carlo Lobrano <c.lobrano at gmail.com> wrote:
> I manage to replicate only a slightly different behavior, the log is in
> attachment.
>
>
> The test case is the following:
>   1. modem connected to the network and automatic reconnection set in the nm
> gui.
>   2. system in suspend (I used rtcwake), the MiniPCI modem is de-enumerated
>   3. system wake up, the modem is re-enumerated and probed again by
> ModemManager
>
> At this point #PORTCFG is sent to ACM0, the modem replies, but still
> getportcfg_ready() prints out that the command timed out. This happens 3
> times, then MM gives up.
>
>
> The following excerpt is one of the three times the portcfg times out
>     Jul  7 17:09:42 ubuntu ModemManager[5302]: <debug> [1467904182.176461]
> [mm-port-serial-at.c:459] debug_log(): (ttyACM0): --> 'AT#PORTCFG?<CR>'
>     ...
>    Jul  7 17:09:43 ubuntu ModemManager[5302]: <debug> [1467904183.295449]
> [mm-port-serial-at.c:459] debug_log(): (ttyACM0): <-- '<CR><LF>'
>    Jul  7 17:09:43 ubuntu ModemManager[5302]: <debug> [1467904183.296489]
> [mm-port-serial-at.c:459] debug_log(): (ttyACM0): <-- '#PORTCFG:
> 1,1<CR><LF><CR><LF>OK<CR><LF>'
>    Jul  7 17:09:45 ubuntu ModemManager[5302]: <debug> [1467904185.574674]
> [telit/mm-plugin-telit.c:231] getportcfg_ready(): telit: couldn't get port
> mode: 'Serial command timed out'
>
> While the following comes from a valid run
>    Jul  7 17:09:06 ubuntu ModemManager[5302]: <debug> [1467904146.343436]
> [mm-port-serial-at.c:459] debug_log(): (ttyACM0): --> 'AT#PORTCFG?<CR>'
>    ...
>    Jul  7 17:09:07 ubuntu ModemManager[5302]: <debug> [1467904147.462010]
> [mm-port-serial-at.c:459] debug_log(): (ttyACM0): <-- '<CR><LF>'
>    Jul  7 17:09:07 ubuntu ModemManager[5302]: <debug> [1467904147.463136]
> [mm-port-serial-at.c:459] debug_log(): (ttyACM0): <-- '#PORTCFG:
> 1,1<CR><LF><CR><LF>OK<CR><LF>'
>    Jul  7 17:09:07 ubuntu ModemManager[5302]: <debug> [1467904147.463371]
> [telit/mm-plugin-telit.c:247] getportcfg_ready(): telit: retrieving port
> mode layout
>
> The only idea I can come up with is that the parser is receiving the wrong
> message. That was, in fact, the behavior I saw the first time, but as I said
> before this time the problem is slightly different because
> mm_port_serial_at_command_finish in mm-plugin-telit:getportcfg_ready returns
> with error this time, while the first time I saw the problem, no error was
> returned and the response was NULL, the process continued till
> mm-plugin-telit.c:cache_port_mode at line 248 and then the regex inside that
> function returned with error being unable to parse the NULL string.

This is a bit strange; we do see the reply printed in the debug log,
so that means we received it, but then it doesn't end up being flagged
as a response to the command, which is weird. Could you add some debug
traces in mm-port-serial.c::parse_response_buffer() and
mm-port-serial-at.c::parse_response() to see where exactly we end up
ignoring the response? E.g. I'm assuming that in this case the
parse_response() callback within parse_response_buffer() is returning
MM_PORT_SERIAL_RESPONSE_NONE; we should try to understand why is that.

-- 
Aleksander
https://aleksander.es