secure http issue, works first time, data corruption after first time...

[Anthony Ambuehl]

I"m using SLM from NCS 1.6.1.  

I'm testing HTTPCREQ with HTTPC port 443 and security tag = 1.   After I reset SLM, my send is successful and passes server validation checks.  If I repeat the procedure sending the exact same data, the server is detecting a validation failure indicating something in the data has changed.  The only way to get a successful server validation is by reseting SLM.  I suspect there is some state that is not complete reset by XHTTPCCON=0 in the TLS implementation.   When I test the same with non-secure HTTP (port 80) to postman-echo my payloads are identical.  

Is there any equivalent to postman-echo with an https variant? 

Any idea why it breaks after the first successful attempt?

[Charlie]

Hi Anthony, 

I have forward your logs to our expert for further analysis. 

I just wonder did you experience any difference if you test with LinkMonitor or any other computer based serial terminal as at host?

Best regards,

Charlie

[Anthony Ambuehl]

Hi Charlie,   

  No I haven't tried that.  I need this to work in the intended design which requires interfacing to an nrf52840 via UART.  

a*

[Charlie]

Hi Anthony,

Feedback from our expert:

In the fail case(ncs_sdk_170_4.log), after first UART chunk(256 bytes), there is only one byte(0x37) received from UART

00> [00:01:14.501,647] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:01:14.502,136] <inf> slm_at_host: Raw send 256
00> [00:01:14.502,471] <dbg> slm_at_host.RX-DATAMODE
00> 2d 2d 2d 2d 2d 2d 63 41 4c 61 42 30 75 4e 64 34 |------cA LaB0uNd4
00> [00:01:14.504,150] <dbg> slm_at_host.uart_callback: RX_RDY 1
00> [00:01:14.504,730] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:01:14.505,218] <inf> slm_httpc: datamode send: 0
00> [00:01:14.505,584] <dbg> slm_at_host.TX
00> 0d 0a 4f 4b 0d 0a |..OK..
00> [00:01:14.506,530] <inf> slm_at_host: Raw send 1
00> [00:01:14.506,896] <dbg> slm_at_host.RX-DATAMODE
00> 37 |7
00> [00:01:14.508,514] <dbg> slm_httpc.do_send_payload: send 1 bytes payload
00> [00:01:14.508,941] <inf> slm_httpc: datamode send: 0
00> [00:01:14.509,338] <dbg> slm_at_host.TX
00> 0d 0a 4f 4b 0d 0a |..OK..
00> [00:01:24.475,463] <dbg> net_http.http_wait_data: Connection error (116)
00> [00:01:24.475,891] <dbg> net_http.http_client_req: (0x200151a8): Wait data failure (-116)

In normal case the second chunk received from UART should be another 256 bytes, and the first 16 bytes of second chunk are (37 34 35 36 36 34 33 31 44 37 30 44 33 31 41 43), so it is not few bytes missing. The whold data after 256+1 bytes are not received from SLM. Please ask customer to confirm the external MCU send full UART chunk by logic analyzer.

Could you verify your external MCU? I also suggest you test with LinkMonitor as host for comparation.

Best regards,

Charlie

[Anthony Ambuehl]

Hi Charlie,

The expert has missed the fact that the slm_at_host has exited datamode and sent the #XHTTPCREQ: 0 indicating all data was received before the log line he highlighted.

00> [00:01:14.470,611] <inf> slm_at_host: Enter datamode
00> [00:01:14.470,977] <dbg> slm_at_host.TX
00> 0d 0a 23 58 48 54 54 50 43 52 45 51 3a 20 31 0d |..#XHTTP CREQ: 1.
00> 0a |.
00> [00:01:14.472,686] <dbg> slm_httpc.payload_cb: wait until payload is ready
00> [00:01:14.473,114] <dbg> slm_at_host.TX
00> 0d 0a 23 58 48 54 54 50 43 52 45 51 3a 20 30 0d |..#XHTTP CREQ: 0.
00> 0a |.
00> [00:01:14.474,914] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:01:14.501,647] <dbg> slm_at_host.uart_callback: RX_RDY 256

Looking at this code in slm_at_host:

	if (httpc.pl_len > 0) {
		enter_datamode(httpc_datamode_callback);
		sprintf(rsp_buf, "\r\n#XHTTPCREQ: 1\r\n");
		rsp_send(rsp_buf, strlen(rsp_buf));
		/* Wait until all payload is sent */
		LOG_DBG("wait until payload is ready");
		k_sem_take(&http_req_sem, K_FOREVER);
	}
	httpc.state = HTTPC_REQ_DONE;
	sprintf(rsp_buf, "\r\n#XHTTPCREQ: 0\r\n");
	rsp_send(rsp_buf, strlen(rsp_buf));

I would guess that k_sem_take(http_req_sem, K_FOREVER) is not blocking on the second call..

Upon receiving the "#XHTTPCREQ: 0" my mcu stops sending data since that indicates datamode operation has completed.

I'm just perusing the code but it seems during non-error processing, the http_req sem is given in 2 different places 

1) do_send_payload when the sent data is the same as the requested length

2) in httpc_datamode_callback when the event with op type DATAMODE_EXIT is received.

I suspect the first case in do_send_payload is incorrect and a remnant of the older at datamode handling.

Giving the semaphore from 2 places but only taking it from 1 will result in the semaphore be already available at the start of the second httpc datamode operation.

 

[Anthony Ambuehl]

It appears the second case, in my comment above is only sent by silence_timer_handler so it may not have been sent.  Nonetheless, its clear that XHTTPCREQ:0 occurs before all data is sent, which is an error in the SLM and explains why my external mcu stopped sending data.

I will try to set up to capture with logic analyzer and also add some logs around the silence handler.  However, it would be helpful if Nordic could test this code instead of putting the burden on their customers.