"./sync.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestServerSideMove|TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors)$'" - Starting (try 2/5)
2021/06/01 05:39:29 DEBUG : Creating backend with remote "TestDropbox:rclone-test-jafucis2voleval5museyov4"
2021/06/01 05:39:29 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/06/01 05:39:29 DEBUG : Creating backend with remote "/tmp/rclone779897196"
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
    run.go:176: Remote "Dropbox root 'rclone-test-jafucis2voleval5museyov4'", Local "Local file system at /tmp/rclone779897196", Modify Window "1s"
2021/06/01 05:39:31 DEBUG : b/potato: Uploading chunk 1/1
2021/06/01 05:39:31 DEBUG : b/potato: Uploading chunk 2/1
2021/06/01 05:39:32 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Adding "/rclone-test-jafucis2voleval5museyov4/b/potato" to batch
2021/06/01 05:39:32 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Batch idle for 500ms so committing
2021/06/01 05:39:32 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committing sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/b/potato
2021/06/01 05:39:33 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:39:33 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:39:34 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:39:34 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committed sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/b/potato
2021/06/01 05:39:35 DEBUG : c/non empty space: Uploading chunk 1/1
2021/06/01 05:39:35 DEBUG : c/non empty space: Uploading chunk 2/1
2021/06/01 05:39:36 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Adding "/rclone-test-jafucis2voleval5museyov4/c/non empty space" to batch
2021/06/01 05:39:37 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Batch idle for 500ms so committing
2021/06/01 05:39:37 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committing sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/c/non empty space
2021/06/01 05:39:37 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:39:38 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:39:38 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:39:39 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:39:40 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:39:41 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/06/01 05:39:42 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/06/01 05:39:43 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/06/01 05:39:45 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/06/01 05:39:46 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committed sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/c/non empty space
2021/06/01 05:39:46 DEBUG : d: Making directory
2021/06/01 05:39:49 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2021/06/01 05:39:49 DEBUG : c/non empty space: Unchanged skipping
2021/06/01 05:39:49 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Waiting for checks to finish
2021/06/01 05:39:49 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Waiting for transfers to finish
2021/06/01 05:39:49 DEBUG : a/potato2: Uploading chunk 1/1
2021/06/01 05:39:50 DEBUG : a/potato2: Uploading chunk 2/1
2021/06/01 05:39:51 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Adding "/rclone-test-jafucis2voleval5museyov4/a/potato2" to batch
2021/06/01 05:39:51 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Batch idle for 500ms so committing
2021/06/01 05:39:51 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committing sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/a/potato2
2021/06/01 05:39:52 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:39:52 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:39:53 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:39:53 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:39:54 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:39:56 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/06/01 05:39:57 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committed sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/a/potato2
2021/06/01 05:39:57 DEBUG : a/potato2: dropbox = a979481df794fed9c3990a6a422e0b1044ac802c15fab13af9c687f8bdbee01a OK
2021/06/01 05:39:57 INFO  : a/potato2: Copied (new)
2021/06/01 05:39:57 ERROR : Dropbox root 'rclone-test-jafucis2voleval5museyov4': not deleting files as there were IO errors
2021/06/01 05:39:57 ERROR : Dropbox root 'rclone-test-jafucis2voleval5museyov4': not deleting directories as there were IO errors
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (36.98s)
=== RUN   TestServerSideMove
    run.go:176: Remote "Dropbox root 'rclone-test-jafucis2voleval5museyov4'", Local "Local file system at /tmp/rclone779897196", Modify Window "1s"
2021/06/01 05:40:06 DEBUG : Creating backend with remote "TestDropbox:rclone-test-rexopun2feracid1dosapex9"
2021/06/01 05:40:07 DEBUG : potato2: Uploading chunk 1/1
2021/06/01 05:40:08 DEBUG : potato2: Uploading chunk 2/1
2021/06/01 05:40:09 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Adding "/rclone-test-jafucis2voleval5museyov4/potato2" to batch
2021/06/01 05:40:10 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Batch idle for 500ms so committing
2021/06/01 05:40:10 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committing sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/potato2
2021/06/01 05:40:10 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:40:11 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:40:11 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:40:12 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:40:13 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:40:14 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/06/01 05:40:15 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/06/01 05:40:16 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/06/01 05:40:18 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committed sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/potato2
2021/06/01 05:40:19 DEBUG : empty space: Uploading chunk 1/1
2021/06/01 05:40:19 DEBUG : empty space: Uploading chunk 2/1
2021/06/01 05:40:20 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Adding "/rclone-test-jafucis2voleval5museyov4/empty space" to batch
2021/06/01 05:40:21 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Batch idle for 500ms so committing
2021/06/01 05:40:21 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committing sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/empty space
2021/06/01 05:40:21 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:40:22 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:40:22 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:40:23 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:40:24 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:40:25 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/06/01 05:40:26 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/06/01 05:40:27 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/06/01 05:40:28 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/06/01 05:40:30 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committed sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/empty space
2021/06/01 05:40:31 DEBUG : potato3: Uploading chunk 1/1
2021/06/01 05:40:31 DEBUG : potato3: Uploading chunk 2/1
2021/06/01 05:40:32 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Adding "/rclone-test-jafucis2voleval5museyov4/potato3" to batch
2021/06/01 05:40:33 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Batch idle for 500ms so committing
2021/06/01 05:40:33 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committing sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/potato3
2021/06/01 05:40:33 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:40:34 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:40:34 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:40:35 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:40:36 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:40:37 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/06/01 05:40:38 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/06/01 05:40:39 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Committed sync batch length 1 starting with: /rclone-test-jafucis2voleval5museyov4/potato3
    sync_test.go:1245: Server side move (if possible) Dropbox root 'rclone-test-jafucis2voleval5museyov4' -> Dropbox root 'rclone-test-rexopun2feracid1dosapex9'
2021/06/01 05:40:41 DEBUG : empty space: Uploading chunk 1/1
2021/06/01 05:40:42 DEBUG : empty space: Uploading chunk 2/1
2021/06/01 05:40:43 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Adding "/rclone-test-rexopun2feracid1dosapex9/empty space" to batch
2021/06/01 05:40:44 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Batch idle for 500ms so committing
2021/06/01 05:40:44 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Committing sync batch length 1 starting with: /rclone-test-rexopun2feracid1dosapex9/empty space
2021/06/01 05:40:44 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:40:45 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:40:45 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:40:46 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:40:47 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:40:48 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/06/01 05:40:49 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/06/01 05:40:50 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Committed sync batch length 1 starting with: /rclone-test-rexopun2feracid1dosapex9/empty space
2021/06/01 05:40:51 DEBUG : potato3: Uploading chunk 1/1
2021/06/01 05:40:51 DEBUG : potato3: Uploading chunk 2/1
2021/06/01 05:40:52 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Adding "/rclone-test-rexopun2feracid1dosapex9/potato3" to batch
2021/06/01 05:40:52 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Batch idle for 500ms so committing
2021/06/01 05:40:52 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Committing sync batch length 1 starting with: /rclone-test-rexopun2feracid1dosapex9/potato3
2021/06/01 05:40:53 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/06/01 05:40:53 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/06/01 05:40:54 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/06/01 05:40:54 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/06/01 05:40:55 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/06/01 05:40:57 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Committed sync batch length 1 starting with: /rclone-test-rexopun2feracid1dosapex9/potato3
2021/06/01 05:40:57 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Using server-side directory move
2021/06/01 05:40:57 INFO  : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2021/06/01 05:40:58 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/06/01 05:40:58 DEBUG : empty space: Unchanged skipping
2021/06/01 05:40:58 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2021/06/01 05:40:58 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Waiting for checks to finish
2021/06/01 05:40:58 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/..)
2021/06/01 05:40:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2021/06/01 05:40:58 INFO  : empty space: Deleted
2021/06/01 05:40:58 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Waiting for transfers to finish
2021/06/01 05:40:59 DEBUG : pacer: Reducing sleep to 15ms
2021/06/01 05:40:59 INFO  : potato3: Deleted
2021/06/01 05:40:59 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/..)
2021/06/01 05:40:59 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2021/06/01 05:41:00 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/...)
2021/06/01 05:41:00 DEBUG : pacer: Rate limited, increasing sleep to 60ms
2021/06/01 05:41:00 DEBUG : pacer: Reducing sleep to 45ms
2021/06/01 05:41:00 INFO  : potato2: Moved (server-side)
2021/06/01 05:41:02 DEBUG : pacer: Reducing sleep to 33.75ms
2021/06/01 05:41:02 INFO  : potato3: Moved (server-side)
2021/06/01 05:41:02 INFO  : There was nothing to transfer
2021/06/01 05:41:02 DEBUG : pacer: Reducing sleep to 25.3125ms
2021/06/01 05:41:02 DEBUG : Creating backend with remote "TestDropbox:rclone-test-budubat4jefuxul5voyixix6"
2021/06/01 05:41:02 DEBUG : Dropbox root 'rclone-test-budubat4jefuxul5voyixix6': Using server-side directory move
2021/06/01 05:41:04 INFO  : Dropbox root 'rclone-test-budubat4jefuxul5voyixix6': Server side directory move succeeded
2021/06/01 05:41:05 DEBUG : pacer: Reducing sleep to 18.984375ms
2021/06/01 05:41:05 ERROR : : error listing: directory not found
2021/06/01 05:41:05 DEBUG : Dropbox root 'rclone-test-budubat4jefuxul5voyixix6': Purge remote
2021/06/01 05:41:06 DEBUG : Dropbox root 'rclone-test-rexopun2feracid1dosapex9': Purge remote
2021/06/01 05:41:06 DEBUG : pacer: Reducing sleep to 14.238281ms
2021/06/01 05:41:06 purge failed: path_lookup/not_found/.
--- PASS: TestServerSideMove (60.12s)
PASS
2021/06/01 05:41:06 DEBUG : Dropbox root 'rclone-test-jafucis2voleval5museyov4': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestServerSideMove|TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors)$'" - Finished OK in 1m38.645116342s (try 2/5)