"Server did not honor partial content request"

[Jared]

Hey DZ,

I'm having some trouble with the download_client. It's not playing nice with the HTTP server I'm using. On the last chunk of data, the nRF91 is issuing a Content-Range that doesn't always play nice with all server implementations. The server I'm using is returning a 416 error. 

Here's the progress from the embedded side:

2021-03-09T02:02:42.279Z DEBUG modem << [00:01:00.078,948] [0m<inf> download_client: Downloaded 194560/200595 bytes (96%)[0m
2021-03-09T02:02:42.760Z DEBUG modem << [00:01:00.558,929] [0m<inf> download_client: Downloaded 196608/200595 bytes (98%)[0m
2021-03-09T02:02:43.135Z DEBUG modem << [00:01:00.934,387] [0m<inf> download_client: Downloaded 198656/200595 bytes (99%)[0m
2021-03-09T02:02:43.529Z DEBUG modem << [00:01:01.325,347] [1;31m<err> download_client: Server did not honor partial content request[0m
2021-03-09T02:02:43.558Z DEBUG modem << [00:01:01.335,388] [1;31m<err> fota_download: Download client error[0m
2021-03-09T02:02:43.559Z DEBUG modem << [00:01:01.341,766] [0m<inf> dfu_target_mcuboot: MCUBoot image upgrade aborted.[0m

Here's the log from the HTTP server.

{"level":"info","ts":1615255361.8753276,"logger":"http.log.access","msg":"handled request","request":{"remote_addr":"52.12.23.139:64562","proto":"HTTP/1.1","method":"GET","host":"pyrinas-dev-ota.jaredwolff.com","uri":"/images/352656102712240.bin","headers":{"Range":["bytes=196608-198655"],"Connection":["keep-alive"]},"tls":{"resumed":false,"version":771,"cipher_suite":49162,"proto":"","proto_mutual":true,"server_name":"pyrinas-dev-ota.jaredwolff.com"}},"common_log":"52.12.23.139 - - [09/Mar/2021:02:02:41 +0000] \"GET /images/352656102712240.bin HTTP/1.1\" 206 2048","duration":0.00488638,"size":2048,"status":206,"resp_headers":{"Accept-Ranges":["bytes"],"Last-Modified":["Tue, 09 Mar 2021 01:50:16 GMT"],"Server":["Caddy"],"Date":["Tue, 09 Mar 2021 02:02:40 GMT"],"Content-Range":["bytes 196608-198655/200595"],"Content-Length":["2048"],"Content-Type":["application/octet-stream"]}}
{"level":"error","ts":1615255362.3557446,"logger":"http.log.access","msg":"handled request","request":{"remote_addr":"52.12.23.139:64562","proto":"HTTP/1.1","method":"GET","host":"pyrinas-dev-ota.jaredwolff.com","uri":"/images/352656102712240.bin","headers":{"Range":["bytes=198656-200595"],"Connection":["keep-alive"]},"tls":{"resumed":false,"version":771,"cipher_suite":49162,"proto":"","proto_mutual":true,"server_name":"pyrinas-dev-ota.jaredwolff.com"}},"common_log":"52.12.23.139 - - [09/Mar/2021:02:02:42 +0000] \"GET /images/352656102712240.bin HTTP/1.1\" 416 0","duration":0.00314682,"size":0,"status":416,"resp_headers":{"Content-Length":["0"],"Date":["Tue, 09 Mar 2021 02:02:42 GMT"],"Server":["Caddy"],"Content-Range":["bytes */200595"]}}

Are there any workarounds for this? I'm downloading a FOTA update so there's a need for the payload size to be fixed. (Currently set to 2048)

Thank you!

Jared

[Håkon Alseth]

Hi,

 

Does your server support partial content requests? Do you know which httpd and version is running? 

Are you able to do a tcpdump on the server side, or provide a modem trace of the FOTA transaction?

 

Here's a .pcap of the http_update/application_update which I took just to see how the nRF sends its http requests:

trace-2021-03-09T12-49-16.pcap

 

Kind regards,

Håkon

[Jared]

So after playing with the issue more, it appears that the HTTP client, when requesting the range, is requesting a range that is not indexed from 0. 

I wrote up a full bug report on the server only to review their tests and other HTTP implementation notes to understand this better.

If this is true I should be able to modify the requested size for the last chunk in the FOTA library. Will check to be sure.

[Håkon Alseth]

Hi Jared,

 

Jared said:

So after playing with the issue more, it appears that the HTTP client, when requesting the range, is requesting a range that is not indexed from 0. 

I wrote up a full bug report on the server only to review their tests and other HTTP implementation notes to understand this better.

If this is true I should be able to modify the requested size for the last chunk in the FOTA library. Will check to be sure.

Great job! This is impressive debugging work. Let me know if you think it might be related to how we do partial requests.

 

Kind regards,

Håkon

[Jared]

Honestly, I think the MFW is doing exactly what it should be. I've tried the same type of request on other HTTP servers and all worked ok. Seems like the implementation in warp doesn't cover the edge case if the end byte count == file size it shouldn't bork.

I haven't heard back from the main dev, not sure if I will, I may just roll with a patched version of warp for now. Thanks for your help!

[Jared]

This has been patched in warp. I think is a corner case in the HTTP specification that is not very well defined. It's been working great over the past two months since it was implemented! Here's the PR: github.com/.../818