"./sync.test -test.v -test.timeout 1h0m0s -remote TestTardigrade: -verbose -test.run '^(TestServerSideMove|TestServerSideMoveDeleteEmptySourceDirs|TestServerSideMoveWithFilter)$'" - Starting (try 2/5)
2020/12/12 06:02:29 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-tebejad2jenihus4jafuhez2"
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: connecting...
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: connected: <nil>
2020/12/12 06:02:29 DEBUG : Creating backend with remote "/tmp/rclone126100379"
=== RUN   TestServerSideMove
    run.go:176: Remote "FS sj://rclone-test-tebejad2jenihus4jafuhez2", Local "Local file system at /tmp/rclone126100379", Modify Window "1ns"
2020/12/12 06:02:29 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-wubacud8yowuxin0quqifim2"
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: connecting...
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: connected: <nil>
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: mkdir -p ./
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./potato2 # [] 60
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./empty space # [] 1
2020/12/12 06:02:29 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./potato3 # [] 68
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
    sync_test.go:1294: Server side move (if possible) FS sj://rclone-test-tebejad2jenihus4jafuhez2 -> FS sj://rclone-test-wubacud8yowuxin0quqifim2
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: mkdir -p ./
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: cp input ./empty space # [] 1
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: cp input ./potato3 # [] 60
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: ls -R ./
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: OBJ ls -R ./ ("rclone-test-wubacud8yowuxin0quqifim2", "")
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: ls ./
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: OBJ ls ./ ("rclone-test-wubacud8yowuxin0quqifim2", "")
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls ./
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:30 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ns)
2020/12/12 06:02:30 DEBUG : empty space: Unchanged skipping
2020/12/12 06:02:30 DEBUG : empty space: rm sj://rclone-test-tebejad2jenihus4jafuhez2/empty space
2020/12/12 06:02:30 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2020/12/12 06:02:30 DEBUG : potato3: cat sj://rclone-test-tebejad2jenihus4jafuhez2/potato3 # [HashesOption([])]
2020/12/12 06:02:30 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:30 DEBUG : potato2: cat sj://rclone-test-tebejad2jenihus4jafuhez2/potato2 # [HashesOption([])]
2020/12/12 06:02:30 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: Waiting for checks to finish
2020/12/12 06:02:30 INFO  : empty space: Deleted
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: Waiting for transfers to finish
2020/12/12 06:02:30 DEBUG : potato3: cp input ./potato3 [HashesOption([])]
2020/12/12 06:02:30 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:31 INFO  : potato3: Copied (replaced existing)
2020/12/12 06:02:31 DEBUG : potato3: rm sj://rclone-test-tebejad2jenihus4jafuhez2/potato3
2020/12/12 06:02:31 INFO  : potato3: Deleted
2020/12/12 06:02:31 INFO  : potato2: Copied (new)
2020/12/12 06:02:31 DEBUG : potato2: rm sj://rclone-test-tebejad2jenihus4jafuhez2/potato2
2020/12/12 06:02:31 INFO  : potato2: Deleted
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: OBJ ls -R ./ ("rclone-test-wubacud8yowuxin0quqifim2", "")
2020/12/12 06:02:31 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-giyaxij1karimew0lahisah7"
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: connecting...
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: connected: <nil>
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: ls ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: OBJ ls ./ ("rclone-test-giyaxij1karimew0lahisah7", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: ls ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: OBJ ls ./ ("rclone-test-wubacud8yowuxin0quqifim2", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:31 DEBUG : empty space: cat sj://rclone-test-wubacud8yowuxin0quqifim2/empty space # [HashesOption([])]
2020/12/12 06:02:31 DEBUG : empty space: range 0 + -1
2020/12/12 06:02:31 DEBUG : potato2: cat sj://rclone-test-wubacud8yowuxin0quqifim2/potato2 # [HashesOption([])]
2020/12/12 06:02:31 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: Waiting for checks to finish
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: Waiting for transfers to finish
2020/12/12 06:02:31 DEBUG : potato3: cat sj://rclone-test-wubacud8yowuxin0quqifim2/potato3 # [HashesOption([])]
2020/12/12 06:02:31 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./empty space # [HashesOption([])] 1
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:31 ERROR : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./potato2 [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:64
	storj.io/uplink.(*Upload).Abort:162
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put.func1:548
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put:581
	github.com/rclone/rclone/fs/operations.Copy:468
	github.com/rclone/rclone/fs/operations.Move:593
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:388
2020/12/12 06:02:31 DEBUG : potato2: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2020/12/12 06:02:31 DEBUG : potato2: cat sj://rclone-test-wubacud8yowuxin0quqifim2/potato2 # [HashesOption([])]
2020/12/12 06:02:31 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:31 ERROR : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./potato3 [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:64
	storj.io/uplink.(*Upload).Abort:162
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put.func1:548
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put:581
	github.com/rclone/rclone/fs/operations.Copy:468
	github.com/rclone/rclone/fs/operations.Move:593
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:388
2020/12/12 06:02:31 DEBUG : potato3: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2020/12/12 06:02:31 DEBUG : potato3: cat sj://rclone-test-wubacud8yowuxin0quqifim2/potato3 # [HashesOption([])]
2020/12/12 06:02:31 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:31 INFO  : potato2: Copied (new)
2020/12/12 06:02:31 DEBUG : potato2: rm sj://rclone-test-wubacud8yowuxin0quqifim2/potato2
2020/12/12 06:02:31 INFO  : empty space: Copied (new)
2020/12/12 06:02:31 DEBUG : empty space: rm sj://rclone-test-wubacud8yowuxin0quqifim2/empty space
2020/12/12 06:02:31 INFO  : potato3: Copied (new)
2020/12/12 06:02:31 DEBUG : potato3: rm sj://rclone-test-wubacud8yowuxin0quqifim2/potato3
2020/12/12 06:02:31 INFO  : potato2: Deleted
2020/12/12 06:02:31 INFO  : empty space: Deleted
2020/12/12 06:02:31 INFO  : potato3: Deleted
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: OBJ ls -R ./ ("rclone-test-giyaxij1karimew0lahisah7", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: OBJ ls -R ./ ("rclone-test-wubacud8yowuxin0quqifim2", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: OBJ ls -R ./ ("rclone-test-giyaxij1karimew0lahisah7", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: Purge object "potato3"
2020/12/12 06:02:31 DEBUG : potato3: rm sj://rclone-test-giyaxij1karimew0lahisah7/potato3
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: Purge object "empty space"
2020/12/12 06:02:31 DEBUG : empty space: rm sj://rclone-test-giyaxij1karimew0lahisah7/empty space
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: Purge object "potato2"
2020/12/12 06:02:31 DEBUG : potato2: rm sj://rclone-test-giyaxij1karimew0lahisah7/potato2
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: Purge dir ""
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-giyaxij1karimew0lahisah7: rmdir ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: OBJ ls -R ./ ("rclone-test-wubacud8yowuxin0quqifim2", "")
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: Purge dir ""
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-wubacud8yowuxin0quqifim2: rmdir ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:31 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
--- PASS: TestServerSideMove (2.41s)
=== RUN   TestServerSideMoveWithFilter
    run.go:176: Remote "FS sj://rclone-test-tebejad2jenihus4jafuhez2", Local "Local file system at /tmp/rclone126100379", Modify Window "1ns"
2020/12/12 06:02:32 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-metebaz7sejobis7ruhufev1"
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: connecting...
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: connected: <nil>
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./potato2 # [] 60
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./empty space # [] 1
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./potato3 # [] 68
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
    sync_test.go:1294: Server side move (if possible) FS sj://rclone-test-tebejad2jenihus4jafuhez2 -> FS sj://rclone-test-metebaz7sejobis7ruhufev1
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: mkdir -p ./
2020/12/12 06:02:32 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: cp input ./empty space # [] 1
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: cp input ./potato3 # [] 60
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: ls -R ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: OBJ ls -R ./ ("rclone-test-metebaz7sejobis7ruhufev1", "")
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: ls ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: OBJ ls ./ ("rclone-test-metebaz7sejobis7ruhufev1", "")
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:33 DEBUG : empty space: Excluded
2020/12/12 06:02:33 DEBUG : empty space: Excluded
2020/12/12 06:02:33 DEBUG : potato2: cat sj://rclone-test-tebejad2jenihus4jafuhez2/potato2 # [HashesOption([])]
2020/12/12 06:02:33 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:33 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2020/12/12 06:02:33 DEBUG : potato3: cat sj://rclone-test-tebejad2jenihus4jafuhez2/potato3 # [HashesOption([])]
2020/12/12 06:02:33 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: Waiting for checks to finish
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: Waiting for transfers to finish
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:33 DEBUG : potato3: cp input ./potato3 [HashesOption([])]
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:33 INFO  : potato2: Copied (new)
2020/12/12 06:02:33 DEBUG : potato2: rm sj://rclone-test-tebejad2jenihus4jafuhez2/potato2
2020/12/12 06:02:33 INFO  : potato2: Deleted
2020/12/12 06:02:33 INFO  : potato3: Copied (replaced existing)
2020/12/12 06:02:33 DEBUG : potato3: rm sj://rclone-test-tebejad2jenihus4jafuhez2/potato3
2020/12/12 06:02:33 INFO  : potato3: Deleted
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: ls -R ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: OBJ ls -R ./ ("rclone-test-metebaz7sejobis7ruhufev1", "")
2020/12/12 06:02:33 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-kayukag9bidiqap7peyatuv8"
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: connecting...
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: connected: <nil>
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: ls ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: OBJ ls ./ ("rclone-test-metebaz7sejobis7ruhufev1", "")
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: ls ./
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: OBJ ls ./ ("rclone-test-kayukag9bidiqap7peyatuv8", "")
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:33 DEBUG : empty space: Excluded
2020/12/12 06:02:33 DEBUG : potato2: cat sj://rclone-test-metebaz7sejobis7ruhufev1/potato2 # [HashesOption([])]
2020/12/12 06:02:33 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:33 DEBUG : potato3: cat sj://rclone-test-metebaz7sejobis7ruhufev1/potato3 # [HashesOption([])]
2020/12/12 06:02:33 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: Waiting for checks to finish
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: Waiting for transfers to finish
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:33 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:34 ERROR : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: cp input ./potato3 [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:64
	storj.io/uplink.(*Upload).Abort:162
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put.func1:548
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put:577
	github.com/rclone/rclone/fs/operations.Copy:468
	github.com/rclone/rclone/fs/operations.Move:593
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:388
2020/12/12 06:02:34 ERROR : potato3: Failed to copy: uplink: bucket: metainfo error: unable to create bucket
2020/12/12 06:02:34 ERROR : potato3: Not deleting source as copy failed: uplink: bucket: metainfo error: unable to create bucket
2020/12/12 06:02:34 ERROR : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: cp input ./potato2 [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:64
	storj.io/uplink.(*Upload).Abort:162
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put.func1:548
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put:581
	github.com/rclone/rclone/fs/operations.Copy:468
	github.com/rclone/rclone/fs/operations.Move:593
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:388
2020/12/12 06:02:34 DEBUG : potato2: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2020/12/12 06:02:34 DEBUG : potato2: cat sj://rclone-test-metebaz7sejobis7ruhufev1/potato2 # [HashesOption([])]
2020/12/12 06:02:34 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:34 INFO  : potato2: Copied (new)
2020/12/12 06:02:34 DEBUG : potato2: rm sj://rclone-test-metebaz7sejobis7ruhufev1/potato2
2020/12/12 06:02:34 INFO  : potato2: Deleted
    sync_test.go:1331: 
        	Error Trace:	sync_test.go:1331
        	            				sync_test.go:1413
        	Error:      	Received unexpected error:
        	            	uplink: bucket: metainfo error: unable to create bucket
        	Test:       	TestServerSideMoveWithFilter
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: ls -R ./
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: OBJ ls -R ./ ("rclone-test-kayukag9bidiqap7peyatuv8", "")
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: Purge object "potato2"
2020/12/12 06:02:34 DEBUG : potato2: rm sj://rclone-test-kayukag9bidiqap7peyatuv8/potato2
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: Purge dir ""
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-kayukag9bidiqap7peyatuv8: rmdir ./
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: ls -R ./
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: OBJ ls -R ./ ("rclone-test-metebaz7sejobis7ruhufev1", "")
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: Purge object "potato3"
2020/12/12 06:02:34 DEBUG : potato3: rm sj://rclone-test-metebaz7sejobis7ruhufev1/potato3
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: Purge object "empty space"
2020/12/12 06:02:34 DEBUG : empty space: rm sj://rclone-test-metebaz7sejobis7ruhufev1/empty space
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: Purge dir ""
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-metebaz7sejobis7ruhufev1: rmdir ./
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:34 DEBUG : empty space: rm sj://rclone-test-tebejad2jenihus4jafuhez2/empty space
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:34 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
--- FAIL: TestServerSideMoveWithFilter (3.17s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:176: Remote "FS sj://rclone-test-tebejad2jenihus4jafuhez2", Local "Local file system at /tmp/rclone126100379", Modify Window "1ns"
2020/12/12 06:02:35 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-nehuhuj4gegaloh9faquwum8"
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: connecting...
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: connected: <nil>
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./potato2 # [] 60
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./empty space # [] 1
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: cp input ./potato3 # [] 68
2020/12/12 06:02:35 DEBUG : tomatoDir: Making directory
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: mkdir -p ./tomatoDir
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:35 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
    sync_test.go:1294: Server side move (if possible) FS sj://rclone-test-tebejad2jenihus4jafuhez2 -> FS sj://rclone-test-nehuhuj4gegaloh9faquwum8
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: mkdir -p ./
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: cp input ./empty space # [] 1
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: cp input ./potato3 # [] 60
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls -R ./
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls -R ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls ./
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls ./
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:36 DEBUG : potato2: cat sj://rclone-test-tebejad2jenihus4jafuhez2/potato2 # [HashesOption([])]
2020/12/12 06:02:36 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:36 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ns)
2020/12/12 06:02:36 DEBUG : empty space: Unchanged skipping
2020/12/12 06:02:36 DEBUG : empty space: rm sj://rclone-test-tebejad2jenihus4jafuhez2/empty space
2020/12/12 06:02:36 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2020/12/12 06:02:36 DEBUG : potato3: cat sj://rclone-test-tebejad2jenihus4jafuhez2/potato3 # [HashesOption([])]
2020/12/12 06:02:36 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: Waiting for checks to finish
2020/12/12 06:02:36 DEBUG : potato3: cp input ./potato3 [HashesOption([])]
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:36 INFO  : empty space: Deleted
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: Waiting for transfers to finish
2020/12/12 06:02:36 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:36 INFO  : potato3: Copied (replaced existing)
2020/12/12 06:02:36 DEBUG : potato3: rm sj://rclone-test-tebejad2jenihus4jafuhez2/potato3
2020/12/12 06:02:36 INFO  : potato3: Deleted
2020/12/12 06:02:37 INFO  : potato2: Copied (new)
2020/12/12 06:02:37 DEBUG : potato2: rm sj://rclone-test-tebejad2jenihus4jafuhez2/potato2
2020/12/12 06:02:37 INFO  : potato2: Deleted
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls -R ./
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls -R ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:37 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-finiyiw0hegisut2yezatab0"
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: connecting...
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: connected: <nil>
2020/12/12 06:02:37 DEBUG : tomatoDir: Making directory
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: mkdir -p ./tomatoDir
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: ls ./
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: OBJ ls ./ ("rclone-test-finiyiw0hegisut2yezatab0", "")
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls ./
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2020/12/12 06:02:37 DEBUG : empty space: cat sj://rclone-test-nehuhuj4gegaloh9faquwum8/empty space # [HashesOption([])]
2020/12/12 06:02:37 DEBUG : empty space: range 0 + -1
2020/12/12 06:02:37 DEBUG : potato3: cat sj://rclone-test-nehuhuj4gegaloh9faquwum8/potato3 # [HashesOption([])]
2020/12/12 06:02:37 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:37 DEBUG : potato2: cat sj://rclone-test-nehuhuj4gegaloh9faquwum8/potato2 # [HashesOption([])]
2020/12/12 06:02:37 DEBUG : potato2: range 0 + -1
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: Waiting for checks to finish
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: Waiting for transfers to finish
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./empty space # [HashesOption([])] 1
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./potato2 # [HashesOption([])] 60
2020/12/12 06:02:37 ERROR : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./potato3 [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:64
	storj.io/uplink.(*Upload).Abort:162
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put.func1:548
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put:581
	github.com/rclone/rclone/fs/operations.Copy:468
	github.com/rclone/rclone/fs/operations.Move:593
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:388
2020/12/12 06:02:37 DEBUG : potato3: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2020/12/12 06:02:37 DEBUG : potato3: cat sj://rclone-test-nehuhuj4gegaloh9faquwum8/potato3 # [HashesOption([])]
2020/12/12 06:02:37 DEBUG : potato3: range 0 + -1
2020/12/12 06:02:37 ERROR : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./empty space [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:64
	storj.io/uplink.(*Upload).Abort:162
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put.func1:548
	github.com/rclone/rclone/backend/tardigrade.(*Fs).Put:581
	github.com/rclone/rclone/fs/operations.Copy:468
	github.com/rclone/rclone/fs/operations.Move:593
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:388
2020/12/12 06:02:37 DEBUG : empty space: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2020/12/12 06:02:37 DEBUG : empty space: cat sj://rclone-test-nehuhuj4gegaloh9faquwum8/empty space # [HashesOption([])]
2020/12/12 06:02:37 DEBUG : empty space: range 0 + -1
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./empty space # [HashesOption([])] 1
2020/12/12 06:02:37 INFO  : potato2: Copied (new)
2020/12/12 06:02:37 DEBUG : potato2: rm sj://rclone-test-nehuhuj4gegaloh9faquwum8/potato2
2020/12/12 06:02:37 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: cp input ./potato3 # [HashesOption([])] 68
2020/12/12 06:02:37 INFO  : potato2: Deleted
2020/12/12 06:02:37 INFO  : empty space: Copied (new)
2020/12/12 06:02:37 DEBUG : empty space: rm sj://rclone-test-nehuhuj4gegaloh9faquwum8/empty space
2020/12/12 06:02:37 INFO  : empty space: Deleted
2020/12/12 06:02:38 INFO  : potato3: Copied (new)
2020/12/12 06:02:38 DEBUG : potato3: rm sj://rclone-test-nehuhuj4gegaloh9faquwum8/potato3
2020/12/12 06:02:38 INFO  : potato3: Deleted
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: OBJ ls -R ./ ("rclone-test-finiyiw0hegisut2yezatab0", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls -R ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls -R ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: OBJ ls -R ./ ("rclone-test-finiyiw0hegisut2yezatab0", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: Purge object "potato3"
2020/12/12 06:02:38 DEBUG : potato3: rm sj://rclone-test-finiyiw0hegisut2yezatab0/potato3
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: Purge object "potato2"
2020/12/12 06:02:38 DEBUG : potato2: rm sj://rclone-test-finiyiw0hegisut2yezatab0/potato2
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: Purge object "empty space"
2020/12/12 06:02:38 DEBUG : empty space: rm sj://rclone-test-finiyiw0hegisut2yezatab0/empty space
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: Purge dir ""
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-finiyiw0hegisut2yezatab0: rmdir ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: OBJ ls -R ./ ("rclone-test-nehuhuj4gegaloh9faquwum8", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: Purge dir ""
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-nehuhuj4gegaloh9faquwum8: rmdir ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (3.43s)
FAIL
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: ls -R ./
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: OBJ ls -R ./ ("rclone-test-tebejad2jenihus4jafuhez2", "")
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: Purge dir ""
2020/12/12 06:02:38 DEBUG : FS sj://rclone-test-tebejad2jenihus4jafuhez2: rmdir ./
"./sync.test -test.v -test.timeout 1h0m0s -remote TestTardigrade: -verbose -test.run '^(TestServerSideMove|TestServerSideMoveDeleteEmptySourceDirs|TestServerSideMoveWithFilter)$'" - Finished ERROR in 9.224896375s (try 2/5): exit status 1: Failed [TestServerSideMoveWithFilter]