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,

 

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) 

Just to clarify, from which side is it set low?

 

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

If you set the log level to debug (4) here:

https://github.com/nrfconnect/sdk-nrf/blob/v1.6.1/applications/serial_lte_modem/prj.conf#L8

 

Then it should print out debug logs over RTT. Could you try this and attach the log showing the issue?

 

Kind regards,

Håkon

[Anthony Ambuehl]

I worked on it some more this morning and identified an issue in my code, that is caused by an unusual behavior from the SLM.  

While in datamode receiving the payload data, the SLM will periodically send the OK_STR ("OK").  My code was not expecting the OK to be sent until after the data was fully transferred so it proceeded into a state where waiting for the XHTTPCRSP message.  

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

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. 

a*

[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?

[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