This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

"Server did not honor partial content request"

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

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

    I'm using Caddy (caddy-2.2.0 on FreeBSD) as a reverse proxy to the plaintext server. It does support partial content requests. The nRF9160 was able to download up until the last chunk of data. The one that is causing the 416 error is Caddy on the HTTPS side. The proxied server never sees the last request when Content-Range header was set to:

    "Content-Range":["bytes */200595"]

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

    The http requests are handled by the MFW correct?

    I'll get a modem trace to you later today. Thanks for the support!

  • By the way here are the full logs from LTE Link Monitor

    þ~iRnéÙ3Y~_¹ñ©IËý)o¶Yj¿ZOVìOVÝÖnK¯vKÝiÙIj¿)ÏzIj¿_¯OîIJ‰‰iÏYùji‹YùÙi‹YùىÊYÙMYkYùÙikYYËjm³YËiËYùjiOYùÙù‰Yéjù‰Yùjù™ÉêËùNYù‰JNYù‰JYùÙùMYù‰JÏYéjùKI™ÙùJYùÙù]YùÙùJIù‰JJIù‰JËYùjùï¶ùlYëYù‰R{ñyíkIÊ_QbIR|kv|Iý*** Booting Zephyr OS build v2.4.99-ncs1  ***
    2021-03-09T01:54:50.195Z DEBUG modem << [00:00:00.306,427] [0m<inf> main: Provisioning certificate
    2021-03-09T01:54:50.198Z DEBUG modem << [0m
    2021-03-09T01:54:50.308Z DEBUG modem << [00:00:00.416,473] [0m<inf> cellular: LTE Link Connecting ...[0m
    2021-03-09T01:56:53.899Z INFO Modem port is closed
    2021-03-09T01:57:19.178Z INFO Modem port is opened
    2021-03-09T01:57:19.181Z DEBUG modem >> AT+CFUN?
    2021-03-09T01:57:23.288Z DEBUG modem << ~IRnö˞pê_¹ñYIËÝO¶YJ¿ZOviv,KÝÖnZoÅ_ÙIÙÙËýÏùij¿K„`êù–Y©‰‰IYiëZêIIiëZêIIiëZªJYiëZʖY©ÙiKYùŽmï–ÉëZmYIJénJ©‰
    2021-03-09T01:57:23.299Z DEBUG modem << NÉêë_ЉYéJù™IiëZáNIù‰JNIù‰JNIù‰JNIù‰jÏI9JùÛY¹Ù9ÊYùÙù]É©ÙùJY©‰JJY©‰JŠÉêëßÊï§9ëZá‰YéJÑ~ëynYéš4O„`]Ë0oåz¶*** Booting Zephyr OS build v2.4.99-ncs1  ***
    2021-03-09T01:57:23.593Z DEBUG modem << [00:00:00.294,708] [0m<inf> main: Provisioning certificate
    2021-03-09T01:57:23.596Z DEBUG modem << [0m
    2021-03-09T01:57:23.827Z DEBUG modem << [00:00:00.526,092] [0m<inf> cellular: LTE Link Connecting ...[0m
    2021-03-09T01:57:28.209Z DEBUG modem << [00:00:04.910,400] [0m<inf> cellular: LTE Link Connected![0m
    2021-03-09T01:57:28.229Z DEBUG modem << [00:00:04.917,266] [0m<inf> pyrinas_cloud: IMEI: 352656102712240[0m
    2021-03-09T01:57:30.481Z DEBUG modem << [00:00:07.181,457] [0m<inf> main: Connected![0m
    2021-03-09T01:57:30.721Z DEBUG modem << [00:00:07.416,595] [0m<inf> pyrinas_cloud: MQTT client connected![0m
    2021-03-09T01:57:30.743Z DEBUG modem << [00:00:07.422,821] [0m<inf> pyrinas_cloud: RSRP 1 46[0m
    2021-03-09T01:57:30.779Z DEBUG modem << [00:00:07.474,060] [0m<inf> pyrinas_cloud: Publishing 27 bytes to topic: 352656102712240/tel/pub len: 23[0m
    2021-03-09T01:57:30.834Z DEBUG modem << [00:00:07.530,761] [0m<inf> pyrinas_cloud: Subscribing to: 352656102712240/ota/sub len 23[0m
    2021-03-09T01:57:31.312Z DEBUG modem << [00:00:08.008,605] [0m<inf> pyrinas_cloud: [mqtt_evt_handler:655] SUBACK packet id: 25237[0m
    2021-03-09T01:57:31.367Z DEBUG modem << [00:00:08.062,957] [0m<inf> pyrinas_cloud: Publishing 3 bytes to topic: 352656102712240/ota/pub len: 23[0m
    2021-03-09T01:57:32.498Z DEBUG modem << [00:00:09.192,718] [0m<inf> pyrinas_cloud: Found 352656102712240/ota/sub. Data size: 93[0m
    2021-03-09T01:57:32.525Z DEBUG modem << [00:00:09.202,484] [0m<inf> pyrinas_cloud_codec: Version: 0.2.2-6-gdc84afe[0m
    2021-03-09T01:57:32.527Z DEBUG modem << [00:00:09.210,479] [0m<inf> pyrinas_cloud_codec: URL: pyrinas-dev-ota.jaredwolff.com/images/352656102712240.bin[0m
    2021-03-09T01:57:32.528Z DEBUG modem << [00:00:09.220,703] [0m<inf> pyrinas_cloud_codec: Force: 0[0m
    2021-03-09T01:57:32.530Z DEBUG modem << [00:00:09.226,287] [0m<inf> pyrinas_cloud: New version? true [0m
    2021-03-09T01:57:32.533Z DEBUG modem << [00:00:09.232,208] [0m<inf> pyrinas_cloud: Start upgrade[0m
    2021-03-09T01:57:32.538Z DEBUG modem << [00:00:09.237,701] [0m<inf> main: FOTA in progress.[0m
    2021-03-09T01:57:39.159Z DEBUG modem << [00:00:15.855,010] [0m<inf> download_client: Setting up TLS credentials, tag 1235[0m
    2021-03-09T01:57:39.164Z DEBUG modem << [00:00:15.862,670] [0m<inf> download_client: Configuring socket timeout (30 s)[0m
    2021-03-09T01:57:39.193Z DEBUG modem << [00:00:15.870,025] [0m<inf> download_client: Connecting to pyrinas-dev-ota.jaredwolff.com[0m
    2021-03-09T01:57:40.163Z DEBUG modem << [00:00:16.856,964] [1;31m<err> download_client: Unable to connect, errno 45[0m
    2021-03-09T01:57:40.168Z DEBUG modem << [00:00:16.865,203] [1;31m<err> pyrinas_cloud: fota_download_start error -45
    2021-03-09T01:57:40.169Z DEBUG modem << [0m
    2021-03-09T01:57:40.193Z DEBUG modem << [00:00:16.872,375] [0m<inf> main: FOTA in progress.[0m
    2021-03-09T01:57:40.675Z DEBUG modem << ~iRnéÙ3Y~_¹ñ©IËý)o¶Yj¿ZOVìOVÝÖnR¼OZZI¶J_ýiÍùÉj¿k¤Olù¶Yù‰‰iYiËùIIiËùIIiËùJYYMYkYùÙikYÙmïÉYËYËYùjénJ‰‰
    2021-03-09T01:57:40.686Z DEBUG modem << nÉêËù‰Yéjù™IiËùNIù‰JNIù‰JNIù‰JNIù‰JÏIjùÛY™ÙÊYùÙù]YùÙùJYù‰JJYù‰JŠÉêËYïVYMù‰YéjQ~ëYnyéš4O¤zm_]rZ¶*** Booting Zephyr OS build v2.4.99-ncs1  ***
    2021-03-09T01:57:42.234Z DEBUG modem << [00:00:01.548,553] [0m<inf> main: Provisioning certificate
    2021-03-09T01:57:42.236Z DEBUG modem << [0m
    2021-03-09T01:57:42.303Z DEBUG modem << [00:00:01.614,990] [0m<inf> cellular: LTE Link Connecting ...[0m
    2021-03-09T01:58:45.349Z DEBUG modem << ABcDAAANAAFkAb9icmMAY29mZhks+P+ehA==
    2021-03-09T02:01:13.641Z INFO Modem port is opened
    2021-03-09T02:01:13.652Z DEBUG modem >> AT+CFUN?
    2021-03-09T02:01:21.361Z INFO Modem port is closed
    2021-03-09T02:01:44.616Z INFO Modem port is opened
    2021-03-09T02:01:44.619Z DEBUG modem >> AT+CFUN?
    2021-03-09T02:01:46.993Z DEBUG modem << [00:00:04.794,677] [0m<inf> cellular: LTE Link Connected![0m
    2021-03-09T02:01:47.019Z DEBUG modem << [00:00:04.801,513] [0m<inf> pyrinas_cloud: IMEI: 352656102712240[0m
    2021-03-09T02:01:49.220Z DEBUG modem << [00:00:07.022,033] [0m<inf> main: Connected![0m
    2021-03-09T02:01:49.537Z DEBUG modem << [00:00:07.334,899] [0m<inf> pyrinas_cloud: MQTT client connected![0m
    2021-03-09T02:01:49.559Z DEBUG modem << [00:00:07.341,125] [0m<inf> pyrinas_cloud: RSRP 1 50[0m
    2021-03-09T02:01:49.595Z DEBUG modem << [00:00:07.392,395] [0m<inf> pyrinas_cloud: Publishing 27 bytes to topic: 352656102712240/tel/pub len: 23[0m
    2021-03-09T02:01:49.651Z DEBUG modem << [00:00:07.448,913] [0m<inf> pyrinas_cloud: Subscribing to: 352656102712240/ota/sub len 23[0m
    2021-03-09T02:01:50.081Z DEBUG modem << [00:00:07.879,180] [0m<inf> pyrinas_cloud: [mqtt_evt_handler:655] SUBACK packet id: 6378[0m
    2021-03-09T02:01:50.136Z DEBUG modem << [00:00:07.933,441] [0m<inf> pyrinas_cloud: Publishing 3 bytes to topic: 352656102712240/ota/pub len: 23[0m
    2021-03-09T02:01:51.291Z DEBUG modem << [00:00:09.086,334] [0m<inf> pyrinas_cloud: Found 352656102712240/ota/sub. Data size: 93[0m
    2021-03-09T02:01:51.314Z DEBUG modem << [00:00:09.096,130] [0m<inf> pyrinas_cloud_codec: Version: 0.2.2-6-gdc84afe[0m
    2021-03-09T02:01:51.316Z DEBUG modem << [00:00:09.104,125] [0m<inf> pyrinas_cloud_codec: URL: pyrinas-dev-ota.jaredwolff.com/images/352656102712240.bin[0m
    2021-03-09T02:01:51.341Z DEBUG modem << [00:00:09.114,349] [0m<inf> pyrinas_cloud_codec: Force: 0[0m
    2021-03-09T02:01:51.365Z DEBUG modem << [00:00:09.119,934] [0m<inf> pyrinas_cloud: New version? true [0m
    2021-03-09T02:01:51.367Z DEBUG modem << [00:00:09.125,854] [0m<inf> pyrinas_cloud: Start upgrade[0m
    2021-03-09T02:01:51.368Z DEBUG modem << [00:00:09.131,347] [0m<inf> main: FOTA in progress.[0m
    2021-03-09T02:01:57.540Z DEBUG modem << [00:00:15.337,371] [0m<inf> download_client: Setting up TLS credentials, tag 1235[0m
    2021-03-09T02:01:57.568Z DEBUG modem << [00:00:15.345,062] [0m<inf> download_client: Configuring socket timeout (30 s)[0m
    2021-03-09T02:01:57.570Z DEBUG modem << [00:00:15.352,416] [0m<inf> download_client: Connecting to pyrinas-dev-ota.jaredwolff.com[0m
    2021-03-09T02:01:59.852Z DEBUG modem << [00:00:17.649,444] [0m<inf> download_client: Downloading: images/352656102712240.bin [0][0m
    2021-03-09T02:01:59.879Z DEBUG modem << [00:00:17.657,653] [0m<inf> main: FOTA in progress.[0m
    2021-03-09T02:02:00.355Z DEBUG modem << [00:00:18.153,991] [0m<inf> download_client: Downloaded 2048/200595 bytes (1%)[0m
    2021-03-09T02:02:00.929Z DEBUG modem << [00:00:18.727,844] [0m<inf> download_client: Downloaded 4096/200595 bytes (2%)[0m
    2021-03-09T02:02:01.478Z DEBUG modem << [00:00:19.276,824] [0m<inf> download_client: Downloaded 6144/200595 bytes (3%)[0m
    2021-03-09T02:02:01.977Z DEBUG modem << [00:00:19.775,848] [0m<inf> download_client: Downloaded 8192/200595 bytes (4%)[0m
    2021-03-09T02:02:02.368Z DEBUG modem << [00:00:20.166,839] [0m<inf> download_client: Downloaded 10240/200595 bytes (5%)[0m
    2021-03-09T02:02:02.840Z DEBUG modem << [00:00:20.638,763] [0m<inf> download_client: Downloaded 12288/200595 bytes (6%)[0m
    2021-03-09T02:02:03.243Z DEBUG modem << [00:00:21.041,717] [0m<inf> download_client: Downloaded 14336/200595 bytes (7%)[0m
    2021-03-09T02:02:03.717Z DEBUG modem << [00:00:21.516,265] [0m<inf> download_client: Downloaded 16384/200595 bytes (8%)[0m
    2021-03-09T02:02:04.095Z DEBUG modem << [00:00:21.893,676] [0m<inf> download_client: Downloaded 18432/200595 bytes (9%)[0m
    2021-03-09T02:02:04.574Z DEBUG modem << [00:00:22.372,802] [0m<inf> download_client: Downloaded 20480/200595 bytes (10%)[0m
    2021-03-09T02:02:04.973Z DEBUG modem << [00:00:22.771,820] [0m<inf> download_client: Downloaded 22528/200595 bytes (11%)[0m
    2021-03-09T02:02:05.455Z DEBUG modem << [00:00:23.253,753] [0m<inf> download_client: Downloaded 24576/200595 bytes (12%)[0m
    2021-03-09T02:02:05.877Z DEBUG modem << [00:00:23.676,300] [0m<inf> download_client: Downloaded 26624/200595 bytes (13%)[0m
    2021-03-09T02:02:06.324Z DEBUG modem << [00:00:24.122,863] [0m<inf> download_client: Downloaded 28672/200595 bytes (14%)[0m
    2021-03-09T02:02:06.723Z DEBUG modem << [00:00:24.522,033] [0m<inf> download_client: Downloaded 30720/200595 bytes (15%)[0m
    2021-03-09T02:02:07.279Z DEBUG modem << [00:00:25.077,880] [0m<inf> download_client: Downloaded 32768/200595 bytes (16%)[0m
    2021-03-09T02:02:07.722Z DEBUG modem << [00:00:25.521,026] [0m<inf> download_client: Downloaded 34816/200595 bytes (17%)[0m
    2021-03-09T02:02:08.198Z DEBUG modem << [00:00:25.996,612] [0m<inf> download_client: Downloaded 36864/200595 bytes (18%)[0m
    2021-03-09T02:02:08.610Z DEBUG modem << [00:00:26.409,240] [0m<inf> download_client: Downloaded 38912/200595 bytes (19%)[0m
    2021-03-09T02:02:09.089Z DEBUG modem << [00:00:26.888,214] [0m<inf> download_client: Downloaded 40960/200595 bytes (20%)[0m
    2021-03-09T02:02:09.480Z DEBUG modem << [00:00:27.279,296] [0m<inf> download_client: Downloaded 43008/200595 bytes (21%)[0m
    2021-03-09T02:02:09.982Z DEBUG modem << [00:00:27.781,280] [0m<inf> download_client: Downloaded 45056/200595 bytes (22%)[0m
    2021-03-09T02:02:10.335Z DEBUG modem << [00:00:28.134,063] [0m<inf> download_client: Downloaded 47104/200595 bytes (23%)[0m
    2021-03-09T02:02:10.868Z DEBUG modem << [00:00:28.667,236] [0m<inf> download_client: Downloaded 49152/200595 bytes (24%)[0m
    2021-03-09T02:02:11.254Z DEBUG modem << [00:00:29.053,070] [0m<inf> download_client: Downloaded 51200/200595 bytes (25%)[0m
    2021-03-09T02:02:11.808Z DEBUG modem << [00:00:29.607,025] [0m<inf> download_client: Downloaded 53248/200595 bytes (26%)[0m
    2021-03-09T02:02:12.200Z DEBUG modem << [00:00:29.999,237] [0m<inf> download_client: Downloaded 55296/200595 bytes (27%)[0m
    2021-03-09T02:02:12.674Z DEBUG modem << [00:00:30.472,991] [0m<inf> download_client: Downloaded 57344/200595 bytes (28%)[0m
    2021-03-09T02:02:13.054Z DEBUG modem << [00:00:30.853,881] [0m<inf> download_client: Downloaded 59392/200595 bytes (29%)[0m
    2021-03-09T02:02:13.534Z DEBUG modem << [00:00:31.332,977] [0m<inf> download_client: Downloaded 61440/200595 bytes (30%)[0m
    2021-03-09T02:02:13.933Z DEBUG modem << [00:00:31.731,964] [0m<inf> download_client: Downloaded 63488/200595 bytes (31%)[0m
    2021-03-09T02:02:14.405Z DEBUG modem << [00:00:32.204,010] [0m<inf> download_client: Downloaded 65536/200595 bytes (32%)[0m
    2021-03-09T02:02:14.815Z DEBUG modem << [00:00:32.613,891] [0m<inf> download_client: Downloaded 67584/200595 bytes (33%)[0m
    2021-03-09T02:02:15.339Z DEBUG modem << [00:00:33.139,099] [0m<inf> download_client: Downloaded 69632/200595 bytes (34%)[0m
    2021-03-09T02:02:15.722Z DEBUG modem << [00:00:33.520,965] [0m<inf> download_client: Downloaded 71680/200595 bytes (35%)[0m
    2021-03-09T02:02:16.194Z DEBUG modem << [00:00:33.993,133] [0m<inf> download_client: Downloaded 73728/200595 bytes (36%)[0m
    2021-03-09T02:02:16.604Z DEBUG modem << [00:00:34.403,015] [0m<inf> download_client: Downloaded 75776/200595 bytes (37%)[0m
    2021-03-09T02:02:17.096Z DEBUG modem << [00:00:34.895,172] [0m<inf> download_client: Downloaded 77824/200595 bytes (38%)[0m
    2021-03-09T02:02:17.483Z DEBUG modem << [00:00:35.282,226] [0m<inf> download_client: Downloaded 79872/200595 bytes (39%)[0m
    2021-03-09T02:02:17.960Z DEBUG modem << [00:00:35.759,094] [0m<inf> download_client: Downloaded 81920/200595 bytes (40%)[0m
    2021-03-09T02:02:18.368Z DEBUG modem << [00:00:36.167,205] [0m<inf> download_client: Downloaded 83968/200595 bytes (41%)[0m
    2021-03-09T02:02:18.843Z DEBUG modem << [00:00:36.642,181] [0m<inf> download_client: Downloaded 86016/200595 bytes (42%)[0m
    2021-03-09T02:02:19.234Z DEBUG modem << [00:00:37.033,111] [0m<inf> download_client: Downloaded 88064/200595 bytes (43%)[0m
    2021-03-09T02:02:19.722Z DEBUG modem << [00:00:37.521,087] [0m<inf> download_client: Downloaded 90112/200595 bytes (44%)[0m
    2021-03-09T02:02:20.123Z DEBUG modem << [00:00:37.922,637] [0m<inf> download_client: Downloaded 92160/200595 bytes (45%)[0m
    2021-03-09T02:02:20.604Z DEBUG modem << [00:00:38.403,045] [0m<inf> download_client: Downloaded 94208/200595 bytes (46%)[0m
    2021-03-09T02:02:21.003Z DEBUG modem << [00:00:38.802,246] [0m<inf> download_client: Downloaded 96256/200595 bytes (47%)[0m
    2021-03-09T02:02:21.482Z DEBUG modem << [00:00:39.282,165] [0m<inf> download_client: Downloaded 98304/200595 bytes (49%)[0m
    2021-03-09T02:02:21.879Z DEBUG modem << [00:00:39.678,161] [0m<inf> download_client: Downloaded 100352/200595 bytes (50%)[0m
    2021-03-09T02:02:22.359Z DEBUG modem << [00:00:40.157,684] [0m<inf> download_client: Downloaded 102400/200595 bytes (51%)[0m
    2021-03-09T02:02:22.762Z DEBUG modem << [00:00:40.561,065] [0m<inf> download_client: Downloaded 104448/200595 bytes (52%)[0m
    2021-03-09T02:02:23.241Z DEBUG modem << [00:00:41.039,855] [0m<inf> download_client: Downloaded 106496/200595 bytes (53%)[0m
    2021-03-09T02:02:23.642Z DEBUG modem << [00:00:41.440,856] [0m<inf> download_client: Downloaded 108544/200595 bytes (54%)[0m
    2021-03-09T02:02:24.122Z DEBUG modem << [00:00:41.921,112] [0m<inf> download_client: Downloaded 110592/200595 bytes (55%)[0m
    2021-03-09T02:02:24.517Z DEBUG modem << [00:00:42.316,650] [0m<inf> download_client: Downloaded 112640/200595 bytes (56%)[0m
    2021-03-09T02:02:25.028Z DEBUG modem << [00:00:42.827,270] [0m<inf> download_client: Downloaded 114688/200595 bytes (57%)[0m
    2021-03-09T02:02:25.402Z DEBUG modem << [00:00:43.201,141] [0m<inf> download_client: Downloaded 116736/200595 bytes (58%)[0m
    2021-03-09T02:02:25.888Z DEBUG modem << [00:00:43.687,316] [0m<inf> download_client: Downloaded 118784/200595 bytes (59%)[0m
    2021-03-09T02:02:26.282Z DEBUG modem << [00:00:44.081,207] [0m<inf> download_client: Downloaded 120832/200595 bytes (60%)[0m
    2021-03-09T02:02:26.768Z DEBUG modem << [00:00:44.567,321] [0m<inf> download_client: Downloaded 122880/200595 bytes (61%)[0m
    2021-03-09T02:02:27.163Z DEBUG modem << [00:00:44.962,310] [0m<inf> download_client: Downloaded 124928/200595 bytes (62%)[0m
    2021-03-09T02:02:27.648Z DEBUG modem << [00:00:45.447,357] [0m<inf> download_client: Downloaded 126976/200595 bytes (63%)[0m
    2021-03-09T02:02:28.039Z DEBUG modem << [00:00:45.837,677] [0m<inf> download_client: Downloaded 129024/200595 bytes (64%)[0m
    2021-03-09T02:02:28.511Z DEBUG modem << [00:00:46.310,241] [0m<inf> download_client: Downloaded 131072/200595 bytes (65%)[0m
    2021-03-09T02:02:28.928Z DEBUG modem << [00:00:46.727,386] [0m<inf> download_client: Downloaded 133120/200595 bytes (66%)[0m
    2021-03-09T02:02:29.374Z DEBUG modem << [00:00:47.173,278] [0m<inf> download_client: Downloaded 135168/200595 bytes (67%)[0m
    2021-03-09T02:02:29.811Z DEBUG modem << [00:00:47.610,321] [0m<inf> download_client: Downloaded 137216/200595 bytes (68%)[0m
    2021-03-09T02:02:30.360Z DEBUG modem << [00:00:48.159,393] [0m<inf> download_client: Downloaded 139264/200595 bytes (69%)[0m
    2021-03-09T02:02:30.763Z DEBUG modem << [00:00:48.562,347] [0m<inf> download_client: Downloaded 141312/200595 bytes (70%)[0m
    2021-03-09T02:02:31.249Z DEBUG modem << [00:00:49.048,217] [0m<inf> download_client: Downloaded 143360/200595 bytes (71%)[0m
    2021-03-09T02:02:31.634Z DEBUG modem << [00:00:49.433,593] [0m<inf> download_client: Downloaded 145408/200595 bytes (72%)[0m
    2021-03-09T02:02:32.128Z DEBUG modem << [00:00:49.927,368] [0m<inf> download_client: Downloaded 147456/200595 bytes (73%)[0m
    2021-03-09T02:02:32.529Z DEBUG modem << [00:00:50.328,216] [0m<inf> download_client: Downloaded 149504/200595 bytes (74%)[0m
    2021-03-09T02:02:33.008Z DEBUG modem << [00:00:50.807,434] [0m<inf> download_client: Downloaded 151552/200595 bytes (75%)[0m
    2021-03-09T02:02:33.401Z DEBUG modem << [00:00:51.200,042] [0m<inf> download_client: Downloaded 153600/200595 bytes (76%)[0m
    2021-03-09T02:02:33.889Z DEBUG modem << [00:00:51.688,385] [0m<inf> download_client: Downloaded 155648/200595 bytes (77%)[0m
    2021-03-09T02:02:34.303Z DEBUG modem << [00:00:52.102,416] [0m<inf> download_client: Downloaded 157696/200595 bytes (78%)[0m
    2021-03-09T02:02:34.849Z DEBUG modem << [00:00:52.648,559] [0m<inf> download_client: Downloaded 159744/200595 bytes (79%)[0m
    2021-03-09T02:02:35.249Z DEBUG modem << [00:00:53.048,431] [0m<inf> download_client: Downloaded 161792/200595 bytes (80%)[0m
    2021-03-09T02:02:35.723Z DEBUG modem << [00:00:53.522,460] [0m<inf> download_client: Downloaded 163840/200595 bytes (81%)[0m
    2021-03-09T02:02:36.120Z DEBUG modem << [00:00:53.919,433] [0m<inf> download_client: Downloaded 165888/200595 bytes (82%)[0m
    2021-03-09T02:02:36.598Z DEBUG modem << [00:00:54.396,881] [0m<inf> download_client: Downloaded 167936/200595 bytes (83%)[0m
    2021-03-09T02:02:37.008Z DEBUG modem << [00:00:54.807,312] [0m<inf> download_client: Downloaded 169984/200595 bytes (84%)[0m
    2021-03-09T02:02:37.454Z DEBUG modem << [00:00:55.254,302] [0m<inf> download_client: Downloaded 172032/200595 bytes (85%)[0m
    2021-03-09T02:02:37.889Z DEBUG modem << [00:00:55.688,476] [0m<inf> download_client: Downloaded 174080/200595 bytes (86%)[0m
    2021-03-09T02:02:38.364Z DEBUG modem << [00:00:56.163,574] [0m<inf> download_client: Downloaded 176128/200595 bytes (87%)[0m
    2021-03-09T02:02:38.757Z DEBUG modem << [00:00:56.556,579] [0m<inf> download_client: Downloaded 178176/200595 bytes (88%)[0m
    2021-03-09T02:02:39.257Z DEBUG modem << [00:00:57.056,457] [0m<inf> download_client: Downloaded 180224/200595 bytes (89%)[0m
    2021-03-09T02:02:39.640Z DEBUG modem << [00:00:57.439,392] [0m<inf> download_client: Downloaded 182272/200595 bytes (90%)[0m
    2021-03-09T02:02:40.133Z DEBUG modem << [00:00:57.932,525] [0m<inf> download_client: Downloaded 184320/200595 bytes (91%)[0m
    2021-03-09T02:02:40.520Z DEBUG modem << [00:00:58.319,549] [0m<inf> download_client: Downloaded 186368/200595 bytes (92%)[0m
    2021-03-09T02:02:41.003Z DEBUG modem << [00:00:58.802,520] [0m<inf> download_client: Downloaded 188416/200595 bytes (93%)[0m
    2021-03-09T02:02:41.410Z DEBUG modem << [00:00:59.209,533] [0m<inf> download_client: Downloaded 190464/200595 bytes (94%)[0m
    2021-03-09T02:02:41.881Z DEBUG modem << [00:00:59.679,992] [0m<inf> download_client: Downloaded 192512/200595 bytes (95%)[0m
    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
    2021-03-09T02:02:43.561Z DEBUG modem << Received error from fota_download
    2021-03-09T02:02:43.562Z DEBUG modem << [00:01:01.352,233] [0m<inf> main: FOTA in progress.[0m
    2021-03-09T02:02:44.062Z DEBUG modem <<
    

  • Looking more closely it looks like the Range is specified correctly

    Second to last:

    Range":["bytes=196608-198655"]

    Last (that fails)

    "Range":["bytes=198656-200595"]

    For some reason the Caddy doesn't like the last request. Or I'm simply not seeing any log output from the HTTP server that's actually handling the data. Looking into this more..

  • Looks like if I try to do this manually it also fails:

    curl https://pyrinas-dev-ota.jaredwolff.com/images/352656102712240.bin -H "Content-Type: application/octet-stream" -H "Range: bytes=198656-200595" --output bob.bin

    If I decrease the size by one byte it retrieves the last 1939 bytes

    curl https://pyrinas-dev-ota.jaredwolff.com/images/352656102712240.bin -H "Content-Type: application/octet-stream" -H "Range: bytes=198656-200594" --output bob.bin

    Seems like a bug in the implementation on Caddy whereas the byte count is indexed from 0 instead of starting at 1. Not 100% sure but I'll play with it some more..

    Update:

    Trying something similar where it's statically hosted doesn't fail. That would lead me to think that there's an issue one step lower in the stack.

    curl  https://www.jaredwolff.com/testing-hardware-using-rust/images/Screen_Shot_2021-01-06_at_10.30.55_AM.png -H "Range: bytes=125801-125808" --output test.bin

Related