Handling empty row from AT command

Handling empty row from AT command

[Mattias =?unknown-8bit?q?M=C3=A5nsson?=]

[-- Attachment #1: Type: text/plain, Size: 516 bytes --]

I'm integrating a new Cinterion module and have a small issue I haven't been able to solve nicely in Ofono. One of their commands responds with a list of stuff, followed by an OK but also after the OK there is an empty line. Which is of course wrong, but it might not be solved for a while. Using the g_at_chat_send function with a callback doesn't seem to work then, the callback will not be called it seems and I get stuck in the sequence. Can I without modifying the AT parser handle this somehow?


/Mattias

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 1012 bytes --]

Re: Handling empty row from AT command

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 861 bytes --]

Hi Mattias,

On 06/20/2018 02:34 AM, Mattias Månsson wrote:
> I'm integrating a new Cinterion module and have a small issue I haven't 
> been able to solve nicely in Ofono. One of their commands responds with 
> a list of stuff, followed by an OK but also after the OK there is an 
> empty line. Which is of course wrong, but it might not be solved for a 
> while. Using the g_at_chat_send function with a callback doesn't seem to 
> work then, the callback will not be called it seems and I get stuck in 
> the sequence. Can I without modifying the AT parser handle this somehow?
> 

Nope, the parser is what actually drives command recognition.  So 
sending empty commands, etc won't work.

If you're using the gsmv1 parser, then try switching to permissive. 
Permissive is generally able to deal with such situations.

Regards,
-Denis

SV: Handling empty row from AT command

[Mattias =?unknown-8bit?q?M=C3=A5nsson?=]

[-- Attachment #1: Type: text/plain, Size: 1187 bytes --]

It seems we already use that parser though:

syntax = g_at_syntax_new_gsm_permissive();
chat = g_at_chat_new(channel, syntax);

________________________________
Från: Denis Kenzior <denkenz@gmail.com>
Skickat: den 20 juni 2018 15:20:13
Till: Mattias Månsson; ofono(a)ofono.org
Ämne: Re: Handling empty row from AT command

Hi Mattias,

On 06/20/2018 02:34 AM, Mattias Månsson wrote:
> I'm integrating a new Cinterion module and have a small issue I haven't
> been able to solve nicely in Ofono. One of their commands responds with
> a list of stuff, followed by an OK but also after the OK there is an
> empty line. Which is of course wrong, but it might not be solved for a
> while. Using the g_at_chat_send function with a callback doesn't seem to
> work then, the callback will not be called it seems and I get stuck in
> the sequence. Can I without modifying the AT parser handle this somehow?
>

Nope, the parser is what actually drives command recognition.  So
sending empty commands, etc won't work.

If you're using the gsmv1 parser, then try switching to permissive.
Permissive is generally able to deal with such situations.

Regards,
-Denis

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 2090 bytes --]

Re: SV: Handling empty row from AT command

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 731 bytes --]

Hi Mattias,

On 06/20/2018 08:24 AM, Mattias Månsson wrote:
> It seems we already use that parser though:
> 
> syntax = g_at_syntax_new_gsm_permissive();
> chat = g_at_chat_new(channel, syntax);
> 

Not sure then.  Permissive should be taking care of the issue you 
describe, e.g it skips any empty lines:

                 case GSM_PERMISSIVE_STATE_IDLE:
                         if (byte == '\r' || byte == '\n')
                                 /* ignore */;

Maybe there's something more subtle going on?  Are there stray 
whitespace characters or something else in the spurious response?  You 
would have to trace why the permissive syntax fails and either fix it or 
design your own.

Regards,
-Denis

SV: SV: Handling empty row from AT command

[Mattias =?unknown-8bit?q?M=C3=A5nsson?=]

[-- Attachment #1: Type: text/plain, Size: 997 bytes --]

I will do some experiments and come back to you with logs...

________________________________
Från: Denis Kenzior <denkenz@gmail.com>
Skickat: den 20 juni 2018 15:30:00
Till: Mattias Månsson; ofono(a)ofono.org
Ämne: Re: SV: Handling empty row from AT command

Hi Mattias,

On 06/20/2018 08:24 AM, Mattias Månsson wrote:
> It seems we already use that parser though:
>
> syntax = g_at_syntax_new_gsm_permissive();
> chat = g_at_chat_new(channel, syntax);
>

Not sure then.  Permissive should be taking care of the issue you
describe, e.g it skips any empty lines:

                 case GSM_PERMISSIVE_STATE_IDLE:
                         if (byte == '\r' || byte == '\n')
                                 /* ignore */;

Maybe there's something more subtle going on?  Are there stray
whitespace characters or something else in the spurious response?  You
would have to trace why the permissive syntax fails and either fix it or
design your own.

Regards,
-Denis

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 2174 bytes --]

SV: SV: Handling empty row from AT command

[Mattias =?unknown-8bit?q?M=C3=A5nsson?=]

[-- Attachment #1: Type: text/plain, Size: 5777 bytes --]

OK, I think the problem is not exactly as I described it. It is probably caused by the empty line, but the result is that the next AT command never completes.


My sequence is started as this:


g_at_chat_send(data->app, "AT+XSYSTRACE=30", none_prefix, trace_start_at_cb, data, NULL);

then in trace_start_at_cb increase a counter and send a new command each time the callback is called. In total I send this sequence:

g_at_chat_send(data->app, "AT+XSYSTRACE=30", none_prefix, trace_start_at_cb, data, NULL);
g_at_chat_send(data->app, "AT+XSYSTRACE=40", none_prefix, trace_start_at_cb, data, NULL);
g_at_chat_send(data->app, "AT+XSYSTRACE=50", none_prefix, trace_start_at_cb, data, NULL);

g_at_chat_send(data->app, "AT+XSYSTRACE=0,<huge mask>", none_prefix, trace_start_at_cb, data, NULL);


The problem is that if I run this sequence, I never get passed the AT+XSYSTRACE=50 as seen here:


Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT\r
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nOK\r\n
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: AppFinally woke up the modem
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=30\r
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nOK\r\n
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: plugins/verimalto.c:trace_start_at_cb()
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=40\r
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nDecoder List 0 bytes sent\r\nOK\r\n
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: plugins/verimalto.c:trace_start_at_cb()
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=50\r
Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\n\r\n

But if I skip the AT+XSYSTRACE=40, the sequence runs fine:

Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT\r
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: AppFinally woke up the modem
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=30\r
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: plugins/verimalto.c:trace_start_at_cb()
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=50\r
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: plugins/verimalto.c:trace_start_at_cb()
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: plugins/verimalto.c:trace_start_at_cb() Trace cmd: AT+XSYSTRACE=0,"bb_sw=1;3g_sw=1;lte_l1_sw=1;digrfx=1;3g_dsp=1","bb_sw=sdl:th,tr,st,pr,mo,lt,db,li,syfts:xllt(gprs,umts),mon(gprs,umts),sdl(gprs,umts),llt(gprs,umts)|egdci:0x00000001|lte_stk:0x02,0x83FFFFFF|ims:1|lte_stk:0x01,0xFFFFFFFF,0xFFFFFFFF,0xFFFFFFFF,0xFFFFFFFFxllt:xllt_set_template(1,{basic});digrfx=0x0003;lte_l1_sw=(ALL,NORMAL,ALL,ALL)","oct=4;oct_fcs=16"
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=0,"bb_sw=1;3g_sw=1;lte_l1_sw=1;digrfx=1;3g_dsp=1","bb_sw=sdl:th,tr,st,pr,mo,lt,db,li,syfts:xllt(gprs,umts),mon(gprs,umts),sdl(gprs,umts),llt(gprs,umts)|egdci:0x00000001|lte_stk:0x02,0x83FFFFFF|ims:1|lte_stk:0x01,0xFFFFFFFF,0xFFFFFFFF,0xFFFFFFFF,0xFFFFFFFFxllt:xllt_set_template(1,{basic});digrfx=0x0003;lte_l1_sw=(ALL,NORMAL,ALL,ALL)","oct=4;oct_fcs=16"\r
Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n

So I'm suspecting that somehow the extra empty line from AT+XSYSTRACE=40 ends up as the response for the AT+XSYSTRACE=50, but as it is not an OK it expects more, which for some reason isn't read... Don't know why...

Here is my full callback source btw:

static void trace_start_at_cb(gboolean ok, GAtResult *result, gpointer user_data)
{
struct verimalto_data *data = user_data;
DBusMessage *reply;

DBG("");

if (!ok)
goto error;

switch (data->trace->step) {
case 1:
data->trace->step++;
g_at_chat_send(data->app, "AT+XSYSTRACE=40", none_prefix, trace_start_at_cb, data, NULL);
      break;

case 2:
data->trace->step++;
g_at_chat_send(data->app, "AT+XSYSTRACE=50", none_prefix, trace_start_at_cb, data, NULL);
      break;

case 3:
DBG("Trace cmd: %s", data->trace->mask_cmd);
g_at_chat_send(data->app, data->trace->mask_cmd, none_prefix, NULL, data, NULL);

g_free(data->trace->mask_cmd);
data->trace->mask_cmd = NULL;

reply = dbus_message_new_method_return(data->trace->msg);

  __ofono_dbus_pending_reply(&data->trace->msg, reply);
break;
}

return;

error:
g_free(data->trace->mask_cmd);
data->trace->mask_cmd = NULL;

__ofono_dbus_pending_reply(&data->info->msg,
__ofono_error_failed(data->info->msg));
}

/Mattias

________________________________
Från: Mattias Månsson
Skickat: den 20 juni 2018 15:33:05
Till: Denis Kenzior; ofono(a)ofono.org
Ämne: SV: SV: Handling empty row from AT command


I will do some experiments and come back to you with logs...

________________________________
Från: Denis Kenzior <denkenz@gmail.com>
Skickat: den 20 juni 2018 15:30:00
Till: Mattias Månsson; ofono(a)ofono.org
Ämne: Re: SV: Handling empty row from AT command

Hi Mattias,

On 06/20/2018 08:24 AM, Mattias Månsson wrote:
> It seems we already use that parser though:
>
> syntax = g_at_syntax_new_gsm_permissive();
> chat = g_at_chat_new(channel, syntax);
>

Not sure then.  Permissive should be taking care of the issue you
describe, e.g it skips any empty lines:

                 case GSM_PERMISSIVE_STATE_IDLE:
                         if (byte == '\r' || byte == '\n')
                                 /* ignore */;

Maybe there's something more subtle going on?  Are there stray
whitespace characters or something else in the spurious response?  You
would have to trace why the permissive syntax fails and either fix it or
design your own.

Regards,
-Denis

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 11623 bytes --]

Re: SV: SV: Handling empty row from AT command

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 2460 bytes --]

Hi Mattias,

By the way, please no top-posting on this list.

> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT\r
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nOK\r\n
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: AppFinally woke up the modem
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=30\r
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nOK\r\n
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: 
> plugins/verimalto.c:trace_start_at_cb()
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=40\r
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nDecoder List 0 
> bytes sent\r\nOK\r\n
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: 
> plugins/verimalto.c:trace_start_at_cb()
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=50\r

So this tells me that XSYSTRACE=40 command response was processed 
correctly (e.g. OK was detected) and we start the XSYSTRACE=50 command.

> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\n\r\n
> 

This tells me the modem is buggered and isn't responding with anything 
resembling a 'proper' response.  The AT trace will still show anything 
that is being sent on the serial port, so if there's no 'OK' showing up, 
there isn't much that oFono can do.

> But if I skip the AT+XSYSTRACE=40, the sequence runs fine:
> 
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT\r
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: AppFinally woke up the modem
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=30\r
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: 
> plugins/verimalto.c:trace_start_at_cb()
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=50\r
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: 

Right, so something in the earlier XSYSTRACE sequence is screwing up the 
firmware.  Get your vendor on the line.

> 
> So I'm suspecting that somehow the extra empty line from AT+XSYSTRACE=40 
> ends up as the response for the AT+XSYSTRACE=50, but as it is not an OK 
> it expects more, which for some reason isn't read... Don't know why...

Nope.  The socket is read and data is printed to debug output regardless 
of what the syntax state is.  See gatio.c:received_data()

Regards,
-Denis

SV: SV: SV: Handling empty row from AT command

[Mattias =?unknown-8bit?q?M=C3=A5nsson?=]

[-- Attachment #1: Type: text/plain, Size: 2693 bytes --]

OK, thanks! I will talk to them :)

________________________________
Från: Denis Kenzior <denkenz@gmail.com>
Skickat: den 20 juni 2018 16:28:12
Till: Mattias Månsson; ofono(a)ofono.org
Ämne: Re: SV: SV: Handling empty row from AT command

Hi Mattias,

By the way, please no top-posting on this list.

> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT\r
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nOK\r\n
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: AppFinally woke up the modem
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=30\r
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nOK\r\n
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]:
> plugins/verimalto.c:trace_start_at_cb()
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=40\r
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\nDecoder List 0
> bytes sent\r\nOK\r\n
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]:
> plugins/verimalto.c:trace_start_at_cb()
> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App> AT+XSYSTRACE=50\r

So this tells me that XSYSTRACE=40 command response was processed
correctly (e.g. OK was detected) and we start the XSYSTRACE=50 command.

> Jun 20 13:44:03 lev-26e7jvbe ofonod[16440]: App< \r\n\r\n
>

This tells me the modem is buggered and isn't responding with anything
resembling a 'proper' response.  The AT trace will still show anything
that is being sent on the serial port, so if there's no 'OK' showing up,
there isn't much that oFono can do.

> But if I skip the AT+XSYSTRACE=40, the sequence runs fine:
>
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT\r
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: AppFinally woke up the modem
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=30\r
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]:
> plugins/verimalto.c:trace_start_at_cb()
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App> AT+XSYSTRACE=50\r
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]: App< \r\nOK\r\n
> Jun 20 13:54:04 lev-26e7jvbe ofonod[16598]:

Right, so something in the earlier XSYSTRACE sequence is screwing up the
firmware.  Get your vendor on the line.

>
> So I'm suspecting that somehow the extra empty line from AT+XSYSTRACE=40
> ends up as the response for the AT+XSYSTRACE=50, but as it is not an OK
> it expects more, which for some reason isn't read... Don't know why...

Nope.  The socket is read and data is printed to debug output regardless
of what the syntax state is.  See gatio.c:received_data()

Regards,
-Denis

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 3779 bytes --]