"./sync.test -test.v -test.timeout 1h0m0s -remote TestTardigrade: -verbose -test.run '^TestServerSideMove$'" - Starting (try 2/5)
2021/07/25 06:03:29 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-qomohod8sowaruv0zaducus5"
2021/07/25 06:03:29 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/07/25 06:03:29 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: connecting...
2021/07/25 06:03:29 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: connected: <nil>
2021/07/25 06:03:29 DEBUG : Creating backend with remote "/tmp/rclone938504126"
=== RUN   TestServerSideMove
    run.go:176: Remote "FS sj://rclone-test-qomohod8sowaruv0zaducus5", Local "Local file system at /tmp/rclone938504126", Modify Window "1ns"
2021/07/25 06:03:29 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-zifuzos3ramiseq9hobefup2"
2021/07/25 06:03:29 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: connecting...
2021/07/25 06:03:29 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: connected: <nil>
2021/07/25 06:03:29 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: mkdir -p ./
2021/07/25 06:03:29 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: cp input ./potato2 # [] 60
2021/07/25 06:03:30 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: cp input ./empty space # [] 1
2021/07/25 06:03:30 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: cp input ./potato3 # [] 68
2021/07/25 06:03:30 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: ls -R ./
2021/07/25 06:03:30 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: OBJ ls -R ./ ("rclone-test-qomohod8sowaruv0zaducus5", "")
    sync_test.go:1245: Server side move (if possible) FS sj://rclone-test-qomohod8sowaruv0zaducus5 -> FS sj://rclone-test-zifuzos3ramiseq9hobefup2
2021/07/25 06:03:30 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: mkdir -p ./
2021/07/25 06:03:30 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: cp input ./empty space # [] 1
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: cp input ./potato3 # [] 60
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: ls -R ./
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: OBJ ls -R ./ ("rclone-test-zifuzos3ramiseq9hobefup2", "")
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: ls ./
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: OBJ ls ./ ("rclone-test-zifuzos3ramiseq9hobefup2", "")
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: ls ./
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: OBJ ls ./ ("rclone-test-qomohod8sowaruv0zaducus5", "")
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2021/07/25 06:03:31 DEBUG : potato2: cat sj://rclone-test-qomohod8sowaruv0zaducus5/potato2 # [HashesOption([])]
2021/07/25 06:03:31 DEBUG : potato2: range 0 + -1
2021/07/25 06:03:31 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ns)
2021/07/25 06:03:31 DEBUG : empty space: Unchanged skipping
2021/07/25 06:03:31 DEBUG : empty space: rm sj://rclone-test-qomohod8sowaruv0zaducus5/empty space
2021/07/25 06:03:31 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2021/07/25 06:03:31 DEBUG : potato3: cat sj://rclone-test-qomohod8sowaruv0zaducus5/potato3 # [HashesOption([])]
2021/07/25 06:03:31 DEBUG : potato3: range 0 + -1
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: Waiting for checks to finish
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: cp input ./potato2 # [HashesOption([])] 60
2021/07/25 06:03:31 INFO  : potato2: Copied (new)
2021/07/25 06:03:31 DEBUG : potato2: rm sj://rclone-test-qomohod8sowaruv0zaducus5/potato2
2021/07/25 06:03:31 INFO  : potato2: Deleted
2021/07/25 06:03:31 INFO  : empty space: Deleted
2021/07/25 06:03:31 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: Waiting for transfers to finish
2021/07/25 06:03:32 DEBUG : potato3: cp input ./potato3 [HashesOption([])]
2021/07/25 06:03:32 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: cp input ./potato3 # [HashesOption([])] 68
2021/07/25 06:03:33 INFO  : potato3: Copied (replaced existing)
2021/07/25 06:03:33 DEBUG : potato3: rm sj://rclone-test-qomohod8sowaruv0zaducus5/potato3
2021/07/25 06:03:33 INFO  : potato3: Deleted
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: ls -R ./
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: OBJ ls -R ./ ("rclone-test-qomohod8sowaruv0zaducus5", "")
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: ls -R ./
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: OBJ ls -R ./ ("rclone-test-zifuzos3ramiseq9hobefup2", "")
2021/07/25 06:03:33 DEBUG : Creating backend with remote "TestTardigrade:rclone-test-bocujan8xibapoc2hifahut6"
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: connecting...
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: connected: <nil>
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: ls ./
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: OBJ ls ./ ("rclone-test-bocujan8xibapoc2hifahut6", "")
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: ls ./
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: OBJ ls ./ ("rclone-test-zifuzos3ramiseq9hobefup2", "")
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: opts &{Prefix: Cursor: Recursive:false System:true Custom:true}
2021/07/25 06:03:33 DEBUG : empty space: cat sj://rclone-test-zifuzos3ramiseq9hobefup2/empty space # [HashesOption([])]
2021/07/25 06:03:33 DEBUG : empty space: range 0 + -1
2021/07/25 06:03:33 DEBUG : potato2: cat sj://rclone-test-zifuzos3ramiseq9hobefup2/potato2 # [HashesOption([])]
2021/07/25 06:03:33 DEBUG : potato2: range 0 + -1
2021/07/25 06:03:33 DEBUG : potato3: cat sj://rclone-test-zifuzos3ramiseq9hobefup2/potato3 # [HashesOption([])]
2021/07/25 06:03:33 DEBUG : potato3: range 0 + -1
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: Waiting for checks to finish
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: Waiting for transfers to finish
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./empty space # [HashesOption([])] 1
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./potato3 # [HashesOption([])] 68
2021/07/25 06:03:33 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./potato2 # [HashesOption([])] 60
2021/07/25 06:03:34 ERROR : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./potato2 [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:79
	storj.io/uplink.(*Upload).Abort:160
	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:472
	github.com/rclone/rclone/fs/operations.Move:620
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:398
2021/07/25 06:03:34 DEBUG : potato2: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2021/07/25 06:03:34 DEBUG : potato2: cat sj://rclone-test-zifuzos3ramiseq9hobefup2/potato2 # [HashesOption([])]
2021/07/25 06:03:34 DEBUG : potato2: range 0 + -1
2021/07/25 06:03:34 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./potato2 # [HashesOption([])] 60
2021/07/25 06:03:34 INFO  : potato3: Copied (new)
2021/07/25 06:03:34 DEBUG : potato3: rm sj://rclone-test-zifuzos3ramiseq9hobefup2/potato3
2021/07/25 06:03:34 ERROR : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./empty space [HashesOption([])]: uplink: upload done: already committed
	storj.io/uplink.errwrapf:79
	storj.io/uplink.(*Upload).Abort:160
	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:472
	github.com/rclone/rclone/fs/operations.Move:620
	github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove:398
2021/07/25 06:03:34 DEBUG : empty space: Received error: bucket was not available, now created, the upload must be retried - low level retry 1/10
2021/07/25 06:03:34 DEBUG : empty space: cat sj://rclone-test-zifuzos3ramiseq9hobefup2/empty space # [HashesOption([])]
2021/07/25 06:03:34 DEBUG : empty space: range 0 + -1
2021/07/25 06:03:34 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: cp input ./empty space # [HashesOption([])] 1
2021/07/25 06:03:34 INFO  : potato2: Copied (new)
2021/07/25 06:03:34 DEBUG : potato2: rm sj://rclone-test-zifuzos3ramiseq9hobefup2/potato2
2021/07/25 06:03:34 INFO  : potato2: Deleted
2021/07/25 06:03:34 INFO  : potato3: Deleted
2021/07/25 06:03:35 INFO  : empty space: Copied (new)
2021/07/25 06:03:35 DEBUG : empty space: rm sj://rclone-test-zifuzos3ramiseq9hobefup2/empty space
2021/07/25 06:03:35 INFO  : empty space: Deleted
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: ls -R ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: OBJ ls -R ./ ("rclone-test-bocujan8xibapoc2hifahut6", "")
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: ls -R ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: OBJ ls -R ./ ("rclone-test-zifuzos3ramiseq9hobefup2", "")
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: ls -R ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: OBJ ls -R ./ ("rclone-test-bocujan8xibapoc2hifahut6", "")
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: Purge object "potato2"
2021/07/25 06:03:35 DEBUG : potato2: rm sj://rclone-test-bocujan8xibapoc2hifahut6/potato2
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: Purge object "potato3"
2021/07/25 06:03:35 DEBUG : potato3: rm sj://rclone-test-bocujan8xibapoc2hifahut6/potato3
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: Purge object "empty space"
2021/07/25 06:03:35 DEBUG : empty space: rm sj://rclone-test-bocujan8xibapoc2hifahut6/empty space
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: Purge dir ""
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-bocujan8xibapoc2hifahut6: rmdir ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: ls -R ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: OBJ ls -R ./ ("rclone-test-zifuzos3ramiseq9hobefup2", "")
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: Purge dir ""
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-zifuzos3ramiseq9hobefup2: rmdir ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: ls -R ./
2021/07/25 06:03:35 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: OBJ ls -R ./ ("rclone-test-qomohod8sowaruv0zaducus5", "")
2021/07/25 06:03:36 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: ls -R ./
2021/07/25 06:03:36 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: OBJ ls -R ./ ("rclone-test-qomohod8sowaruv0zaducus5", "")
--- PASS: TestServerSideMove (6.91s)
PASS
2021/07/25 06:03:36 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: ls -R ./
2021/07/25 06:03:36 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: OBJ ls -R ./ ("rclone-test-qomohod8sowaruv0zaducus5", "")
2021/07/25 06:03:36 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: Purge dir ""
2021/07/25 06:03:36 DEBUG : FS sj://rclone-test-qomohod8sowaruv0zaducus5: rmdir ./
"./sync.test -test.v -test.timeout 1h0m0s -remote TestTardigrade: -verbose -test.run '^TestServerSideMove$'" - Finished OK in 7.120320708s (try 2/5)