"./operations.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestCopyFileCopyDest|TestListDirSorted|TestRmdirsNoLeaveRoot)$'" - Starting (try 2/5)
2025/07/02 01:30:06 DEBUG : Creating backend with remote "TestDropbox:rclone-test-kamasor3babo"
2025/07/02 01:30:06 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/07/02 01:30:06 DEBUG : Creating backend with remote "/tmp/rclone3569106799"
=== RUN   TestCopyFileCopyDest
    run.go:180: Remote "Dropbox root 'rclone-test-kamasor3babo'", Local "Local file system at /tmp/rclone3569106799", Modify Window "1s"
2025/07/02 01:30:06 DEBUG : Creating backend with remote "TestDropbox:rclone-test-kamasor3babo/dst"
2025/07/02 01:30:07 DEBUG : Creating backend with remote "TestDropbox:rclone-test-kamasor3babo/CopyDest"
2025/07/02 01:30:07 DEBUG : one: Need to transfer - File not found at Destination
2025/07/02 01:30:08 DEBUG : one: Uploading chunk 1/1
2025/07/02 01:30:08 DEBUG : one: Uploading chunk 2/1
2025/07/02 01:30:09 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Adding "one" to batch
2025/07/02 01:30:09 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Batch idle for 500ms so committing
2025/07/02 01:30:09 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Committing sync batch length 1 starting with: one
2025/07/02 01:30:10 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Committed sync batch length 1 starting with: one
2025/07/02 01:30:10 DEBUG : one: dropbox = fe8d7a873dc48961a6af334c996b2cb3ce37149d5ce9c9253952a54c6a92c1ad OK
2025/07/02 01:30:10 INFO  : one: Copied (new)
2025/07/02 01:30:13 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/07/02 01:30:14 DEBUG : one: Uploading chunk 1/1
2025/07/02 01:30:14 DEBUG : one: Uploading chunk 2/1
2025/07/02 01:30:15 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Adding "one" to batch
2025/07/02 01:30:15 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Batch idle for 500ms so committing
2025/07/02 01:30:15 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Committing sync batch length 1 starting with: one
2025/07/02 01:30:17 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Committed sync batch length 1 starting with: one
2025/07/02 01:30:17 DEBUG : one: dropbox = 7da8d117f9fb226817d81adc15c72720c9879c8b7fb821d27f217d198bd79d0d OK
2025/07/02 01:30:17 INFO  : one: Copied (replaced existing)
2025/07/02 01:30:18 DEBUG : dst/one: Uploading chunk 1/1
2025/07/02 01:30:18 DEBUG : dst/one: Uploading chunk 2/1
2025/07/02 01:30:19 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "dst/one" to batch
2025/07/02 01:30:20 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:20 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: dst/one
2025/07/02 01:30:21 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: dst/one
2025/07/02 01:30:21 DEBUG : CopyDest/one: Uploading chunk 1/1
2025/07/02 01:30:21 DEBUG : CopyDest/one: Uploading chunk 2/1
2025/07/02 01:30:21 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "CopyDest/one" to batch
2025/07/02 01:30:22 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:22 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: CopyDest/one
2025/07/02 01:30:23 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: CopyDest/one
2025/07/02 01:30:23 DEBUG : Creating backend with remote "TestDropbox:rclone-test-kamasor3babo/BackupDir"
2025/07/02 01:30:24 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/07/02 01:30:24 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/07/02 01:30:24 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/07/02 01:30:26 INFO  : one: Moved (server-side)
2025/07/02 01:30:26 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/.)
2025/07/02 01:30:26 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/07/02 01:30:27 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/)
2025/07/02 01:30:27 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/07/02 01:30:28 DEBUG : pacer: Reducing sleep to 30ms
2025/07/02 01:30:28 DEBUG : one: dropbox = 7da8d117f9fb226817d81adc15c72720c9879c8b7fb821d27f217d198bd79d0d OK
2025/07/02 01:30:28 INFO  : one: Copied (server-side copy)
2025/07/02 01:30:28 DEBUG : one: Destination found in --copy-dest, using server-side copy
2025/07/02 01:30:28 DEBUG : CopyDest/two: Uploading chunk 1/1
2025/07/02 01:30:29 DEBUG : CopyDest/two: Uploading chunk 2/1
2025/07/02 01:30:29 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "CopyDest/two" to batch
2025/07/02 01:30:30 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:30 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: CopyDest/two
2025/07/02 01:30:30 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: CopyDest/two
2025/07/02 01:30:31 DEBUG : pacer: Reducing sleep to 22.5ms
2025/07/02 01:30:31 DEBUG : two: Need to transfer - File not found at Destination
2025/07/02 01:30:32 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/07/02 01:30:32 DEBUG : pacer: Reducing sleep to 16.875ms
2025/07/02 01:30:33 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/07/02 01:30:33 DEBUG : two: dropbox = 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8 OK
2025/07/02 01:30:33 INFO  : two: Copied (server-side copy)
2025/07/02 01:30:33 DEBUG : two: Destination found in --copy-dest, using server-side copy
2025/07/02 01:30:34 DEBUG : pacer: Reducing sleep to 10ms
2025/07/02 01:30:34 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/07/02 01:30:34 DEBUG : two: Unchanged skipping
2025/07/02 01:30:35 DEBUG : CopyDest/three: Uploading chunk 1/1
2025/07/02 01:30:35 DEBUG : CopyDest/three: Uploading chunk 2/1
2025/07/02 01:30:35 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "CopyDest/three" to batch
2025/07/02 01:30:36 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:36 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: CopyDest/three
2025/07/02 01:30:37 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: CopyDest/three
2025/07/02 01:30:37 DEBUG : three: Need to transfer - File not found at Destination
2025/07/02 01:30:38 DEBUG : three: Sizes differ (src 7 vs dst 5)
2025/07/02 01:30:38 DEBUG : three: Destination not found in --copy-dest
2025/07/02 01:30:38 DEBUG : three: Uploading chunk 1/1
2025/07/02 01:30:38 DEBUG : three: Uploading chunk 2/1
2025/07/02 01:30:39 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Adding "three" to batch
2025/07/02 01:30:39 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Batch idle for 500ms so committing
2025/07/02 01:30:39 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Committing sync batch length 1 starting with: three
2025/07/02 01:30:40 DEBUG : Dropbox root 'rclone-test-kamasor3babo/dst': Committed sync batch length 1 starting with: three
2025/07/02 01:30:40 DEBUG : three: dropbox = 78af7ad260025156e50fd9648fd9a36509cd3541c9a8d02597e9b3c598937cbd OK
2025/07/02 01:30:40 INFO  : three: Copied (new)
2025/07/02 01:30:50 INFO  : Dropbox root 'rclone-test-kamasor3babo/CopyDest': Committing uploads - please wait...
2025/07/02 01:30:50 INFO  : Dropbox root 'rclone-test-kamasor3babo/BackupDir': Committing uploads - please wait...
--- PASS: TestCopyFileCopyDest (44.09s)
=== RUN   TestListDirSorted
    run.go:180: Remote "Dropbox root 'rclone-test-kamasor3babo'", Local "Local file system at /tmp/rclone3569106799", Modify Window "1s"
2025/07/02 01:30:51 DEBUG : a.txt: Uploading chunk 1/1
2025/07/02 01:30:51 DEBUG : a.txt: Uploading chunk 2/1
2025/07/02 01:30:51 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "a.txt" to batch
2025/07/02 01:30:52 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:52 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: a.txt
2025/07/02 01:30:53 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: a.txt
2025/07/02 01:30:53 DEBUG : zend.txt: Uploading chunk 1/1
2025/07/02 01:30:53 DEBUG : zend.txt: Uploading chunk 2/1
2025/07/02 01:30:54 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "zend.txt" to batch
2025/07/02 01:30:54 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:54 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: zend.txt
2025/07/02 01:30:55 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: zend.txt
2025/07/02 01:30:55 DEBUG : sub dir/hello world: Uploading chunk 1/1
2025/07/02 01:30:56 DEBUG : sub dir/hello world: Uploading chunk 2/1
2025/07/02 01:30:56 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "sub dir/hello world" to batch
2025/07/02 01:30:57 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:57 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: sub dir/hello world
2025/07/02 01:30:57 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: sub dir/hello world
2025/07/02 01:30:58 DEBUG : sub dir/hello world2: Uploading chunk 1/1
2025/07/02 01:30:58 DEBUG : sub dir/hello world2: Uploading chunk 2/1
2025/07/02 01:30:59 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "sub dir/hello world2" to batch
2025/07/02 01:30:59 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:30:59 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: sub dir/hello world2
2025/07/02 01:31:00 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: sub dir/hello world2
2025/07/02 01:31:00 DEBUG : sub dir/ignore dir/.ignore: Uploading chunk 1/1
2025/07/02 01:31:01 DEBUG : sub dir/ignore dir/.ignore: Uploading chunk 2/1
2025/07/02 01:31:01 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "sub dir/ignore dir/.ignore" to batch
2025/07/02 01:31:02 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:31:02 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: sub dir/ignore dir/.ignore
2025/07/02 01:31:03 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: sub dir/ignore dir/.ignore
2025/07/02 01:31:03 DEBUG : sub dir/ignore dir/should be ignored: Uploading chunk 1/1
2025/07/02 01:31:03 DEBUG : sub dir/ignore dir/should be ignored: Uploading chunk 2/1
2025/07/02 01:31:04 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "sub dir/ignore dir/should be ignored" to batch
2025/07/02 01:31:04 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:31:04 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: sub dir/ignore dir/should be ignored
2025/07/02 01:31:05 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: sub dir/ignore dir/should be ignored
2025/07/02 01:31:06 DEBUG : sub dir/sub sub dir/hello world3: Uploading chunk 1/1
2025/07/02 01:31:06 DEBUG : sub dir/sub sub dir/hello world3: Uploading chunk 2/1
2025/07/02 01:31:07 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "sub dir/sub sub dir/hello world3" to batch
2025/07/02 01:31:07 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:31:07 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: sub dir/sub sub dir/hello world3
2025/07/02 01:31:08 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: sub dir/sub sub dir/hello world3
2025/07/02 01:31:09 DEBUG : a.txt: Excluded (Size Filter)
2025/07/02 01:31:09 DEBUG : a.txt: Excluded
2025/07/02 01:31:09 DEBUG : sub dir/hello world: Excluded (Size Filter)
2025/07/02 01:31:09 DEBUG : sub dir/hello world: Excluded
2025/07/02 01:31:09 DEBUG : sub dir/hello world2: Excluded (Size Filter)
2025/07/02 01:31:09 DEBUG : sub dir/hello world2: Excluded
2025/07/02 01:31:10 DEBUG : sub dir/ignore dir: Excluded
2025/07/02 01:31:10 DEBUG : sub dir/hello world: Excluded (Size Filter)
2025/07/02 01:31:10 DEBUG : sub dir/hello world: Excluded
2025/07/02 01:31:10 DEBUG : sub dir/hello world2: Excluded (Size Filter)
2025/07/02 01:31:10 DEBUG : sub dir/hello world2: Excluded
2025/07/02 01:31:10 DEBUG : sub dir/ignore dir: Excluded
--- PASS: TestListDirSorted (29.35s)
=== RUN   TestRmdirsNoLeaveRoot
    run.go:180: Remote "Dropbox root 'rclone-test-kamasor3babo'", Local "Local file system at /tmp/rclone3569106799", Modify Window "1s"
2025/07/02 01:31:20 DEBUG : A1/B1/C1/one: Uploading chunk 1/1
2025/07/02 01:31:21 DEBUG : A1/B1/C1/one: Uploading chunk 2/1
2025/07/02 01:31:21 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "A1/B1/C1/one" to batch
2025/07/02 01:31:22 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:31:22 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: A1/B1/C1/one
2025/07/02 01:31:23 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: A1/B1/C1/one
2025/07/02 01:31:23 INFO  : A2: Making directory
2025/07/02 01:31:24 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/.)
2025/07/02 01:31:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/07/02 01:31:24 DEBUG : pacer: Reducing sleep to 15ms
2025/07/02 01:31:24 INFO  : A1/B2: Making directory
2025/07/02 01:31:25 DEBUG : pacer: Reducing sleep to 11.25ms
2025/07/02 01:31:25 DEBUG : pacer: Reducing sleep to 10ms
2025/07/02 01:31:25 INFO  : A1/B2/C2: Making directory
2025/07/02 01:31:26 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/...)
2025/07/02 01:31:26 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/07/02 01:31:26 DEBUG : pacer: Reducing sleep to 15ms
2025/07/02 01:31:26 INFO  : A1/B1/C3: Making directory
2025/07/02 01:31:26 DEBUG : pacer: Reducing sleep to 11.25ms
2025/07/02 01:31:27 DEBUG : pacer: Reducing sleep to 10ms
2025/07/02 01:31:27 INFO  : A3: Making directory
2025/07/02 01:31:28 INFO  : A3/B3: Making directory
2025/07/02 01:31:28 INFO  : A3/B3/C4: Making directory
2025/07/02 01:31:30 DEBUG : A1/two: Uploading chunk 1/1
2025/07/02 01:31:30 DEBUG : A1/two: Uploading chunk 2/1
2025/07/02 01:31:30 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Adding "A1/two" to batch
2025/07/02 01:31:31 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Batch idle for 500ms so committing
2025/07/02 01:31:31 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committing sync batch length 1 starting with: A1/two
2025/07/02 01:31:31 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Committed sync batch length 1 starting with: A1/two
2025/07/02 01:31:33 DEBUG : removing 1 level 3 directories
2025/07/02 01:31:33 INFO  : A3/B3/C4: Removing directory
2025/07/02 01:31:36 DEBUG : removing 2 level 3 directories
2025/07/02 01:31:36 INFO  : A1/B2/C2: Removing directory
2025/07/02 01:31:36 INFO  : A1/B1/C3: Removing directory
2025/07/02 01:31:37 DEBUG : removing 2 level 2 directories
2025/07/02 01:31:37 INFO  : A3/B3: Removing directory
2025/07/02 01:31:37 INFO  : A1/B2: Removing directory
2025/07/02 01:31:39 DEBUG : removing 2 level 1 directories
2025/07/02 01:31:39 INFO  : A3: Removing directory
2025/07/02 01:31:39 INFO  : A2: Removing directory
2025/07/02 01:31:44 DEBUG : removing 1 level 3 directories
2025/07/02 01:31:44 INFO  : A1/B1/C1: Removing directory
2025/07/02 01:31:46 DEBUG : removing 1 level 2 directories
2025/07/02 01:31:46 INFO  : A1/B1: Removing directory
2025/07/02 01:31:47 DEBUG : removing 1 level 1 directories
2025/07/02 01:31:47 INFO  : A1: Removing directory
2025/07/02 01:31:49 DEBUG : removing 1 level 0 directories
2025/07/02 01:31:49 INFO  : Dropbox root 'rclone-test-kamasor3babo': Removing directory
2025/07/02 01:31:51 ERROR : error listing: directory not found
2025/07/02 01:31:51 ERROR : error listing: directory not found
--- PASS: TestRmdirsNoLeaveRoot (31.14s)
PASS
2025/07/02 01:31:51 DEBUG : Dropbox root 'rclone-test-kamasor3babo': Purge remote
2025/07/02 01:31:51 NOTICE: purge failed: path_lookup/not_found/
"./operations.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestCopyFileCopyDest|TestListDirSorted|TestRmdirsNoLeaveRoot)$'" - Finished OK in 1m45.181230246s (try 2/5)