• State Suggested Answer
  • Replies 13 replies
  • Answers 1 answer
  • Subscribers 63 subscribers
  • Views 2348 views
  • Users 0 members are here
Attachments (1) Download All
Nordic Case Info
  • Case ID: 259571
Options
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

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.

Parents Reply Children
  • 0 in reply to Carl Richard

    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.

  • 0 in reply to Carl Richard

    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.

  • 0 in reply to Carl Richard

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

  • 0 in reply to Michal Vacha

    Thanks for the trace and the logs. From what I can see the modem crashes at some point, but I have forwarded the trace to the modem team so they can have a look. In the meantime, could you enable debug messages for the RTT log? Change/add the following to prj.conf:

    CONFIG_AT_CMD_LOG_LEVEL_DBG=y
CONFIG_SLM_LOG_LEVEL_DBG=y


    This could give some more insight to what's happening.

    The watchdog solution is not ideal, but I'm glad that it works. 

    Best regards,
    Carl Richard

  • 0 in reply to Carl Richard

    I was unable to enable debug as the app then started crashing on stack overflow exception. So I've just replaced DBG logs to INF. 


    This is the end of the log collected over RTT:

    00> 23 58 48 54 54 50 43 43  4f 4e 3a 30 0d 0a       |#XHTTPCC ON:0..  
00> [00:06:11.588,409] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:11.594,573] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 43 4f 4e 3d 31 2c 22 |AT#XHTTP CCON=1,"
00> 69 6e 67 72 65 73 73 2e  64 65 76 2e 74 65 6d 70 |ingress. dev.temp
00> 65 67 67 2e 63 6f 6d 22  2c 38 30                |egg.com" ,80     
00> [00:06:11.594,940] <inf> httpc: Connect from http server
00> [00:06:11.595,062] <inf> at_host: RX_DISABLED
00> [00:06:12.105,895] <err> httpc: Failed to resolve hostname ingress.dev.tempegg.com on IPv6
00> [00:06:12.121,826] <inf> httpc: Attempting to connect over IPv4
00> [00:06:12.312,316] <inf> httpc: Connected to ingress.dev.tempegg.com
00> [00:06:12.312,316] <inf> httpc: Configuring socket timeout (10 s)
00> [00:06:12.312,377] <inf> at_host: TX
00> 23 58 48 54 54 50 43 43  4f 4e 3a 31 0d 0a       |#XHTTPCC ON:1..  
00> [00:06:12.329,528] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:12.337,188] <inf> at_host: RX_DISABLED
00> [00:06:12.339,050] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 52 45 51 3d 22 50 4f |AT#XHTTP CREQ="PO
00> 53 54 22 2c 22 2f 61 75  74 68 22 2c 22 43 6f 6e |ST","/au th","Con
00> 74 65 6e 74 2d 4c 65 6e  67 74 68 3a 20 35 31 0d |tent-Len gth: 51.
00> 0a 22 2c 35 31                                   |.",51            
00> [00:06:12.339,508] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:12.340,301] <inf> httpc: send header: 20 bytes
00> [00:06:12.358,306] <inf> at_host: TX
00> 23 58 48 54 54 50 43 52  45 51 3a 31 0d 0a       |#XHTTPCR EQ:1..  
00> [00:06:12.358,306] <inf> httpc: wait until payload is ready
00> [00:06:12.365,814] <inf> at_host: RX
00> 7b 22 64 61 74 61 22 3a  22 30 30 31 31 32 32 33 |{"data": "0011223
00> 33 34 34 35 35 36 36 37  37 38 38 39 39 41 41 42 |34455667 78899AAB
00> 42 43 43 44 44 45 45 46  46 30 30 30 30 30 30 30 |BCCDDEEF F0000000
00> 31 22 7d                                         |1"}              
00> [00:06:12.366,302] <inf> at_host: RX_DISABLED
00> [00:06:12.366,973] <inf> httpc: send 51 bytes payload
00> [00:06:12.367,004] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:12.367,431] <inf> at_host: TX
00> 23 58 48 54 54 50 43 52  45 51 3a 30 0d 0a       |#XHTTPCR EQ:0..  
00> [00:06:13.033,752] <inf> httpc: Partial data received (277 bytes)
00> [00:06:13.033,782] <inf> httpc: All the data received (277 bytes)
00> [00:06:13.033,843] <inf> at_host: TX
00> 23 58 48 54 54 50 43 52  53 50 3a 32 37 37 2c 30 |#XHTTPCR SP:277,0
00> 0d 0a                                            |..               
00> [00:06:13.042,541] <inf> at_host: TX
00> 48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d |HTTP/1.1  200 OK.
00> 0a 43 6f 6e 74 65 6e 74  2d 4c 65 6e 67 74 68 3a |.Content -Length:
00> 20 38 36 0d 0a 43 6f 6e  74 65 6e 74 2d 54 79 70 | 86..Con tent-Typ
00> 65 3a 20 61 70 70 6c 69  63 61 74 69 6f 6e 2f 6a |e: appli cation/j
00> 73 6f 6e 3b 20 63 68 61  72 73 65 74 3d 75 74 66 |son; cha rset=utf
00> 2d 38 0d 0a 52 65 71 75  65 73 74 2d 43 6f 6e 74 |-8..Requ est-Cont
00> 65 78 74 3a 20 61 70 70  49 64 3d 63 69 64 2d 76 |ext: app Id=cid-v
00> 31 3a 66 32 66 61 65 37  35 66 2d 63 35 31 65 2d |1:f2fae7 5f-c51e-
00> 34 38 37 63 2d 61 37 34  30 2d 32 39 63 33 31 36 |487c-a74 0-29c316
00> 37 37 38 38 31 65 0d 0a  44 61 74 65 3a 20 54 68 |77881e.. Date: Th
00> 75 2c 20 31 32 20 4e 6f  76 20 32 30 32 30 20 32 |u, 12 No v 2020 2
00> 32 3a 31 34 3a 34 30 20  47 4d 54 0d 0a 0d 0a 7b |2:14:40  GMT....{
00> 22 64 61 74 61 22 3a 22  33 35 38 32 65 32 31 39 |"data":" 3582e219
00> 32 39 30 30 39 39 64 38  62 34 38 62 66 61 34 38 |290099d8 b48bfa48
00> 31 34 38 65 39 64 35 34  32 33 34 64 65 63 37 31 |148e9d54 234dec71
00> 65 37 62 34 30 34 62 38  32 38 64 66 33 66 66 36 |e7b404b8 28df3ff6
00> 32 62 34 35 37 65 63 32  22 2c 22 63 6d 64 22 3a |2b457ec2 ","cmd":
00> 6e 75 6c 6c 7d                                   |null}            
00> [00:06:13.075,561] <inf> at_host: RX_DISABLED
00> [00:06:13.081,695] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 43 4f 4e 3f          |AT#XHTTP CCON?   
00> [00:06:13.082,031] <inf> at_host: TX
00> 23 58 48 54 54 50 43 43  4f 4e 3a 20 31 2c 22 69 |#XHTTPCC ON: 1,"i
00> 6e 67 72 65 73 73 2e 64  65 76 2e 74 65 6d 70 65 |ngress.d ev.tempe
00> 67 67 2e 63 6f 6d 22 2c  38 30 0d 0a             |gg.com", 80..    
00> [00:06:13.085,998] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:13.090,118] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 43 4f 4e 3d 30       |AT#XHTTP CCON=0  
00> [00:06:13.090,362] <inf> httpc: Disconnect from http server
00> [00:06:13.090,362] <inf> httpc: Closing socket 1
00> [00:06:13.090,637] <inf> at_host: RX_DISABLED
00> [00:06:13.090,728] <inf> at_host: TX
00> 23 58 48 54 54 50 43 43  4f 4e 3a 30 0d 0a       |#XHTTPCC ON:0..  
00> [00:06:13.100,677] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:13.106,842] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 43 4f 4e 3d 31 2c 22 |AT#XHTTP CCON=1,"
00> 69 6e 67 72 65 73 73 2e  64 65 76 2e 74 65 6d 70 |ingress. dev.temp
00> 65 67 67 2e 63 6f 6d 22  2c 38 30                |egg.com" ,80     
00> [00:06:13.107,208] <inf> httpc: Connect from http server
00> [00:06:13.107,330] <inf> at_host: RX_DISABLED
00> [00:06:14.072,418] <err> httpc: Failed to resolve hostname ingress.dev.tempegg.com on IPv6
00> [00:06:14.325,744] <inf> httpc: Attempting to connect over IPv4
00> [00:06:14.427,337] <inf> httpc: Connected to ingress.dev.tempegg.com
00> [00:06:14.427,368] <inf> httpc: Configuring socket timeout (10 s)
00> [00:06:14.427,398] <inf> at_host: TX
00> 23 58 48 54 54 50 43 43  4f 4e 3a 31 0d 0a       |#XHTTPCC ON:1..  
00> [00:06:14.444,915] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:14.452,117] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 52 45 51 3d 22 50 4f |AT#XHTTP CREQ="PO
00> 53 54 22 2c 22 2f 61 75  74 68 22 2c 22 43 6f 6e |ST","/au th","Con
00> 74 65 6e 74 2d 4c 65 6e  67 74 68 3a 20 35 31 0d |tent-Len gth: 51.
00> 0a 22 2c 35 31                                   |.",51            
00> [00:06:14.452,575] <inf> at_host: RX_DISABLED
00> [00:06:14.452,606] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:14.453,399] <inf> httpc: send header: 20 bytes
00> [00:06:14.472,717] <inf> at_host: TX
00> 23 58 48 54 54 50 43 52  45 51 3a 31 0d 0a       |#XHTTPCR EQ:1..  
00> [00:06:14.472,747] <inf> httpc: wait until payload is ready
00> [00:06:14.479,919] <inf> at_host: RX
00> 7b 22 64 61 74 61 22 3a  22 30 30 31 31 32 32 33 |{"data": "0011223
00> 33 34 34 35 35 36 36 37  37 38 38 39 39 41 41 42 |34455667 78899AAB
00> 42 43 43 44 44 45 45 46  46 30 30 30 30 30 30 30 |BCCDDEEF F0000000
00> 31 22 7d                                         |1"}              
00> [00:06:14.480,407] <inf> at_host: RX_DISABLED
00> [00:06:14.481,475] <inf> httpc: send 51 bytes payload
00> [00:06:14.481,506] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:14.481,933] <inf> at_host: TX
00> 23 58 48 54 54 50 43 52  45 51 3a 30 0d 0a       |#XHTTPCR EQ:0..  
00> [00:06:24.451,202] <inf> at_host: RX_DISABLED
00> [00:06:25.460,388] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 43 4f 4e 3f          |AT#XHTTP CCON?   
00> [00:06:25.460,754] <inf> at_host: TX
00> 23 58 48 54 54 50 43 43  4f 4e 3a 20 31 2c 22 69 |#XHTTPCC ON: 1,"i
00> 6e 67 72 65 73 73 2e 64  65 76 2e 74 65 6d 70 65 |ngress.d ev.tempe
00> 67 67 2e 63 6f 6d 22 2c  38 30 0d 0a             |gg.com", 80..    
00> [00:06:25.464,691] <inf> at_host: TX
00> 4f 4b 0d 0a                                      |OK..             
00> [00:06:25.468,811] <inf> at_host: RX
00> 41 54 23 58 48 54 54 50  43 43 4f 4e 3d 30       |AT#XHTTP CCON=0  
00> [00:06:25.469,055] <inf> httpc: Disconnect from http server
00> [00:06:25.469,055] <inf> httpc: Closing socket 1
00> [00:06:25.469,329] <inf> at_host: RX_DISABLED

    After that it reboots. Unfortunately I've found that the watchdog does not always work. When the ESP reboots, it sends garbage over the UART, nRF gets stuck, but never reboots.

Related