Hmm, no. It still seems to be failing in the same way. Hmm, this one also says "8355840" which seems a little suspicious!
2020/01/29 06:36:11 DEBUG : rclone: Version "v1.50.2-195-gacd1a502-fix-3131-onedrive-416-beta" starting with parameters ["/home/sweh/XX/rclone" "-vv" "-c" "--stats=60s" "--max-size=40000M" "--config" "/home/sweh/.config/rclone/rclone.conf" "--size-only" "sync" "." "OneDriveTST:"]
2020/01/29 10:06:43 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 786432000/5370019872 size 10485760
2020/01/29 10:06:57 DEBUG : pacer: low level retry 1/10 (error generalException: General Exception While Processing)
2020/01/29 10:06:57 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/01/29 10:06:57 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:57 DEBUG : pacer: Reducing sleep to 15ms
2020/01/29 10:06:57 DEBUG : pacer: Reducing sleep to 11.25ms
2020/01/29 10:06:57 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:57 DEBUG : pacer: low level retry 2/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:57 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 16.875ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:58 DEBUG : pacer: low level retry 3/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:58 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 25.3125ms
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 18.984375ms
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 14.238281ms
2020/01/29 10:06:58 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:58 DEBUG : pacer: low level retry 4/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:58 DEBUG : pacer: Rate limited, increasing sleep to 28.476562ms
2020/01/29 10:06:58 DEBUG : pacer: Reducing sleep to 21.357421ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 16.018065ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:59 DEBUG : pacer: low level retry 5/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:59 DEBUG : pacer: Rate limited, increasing sleep to 32.03613ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 24.027097ms
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 18.020322ms
2020/01/29 10:06:59 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:06:59 DEBUG : pacer: low level retry 6/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:06:59 DEBUG : pacer: Rate limited, increasing sleep to 36.040644ms
2020/01/29 10:06:59 DEBUG : pacer: Reducing sleep to 27.030483ms
2020/01/29 10:07:00 DEBUG : pacer: Reducing sleep to 20.272862ms
2020/01/29 10:07:00 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:00 DEBUG : pacer: Reducing sleep to 15.204646ms
2020/01/29 10:07:00 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:00 DEBUG : pacer: low level retry 7/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:00 DEBUG : pacer: Rate limited, increasing sleep to 30.409292ms
2020/01/29 10:07:01 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 22.806969ms
2020/01/29 10:07:01 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:01 DEBUG : pacer: low level retry 8/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:01 DEBUG : pacer: Rate limited, increasing sleep to 45.613938ms
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 34.210453ms
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 25.657839ms
2020/01/29 10:07:01 DEBUG : pacer: Reducing sleep to 19.243379ms
2020/01/29 10:07:01 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 14.432534ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:02 DEBUG : pacer: low level retry 9/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:02 DEBUG : pacer: Rate limited, increasing sleep to 28.865068ms
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 21.648801ms
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 16.2366ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 12.17745ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Read position 794787840, chunk is 786432000..796917760, bytes to skip = 8355840
2020/01/29 10:07:02 DEBUG : pacer: low level retry 10/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/01/29 10:07:02 DEBUG : pacer: Rate limited, increasing sleep to 24.3549ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Error encountered during upload: retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Cancelling multipart upload
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 18.266175ms
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 13.699631ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al: Received error: retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received. - low level retry 1/10
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Starting multipart upload
2020/01/29 10:07:02 DEBUG : pacer: Reducing sleep to 10.274723ms
2020/01/29 10:07:02 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 0/5370019872 size 10485760
2020/01/29 10:07:03 DEBUG : pacer: Reducing sleep to 10ms
2020/01/29 10:07:04 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 10485760/5370019872 size 10485760
2020/01/29 10:07:05 DEBUG : penfold/20200112._FastData.0.gz_al.bin: Uploading segment 20971520/5370019872 size 10485760
...
Hmm, I double checked the code but I can't see the problem.
Can you do a run with -vv --dump responses? This will be a massive log! I'd like to see the request+responses to the failing 500 error, the GET for the get position and the next failure response if possible.
I'm beginning to think after reading the docs very carefully, that there is something I'm missing so I'm going to go through the other SDKs to see if I can spot something.
It might, of course, be a bug in onedrive - we've found a few of those!
Thanks for the log. A bit of investigation showed that rclone wasn't sending the correct Content-Range header due to a really stupid scoping issue (it is easy to shadow variables in an outer scope in go - I wish it was illegal!)
Here is the fixed version. I really hope this works!
New test started, but only -vv, no dumping. This should let us see the error and retry and continuation. Afterwards copy the file back down and verify it matches the original.
OK, another complete run later and there's an overlap
2020/02/01 10:28:00 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Uploading segment 4456448000/5370019872 size 10485760
2020/02/01 10:28:30 DEBUG : pacer: low level retry 1/10 (error generalException:
General Exception While Processing)
2020/02/01 10:28:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/02/01 10:28:30 DEBUG : pacer: Reducing sleep to 15ms
2020/02/01 10:28:30 DEBUG : penfold/20200112._FastData.0.gz_ah.bin: Uploading se
gment 3806330880/5370019872 size 10485760
2020/02/01 10:28:30 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2020/02/01 10:28:31 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Read position 4464803840, chunk is 4456448000..4466933760, bytes to skip = 8355840
2020/02/01 10:28:31 DEBUG : pacer: low level retry 2/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2020/02/01 10:28:31 DEBUG : penfold/20200112._FastData.0.gz_ag.bin: Uploading segment 4466933760/5370019872 size 10485760
So if I'm reading that correctly, we get the "general error", which causes a "pacer 1/10 retry" error. That caused the 416 overlap, which causes a "pacer 2/10 retry skipping lots of bytes" error.
It's a little confusing that there "we need to retry" error comes before the pacer message and nothing after the pacer message indicates the retry with the shorter block, but I guess it worked because the next full size block was then sent.
At the end I was able to re-download the file in question and it shows as being identical to the original.