AT Command interface hangs

[kt1024]

Hi,

without providing too much code right away, I would like to ask how I could circumvent AT command interface hangups. My current test application calls AT commands like

static const char cereg[] = "AT+CEREG?";

static const char cesq[] = "AT+CESQ";

static const char vbat[] = "AT%XVBAT";

I just modified lte_lc. for this

in the main loop with an interval of 10s by calling k_sleep(K_MSEC(10000)); in between. So the commands are sent to the modem via the socket, the results are received and evaluated and then sent to our cloud via UDP. Between each command passed to the modem lie 10 seconds.

What I would like to know is how I can prevent the AT command interface hangup, and if it happens anyway how can I reset the modem separately from the Cortex-M33.

Typically I can go through the above sequence 4 times and then the AT Command interface hangs. This is not acceptable, so I have to find a way to prevent this from happening.

Best Regards,

KT

[Jan Tore Guggedal]

Hi kt1024,

Could you share the changes that you've made in lte_lc.c/h and how you call the functions?
It would also be good to know which versions of the SDK your working on, for example the latest commits of the -zephyr and -nrf repositories in particular, along with modem version. That way others can replicate what your setup and possibly provide better help.

Best regards,

Jan Tore

[kt1024]

Well the tags are:

\zephyr>git log
commit 82fe1f9dfcf0e100d6fc952c07cf63d63aa08a0e (HEAD, tag: v1.13.99-ncs2-rc2, tag: v1.13.99-ncs2)

\nrf>git log
commit 5ad94691363cb0832943d8cb759df7db982a2e63 (HEAD, tag: v0.3.0)

\nrfxlib>git log
commit 891c089577857d8a197b7360e007a0d84e6dbe54 (HEAD, tag: v0.3.0)

any newer versions would be great to have, I just went through the Getting Started App for this.

The modem firmware is:

mfw_nb1_nrf9160_0.3.0-73.prealpha.zip

The main change to lte_lc.c is:

static int at_cmd_wret(int fd, const char *cmd, size_t size, char * const ret)
{
    int len;
    uint32_t retCount = 0;
    int fnc_return;
    u8_t buffer[LC_MAX_READ_LENGTH];

    char *pLine[2] =
    { NULL, NULL };

    LOG_DBG("send: %s", cmd);
    len = send(fd, cmd, size, 0);
    if (len != size)
    {
        LOG_ERR("send: failed");
        return -EIO;
    }

    len = recv(fd, buffer, LC_MAX_READ_LENGTH, 0);

    memset(ret,0,LC_MAX_READ_LENGTH);
    do
    {
        if (len < AT_CMD_SIZE(success))
        {
            LOG_ERR("recv: %s", buffer);
            fnc_return = -EIO;
        }
        else
        {
            pLine[0] = buffer;
            pLine[1] = memchr(buffer, '\n', LC_MAX_READ_LENGTH);
            pLine[1][0]='\0';
            pLine[1]++;
            if (memcmp(success, &pLine[1][0], AT_CMD_SIZE(success)) == 0)
            {
                memmove(ret, pLine[0], strlen(pLine[0]));
                fnc_return = 0L;
            }
            else
            {
                LOG_ERR("recv: %s", buffer);
                fnc_return = -EIO;
            }

        }

        printk("rx1: %s\n", pLine[0]);
        printk("rx2: %s\n", pLine[1]);
        printk("rx3: %s\n", ret);
        retCount++;
    }
    while (retCount < 1U);

    return fnc_return;
}

   

and to give an example of using this function:

int exl_lte_lc_get_cereg(exl_lte_lc_cereg_t * const pCereg)
{
    int errVal;
    int at_socket_fd;
    u8_t buffer[LC_MAX_READ_LENGTH];

    at_socket_fd = socket(AF_LTE, 0, NPROTO_AT);
    if (at_socket_fd == -1)
    {
        return -EFAULT;
    }

    errVal = at_cmd_wret(at_socket_fd, cereg, AT_CMD_SIZE(cereg), buffer);

    if (errVal == 0L)
    {
        // "+CEREG: 2,5,\"C76A\",\"01ACB906\",9"

        sscanf(&buffer[8], "%u,%u,\"%[^\"]\",\"%[^\"]\",%u", (unsigned int *)&pCereg->n, (unsigned int *)&pCereg->stat, pCereg->tac,
                pCereg->ci, (unsigned int *)&pCereg->act);

    }
    else
    {
        return errVal;
    }

    close(at_socket_fd);
    return 0;
}

The main loop looks like the following:

int main(void)
{
    int32_t s;
    char imei[16];
    uint8_t stage = 0U;
    char dgram[256];
    int32_t Rsrp;
    uint32_t uptime;
    uint32_t vbat;
    exl_lte_lc_cereg_t Cereg;


    printk("Application started\n");

    memset(dgram,0,sizeof(dgram));
    memset(&Rsrp,0,sizeof(Rsrp));
    memset(&uptime,0,sizeof(uptime));
    memset(&vbat,0,sizeof(vbat));
    memset(&Cereg,0,sizeof(Cereg));
    memset(imei,0,sizeof(imei));

    buttons_leds_init();
    work_init();
    modem_configure();

    s = udp_connect();

    if (IS_ENABLED(CONFIG_CLOUD_UA_CONSOLE))
    {
        console_init();
    }

    // get imei
    exl_lte_lc_get_imei(imei);

    while (true)
    {
        if (s >= 0L)
        {
            uint32_t slen;


            uptime = (uint32_t)(k_uptime_get() / 1000L);


            switch (stage)
            {

            case 0:
                stage=0U;
                break;
            case 1:
                exl_lte_lc_get_cereg(&Cereg);
                stage=2U;
                break;
            case 2:
                exl_lte_lc_get_cesq(&Rsrp);
                stage=0U;
                break;
            case 3:
                exl_lte_lc_get_vbat(&vbat);
                stage=0U;
                break;

            default:
                stage=0U;
            }

            sprintf(dgram, "%s?b=[s=\"Test\",c=%s,tc=%s,r=%.1f,ti=\"%u\",a=%u]", imei, Cereg.ci, Cereg.tac,
                    (float)1.0f * Rsrp, (unsigned int)uptime, (unsigned int)((100 * vbat) / 5000U));

            printk("%s", dgram);

            slen = nrf_strnlen(dgram, sizeof(dgram));
            if (send(s, dgram, slen, 0L) != slen)
            {
                printk("partial/failed write\n");
            }
            else
            {
                printk("Sent %u Bytes\n", (unsigned int)slen);
            }


        }
        /* if logging is enabled, sleep */
        k_sleep(K_MSEC(10000));

    }

    return 0L;
}

Should  I change the approach in exl_lte_lc_* I'll go with the one used in at_client. For now I don't need to use AT_commands in the main loop.

Regards,

KT

[Jan Tore Guggedal]

Hi,

I think the problem is on line 25 in the middle code block you posted. In case of return, the socket remains open, but a new one is opened in the next run. In the end you run out of available sockets, and I guess you would see -EFAULT returned from exl_lte_lc_get_cereg(). You can either just keep the socket open all the time, or ensure that you close it also when something fails.

Update: You can see the new implementation of the AT host for tips on how you can send and receive AT commands in a dedicated thread, and receive callbacks whenever there's data on the socket: https://github.com/NordicPlayground/fw-nrfconnect-nrf/blob/master/lib/at_host/at_host.c 
This allows you to receive notifications for example when the signal strength changes, without having to poll the modem, using the Nordic proprietary AT command AT%CESQ: www.nordicsemi.com/.../proc_cesq

[kt1024]

Hi,

I tried instrumenting the code around socket() and found that the socket descriptor never changes its value and stays at 2, also it never reaches return -EFAULT.

int exl_lte_lc_get_cereg(exl_lte_lc_cereg_t * const pCereg)
{
    int errVal;
    int at_socket_fd;
    u8_t buffer[LC_MAX_READ_LENGTH];

    at_socket_fd = socket(AF_LTE, 0, NPROTO_AT);
    if (at_socket_fd == -1)
    {
        printk("%s:%u: Error EFAULT\n",__FUNCTION__,__LINE__);
        return -EFAULT;
    }

    printk("%s:%u: Socket: %d\n",__FUNCTION__,__LINE__,at_socket_fd);

    errVal = at_cmd_wret(at_socket_fd, cereg, AT_CMD_SIZE(cereg), buffer);

    if (errVal == 0L)
    {
        // "+CEREG: 2,5,\"C76A\",\"01ACB906\",9"

        sscanf(&buffer[8], "%u,%u,\"%[^\"]\",\"%[^\"]\",%u", (unsigned int *)&pCereg->n, (unsigned int *)&pCereg->stat, pCereg->tac,
                pCereg->ci, (unsigned int *)&pCereg->act);

    }
    else
    {
        return errVal;
    }

    close(at_socket_fd);
    return 0;
}

There is a high consistency in reaching the 140 seconds mark and not getting further. Also it hangs in at_cmd_wret():recv() and not elsewhere. All this lets me think that awneil is on the right track, despite my sloppy coding involving not checkng return values and returning from a function in more than one place.

Let me add a bit of output from UART_0:

s
exl_lte_lc_get_cesq:312: Socket: 2
Before recv
After recv
rx1: +CESQ: 99,99,255,255,255,61
rx2: OK

rx3: +CESQ: 99,99,255,255,255,61
352656100000036?b=[s="Test",c=01ACB906,tc=C76A,r=-79.0,ti="127",a=0]Sent 68 Bytes
352656100000036?b=[s="Test",c=01ACB906,tc=C76A,r=-79.0,ti="137",a=0]Sent 68 Bytes
exl_lte_lc_get_cereg:247: Socket: 2
Before recv
After recv
rx1: +CEREG: 0,5,"C76A","01ACB906",9
rx2: OK

rx3: +CEREG: 0,5,"C76A","01ACB906",9
352656100000036?b=[s="Test",c=01ACB906,tc=C76A,r=-79.0,ti="147",a=0]Sent 68 Bytes
exl_lte_lc_get_cesq:312: Socket: 2
Before recv

Thanks for the update about at_host.c I'm using this in its older form already. Using a separate thread for reading the interface is something I may also try in the future.

Regards,

KT

[Jan Tore Guggedal]

Thanks for the log output! I was able to reproduce locally, and it seems you've hit a bump with regards to missing implementation of the function bsd_os_timedwait(). Could you try this hack in nrf/lib/bsdlib/bsd_os.c :

int32_t bsd_os_timedwait(uint32_t context, uint32_t timeout)
{
	    /* TODO: to be implemented */
    	k_sleep(timeout);
	    return 0;
}

This is not a long term solution, but it can help you overcome this weird issue for now and isolate the issue.

[kt1024]

I tried this, it doesn't prevent recv() from hanging.

Regards,

KT

[Jan Tore Guggedal]

Bummer, then I'm starting to run out of ideas, but will come back to you if I can find something. If your code is on a public git branch somewhere, that would be great, to reproduce it exactly as you have it locally. If you don't want to have it public, you can open a private ticket and share your code only with tech support.

[kt1024]

Unfortunately I don't have time next week. So I'll have to let the case linger for a bit. Also since at_host behaves much better and I strongly believe that since recv() is meant to be called with way more error handling and retries anyway, I would rather change my code to something like at_host has to offer.

On the other hand if you think that there might be some issue with the modem or the binary code in nrfxlib I would be happy if it can become more stable.

Regards,

KT

[kt1024]

I found some time. I tried to setup a thread that creates the socket to the AT command interface, reads and send bytes to the AT socket and fills and empties a queue for rx and tx bytes that connects with the main task .While I can read from the socket it only ever returns 'E' characters

Line1: EEEEEEEEE

This result came about when I sent "AT+CGSN=1\r\n". This happens only once. I didn't use any mutexes since I expected the queues to be sufficiently protected and the socket was only used in the read/write task.

If you have seen this before let me know, otherwise I will get rid of the threadding and just don't close the socket in lte_lc.c

Regards,

KT

[Jan Tore Guggedal]

Hi,

I've never seen that. It's really curious.

It would be very useful for both others and me to see a repository or something with your codebase so that we can reproduce locally and get to the bottom of this.

One thing you could try just to eliminate one thing, is to include a k_sleep(100) or k_sleep(10) in the bsd_os_timedwait function i mentioned earlier. That might help narrow things down a bit.

BR,
Jan Tore