"./operations.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^TestCopyFileCopyDest$'" - Starting (try 5/5)
2021/07/25 05:22:36 DEBUG : Creating backend with remote "TestDropbox:rclone-test-mozuteb6raticuj9zayawuv1"
2021/07/25 05:22:36 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/07/25 05:22:36 DEBUG : Creating backend with remote "/tmp/rclone121459069"
=== RUN   TestCopyFileCopyDest
    run.go:176: Remote "Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1'", Local "Local file system at /tmp/rclone121459069", Modify Window "1s"
2021/07/25 05:22:36 DEBUG : Creating backend with remote "TestDropbox:rclone-test-mozuteb6raticuj9zayawuv1/dst"
2021/07/25 05:22:36 DEBUG : Creating backend with remote "TestDropbox:rclone-test-mozuteb6raticuj9zayawuv1/CopyDest"
2021/07/25 05:22:37 DEBUG : one: Need to transfer - File not found at Destination
2021/07/25 05:22:37 DEBUG : one: Uploading chunk 1/1
2021/07/25 05:22:38 DEBUG : one: Uploading chunk 2/1
2021/07/25 05:22:38 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/dst/one" to batch
2021/07/25 05:22:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Batch idle for 500ms so committing
2021/07/25 05:22:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/one
2021/07/25 05:22:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:22:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:22:40 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:22:40 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:22:41 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:22:42 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:22:43 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 05:22:44 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 05:22:46 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 05:22:47 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 10/120
2021/07/25 05:22:48 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/one
2021/07/25 05:22:48 DEBUG : one: dropbox = fe8d7a873dc48961a6af334c996b2cb3ce37149d5ce9c9253952a54c6a92c1ad OK
2021/07/25 05:22:48 INFO  : one: Copied (new)
2021/07/25 05:22:49 DEBUG : one: Sizes differ (src 5 vs dst 3)
2021/07/25 05:22:49 DEBUG : one: Uploading chunk 1/1
2021/07/25 05:22:49 DEBUG : one: Uploading chunk 2/1
2021/07/25 05:22:50 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/dst/one" to batch
2021/07/25 05:22:51 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Batch idle for 500ms so committing
2021/07/25 05:22:51 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/one
2021/07/25 05:22:51 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:22:51 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:22:51 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:22:52 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:22:53 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:22:54 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:22:55 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/one
2021/07/25 05:22:55 DEBUG : one: dropbox = 7da8d117f9fb226817d81adc15c72720c9879c8b7fb821d27f217d198bd79d0d OK
2021/07/25 05:22:55 INFO  : one: Copied (replaced existing)
2021/07/25 05:22:56 DEBUG : dst/one: Uploading chunk 1/1
2021/07/25 05:22:56 DEBUG : dst/one: Uploading chunk 2/1
2021/07/25 05:22:57 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/dst/one" to batch
2021/07/25 05:22:57 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Batch idle for 500ms so committing
2021/07/25 05:22:57 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/one
2021/07/25 05:22:57 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:22:58 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:22:58 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:22:58 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:22:59 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:23:01 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:23:02 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 05:23:03 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 05:23:04 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 05:23:05 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 10/120
2021/07/25 05:23:06 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 11/120
2021/07/25 05:23:07 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 12/120
2021/07/25 05:23:08 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/one
2021/07/25 05:23:09 DEBUG : CopyDest/one: Uploading chunk 1/1
2021/07/25 05:23:09 DEBUG : CopyDest/one: Uploading chunk 2/1
2021/07/25 05:23:09 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/one" to batch
2021/07/25 05:23:10 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Batch idle for 500ms so committing
2021/07/25 05:23:10 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/one
2021/07/25 05:23:10 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:23:10 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:23:11 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:23:11 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:23:12 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:23:13 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:23:14 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 05:23:16 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 05:23:17 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 05:23:18 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 10/120
2021/07/25 05:23:19 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/one
2021/07/25 05:23:19 DEBUG : Creating backend with remote "TestDropbox:rclone-test-mozuteb6raticuj9zayawuv1/BackupDir"
2021/07/25 05:23:19 DEBUG : Config file has changed externaly - reloading
2021/07/25 05:23:20 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2021/07/25 05:23:20 DEBUG : one: Sizes differ (src 5 vs dst 3)
2021/07/25 05:23:22 INFO  : one: Moved (server-side)
2021/07/25 05:23:23 DEBUG : one: dropbox = 7da8d117f9fb226817d81adc15c72720c9879c8b7fb821d27f217d198bd79d0d OK
2021/07/25 05:23:23 INFO  : one: Copied (server-side copy)
2021/07/25 05:23:23 DEBUG : one: Destination found in --copy-dest, using server-side copy
2021/07/25 05:23:24 DEBUG : CopyDest/two: Uploading chunk 1/1
2021/07/25 05:23:24 DEBUG : CopyDest/two: Uploading chunk 2/1
2021/07/25 05:23:25 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/two" to batch
2021/07/25 05:23:25 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Batch idle for 500ms so committing
2021/07/25 05:23:25 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/two
2021/07/25 05:23:26 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:23:26 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:23:26 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:23:27 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:23:28 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:23:29 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:23:30 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 05:23:31 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 05:23:32 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 05:23:33 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 10/120
2021/07/25 05:23:34 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/two
2021/07/25 05:23:35 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2021/07/25 05:23:36 DEBUG : two: dropbox = 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8 OK
2021/07/25 05:23:36 INFO  : two: Copied (server-side copy)
2021/07/25 05:23:36 DEBUG : two: Destination found in --copy-dest, using server-side copy
2021/07/25 05:23:37 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2021/07/25 05:23:37 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2021/07/25 05:23:37 DEBUG : two: Unchanged skipping
2021/07/25 05:23:37 DEBUG : CopyDest/three: Uploading chunk 1/1
2021/07/25 05:23:38 DEBUG : CopyDest/three: Uploading chunk 2/1
2021/07/25 05:23:38 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/three" to batch
2021/07/25 05:23:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Batch idle for 500ms so committing
2021/07/25 05:23:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/three
2021/07/25 05:23:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:23:39 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:23:40 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:23:40 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:23:41 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:23:42 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:23:43 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 05:23:44 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 05:23:46 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 05:23:47 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 10/120
2021/07/25 05:23:48 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Wait for batch: sleeping for 1s after status: "in_progress": try 11/120
2021/07/25 05:23:49 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/CopyDest/three
2021/07/25 05:23:50 DEBUG : three: Sizes differ (src 7 vs dst 5)
2021/07/25 05:23:50 DEBUG : three: Destination not found in --copy-dest
2021/07/25 05:23:50 DEBUG : three: Need to transfer - File not found at Destination
2021/07/25 05:23:50 DEBUG : three: Uploading chunk 1/1
2021/07/25 05:23:51 DEBUG : three: Uploading chunk 2/1
2021/07/25 05:23:51 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Adding "/rclone-test-mozuteb6raticuj9zayawuv1/dst/three" to batch
2021/07/25 05:23:52 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Batch idle for 500ms so committing
2021/07/25 05:23:52 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Committing sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/three
2021/07/25 05:23:52 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 05:23:52 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 05:23:52 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 05:23:53 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 05:23:54 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 05:23:55 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 05:23:56 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 05:23:57 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1/dst': Committed sync batch length 1 starting with: /rclone-test-mozuteb6raticuj9zayawuv1/dst/three
2021/07/25 05:23:57 DEBUG : three: dropbox = 78af7ad260025156e50fd9648fd9a36509cd3541c9a8d02597e9b3c598937cbd OK
2021/07/25 05:23:57 INFO  : three: Copied (new)
--- PASS: TestCopyFileCopyDest (94.21s)
PASS
2021/07/25 05:24:10 DEBUG : Dropbox root 'rclone-test-mozuteb6raticuj9zayawuv1': Purge remote
"./operations.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^TestCopyFileCopyDest$'" - Finished OK in 1m35.383763759s (try 5/5)