gsmd misbehaves on back-to-back AT+CFUN=1/AT+COPS=0

[cesarb@…]

Starting gsmd manually (so the GUI does not tell it to register), and typing "O"
and "r" very quickly to libgsmd-tool's shell (so both commands are sent almost
at the same time to the modem) results on gsmd receiving only one answer and
getting confused:

Tue Feb 1 00:22:25 2000 <1> atcmd.c:545:atcmd_submit() submitting command
`AT+CFUN=1'
Tue Feb 1 00:22:25 2000 <1> atcmd.c:545:atcmd_submit() submitting command
`AT+COPS=0'
Tue Feb 1 00:22:25 2000 <1> atcmd.c:210:ml_parse() buf=`OK'(2)
Tue Feb 1 00:22:25 2000 <1> atcmd.c:406:ml_parse() Calling final cmd->cb()
Tue Feb 1 00:22:25 2000 <1> usock.c:249:phone_powerup_cb() Radio powered-up
Tue Feb 1 00:22:25 2000 <1> atcmd.c:415:ml_parse() Clearing mlbuf
(gets stuck at this point, no more answers)

Telling it to power off ("o") is enough to get it unstuck. If you wait a couple
of seconds between the "O" and the "r", gsmd receives an answer before sending
the AT+COPS=0, and everything works fine.

[mickey@…]

Making this depend on 574 since the problem obviously roots in timing / response
mapping issues.

[cesarb@…]

I think I understand now why does gsmd submit two commands back-to-back, even
when there's a break on atcmd_select_cb() commented as /* we only send one cmd
at the moment */, which should make it send only one command at a time.

After the break, select() is told to not generate a write event on the socket:

/* Either pending_atcmds is empty or a command has to wait */
g->gfd_uart.when &= ~GSMD_FD_WRITE;

However, g->pending_atcmds is now empty (the command was moved from it to
g->busy_atcmds just before the break). When it is empty, atcmd_submit() enables
GSMD_FD_WRITE, which makes the command be sent immediately, without waiting for
the command to receive its response.

So, if we want to enforce one-command-at-a-time behaviour for every command, we
should also check for llist_empty(&g->busy_atcmds) on atcmd_submit() (the patch
I attached to this bug should not be needed then). I will test it later today.

While looking at this, I found another potential bug: the return value for the
write(fd, "\r", 1) on atcmd_select_cb() is never checked, which could result on
a CR being dropped on a short write.

[cesarb@…]

Patch to work around this issue

[cesarb@…]

Debugging patch

[cesarb@…]

Fix GSMD_FD_WRITE setting on atcmd_submit()

[cesarb@…]

As an aside: with this patch, there's no need for all the powering off/on/off/on
dance on /etc/init.d/gsmd, which helps avoid hitting #788.

[cesarb@…]

There seems to still be a problem with the gsmd/modem interaction, saw the
following once (with my patch and powering off/resetting the modem disabled on
/etc/init.d/gsmd):

root@fic-gta01:~$ cat /tmp/gsm.log
Sat Sep 8 02:35:28 2007 <1> machine.c:131:gsmd_machine_plugin_init() detected
'GTA01' hardware
Sat Sep 8 02:35:28 2007 <1> machine.c:72:gsmd_machine_plugin_load() loading
machine plugin "generic"
Sat Sep 8 02:35:28 2007 <1> vendor.c:75:gsmd_vendor_plugin_load() loading
vendor plugin "ti"
Sat Sep 8 02:35:28 2007 <1> machine.c:56:gsmd_machine_plugin_find() selecting
machine plugin "generic"
Sat Sep 8 02:35:29 2007 <1> atcmd.c:570:atcmd_drain() c_iflag = 0x00000500,
c_oflag = 0x00000005, c_cflag = 0x800018b2, c_lflag = 0x00008a3b
Sat Sep 8 02:35:29 2007 <1> vendor.c:59:gsmd_vendor_plugin_find() selecting
vendor plugin "TI Calypso"
Sat Sep 8 02:35:29 2007 <1> atcmd.c:554:atcmd_submit() submitting command `ATZ'
Sat Sep 8 02:35:29 2007 <1> atcmd.c:491:atcmd_select_cb() write `ATZ'(3/3)
Sat Sep 8 02:35:50 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CFUN=1'
Sat Sep 8 02:36:10 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+COPS=0'

The other times I tried, it worked fine (unlike before, where it reliably didn't
work).

[cesarb@…]

A different one where it didn't work:

Sat Sep 8 03:43:56 2007 <1> machine.c:131:gsmd_machine_plugin_init() detected
'GTA01' hardware
Sat Sep 8 03:43:56 2007 <1> machine.c:72:gsmd_machine_plugin_load() loading
machine plugin "generic"
Sat Sep 8 03:43:56 2007 <1> vendor.c:75:gsmd_vendor_plugin_load() loading
vendor plugin "ti"
Sat Sep 8 03:43:56 2007 <1> machine.c:56:gsmd_machine_plugin_find() selecting
machine plugin "generic"
Sat Sep 8 03:43:57 2007 <1> atcmd.c:570:atcmd_drain() c_iflag = 0x00000500,
c_oflag = 0x00000005, c_cflag = 0x800018b2, c_lflag = 0x00008a3b
Sat Sep 8 03:43:57 2007 <1> vendor.c:59:gsmd_vendor_plugin_find() selecting
vendor plugin "TI Calypso"
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command `ATZ'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:491:atcmd_select_cb() write `ATZ'(3/3)
Sat Sep 8 03:43:57 2007 <1> atcmd.c:210:ml_parse() buf=`AT-Command Interpreter
ready'(28)
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command `ATZ'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:232:ml_parse() synthetic error
Sat Sep 8 03:43:57 2007 <1> atcmd.c:414:ml_parse() Calling final cmd->cb()
Sat Sep 8 03:43:57 2007 <7> gsmd.c:210:firstcmd_atcb() response 'ERROR' to
initial command invalidSat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit()
submitting command `ATE0V1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CRC=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CREG=2'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CMEE=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CLIP=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+COLP=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CMGF=0'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CMGF=0'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CTZR=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT%CTZV=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT%CPRI=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT%CSQ=1'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT%CUNS=0'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT%CPI=?'
Sat Sep 8 03:43:57 2007 <1> atcmd.c:423:ml_parse() Clearing mlbuf
Sat Sep 8 03:43:57 2007 <1> atcmd.c:491:atcmd_select_cb() write `ATZ'(3/3)
Sat Sep 8 03:44:21 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+CFUN=1'
Sat Sep 8 03:44:41 2007 <1> atcmd.c:554:atcmd_submit() submitting command
`AT+COPS=0'

[cesarb@…]

Another debugging patch

[tick@…]

It's work for me now for current SVN version R3572