• State Not Answered
  • Replies 14 replies
  • Subscribers 64 subscribers
  • Views 1891 views
  • Users 0 members are here
Attachments (1) Download All
Nordic Case Info
  • Case ID: 276684
Options
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

SLM HTTP client hangs with large payload

Anthony Ambuehl

I recently switched  from 1.5.1 to 1.6.1 and I'm now finding the SLM is misbehaving.

When I try to send a large payload such as 933 bytes of data, I find the CTS signal goes low after 274 bytes of data were sent.  (There is some buffering in my mcu so probably less received at SLM uart) 

It seems like the SLM data mode uses a ring buffer that is only 256 lines and the datamode cannot handle payloads longer than this.  

Please confirm large payloads work in 1.6.1.  

Also any advice on how to get debug logging from SLM_AT_HOST and SLM_AT_HTTPC ?  I'm running from SES with stock SLM example...

Parents
  • 0

    I'm attaching some debugging logs from SLM

    Fullscreen ncs_1.6.1_slm_at_httpc.log Download 
    # SEGGER J-Link RTT Viewer V6.94b Terminal Log File
# Compiled: 18:05:14 on Jan 26 2021
# Logging started @ 21 Sep 2021 09:44:19
00> [00:04:11.916,931] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:04:11.923,217] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:04:12.025,634] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CEREG: 0
00> 
00> [00:04:12.025,909] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:04:12.025,939] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:04:13.433,166] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:04:13.433,166] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:04:13.433,288] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:04:13.433,319] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.653,778] <dbg> at_cmd.at_write: Sending command AT
00> [00:05:46.660,125] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:05:46.660,186] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:05:46.660,217] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.660,308] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.660,339] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.669,616] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:05:46.675,903] <dbg> at_cmd.at_cmd_write: Awaiting response for <log_strdup alloc failed>
00> [00:05:46.676,086] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, <log_strdup alloc failed>
00> [00:05:46.676,086] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.676,177] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.676,177] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.685,363] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:05:46.691,680] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:05:46.691,833] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:05:46.691,833] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.691,955] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.691,986] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.695,159] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:05:46.701,446] <dbg> at_cmd.at_cmd_write: Awaiting response for <log_strdup alloc failed>
00> [00:05:46.701,629] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, <log_strdup alloc failed>
00> [00:05:46.701,660] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.701,751] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.701,751] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.710,418] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:05:46.716,705] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:05:46.716,857] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:05:46.716,888] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.716,949] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.716,979] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.727,569] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:05:46.733,825] <dbg> at_cmd.at_cmd_write: Awaiting response for <log_strdup alloc failed>
00> [00:05:46.733,978] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, <log_strdup alloc failed>
00> [00:05:46.734,008] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.734,100] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.734,100] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:46.742,492] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:05:46.748,809] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:05:46.778,564] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:05:46.778,564] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:05:46.778,686] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:46.778,686] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:48.103,546] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:05:48.103,851] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:48.103,881] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:05:48.736,541] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","1~
00> [00:05:48.736,846] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:05:48.736,846] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:00.797,393] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:06:00.803,680] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:06:00.890,350] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CEREG: 0
00> 
00> [00:06:00.890,625] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:00.890,655] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:02.289,978] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:06:02.290,008] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:06:02.290,130] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:02.290,130] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:17.573,730] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:06:17.580,047] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:06:17.580,200] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:06:17.580,200] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:06:17.580,322] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:17.580,352] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:17.583,526] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:06:17.589,782] <dbg> at_cmd.at_cmd_write: Awaiting response for <log_strdup alloc failed>
00> [00:06:17.589,996] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, <log_strdup alloc failed>
00> [00:06:17.589,996] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:06:17.590,087] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:17.590,087] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:17.598,754] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:06:17.605,041] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:06:17.605,194] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:06:17.605,224] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:06:17.605,285] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:17.605,316] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:17.612,884] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:06:17.619,140] <dbg> at_cmd.at_cmd_write: Awaiting response for <log_strdup alloc failed>
00> [00:06:17.619,293] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, <log_strdup alloc failed>
00> [00:06:17.619,323] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:06:17.619,415] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:17.619,415] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:17.624,786] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:06:17.631,103] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:06:17.660,827] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:06:17.660,858] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:06:17.660,949] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:17.660,980] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:18.984,924] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:06:18.985,260] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:18.985,260] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:19.697,937] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","1~
00> [00:06:19.698,272] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:06:19.698,303] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:06:19.829,498] <err> httpc: Failed to resolve hostname api.cloud.calahealth.com on IPv6
00> [00:06:19.919,647] <inf> httpc: Attempting to connect over IPv4
00> [00:06:19.920,196] <inf> httpc: Setting up TLS credentials
00> [00:06:21.961,181] <inf> httpc: Connected to api.cloud.calahealth.com
00> [00:06:21.992,095] <inf> at_host: Enter datamode
00> [00:06:22.023,590] <inf> at_host: Raw send 256
00> [00:06:22.053,985] <inf> at_host: Raw send 256
00> [00:06:22.070,922] <inf> at_host: Raw send 138
00> [00:06:22.070,953] <wrn> httpc: send unexpected payload 2
00> [00:06:22.724,884] <inf> at_host: Exit datamode
00> [00:06:26.149,871] <err> httpc: Failed to resolve hostname api.cloud.calahealth.com on IPv6
00> [00:06:26.150,329] <inf> httpc: Attempting to connect over IPv4
00> [00:06:26.150,634] <inf> httpc: Setting up TLS credentials
00> [00:06:28.118,347] <inf> httpc: Connected to api.cloud.calahealth.com
00> [00:06:28.149,597] <inf> at_host: Enter datamode
00> [00:06:28.181,060] <inf> at_host: Raw send 256
00> [00:06:28.211,425] <inf> at_host: Raw send 256
00> [00:06:28.228,393] <inf> at_host: Raw send 138
00> [00:06:28.228,424] <wrn> httpc: send unexpected payload 2
00> [00:06:28.865,173] <inf> at_host: Exit datamode

# Logging stopped @ 21 Sep 2021  9:45:16

    My code was (intentionally) sending some extra bytes after the paylaod in this example, thus producing some additional warnings about unexpected payload.

  • 0 in reply to Anthony Ambuehl

    I'm also seeing this sequence which appears to be caused by a small change in timing from my system due to a new CRITICAL_SECTION i added. 

    00> [00:00:57.125,701] <inf> httpc: Setting up TLS credentials
    00> [00:00:59.010,589] <inf> httpc: Connected to api.cloud.calahealth.com
    00> [00:00:59.039,855] <inf> at_host: Enter datamode
    00> [00:00:59.043,090] <inf> at_host: Raw send 1
    00> [00:00:59.069,580] <inf> at_host: Raw send 255
    00> [00:00:59.095,764] <inf> at_host: Raw send 256
    00> [00:00:59.109,893] <inf> at_host: Raw send 136
    00> [00:00:59.738,159] <inf> at_host: Exit datamode

    The first "Raw send" with only 1 byte seems to really screw things up.. I always get an empty response XHTTPCRSP:0,1

    If I change slm_at_host.c line 36 

    #define UART_RX_TIMEOUT_MS      1

    to be a larger number such as 5, the 1 byte raw_send goes away.

Reply
  • 0 in reply to Anthony Ambuehl

    I'm also seeing this sequence which appears to be caused by a small change in timing from my system due to a new CRITICAL_SECTION i added. 

    00> [00:00:57.125,701] <inf> httpc: Setting up TLS credentials
    00> [00:00:59.010,589] <inf> httpc: Connected to api.cloud.calahealth.com
    00> [00:00:59.039,855] <inf> at_host: Enter datamode
    00> [00:00:59.043,090] <inf> at_host: Raw send 1
    00> [00:00:59.069,580] <inf> at_host: Raw send 255
    00> [00:00:59.095,764] <inf> at_host: Raw send 256
    00> [00:00:59.109,893] <inf> at_host: Raw send 136
    00> [00:00:59.738,159] <inf> at_host: Exit datamode

    The first "Raw send" with only 1 byte seems to really screw things up.. I always get an empty response XHTTPCRSP:0,1

    If I change slm_at_host.c line 36 

    #define UART_RX_TIMEOUT_MS      1

    to be a larger number such as 5, the 1 byte raw_send goes away.

Children
Related