Webdav server behind cloudflare fails to download correctly

Suspected Bug
1

What is the problem you are having with rclone?

Using rclone to downloads files via webdav(caddy) hosted behind cloudflare fails to download at first run, if the file is larger then 500MB?,

Run the command 'rclone version' and share the full output of the command.

rclone v1.61.1

  • os/version: ubuntu 22.04 (64 bit)
  • os/kernel: 5.19.0-40-generic (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.19.4
  • go/linking: static
  • go/tags: none

Which cloud storage system are you using? (eg Google Drive)

selfhosted webdav server using caddy hosted behind cloudflare.

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone copy wd:/files/test/ . -stats-file-name-length 0 --multi-thread-streams 16 --progress --checksum -vvv

The rclone config contents with secrets removed.

[wd]
type = webdav
url = https://webdav.my-domain.com
vendor = other
user = admin
pass = **snip**

A log from the command with the -vv flag

2023/04/21 18:06:20 DEBUG : Setting --bind "10.0.1.3" from environment variable RCLONE_BIND="10.0.1.3"
2023/04/21 18:06:20 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "copy" "--stats-file-name-length" "0" "wd:/files/test/" "." "--multi-thread-streams" "16" "--progress" "--checksum" "-vvv"]
2023/04/21 18:06:20 DEBUG : Creating backend with remote "wd:/files/test/"
2023/04/21 18:06:20 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2023/04/21 18:06:20 DEBUG : found headers:
2023/04/21 18:06:20 DEBUG : fs cache: renaming cache item "wd:/files/test/" to be canonical "wd:files/test"
2023/04/21 18:06:20 DEBUG : Creating backend with remote "."
2023/04/21 18:06:20 DEBUG : fs cache: renaming cache item "." to be canonical "/downloads/test"
2023-04-21 18:06:21 DEBUG : Local file system at /downloads/test: Waiting for checks to finish
2023-04-21 18:06:21 DEBUG : Local file system at /downloads/test: Waiting for transfers to finish
2023-04-21 18:06:21 DEBUG : test_video.mp4: Starting multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 18:06:21 DEBUG : test_video.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi starting
2023-04-21 18:06:21 DEBUG : test_video.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi starting
2023-04-21 18:06:21 DEBUG : test_video.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi starting
2023-04-21 18:06:21 DEBUG : test_video.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi starting
2023-04-21 18:06:21 DEBUG : test_video.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi starting
2023-04-21 18:06:56 DEBUG : test_video.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi finished
2023-04-21 18:06:57 DEBUG : test_video.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi finished
2023-04-21 18:06:58 DEBUG : test_video.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi finished
2023-04-21 18:06:58 DEBUG : test_video.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi finished
2023-04-21 18:07:35 DEBUG : test_video.mp4: multi-thread copy: stream 5/5 failed: multipart copy: wrote 1404163477 bytes but expected to write 280614293
2023-04-21 18:07:35 ERROR : test_video.mp4: Failed to copy: multipart copy: wrote 1404163477 bytes but expected to write 280614293
2023-04-21 18:07:35 ERROR : Attempt 1/3 failed with 1 errors and: multipart copy: wrote 1404163477 bytes but expected to write 280614293
2023-04-21 18:07:36 DEBUG : Local file system at /downloads/test: Waiting for checks to finish
2023-04-21 18:07:36 DEBUG : test_video.mp4: Sizes differ (src 1404163477 vs dst 2527712661)
2023-04-21 18:07:36 DEBUG : Local file system at /downloads/test: Waiting for transfers to finish
2023-04-21 18:07:36 DEBUG : test_video.mp4: Starting multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 18:07:36 DEBUG : test_video.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi starting
2023-04-21 18:07:36 DEBUG : test_video.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi starting
2023-04-21 18:07:36 DEBUG : test_video.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi starting
2023-04-21 18:07:36 DEBUG : test_video.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi starting
2023-04-21 18:07:36 DEBUG : test_video.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi starting
2023-04-21 18:08:39 DEBUG : test_video.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi finished
2023-04-21 18:08:40 DEBUG : test_video.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi finished
2023-04-21 18:08:40 DEBUG : test_video.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi finished
2023-04-21 18:08:40 DEBUG : test_video.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi finished
2023-04-21 18:08:41 DEBUG : test_video.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi finished
2023-04-21 18:08:41 DEBUG : test_video.mp4: Finished multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 18:08:41 INFO  : test_video.mp4: Multi-thread Copied (replaced existing)
2023-04-21 18:08:41 ERROR : Attempt 2/3 succeeded
Transferred:        3.662 GiB / 3.662 GiB, 100%, 19.509 MiB/s, ETA 0s
Checks:                 1 / 1, 100%
Transferred:            1 / 1, 100%
Elapsed time:      2m20.6s
2023/04/21 18:08:41 INFO  :
Transferred:        3.662 GiB / 3.662 GiB, 100%, 19.509 MiB/s, ETA 0s
Checks:                 1 / 1, 100%
Transferred:            1 / 1, 100%
Elapsed time:      2m20.6s

2023/04/21 18:08:41 DEBUG : 3 go routines active

as you can see from the logs, first download fails to compute final file for some reason, the actual file size is 1404163477 thus it has been downloaded like 3 times before working correctly. if i start the download again after downloading it for the first time, then the download works as expected. I've noticed that if i bypass cloudflare it works as expected from the first time.

2023/04/21 18:17:52 DEBUG : Setting --bind "10.0.1.3" from environment variable RCLONE_BIND="10.0.1.3"
2023/04/21 18:17:52 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "copy" "--stats-file-name-length" "0" "wd:/files/test/" "." "--multi-thread-streams" "16" "--progress" "--checksum" "-vvv"]
2023/04/21 18:17:52 DEBUG : Creating backend with remote "wd:/files/test/"
2023/04/21 18:17:52 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2023/04/21 18:17:52 DEBUG : found headers:
2023/04/21 18:17:52 DEBUG : fs cache: renaming cache item "wd:/files/test/" to be canonical "wd:files/test"
2023/04/21 18:17:52 DEBUG : Creating backend with remote "."
2023/04/21 18:17:52 DEBUG : fs cache: renaming cache item "." to be canonical "/downloads/test"
2023-04-21 18:17:53 DEBUG : Local file system at /downloads/test: Waiting for checks to finish
2023-04-21 18:17:53 DEBUG : Local file system at /downloads/test: Waiting for transfers to finish
2023-04-21 18:17:53 DEBUG : test_video.mp4: Starting multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 18:17:53 DEBUG : test_video.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi starting
2023-04-21 18:17:53 DEBUG : test_video.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi starting
2023-04-21 18:17:53 DEBUG : test_video.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi starting
2023-04-21 18:17:53 DEBUG : test_video.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi starting
2023-04-21 18:17:53 DEBUG : test_video.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi starting
2023-04-21 18:18:25 DEBUG : test_video.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi finished
2023-04-21 18:18:32 DEBUG : test_video.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi finished
2023-04-21 18:18:45 DEBUG : test_video.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi finished
2023-04-21 18:18:56 DEBUG : test_video.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi finished
2023-04-21 18:19:02 DEBUG : test_video.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi finished
2023-04-21 18:19:02 DEBUG : test_video.mp4: Finished multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 18:19:02 INFO  : test_video.mp4: Multi-thread Copied (new)
Transferred:        1.308 GiB / 1.308 GiB, 100%, 19.762 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       1m9.6s
2023/04/21 18:19:02 INFO  :
Transferred:        1.308 GiB / 1.308 GiB, 100%, 19.762 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       1m9.6s

2023/04/21 18:19:02 DEBUG : 6 go routines active
2

This looks very much like one part of the chain is ignoring the Range: request that rclone is using for multi-thread copy.

Since it works when you do it direct, I'm guessing its cloudflare.

If you run rclone with -vv --dump headers you can see the headers rclone sends. Maybe there is something fishy in there that cloudflare doesn't like?

You can disable multi-thread copies with --multi-thread-streams 0 which will most likely work around the problem.

3

Thanks, I tried with new file with the requested header dump. Here is the logs

2023/04/21 23:03:05 DEBUG : Setting --bind "10.0.1.3" from environment variable RCLONE_BIND="10.0.1.3"
2023/04/21 23:03:05 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "copy" "--stats-file-name-length" "0" "wd:/downloads/test.mp4" "." "--multi-thread-streams" "16" "--progress" "--checksum" "-vvv" "--dump" "headers"]
2023/04/21 23:03:05 DEBUG : Creating backend with remote "wd:/downloads/test.mp4"
2023/04/21 23:03:05 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2023/04/21 23:03:05 DEBUG : found headers:
2023/04/21 23:03:05 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2023/04/21 23:03:05 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/04/21 23:03:05 DEBUG : HTTP REQUEST (req 0xc000b06500)
2023/04/21 23:03:05 DEBUG : PROPFIND /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 1
Referer: https://webdav.my-domain.com/
Accept-Encoding: gzip

2023/04/21 23:03:05 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/04/21 23:03:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/04/21 23:03:06 DEBUG : HTTP RESPONSE (req 0xc000b06500)
2023/04/21 23:03:06 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 662
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: DYNAMIC
Cf-Ray: random_cf_id
Content-Type: text/xml; charset=utf-8
Date: Fri, 21 Apr 2023 20:03:06 GMT
Server: cloudflare

2023/04/21 23:03:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/04/21 23:03:06 DEBUG : fs cache: adding new entry for parent of "wd:/downloads/test.mp4", "wd:downloads"
2023/04/21 23:03:06 DEBUG : Creating backend with remote "."
2023/04/21 23:03:06 DEBUG : fs cache: renaming cache item "." to be canonical "/downloads"
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000b06800)
2023-04-21 23:03:06 DEBUG : PROPFIND /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 1
Referer: https://webdav.my-domain.com/
Accept-Encoding: gzip
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:06 DEBUG : HTTP RESPONSE (req 0xc000b06800)
2023-04-21 23:03:06 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 662
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: DYNAMIC
Cf-Ray: random_cf_id
Content-Type: text/xml; charset=utf-8
Date: Fri, 21 Apr 2023 20:03:06 GMT
Server: cloudflare
2023-04-21 23:03:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:06 DEBUG : test.mp4: Need to transfer - File not found at Destination
2023-04-21 23:03:06 DEBUG : test.mp4: Starting multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 23:03:06 DEBUG : test.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi starting
2023-04-21 23:03:06 DEBUG : test.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi starting
2023-04-21 23:03:06 DEBUG : test.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi starting
2023-04-21 23:03:06 DEBUG : test.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi starting
2023-04-21 23:03:06 DEBUG : test.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi starting
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000b06300)
2023-04-21 23:03:06 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=1123549184-1404163476
Referer: https://webdav.my-domain.com/
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000498200)
2023-04-21 23:03:06 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=0-280887295
Referer: https://webdav.my-domain.com/
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000498b00)
2023-04-21 23:03:06 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=561774592-842661887
Referer: https://webdav.my-domain.com/
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000270700)
2023-04-21 23:03:06 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=280887296-561774591
Referer: https://webdav.my-domain.com/
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000271000)
2023-04-21 23:03:06 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=842661888-1123549183
Referer: https://webdav.my-domain.com/
2023-04-21 23:03:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:03:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:07 DEBUG : HTTP RESPONSE (req 0xc000b06300)
2023-04-21 23:03:07 DEBUG : HTTP/2.0 200 OK
Content-Length: 1404163477
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:03:07 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:03:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:07 DEBUG : HTTP RESPONSE (req 0xc000498200)
2023-04-21 23:03:07 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 0-280887295/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:03:07 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:03:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:07 DEBUG : HTTP RESPONSE (req 0xc000498b00)
2023-04-21 23:03:07 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 561774592-842661887/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:03:07 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:03:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:08 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:08 DEBUG : HTTP RESPONSE (req 0xc000271000)
2023-04-21 23:03:08 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 842661888-1123549183/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:03:08 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:03:08 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:08 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:08 DEBUG : HTTP RESPONSE (req 0xc000270700)
2023-04-21 23:03:08 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 280887296-561774591/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:03:08 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:03:08 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:03:44 DEBUG : test.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi finished
2023-04-21 23:03:46 DEBUG : test.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi finished
2023-04-21 23:03:46 DEBUG : test.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi finished
2023-04-21 23:03:47 DEBUG : test.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi finished
2023-04-21 23:04:28 DEBUG : test.mp4: multi-thread copy: stream 5/5 failed: multipart copy: wrote 1404163477 bytes but expected to write 280614293
2023-04-21 23:04:28 ERROR : test.mp4: Failed to copy: multipart copy: wrote 1404163477 bytes but expected to write 280614293
2023-04-21 23:04:28 ERROR : Attempt 1/3 failed with 1 errors and: multipart copy: wrote 1404163477 bytes but expected to write 280614293
2023-04-21 23:04:28 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:28 DEBUG : HTTP REQUEST (req 0xc000a14a00)
2023-04-21 23:04:28 DEBUG : PROPFIND /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 1
Referer: https://webdav.my-domain.com/
Accept-Encoding: gzip
2023-04-21 23:04:28 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:28 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:28 DEBUG : HTTP RESPONSE (req 0xc000a14a00)
2023-04-21 23:04:28 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 662
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: DYNAMIC
Cf-Ray: random_cf_id
Content-Type: text/xml; charset=utf-8
Date: Fri, 21 Apr 2023 20:04:28 GMT
Server: cloudflare
2023-04-21 23:04:28 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:28 DEBUG : test.mp4: Sizes differ (src 1404163477 vs dst 2527712661)
2023-04-21 23:04:29 DEBUG : test.mp4: Starting multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 23:04:29 DEBUG : test.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi starting
2023-04-21 23:04:29 DEBUG : test.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi starting
2023-04-21 23:04:29 DEBUG : test.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi starting
2023-04-21 23:04:29 DEBUG : test.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi starting
2023-04-21 23:04:29 DEBUG : test.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi starting
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : HTTP REQUEST (req 0xc0004baa00)
2023-04-21 23:04:29 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=1123549184-1404163476
Referer: https://webdav.my-domain.com/
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : HTTP REQUEST (req 0xc000271000)
2023-04-21 23:04:29 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=561774592-842661887
Referer: https://webdav.my-domain.com/
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : HTTP REQUEST (req 0xc00058e100)
2023-04-21 23:04:29 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=0-280887295
Referer: https://webdav.my-domain.com/
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : HTTP REQUEST (req 0xc00058e300)
2023-04-21 23:04:29 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=280887296-561774591
Referer: https://webdav.my-domain.com/
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : HTTP REQUEST (req 0xc00058e500)
2023-04-21 23:04:29 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=842661888-1123549183
Referer: https://webdav.my-domain.com/
2023-04-21 23:04:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : HTTP RESPONSE (req 0xc0004baa00)
2023-04-21 23:04:29 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280614293
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 1123549184-1404163476/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:04:29 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : HTTP RESPONSE (req 0xc000271000)
2023-04-21 23:04:29 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 561774592-842661887/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:04:29 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : HTTP RESPONSE (req 0xc00058e500)
2023-04-21 23:04:29 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 842661888-1123549183/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:04:29 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : HTTP RESPONSE (req 0xc00058e100)
2023-04-21 23:04:29 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 0-280887295/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:04:29 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:04:29 DEBUG : HTTP RESPONSE (req 0xc00058e300)
2023-04-21 23:04:29 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280887296
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 280887296-561774591/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:04:29 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare
2023-04-21 23:04:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023-04-21 23:05:05 DEBUG : test.mp4: multi-thread copy: stream 2/5 (280887296-561774592) size 267.875Mi finished
2023-04-21 23:05:06 DEBUG : test.mp4: multi-thread copy: stream 4/5 (842661888-1123549184) size 267.875Mi finished
2023-04-21 23:05:06 DEBUG : test.mp4: multi-thread copy: stream 3/5 (561774592-842661888) size 267.875Mi finished
2023-04-21 23:05:06 DEBUG : test.mp4: multi-thread copy: stream 5/5 (1123549184-1404163477) size 267.615Mi finished
2023-04-21 23:05:06 DEBUG : test.mp4: multi-thread copy: stream 1/5 (0-280887296) size 267.875Mi finished
2023-04-21 23:05:06 DEBUG : test.mp4: Finished multi-thread copy with 5 parts of size 267.875Mi
2023-04-21 23:05:06 INFO  : test.mp4: Multi-thread Copied (replaced existing)
2023-04-21 23:05:06 ERROR : Attempt 2/3 succeeded
Transferred:        3.662 GiB / 3.662 GiB, 100%, 34.119 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       2m0.6s
2023/04/21 23:05:06 INFO  :
Transferred:        3.662 GiB / 3.662 GiB, 100%, 34.119 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       2m0.6s

2023/04/21 23:05:06 DEBUG : 4 go routines active
4

Here is the request for the 5th part which is actually the first request done

2023-04-21 23:03:06 DEBUG : HTTP REQUEST (req 0xc000b06300)
2023-04-21 23:03:06 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=1123549184-1404163476
Referer: https://webdav.my-domain.com/

And here is the response

2023-04-21 23:03:07 DEBUG : HTTP RESPONSE (req 0xc000b06300)
2023-04-21 23:03:07 DEBUG : HTTP/2.0 200 OK
Content-Length: 1404163477
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:03:07 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare

So cloudflare has returned the entire file even though we've only asked for part of it.

Here is the retry

2023-04-21 23:04:29 DEBUG : HTTP REQUEST (req 0xc0004baa00)
2023-04-21 23:04:29 DEBUG : GET /downloads/test.mp4 HTTP/1.1
Host: webdav.my-domain.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Depth: 0
Range: bytes=1123549184-1404163476
Referer: https://webdav.my-domain.com/

and the response

2023-04-21 23:04:29 DEBUG : HTTP RESPONSE (req 0xc0004baa00)
2023-04-21 23:04:29 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 280614293
Alt-Svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400
Cf-Cache-Status: BYPASS
Cf-Ray: random_cf_id
Content-Range: bytes 1123549184-1404163476/1404163477
Content-Type: video/mp4
Date: Fri, 21 Apr 2023 20:04:29 GMT
Etag: "17580bb2258abcc453b1d595"
Last-Modified: Fri, 21 Apr 2023 20:02:00 GMT
Server: cloudflare

Which is a correct partial content.

I think what is happening is that the origin server isn't returning an Accept-Ranges: bytes header to indicate that it supports range requests. So cloudflare fetches the entire file on the first fetch (this is allowed by HTTP) and then since it now has cached the file, it can support Range requests.

So the question I'd ask is why isn't the origin server sending Accept-Ranges: bytes headers? Maybe these are being filtered out somewhere? Maybe that is a config setting you need to add?

Cloudflare ignoring Range requests on the first fetch seems to be a fairly common problem. I did a bit of searching and found lots of interesting stuff, but I don't know enough about your setup to say which one would be helpful. Hopefully that points you in the right direction.

5

Thanks. If i bypass cloudflare and access caddy webdav directly there is no prolem, so the server is sending the correct Range requests, i think it's due to cloudflare using single stream to download the file from the server it takes a little bit to cache the file in cloudflare after that the requests works as expected. Is it possible to add checks to make sure the rclone range requests actually producing the expected response and then reject if not? it seems there is no validation for the responses from servers at least for wevdav? possibly http requets as well.

6

That is a good point. Rclone doesn't check for a Content-Range header on Range request replies and it probably should.

It wouldn't change the outcome though (other than downloading more data than it needs to) - it would still need to do a retry I think.

Is it worth adding that check to avoid the extra download?

1 Like
7

I believe so, since rclone already has retry logic, at least to prevent wasted bandwidth. I think the way to go is to compute the final file size before kicking off the actual downloads by combining the range requests content-length replies if they match or not. the logic could be to retry the failed range request or switch to single stream download. Imagine downloading hundreds of GBs it will be twice the amount if the downloader doesn’t handle the edge case well.

8

@ncw Should i open bug report about it in github?

9

Potentially all backends which use Range requests (which is about 75% of them) could be doing this check.

I could see a bit of code in lib/rest which checks the Content-Range against the Range sent and sees whether it is OK.

Its probably a good idea - yes make an issue please.

Do you want to have a go at implementing it?

10

I'll go ahead and open issue about it in github, Sadly my coding knowledge extends to PHP, python(barely), i could attempt to hack an implementation for golang, not sure if it will be any good though.

1 Like
11

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.