Upload failed: batcher is shutting down

gustafsonja · November 4, 2022, 11:25pm

What is the problem you are having with rclone?

Copying to an alias to a union are failing, when copying to the union directly works.

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

rclone v1.61.0-beta.6524.5b5fdc6bc

os/version: debian 11.5 (64 bit)
os/kernel: 5.10.0-18-amd64 (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.19.3
go/linking: static
go/tags: none

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

Dropbox

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

rclone copyto /tmp/empty mnta-unencrypted:empty -vvv

The rclone config contents with secrets removed.

[dbx-1]
type = dropbox
token = [snip]

[dbx-2]
type = dropbox
token = [snip]

[dbx-union]
type = union
upstreams = dbx-1:rclone-union-root dbx-2:rclone-union-root

[mnta-unencrypted]
type = alias
remote = dbx-union:mnta-unencrypted

A log from the command with the `-vv` flag

> rclone copyto /tmp/empty mnta-unencrypted:empty -vvv
2022/11/04 16:18:23 DEBUG : rclone: Version "v1.61.0-beta.6524.5b5fdc6bc" starting with parameters ["rclone" "copyto" "/tmp/empty" "mnta-unencrypted:empty" "-vvv"]
2022/11/04 16:18:23 DEBUG : Creating backend with remote "/tmp/empty"
2022/11/04 16:18:23 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/11/04 16:18:23 DEBUG : fs cache: adding new entry for parent of "/tmp/empty", "/tmp"
2022/11/04 16:18:23 DEBUG : Creating backend with remote "mnta-unencrypted:"
2022/11/04 16:18:23 DEBUG : Creating backend with remote "dbx-union:mnta-unencrypted"
2022/11/04 16:18:23 DEBUG : Creating backend with remote "dbx-2:rclone-union-root"
2022/11/04 16:18:23 DEBUG : Creating backend with remote "dbx-1:rclone-union-root"
2022/11/04 16:18:23 DEBUG : Creating backend with remote "dbx-2:rclone-union-root/mnta-unencrypted"
2022/11/04 16:18:23 DEBUG : Creating backend with remote "dbx-1:rclone-union-root/mnta-unencrypted"
2022/11/04 16:18:23 DEBUG : union root 'mnta-unencrypted': actionPolicy = *policy.EpAll, createPolicy = *policy.EpMfs, searchPolicy = *policy.FF
2022/11/04 16:18:23 DEBUG : fs cache: renaming cache item "mnta-unencrypted:" to be canonical "dbx-union:mnta-unencrypted"
2022/11/04 16:18:23 INFO  : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing uploads - please wait...
2022/11/04 16:18:23 INFO  : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing uploads - please wait...
2022/11/04 16:18:23 DEBUG : empty: Need to transfer - File not found at Destination
2022/11/04 16:18:24 DEBUG : empty: Uploading chunk 1/0
2022/11/04 16:18:24 DEBUG : empty: Uploading chunk 2/0
2022/11/04 16:18:24 ERROR : empty: Failed to copy: upload failed: batcher is shutting down
2022/11/04 16:18:24 ERROR : Fatal error received - not attempting retries
2022/11/04 16:18:24 INFO  :
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Errors:                 1 (fatal error encountered)
Elapsed time:         1.5s

2022/11/04 16:18:24 DEBUG : 11 go routines active
2022/11/04 16:18:24 INFO  : Dropbox root 'rclone-union-root': Committing uploads - please wait...
2022/11/04 16:18:24 INFO  : Dropbox root 'rclone-union-root': Committing uploads - please wait...
2022/11/04 16:18:24 Failed to copyto: upload failed: batcher is shutting down

> rclone copyto /tmp/empty dbx-union:empty -vvv
2022/11/04 16:18:36 DEBUG : rclone: Version "v1.61.0-beta.6524.5b5fdc6bc" starting with parameters ["rclone" "copyto" "/tmp/empty" "dbx-union:empty" "-vvv"]
2022/11/04 16:18:36 DEBUG : Creating backend with remote "/tmp/empty"
2022/11/04 16:18:36 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/11/04 16:18:36 DEBUG : fs cache: adding new entry for parent of "/tmp/empty", "/tmp"
2022/11/04 16:18:36 DEBUG : Creating backend with remote "dbx-union:"
2022/11/04 16:18:36 DEBUG : Creating backend with remote "dbx-2:rclone-union-root"
2022/11/04 16:18:36 DEBUG : Creating backend with remote "dbx-1:rclone-union-root"
2022/11/04 16:18:36 DEBUG : union root '': actionPolicy = *policy.EpAll, createPolicy = *policy.EpMfs, searchPolicy = *policy.FF
2022/11/04 16:18:36 DEBUG : empty: Need to transfer - File not found at Destination
2022/11/04 16:18:37 DEBUG : empty: Uploading chunk 1/0
2022/11/04 16:18:37 DEBUG : empty: Uploading chunk 2/0
2022/11/04 16:18:38 DEBUG : Dropbox root 'rclone-union-root': Adding "/rclone-union-root/empty" to batch
2022/11/04 16:18:38 DEBUG : Dropbox root 'rclone-union-root': Batch idle for 500ms so committing
2022/11/04 16:18:38 DEBUG : Dropbox root 'rclone-union-root': Committing sync batch length 1 starting with: /rclone-union-root/empty
2022/11/04 16:18:39 DEBUG : Dropbox root 'rclone-union-root': Committed sync batch length 1 starting with: /rclone-union-root/empty
2022/11/04 16:18:39 DEBUG : empty: dropbox = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK
2022/11/04 16:18:39 INFO  : empty: Copied (new)
2022/11/04 16:18:39 INFO  :
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         2.5s

2022/11/04 16:18:39 DEBUG : 10 go routines active
2022/11/04 16:18:39 INFO  : Dropbox root 'rclone-union-root': Committing uploads - please wait...
2022/11/04 16:18:39 INFO  : Dropbox root 'rclone-union-root': Committing uploads - please wait...

Ole · November 5, 2022, 8:46am

Hi gustafsonja,

The two commands are a little bit different in their use of (underlying) folders.

Please try these commands in exactly this order:

rclone lsd dbx-union:
rclone lsd dbx-1:rclone-union-root
rclone lsd dbx-2:rclone-union-root
rclone copyto /tmp/empty dbx-union:mnta-unencrypted/empty -vvv
rclone copyto /tmp/empty dbx-1:rclone-union-root/mnta-unencrypted/empty1 -vvv
rclone copyto /tmp/empty dbx-2:rclone-union-root/mnta-unencrypted/empty2 -vvv

They may give some additional details (and perhaps provide a workaround by creating the mnta-unencrypted folder on both remotes).

gustafsonja · November 7, 2022, 8:11pm

Hey Ole, thanks for the reply.

> rclone lsd dbx-union:
          -2 2022-11-07 11:58:07        -1 mnta-crypt-obfuscate
          -1 2022-11-07 11:58:07        -1 mnta-crypt-standard
          -2 2022-11-07 11:58:07        -1 mnta-unencrypted

> rclone lsd dbx-1:rclone-union-root
          -1 2022-11-07 11:58:26        -1 mnta-crypt-obfuscate
          -1 2022-11-07 11:58:26        -1 mnta-unencrypted

> rclone lsd dbx-2:rclone-union-root
          -1 2022-11-07 11:58:39        -1 mnta-crypt-obfuscate
          -1 2022-11-07 11:58:39        -1 mnta-crypt-standard
          -1 2022-11-07 11:58:39        -1 mnta-unencrypted

> rclone copyto /tmp/empty dbx-union:mnta-unencrypted/empty -vvv
2022/11/07 12:00:05 DEBUG : rclone: Version "v1.61.0-beta.6524.5b5fdc6bc" starting with parameters ["rclone" "copyto" "/tmp/empty" "dbx-union:mnta-unencrypted/empty" "-vvv"]
2022/11/07 12:00:05 DEBUG : Creating backend with remote "/tmp/empty"
2022/11/07 12:00:05 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/11/07 12:00:05 DEBUG : fs cache: adding new entry for parent of "/tmp/empty", "/tmp"
2022/11/07 12:00:05 DEBUG : Creating backend with remote "dbx-union:mnta-unencrypted/"
2022/11/07 12:00:05 DEBUG : Creating backend with remote "dbx-2:rclone-union-root"
2022/11/07 12:00:05 DEBUG : Creating backend with remote "dbx-1:rclone-union-root"
2022/11/07 12:00:06 DEBUG : Creating backend with remote "dbx-1:rclone-union-root/mnta-unencrypted"
2022/11/07 12:00:06 DEBUG : Creating backend with remote "dbx-2:rclone-union-root/mnta-unencrypted"
2022/11/07 12:00:06 DEBUG : union root 'mnta-unencrypted': actionPolicy = *policy.EpAll, createPolicy = *policy.EpMfs, searchPolicy = *policy.FF
2022/11/07 12:00:06 DEBUG : fs cache: renaming cache item "dbx-union:mnta-unencrypted/" to be canonical "dbx-union:mnta-unencrypted"
2022/11/07 12:00:06 DEBUG : empty: Need to transfer - File not found at Destination
2022/11/07 12:00:07 DEBUG : empty: Uploading chunk 1/0
2022/11/07 12:00:07 DEBUG : empty: Uploading chunk 2/0
2022/11/07 12:00:08 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Adding "/rclone-union-root/mnta-unencrypted/empty" to batch
2022/11/07 12:00:08 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Batch idle for 500ms so committing
2022/11/07 12:00:08 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing sync batch length 1 starting with: /rclone-union-root/mnta-unencrypted/empty
2022/11/07 12:00:09 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Committed sync batch length 1 starting with: /rclone-union-root/mnta-unencrypted/empty
2022/11/07 12:00:09 DEBUG : empty: dropbox = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK
2022/11/07 12:00:09 INFO  : empty: Copied (new)
2022/11/07 12:00:09 INFO  :
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         3.4s

2022/11/07 12:00:09 DEBUG : 13 go routines active
2022/11/07 12:00:09 INFO  : Dropbox root 'rclone-union-root': Committing uploads - please wait...
2022/11/07 12:00:09 INFO  : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing uploads - please wait...
2022/11/07 12:00:09 INFO  : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing uploads - please wait...
2022/11/07 12:00:09 INFO  : Dropbox root 'rclone-union-root': Committing uploads - please wait...

> rclone copyto /tmp/empty dbx-1:rclone-union-root/mnta-unencrypted/empty1 -vvv
2022/11/07 12:00:40 DEBUG : rclone: Version "v1.61.0-beta.6524.5b5fdc6bc" starting with parameters ["rclone" "copyto" "/tmp/empty" "dbx-1:rclone-union-root/mnta-unencrypted/empty1" "-vvv"]
2022/11/07 12:00:40 DEBUG : Creating backend with remote "/tmp/empty"
2022/11/07 12:00:40 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/11/07 12:00:40 DEBUG : fs cache: adding new entry for parent of "/tmp/empty", "/tmp"
2022/11/07 12:00:40 DEBUG : Creating backend with remote "dbx-1:rclone-union-root/mnta-unencrypted/"
2022/11/07 12:00:41 DEBUG : fs cache: renaming cache item "dbx-1:rclone-union-root/mnta-unencrypted/" to be canonical "dbx-1:rclone-union-root/mnta-unencrypted"
2022/11/07 12:00:41 DEBUG : empty: Need to transfer - File not found at Destination
2022/11/07 12:00:41 DEBUG : empty1: Uploading chunk 1/0
2022/11/07 12:00:42 DEBUG : empty1: Uploading chunk 2/0
2022/11/07 12:00:42 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Adding "/rclone-union-root/mnta-unencrypted/empty1" to batch
2022/11/07 12:00:42 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Batch idle for 500ms so committing
2022/11/07 12:00:42 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing sync batch length 1 starting with: /rclone-union-root/mnta-unencrypted/empty1
2022/11/07 12:00:43 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Committed sync batch length 1 starting with: /rclone-union-root/mnta-unencrypted/empty1
2022/11/07 12:00:43 DEBUG : empty: dropbox = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK
2022/11/07 12:00:43 INFO  : empty: Copied (new) to: empty1
2022/11/07 12:00:43 INFO  :
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         2.6s

2022/11/07 12:00:43 DEBUG : 9 go routines active
2022/11/07 12:00:43 INFO  : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing uploads - please wait...

> rclone copyto /tmp/empty dbx-2:rclone-union-root/mnta-unencrypted/empty2 -vvv
2022/11/07 12:01:01 DEBUG : rclone: Version "v1.61.0-beta.6524.5b5fdc6bc" starting with parameters ["rclone" "copyto" "/tmp/empty" "dbx-2:rclone-union-root/mnta-unencrypted/empty2" "-vvv"]
2022/11/07 12:01:01 DEBUG : Creating backend with remote "/tmp/empty"
2022/11/07 12:01:01 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2022/11/07 12:01:01 DEBUG : fs cache: adding new entry for parent of "/tmp/empty", "/tmp"
2022/11/07 12:01:01 DEBUG : Creating backend with remote "dbx-2:rclone-union-root/mnta-unencrypted/"
2022/11/07 12:01:01 DEBUG : fs cache: renaming cache item "dbx-2:rclone-union-root/mnta-unencrypted/" to be canonical "dbx-2:rclone-union-root/mnta-unencrypted"
2022/11/07 12:01:01 DEBUG : empty: Need to transfer - File not found at Destination
2022/11/07 12:01:01 DEBUG : empty2: Uploading chunk 1/0
2022/11/07 12:01:02 DEBUG : empty2: Uploading chunk 2/0
2022/11/07 12:01:02 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Adding "/rclone-union-root/mnta-unencrypted/empty2" to batch
2022/11/07 12:01:03 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Batch idle for 500ms so committing
2022/11/07 12:01:03 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing sync batch length 1 starting with: /rclone-union-root/mnta-unencrypted/empty2
2022/11/07 12:01:03 DEBUG : Dropbox root 'rclone-union-root/mnta-unencrypted': Committed sync batch length 1 starting with: /rclone-union-root/mnta-unencrypted/empty2
2022/11/07 12:01:03 DEBUG : empty: dropbox = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK
2022/11/07 12:01:03 INFO  : empty: Copied (new) to: empty2
2022/11/07 12:01:03 INFO  :
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         2.5s

2022/11/07 12:01:03 DEBUG : 9 go routines active
2022/11/07 12:01:03 INFO  : Dropbox root 'rclone-union-root/mnta-unencrypted': Committing uploads - please wait...

Ole · November 8, 2022, 8:21am

Thanks, that was unexpected, it looks like everything is OK.

Can you please try reproducing again using this command (with a new filename):

rclone copyto /tmp/empty mnta-unencrypted:empty3 -vv --dump headers

ncw · November 8, 2022, 11:50am

What this error means is the dropbox backend has been shutdown.

This has happened before when we've forgotten to pin things in the cache - eg combine: fix errors with backends shutting down while in use · rclone/rclone@821e084 · GitHub which the symptoms look identical.

We've got 3 backends involved here, dropbox, union and alias. The union backend definitely pins backends its created but the alias backend doesn't...

OK after a lot of investigation I've managed to fix it. What was happening is when the alias backend was being renamed in the cache it was finalized when it shouldn't have been. This turned out to be a simple fix in rclone's backend cache.

The problem potentially affects any aliases for backends which implement Shutdown.

Please can you give this a go?

v1.61.0-beta.6534.08bc0cf18.fix-cache-shutdown on branch fix-cache-shutdown (uploaded in 15-30 mins)

gustafsonja · November 9, 2022, 6:00am

Looks like this fixed it!

ncw · November 9, 2022, 4:30pm

Thanks for testing. I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.60.1

system · November 12, 2022, 4:31pm

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