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...

[Håkon Alseth]

Hi,

 

Anthony Ambuehl said:

Is it expected for the OK message to be resent every 27 milliseconds when in datamode?. Is this some sort of progress indication?

This should be printed as a response to a generic AT command. Do you send a specific AT command every 27ms?

Were you able to get the log running? SPM logging is disabled by default, so there should not be any RTT block location issues.

  

Anthony Ambuehl said:

It seems after starting an HTTPCREQ, the OK message should be ignored until the HTTPCRSP is received.  I suspect there is also some case where HTTPCREQ return values other than 0 and 1, which is not documented. 

It should not do this, it should split the packet as per this logic:

https://github.com/nrfconnect/sdk-nrf/blob/v1.6.1/applications/serial_lte_modem/src/http_c/slm_at_httpc.c#L358-L372

each fragment size is set to this define (default 576 bytes):

https://github.com/nrfconnect/sdk-nrf/blob/v1.6.1/applications/serial_lte_modem/src/http_c/slm_at_httpc.c#L26

Even if the actual size is larger, it will fragment the packet for you.

 

Kind regards,

Håkon

[Anthony Ambuehl]

The OK's are coming after receiving +XHTTPCREQ=1    and before receiving +XHTTPCREQ=0, therefore the SLM is in datamode.  I am not sending AT commands, and they should not be received while in datamode anyway.  

After reviewing the code, it seems in datamode that every time data is sent to the network port by httpc, a "\r\nOK\r\n" is produced.  There are 2 triggers for sending data  according to the "Running in data mode" documentation (https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/applications/serial_lte_modem/doc/slm_data_mode.html?highlight=datamode)  one of those triggers is  a "time limit trigger" which explains the periodic "OK" when data is pending.     This is fired from the inactivity_timer_handler in slm_at_handler.

It would be really helpful if the documentation mentioned that an OK would be received on the UART whenever data is sent on the network port.  This behavior appears to be specific to httpc... its in httpc_datamode_callback.    I reviewed other instances of datamode, and none of them include this behavior.  

BTW, in slm_at_httpc.c there is code that returns values other than 0/1.. lines 510..512 which reports error from the socket send/recv.  It would be a good idea to update the documentation, an external implementer like me would need to know that this could occur.  In my current code this would be treated as an unexpected response, and an error reported.  In production, those errors would cause a massive cascade of paperwork explaining why an error occurred, what the root cause was, what corrective actions were taken, etc (e.g. several days with tons of meetings with the quality team).  On the other hand, if I expect these values could occur during normal operation, I can prevent that in the design phase with a few simple comments and an extra conditional clause in the code.

Finally, I'm still unable to get debug logs after the bootloader jumps to the application.   Any help at all with the debug logs would be really really appreciated.  For unmodified 1.6.1, changing the line in prj.conf did not have any effect. 

Maybe you could post a prj.conf that you've confirmed works? 

Also any special steps I need to take after modifying prj.conf?

[Anthony Ambuehl]

BTW, I found that debugging is working when I monitor with J-Link RTT viewer.  For some reason, it does not work from SES.

[Håkon Alseth]

Hi,

 

Anthony Ambuehl said:

BTW, in slm_at_httpc.c there is code that returns values other than 0/1.. lines 510..512 which reports error from the socket send/recv.  It would be a good idea to update the documentation, an external implementer like me would need to know that this could occur.  In my current code this would be treated as an unexpected response, and an error reported.  In production, those errors would cause a massive cascade of paperwork explaining why an error occurred, what the root cause was, what corrective actions were taken, etc (e.g. several days with tons of meetings with the quality team).  On the other hand, if I expect these values could occur during normal operation, I can prevent that in the design phase with a few simple comments and an extra conditional clause in the code.

 The socket calls will return the errno, which can be many different types of return, based on what the failure is. Please see errno.h (https://github.com/nrfconnect/sdk-zephyr/blob/master/lib/libc/minimal/include/errno.h) for more information.

 

 

Anthony Ambuehl said:

BTW, I found that debugging is working when I monitor with J-Link RTT viewer.  For some reason, it does not work from SES.

Could you share the debug log when the issue occurs?

 

Kind regards,

Håkon 

[Anthony Ambuehl]

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.