[PATCH] Hardening PORTCFG parse reply
Carlo Lobrano
c.lobrano at gmail.com
Wed Jul 13 07:41:44 UTC 2016
Hi all,
I added some more debug traces and found out two different problems.
1. passing from common_input_available to parse_response_buffer, it seems
that part of the messag disappear (see attached file). This is the problem
I saw the first time and the result is that Telit plugin's parser
cache_port_mode receives a NULL string to parse and fails
2. The second problem might be even more weird. Parse_response_buffer gets
a valid message and the content of the response is right, but still no
callback is called and the initial call times out.
In the tar.gz attachment there is the full syslog of the test and two more
files with ModemManager's logs only for the two problems (it is easier to
read the content of the received message):
problem 1: portcfg-message-disappear.txt
problem 2: portcfg-complete-no-callback-called.txt
I added also the a diff so you can see where the new debug traces are.
On 11 July 2016 at 13:56, Aleksander Morgado <aleksander at aleksander.es>
wrote:
> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20160713/33760202/attachment-0001.html>
-------------- next part --------------
diff --git a/plugins/telit/mm-plugin-telit.c b/plugins/telit/mm-plugin-telit.c
index d9793d1..6aaf8cb 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 ("telit: Could not recognize string '%s'", reply);
goto out;
+ }
if (!mm_get_uint_from_match_info (match_info, 2, &portcfg_current)) {
mm_dbg ("telit: unrecognized #PORTCFG <active> value");
@@ -240,6 +242,8 @@ getportcfg_ready (MMPortSerialAt *port,
device = mm_port_probe_peek_device (ctx->probe);
+ mm_dbg ("Telit: getportcfg_ready got response '%s'", response);
+
/* 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");
diff --git a/src/mm-port-serial-at.c b/src/mm-port-serial-at.c
index 8e2aa2a..46c860d 100644
--- a/src/mm-port-serial-at.c
+++ b/src/mm-port-serial-at.c
@@ -138,6 +138,8 @@ parse_response (MMPortSerial *port,
if (!response->len)
return MM_PORT_SERIAL_RESPONSE_NONE;
+ mm_dbg ("[TEST] unparsed response '%s' (len %d)", (const char*) response->data, response->len);
+
/* Construct the string that AT-parsing functions expect */
string = g_string_sized_new (response->len + 1);
g_string_append_len (string, (const char *) response->data, response->len);
@@ -149,6 +151,7 @@ parse_response (MMPortSerial *port,
/* Parse it; returns FALSE if there is nothing we can do with this
* response yet. */
if (!self->priv->response_parser_fn (self->priv->response_parser_user_data, string, &inner_error)) {
+ mm_dbg ("[TEST] Nothing to do with parsed string '%s'", string->str);
/* Copy what we got back in the response buffer. */
g_byte_array_append (response, (const guint8 *) string->str, string->len);
g_string_free (string, TRUE);
@@ -163,6 +166,7 @@ parse_response (MMPortSerial *port,
/* Otherwise, build a new GByteArray considered as parsed response */
parsed_len = string->len;
+ mm_dbg ("[TEST] parsed_response is '%s' (len %lu)", string->str, string->len);
*parsed_response = g_byte_array_new_take ((guint8 *) g_string_free (string, FALSE), parsed_len);
return MM_PORT_SERIAL_RESPONSE_BUFFER;
}
diff --git a/src/mm-port-serial.c b/src/mm-port-serial.c
index 2b31dfe..5a18674 100644
--- a/src/mm-port-serial.c
+++ b/src/mm-port-serial.c
@@ -895,6 +895,7 @@ parse_response_buffer (MMPortSerial *self)
* response to process. The parsed string is returned already out of the
* response buffer, and the response buffer is cleaned up accordingly.
*/
+ mm_dbg ("[TEST] unparsed response '%s' (len %d)", (const char*) self->priv->response->data, self->priv->response->len);
g_assert (MM_PORT_SERIAL_GET_CLASS (self)->parse_response != NULL);
switch (MM_PORT_SERIAL_GET_CLASS (self)->parse_response (self,
self->priv->response,
@@ -904,11 +905,13 @@ parse_response_buffer (MMPortSerial *self)
/* We have a valid response to process */
g_assert (parsed_response);
self->priv->n_consecutive_timeouts = 0;
+ mm_dbg ("[TEST] Got valid response '%s'", (const char*) parsed_response->data);
/* Note: may complete last operation and unref the MMPortSerial */
port_serial_got_response (self, parsed_response, NULL);
g_byte_array_unref (parsed_response);
break;
case MM_PORT_SERIAL_RESPONSE_ERROR:
+ mm_dbg ("[TEST] Got error in the response");
/* We have an error to process */
g_assert (error);
self->priv->n_consecutive_timeouts = 0;
@@ -918,6 +921,7 @@ parse_response_buffer (MMPortSerial *self)
break;
case MM_PORT_SERIAL_RESPONSE_NONE:
/* Nothing to do this time */
+ mm_dbg ("[TEST] Serial response NONE");
break;
}
}
@@ -1001,6 +1005,8 @@ common_input_available (MMPortSerial *self,
serial_debug (self, "<--", buf, bytes_read);
g_byte_array_append (self->priv->response, (const guint8 *) buf, bytes_read);
+ mm_dbg ("[TEST] self->priv->response '%s'", (const char*) self->priv->response->data);
+
/* Make sure the response doesn't grow too long */
if ((self->priv->response->len > SERIAL_BUF_SIZE) && self->priv->spew_control) {
/* Notify listeners and then trim the buffer */
-------------- next part --------------
A non-text attachment was scrubbed...
Name: portcfg-issues.tar.gz
Type: application/x-gzip
Size: 72092 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20160713/33760202/attachment-0001.bin>
More information about the ModemManager-devel
mailing list