serial_lte_modem app gets stuck after multiple AT#XHTTPCREQ commands

[Michal Vacha]

We are using nrf9160 as an LTE-M modem with the serial_lte_modem app running on it. Another chip (ESP32) communicates with it using AT commands and after a few minutes of successful communication (~tens of AT#XHTTPCREQ commands) the nrf chip gets stuck and no longer responds to requests.

serial_lte_modem & sdk version: 1.4.0

modem fw version: 1.2.2

network: NB-IOT, Vodafone Czech Republic

nrf log:

00> [00:05:52.526,519] <inf> httpc: Partial data received (235 bytes)
00> [00:05:52.557,861] <inf> httpc: Partial data received (42 bytes)
00> [00:05:52.557,861] <inf> httpc: All the data received (277 bytes)
00> [00:05:52.622,161] <inf> at_host: RX_DISABLED
00> [00:05:52.635,223] <inf> httpc: send header: 20 bytes
00> [00:05:52.635,620] <inf> httpc: wait until payload is ready
00> [00:05:52.644,042] <inf> httpc: send 51 bytes payload
00> [00:05:52.644,195] <inf> at_host: RX_DISABLED
00> [00:05:52.644,226] <wrn> at_host: UART RX buf rsp: -13
00> [00:05:52.644,317] <err> at_cmd: Invalid command
00> [00:05:52.644,317] <err> at_host: AT command error: -22
00> [00:05:52.646,118] <inf> at_host: RX_DISABLED

following two lines repeat aprox. 500 times:

00> [00:05:52.647,827] <err> at_cmd: Invalid command
00> [00:05:52.647,827] <err> at_host: AT command error: -22

00> [00:05:53.708,984] <inf> httpc: Partial data received (277 bytes)
00> [00:05:53.708,984] <inf> httpc: All the data received (277 bytes)

Sometimes the nrf chip reboots on its own, but most of the time it gets stuck and manual reboot is required.

The log contains `[00:04:22.522,003] <wrn> at_host: UART RX buf rsp: -13` but we have also captured logs without this error.

[Michal Vacha]

I have discovered that this error happens after the ESP sends the payload of the XHTTPCREQ command. Instead of receiving #XHTTPCREQ:0 we receive something else. I have captured two different instances of this problem:

Log #1 - Ready is received after the payload has been accepted (via OK) by the NRF. The Ready message signalizes (reboot? reinit?) of the modem, so nrf is not stuck.

ESP>NRF91:
AT#XHTTPCREQ="POST","/auth","Content-Length: 51
",51
NRF91>ESP:OK
NRF91>ESP:#XHTTPCREQ:1
ESP>NRF91:
{"data":"........."}
NRF91>ESP:OK�Ready

Log #2 - ERROR is received after the payload confirmation. Now the NRF modem is stuck, it never reconnects again.

ESP>NRF91:
AT#XHTTPCREQ="POST","/auth","Content-Length: 51
",51
NRF91>ESP:OK
NRF91>ESP:#XHTTPCREQ:1
ESP>NRF91:
{"data":".........."}
NRF91>ESP:OK@
NRF91>ESP:ERROR

[Carl Richard]

Hi, Michal!

Thank you for the patience. I'm looking into the issue. You are correct about "Ready". It means that the modem/nrf9160 has rebooted, indicating some kind of critical error.

While I'm at it could you manage to do a modem trace?

Best regards,
Carl Richard

[Michal Vacha]

Hi Carl,

thank you for your response.

I'm not able to colllect the modem trace easily, as the ESP+NRF91 is on a custom board. But I have both devkits on hand, so I'll try to run the code on them and collect the trace from nrf91DK.

BR, Michal V.

[Michal Vacha]

Hi, so I was finally able to capture the modem trace.

trace-2020-11-12T20-37-10.321Z.bin

The moment the modem got stuck, the trace also stopped.

This is the log from the ESP:

LTEM - CONNECT - to: https://WWW.XXXYYY.ZZZ/auth
LTEM - DISCONNECT
ESP32->AT#XHTTPCCON?
NRF91->#XHTTPCCON: 1,"WWW.XXXYYY.ZZZ",80
NRF91->OK
----------------------------------
ESP32->AT#XHTTPCCON=0
NRF91->#XHTTPCCON:0
NRF91->OK
----------------------------------
ESP32->AT#XHTTPCCON=1,"WWW.XXXYYY.ZZZ",80
NRF91->#XHTTPCCON:1
NRF91->OK
----------------------------------
TEST REQ: 109
AT#XHTTPCREQ="POST","/auth","Content-Length: 51
",51
OK
#XHTTPCREQ:1
{"data":"00112233445566778899AABBCCDDEEFF00000001"}
7B 22 64 61 74 61 22 3A 22 30 30 31 31 32 32 33 33 34 34 35 35 36 36 37 37 38 38 39 39 41 41 42 42 43 43 44 44 45 45 46 46 30 30 
30 30 30 30 30 31 22 7D OK
#XHTTPCREQ:0
#XHTTPCRSP:277,0
Received http response:
HTTP/1.1 200 OK
Content-Length: 86
Content-Type: application/json; charset=utf-8
Request-Context: appId=cid-v1:f2fae75f-c51e-487c-a740-29c31677881e
Date: Thu, 12 Nov 2020 20:39:59 GMT

{"data":"3582e219290099d8b48bfa48148e9d54c74827431dd3fbb46cbaa7cc983d36ab","cmd":null}@
TEST RESPONSE:{"data":"3582e219290099d8b48bfa48148e9d54c74827431dd3fbb46cbaa7cc983d36ab","cmd":null}
==========================================================
LTEM - CONNECT - to: https://WWW.XXXYYY.ZZZ/auth
LTEM - DISCONNECT
ESP32->AT#XHTTPCCON?
NRF91->#XHTTPCCON: 1,"WWW.XXXYYY.ZZZ",80
NRF91->OK
----------------------------------
ESP32->AT#XHTTPCCON=0
NRF91->#XHTTPCCON:0
NRF91->OK
----------------------------------
ESP32->AT#XHTTPCCON=1,"WWW.XXXYYY.ZZZ",80
NRF91->
ERROR: not entire line received!
NRF91->
ERROR: not entire line received!
AT COMMAND FAILED: AT#XHTTPCCON=1,"WWW.XXXYYY.ZZZ",80
----------------------------------

Thanks.

[Michal Vacha]

So far my only workaround is to have a watchdog timer reboot the NRF chip when it gets stuck...