Rclone fails to upload large files to OpenDrive intermittently (Incorrect chunk offset/Invalid upload file size)

Help and Support
1

What is the problem you are having with rclone?

About 80% of the time, rclone will fail to upload any file larger than a single chunk to Opendrive with either Incorrect chunk offset or Invalid upload file size

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

rclone v1.57.0
- os/version: debian 11.2 (64 bit)
- os/kernel: 5.10.0-10-amd64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.17.2
- go/linking: static
- go/tags: none

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

Opendrive

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

 % dd if=/dev/urandom bs=1M count=100 | rclone rcat -vvvv --log-file=rclone.log -P opendrive:test/test

The rclone config contents with secrets removed.

[opendrive]
type = opendrive
username = <user>
password = <pass>

A log from the command with the -vv flag

2022/02/25 16:49:59 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "rcat" "-vvvv" "--log-file=rclone.log" "-P" "opendrive:test/test"]
2022/02/25 16:49:59 DEBUG : Creating backend with remote "opendrive:test/"
2022/02/25 16:49:59 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/02/25 16:49:59 DEBUG : Starting OpenDrive session with ID: 2482362a6177bbed16c030c8baee30df2e2d9157508a50d2a0db39e6a74a303b
2022/02/25 16:49:59 DEBUG : fs cache: renaming cache item "opendrive:test/" to be canonical "opendrive:test"
2022/02/25 16:49:59 DEBUG : OpenDrive root 'test': Target remote doesn't support streaming uploads, creating temporary local FS to spool file
2022/02/25 16:49:59 DEBUG : Creating backend with remote "/tmp/rclone-spool1049813267"
2022/02/25 16:50:00 DEBUG : test: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/02/25 16:50:09 DEBUG : test: Uploading chunk 0, size=10485760, remain=94371840
2022/02/25 16:50:10 DEBUG : test: Uploading chunk 1, size=10485760, remain=83886080
2022/02/25 16:50:10 DEBUG : test: Uploading chunk 2, size=10485760, remain=73400320
2022/02/25 16:50:18 DEBUG : test: Uploading chunk 3, size=10485760, remain=62914560
2022/02/25 16:50:19 DEBUG : test: Uploading chunk 4, size=10485760, remain=52428800
2022/02/25 16:50:26 DEBUG : test: Uploading chunk 5, size=10485760, remain=41943040
2022/02/25 16:50:30 DEBUG : test: Uploading chunk 6, size=10485760, remain=31457280
2022/02/25 16:50:32 DEBUG : test: Uploading chunk 7, size=10485760, remain=20971520
2022/02/25 16:50:32 DEBUG : test: Uploading chunk 8, size=10485760, remain=10485760
2022/02/25 16:50:35 DEBUG : test: Uploading chunk 9, size=10485760, remain=0
2022/02/25 16:50:42 ERROR : test: Failed to copy: failed to create file: Invalid upload file size. Total uploaded=94371840. File size=104857600 (Error 400)
2022/02/25 16:50:42 ERROR : test: Post request rcat error: failed to create file: Invalid upload file size. Total uploaded=94371840. File size=104857600 (Error 400)
2022/02/25 16:50:42 DEBUG : 3 go routines active
2022/02/25 16:50:42 Failed to rcat: failed to create file: Invalid upload file size. Total uploaded=94371840. File size=104857600 (Error 400)

2022/02/25 17:00:32 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "rcat" "-vvvv" "--log-file=rclone.log" "-P" "opendrive:test/test"]
2022/02/25 17:00:32 DEBUG : Creating backend with remote "opendrive:test/"
2022/02/25 17:00:32 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/02/25 17:00:33 DEBUG : Starting OpenDrive session with ID: bad42bb6a97ed2e98046cf448fc051d425242ebe557b7c223f2a7143acb40eff
2022/02/25 17:00:33 DEBUG : fs cache: renaming cache item "opendrive:test/" to be canonical "opendrive:test"
2022/02/25 17:00:33 DEBUG : OpenDrive root 'test': Target remote doesn't support streaming uploads, creating temporary local FS to spool file
2022/02/25 17:00:33 DEBUG : Creating backend with remote "/tmp/rclone-spool3548910675"
2022/02/25 17:00:34 DEBUG : test: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/02/25 17:00:58 DEBUG : test: Uploading chunk 0, size=10485760, remain=94371840
2022/02/25 17:01:14 DEBUG : test: Uploading chunk 1, size=10485760, remain=83886080
2022/02/25 17:01:14 DEBUG : test: Uploading chunk 2, size=10485760, remain=73400320
2022/02/25 17:01:15 ERROR : test: Failed to copy: failed to create file: Incorrect chunk offset: uploaded=10485760, chunk_offset=20971520 (Error 400)
2022/02/25 17:01:15 ERROR : test: Post request rcat error: failed to create file: Incorrect chunk offset: uploaded=10485760, chunk_offset=20971520 (Error 400)
2022/02/25 17:01:15 DEBUG : 3 go routines active
2022/02/25 17:01:15 Failed to rcat: failed to create file: Incorrect chunk offset: uploaded=10485760, chunk_offset=20971520 (Error 400)
2

hello and welcome to the forum,

does this only happen with rclone rcat or does it happens with a pre-created file?

3

This still happens with a pre-created file, however rclone will retry as the file exists on disk.

2022/02/25 18:09:02 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "copy" "-vvv" "-P" "test" "opendrive:test/"]
2022/02/25 18:09:02 DEBUG : Creating backend with remote "test"
2022/02/25 18:09:02 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/02/25 18:09:02 DEBUG : fs cache: adding new entry for parent of "test", "/home/user"
2022/02/25 18:09:02 DEBUG : Creating backend with remote "opendrive:test/"
2022/02/25 18:09:02 DEBUG : Starting OpenDrive session with ID: 043b274c7d54ac26f810273465089089af1321c461714897668668640fbd5a7f
2022/02/25 18:09:02 DEBUG : fs cache: renaming cache item "opendrive:test/" to be canonical "opendrive:test"
2022-02-25 18:09:05 DEBUG : test: Modification times differ by -4m57.515749479s: 2022-02-25 18:08:58.515749479 -0500 EST, 2022-02-25 18:04:01 -0500 EST
2022-02-25 18:09:08 DEBUG : test: Uploading chunk 0, size=10485760, remain=94371840
2022-02-25 18:09:11 DEBUG : test: Uploading chunk 1, size=10485760, remain=83886080
2022-02-25 18:09:14 DEBUG : test: Uploading chunk 2, size=10485760, remain=73400320
2022-02-25 18:09:18 DEBUG : test: Uploading chunk 3, size=10485760, remain=62914560
2022-02-25 18:09:21 DEBUG : test: Uploading chunk 4, size=10485760, remain=52428800
2022-02-25 18:09:24 DEBUG : test: Uploading chunk 5, size=10485760, remain=41943040
2022-02-25 18:09:27 DEBUG : test: Uploading chunk 6, size=10485760, remain=31457280
2022-02-25 18:09:41 DEBUG : test: Uploading chunk 7, size=10485760, remain=20971520
2022-02-25 18:09:49 DEBUG : test: Uploading chunk 8, size=10485760, remain=10485760
2022-02-25 18:09:49 DEBUG : test: Uploading chunk 9, size=10485760, remain=0
2022-02-25 18:09:53 ERROR : test: Failed to copy: failed to create file: Invalid upload file size. Total uploaded=83886080. File size=104857600 (Error 400)
2022-02-25 18:09:53 ERROR : Attempt 1/3 failed with 1 errors and: failed to create file: Invalid upload file size. Total uploaded=83886080. File size=104857600 (Error 400)
2022-02-25 18:09:54 DEBUG : test: Modification times differ by -4m57.515749479s: 2022-02-25 18:08:58.515749479 -0500 EST, 2022-02-25 18:04:01 -0500 EST
2022-02-25 18:09:57 DEBUG : test: Uploading chunk 0, size=10485760, remain=94371840
2022-02-25 18:09:57 DEBUG : test: Uploading chunk 1, size=10485760, remain=83886080
2022-02-25 18:10:17 DEBUG : test: Uploading chunk 2, size=10485760, remain=73400320
2022-02-25 18:10:35 DEBUG : test: Uploading chunk 3, size=10485760, remain=62914560
2022-02-25 18:10:57 DEBUG : test: Uploading chunk 4, size=10485760, remain=52428800
2022-02-25 18:10:57 DEBUG : test: Uploading chunk 5, size=10485760, remain=41943040
2022-02-25 18:10:58 DEBUG : test: Uploading chunk 6, size=10485760, remain=31457280
2022-02-25 18:10:59 DEBUG : test: Uploading chunk 7, size=10485760, remain=20971520
2022-02-25 18:11:17 DEBUG : test: Uploading chunk 8, size=10485760, remain=10485760
2022-02-25 18:11:21 DEBUG : test: Uploading chunk 9, size=10485760, remain=0
2022-02-25 18:11:26 ERROR : test: Failed to copy: failed to create file: Invalid upload file size. Total uploaded=94371840. File size=104857600 (Error 400)
2022-02-25 18:11:26 ERROR : Attempt 2/3 failed with 1 errors and: failed to create file: Invalid upload file size. Total uploaded=94371840. File size=104857600 (Error 400)
2022-02-25 18:11:27 DEBUG : test: Modification times differ by -4m57.515749479s: 2022-02-25 18:08:58.515749479 -0500 EST, 2022-02-25 18:04:01 -0500 EST
2022-02-25 18:11:28 DEBUG : test: Uploading chunk 0, size=10485760, remain=94371840
2022-02-25 18:11:29 DEBUG : test: Uploading chunk 1, size=10485760, remain=83886080
2022-02-25 18:11:29 DEBUG : test: Uploading chunk 2, size=10485760, remain=73400320
2022-02-25 18:11:30 DEBUG : test: Uploading chunk 3, size=10485760, remain=62914560
2022-02-25 18:11:38 DEBUG : test: Uploading chunk 4, size=10485760, remain=52428800
2022-02-25 18:11:39 DEBUG : test: Uploading chunk 5, size=10485760, remain=41943040
2022-02-25 18:11:41 ERROR : test: Failed to copy: failed to create file: Incorrect chunk offset: uploaded=41943040, chunk_offset=52428800 (Error 400)
2022-02-25 18:11:41 ERROR : Attempt 3/3 failed with 1 errors and: failed to create file: Incorrect chunk offset: uploaded=41943040, chunk_offset=52428800 (Error 400)
2022/02/25 18:11:41 DEBUG : 2 go routines active
2022/02/25 18:11:41 Failed to copy: failed to create file: Incorrect chunk offset: uploaded=41943040, chunk_offset=52428800 (Error 400)
4

From the debug it looks like rclone uploads all the chunks but for some reason opendrive doesn't see them at the point the request it finalized.

Can you try --tpslimit 1 to put an artificial pause between the chunks and see if it works?

5

Sadly still has the same issue.

2022/02/27 03:22:56 INFO  : Starting transaction limiter: max 1 transactions/s with burst 1
2022/02/27 03:22:56 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "rcat" "-vvvv" "--log-file=rclone.log" "-P" "--tpslimit" "1" "opendrive:test/test"]
2022/02/27 03:22:56 DEBUG : Creating backend with remote "opendrive:test/"
2022/02/27 03:22:56 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/02/27 03:22:56 DEBUG : Starting OpenDrive session with ID: a047d98a0de87a96b55c0dd8c6171391ac1cfd7dea6edac35b54bb53276adf48
2022/02/27 03:22:57 DEBUG : fs cache: renaming cache item "opendrive:test/" to be canonical "opendrive:test"
2022/02/27 03:22:57 DEBUG : OpenDrive root 'test': Target remote doesn't support streaming uploads, creating temporary local FS to spool file
2022/02/27 03:22:57 DEBUG : Creating backend with remote "/tmp/rclone-spool318229657"
2022/02/27 03:22:58 DEBUG : test: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/02/27 03:22:59 DEBUG : test: Uploading chunk 0, size=10485760, remain=94371840
2022/02/27 03:23:10 DEBUG : test: Uploading chunk 1, size=10485760, remain=83886080
2022/02/27 03:23:42 DEBUG : test: Uploading chunk 2, size=10485760, remain=73400320
2022/02/27 03:23:59 DEBUG : test: Uploading chunk 3, size=10485760, remain=62914560
2022/02/27 03:24:08 DEBUG : test: Uploading chunk 4, size=10485760, remain=52428800
2022/02/27 03:24:18 DEBUG : test: Uploading chunk 5, size=10485760, remain=41943040
2022/02/27 03:24:42 DEBUG : test: Uploading chunk 6, size=10485760, remain=31457280
2022/02/27 03:24:42 DEBUG : test: Uploading chunk 7, size=10485760, remain=20971520
2022/02/27 03:24:45 ERROR : test: Failed to copy: failed to create file: Incorrect chunk offset: uploaded=62914560, chunk_offset=73400320 (Error 400)
2022/02/27 03:24:45 ERROR : test: Post request rcat error: failed to create file: Incorrect chunk offset: uploaded=62914560, chunk_offset=73400320 (Error 400)
2022/02/27 03:24:45 DEBUG : 4 go routines active
2022/02/27 03:24:45 Failed to rcat: failed to create file: Incorrect chunk offset: uploaded=62914560, chunk_offset=73400320 (Error 400)
6

I tried your test 10 times in a row and I couldn't get it to go wrong :frowning:

Can you run your test with -vv --dump responses and attach a failing log here? I'd like to check that opendrive thought each chunk was uploaded properly - maybe rclone is missing something.

7

Interestingly enough I can't reproduce this anymore either. I'm wondering if this was a bug on the OpenDrive side.

8

i forgot to post, that over the weekend, i did the same as @ncw, running a simple command in a loop, approx 20 times.
never once had an issue.

9

Let's call it a glitch at OpenDrive and move on! These things happen at cloud providers.

10

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