"./operations.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestCopyFileCopyDest|TestCopyFileMaxTransfer|TestLsWithFilesFrom)$'" - Starting (try 2/5)
2026/01/16 02:26:55 DEBUG : Creating backend with remote "TestDropbox:rclone-test-fuvavew2lupo"
2026/01/16 02:26:55 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/01/16 02:26:55 DEBUG : Creating backend with remote "/tmp/rclone3459532720"
=== RUN   TestCopyFileCopyDest
    run.go:185: Remote "Dropbox root 'rclone-test-fuvavew2lupo'", Local "Local file system at /tmp/rclone3459532720", Modify Window "1s"
2026/01/16 02:26:55 DEBUG : Creating backend with remote "TestDropbox:rclone-test-fuvavew2lupo/dst"
2026/01/16 02:26:55 DEBUG : Creating backend with remote "TestDropbox:rclone-test-fuvavew2lupo/CopyDest"
2026/01/16 02:26:56 DEBUG : one: Need to transfer - File not found at Destination
2026/01/16 02:26:56 DEBUG : one: Uploading chunk 1/1
2026/01/16 02:26:57 DEBUG : one: Uploading chunk 2/1
2026/01/16 02:26:57 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Adding "one" to batch
2026/01/16 02:26:58 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Batch idle for 500ms so committing
2026/01/16 02:26:58 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Committing sync batch length 1 starting with: one
2026/01/16 02:26:58 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Committed sync batch length 1 starting with: one
2026/01/16 02:26:58 DEBUG : one: size = 3 OK
2026/01/16 02:26:58 DEBUG : one: dropbox = fe8d7a873dc48961a6af334c996b2cb3ce37149d5ce9c9253952a54c6a92c1ad OK
2026/01/16 02:26:58 INFO  : one: Copied (new)
2026/01/16 02:27:00 DEBUG : one: size = 5 (Local file system at /tmp/rclone3459532720)
2026/01/16 02:27:00 DEBUG : one: size = 3 (Dropbox root 'rclone-test-fuvavew2lupo/dst')
2026/01/16 02:27:00 DEBUG : one: Sizes differ
2026/01/16 02:27:00 DEBUG : one: Uploading chunk 1/1
2026/01/16 02:27:00 DEBUG : one: Uploading chunk 2/1
2026/01/16 02:27:01 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Adding "one" to batch
2026/01/16 02:27:01 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Batch idle for 500ms so committing
2026/01/16 02:27:01 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Committing sync batch length 1 starting with: one
2026/01/16 02:27:02 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Committed sync batch length 1 starting with: one
2026/01/16 02:27:02 DEBUG : one: size = 5 OK
2026/01/16 02:27:02 DEBUG : one: dropbox = 7da8d117f9fb226817d81adc15c72720c9879c8b7fb821d27f217d198bd79d0d OK
2026/01/16 02:27:02 INFO  : one: Copied (replaced existing)
2026/01/16 02:27:06 DEBUG : dst/one: Uploading chunk 1/1
2026/01/16 02:27:07 DEBUG : dst/one: Uploading chunk 2/1
2026/01/16 02:27:07 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "dst/one" to batch
2026/01/16 02:27:07 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:27:07 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: dst/one
2026/01/16 02:27:08 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: dst/one
2026/01/16 02:27:09 DEBUG : CopyDest/one: Uploading chunk 1/1
2026/01/16 02:27:09 DEBUG : CopyDest/one: Uploading chunk 2/1
2026/01/16 02:27:10 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "CopyDest/one" to batch
2026/01/16 02:27:10 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:27:10 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: CopyDest/one
2026/01/16 02:27:11 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: CopyDest/one
2026/01/16 02:27:12 DEBUG : Creating backend with remote "TestDropbox:rclone-test-fuvavew2lupo/BackupDir"
2026/01/16 02:27:12 DEBUG : one: size = 5 (Local file system at /tmp/rclone3459532720)
2026/01/16 02:27:12 DEBUG : one: size = 3 (Dropbox root 'rclone-test-fuvavew2lupo/dst')
2026/01/16 02:27:12 DEBUG : one: Sizes differ
2026/01/16 02:27:12 DEBUG : one: size = 5 OK
2026/01/16 02:27:12 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/01/16 02:27:12 DEBUG : one: size = 5 (Local file system at /tmp/rclone3459532720)
2026/01/16 02:27:12 DEBUG : one: size = 3 (Dropbox root 'rclone-test-fuvavew2lupo/dst')
2026/01/16 02:27:12 DEBUG : one: Sizes differ
2026/01/16 02:27:14 INFO  : one: Moved (server-side)
2026/01/16 02:27:15 DEBUG : one: size = 5 OK
2026/01/16 02:27:15 DEBUG : one: dropbox = 7da8d117f9fb226817d81adc15c72720c9879c8b7fb821d27f217d198bd79d0d OK
2026/01/16 02:27:15 INFO  : one: Copied (server-side copy)
2026/01/16 02:27:15 DEBUG : one: Destination found in --copy-dest, using server-side copy
2026/01/16 02:27:16 DEBUG : CopyDest/two: Uploading chunk 1/1
2026/01/16 02:27:16 DEBUG : CopyDest/two: Uploading chunk 2/1
2026/01/16 02:27:17 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "CopyDest/two" to batch
2026/01/16 02:27:17 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:27:17 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: CopyDest/two
2026/01/16 02:27:18 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: CopyDest/two
2026/01/16 02:27:18 DEBUG : two: Need to transfer - File not found at Destination
2026/01/16 02:27:19 DEBUG : two: size = 3 OK
2026/01/16 02:27:19 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/01/16 02:27:20 DEBUG : two: size = 3 OK
2026/01/16 02:27:20 DEBUG : two: dropbox = 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8 OK
2026/01/16 02:27:20 INFO  : two: Copied (server-side copy)
2026/01/16 02:27:20 DEBUG : two: Destination found in --copy-dest, using server-side copy
2026/01/16 02:27:20 DEBUG : two: size = 3 OK
2026/01/16 02:27:20 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/01/16 02:27:20 DEBUG : two: Unchanged skipping
2026/01/16 02:27:22 DEBUG : CopyDest/three: Uploading chunk 1/1
2026/01/16 02:27:22 DEBUG : CopyDest/three: Uploading chunk 2/1
2026/01/16 02:27:22 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "CopyDest/three" to batch
2026/01/16 02:27:23 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:27:23 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: CopyDest/three
2026/01/16 02:27:23 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: CopyDest/three
2026/01/16 02:27:25 DEBUG : three: Need to transfer - File not found at Destination
2026/01/16 02:27:26 DEBUG : three: size = 7 (Local file system at /tmp/rclone3459532720)
2026/01/16 02:27:26 DEBUG : three: size = 5 (Dropbox root 'rclone-test-fuvavew2lupo/CopyDest')
2026/01/16 02:27:26 DEBUG : three: Sizes differ
2026/01/16 02:27:26 DEBUG : three: Destination not found in --copy-dest
2026/01/16 02:27:27 DEBUG : three: Uploading chunk 1/1
2026/01/16 02:27:27 DEBUG : three: Uploading chunk 2/1
2026/01/16 02:27:27 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Adding "three" to batch
2026/01/16 02:27:28 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Batch idle for 500ms so committing
2026/01/16 02:27:28 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Committing sync batch length 1 starting with: three
2026/01/16 02:27:28 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo/dst': Committed sync batch length 1 starting with: three
2026/01/16 02:27:28 DEBUG : three: size = 7 OK
2026/01/16 02:27:28 DEBUG : three: dropbox = 78af7ad260025156e50fd9648fd9a36509cd3541c9a8d02597e9b3c598937cbd OK
2026/01/16 02:27:28 INFO  : three: Copied (new)
2026/01/16 02:27:37 INFO  : Dropbox root 'rclone-test-fuvavew2lupo/CopyDest': Committing uploads - please wait...
2026/01/16 02:27:37 INFO  : Dropbox root 'rclone-test-fuvavew2lupo/BackupDir': Committing uploads - please wait...
--- PASS: TestCopyFileCopyDest (41.80s)
=== RUN   TestCopyFileMaxTransfer
    run.go:185: Remote "Dropbox root 'rclone-test-fuvavew2lupo'", Local "Local file system at /tmp/rclone3459532720", Modify Window "1s"
2026/01/16 02:27:37 DEBUG : TestCopyFileMaxTransfer/file1: Need to transfer - File not found at Destination
2026/01/16 02:27:37 DEBUG : TestCopyFileMaxTransfer/file1: Uploading chunk 1/1
2026/01/16 02:27:38 DEBUG : TestCopyFileMaxTransfer/file1: Uploading chunk 2/1
2026/01/16 02:27:38 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "TestCopyFileMaxTransfer/file1" to batch
2026/01/16 02:27:39 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:27:39 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: TestCopyFileMaxTransfer/file1
2026/01/16 02:27:40 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: TestCopyFileMaxTransfer/file1
2026/01/16 02:27:40 DEBUG : TestCopyFileMaxTransfer/file1: size = 14 OK
2026/01/16 02:27:40 DEBUG : TestCopyFileMaxTransfer/file1: dropbox = d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778 OK
2026/01/16 02:27:40 INFO  : TestCopyFileMaxTransfer/file1: Copied (new)
2026/01/16 02:27:40 DEBUG : TestCopyFileMaxTransfer/file2: Need to transfer - File not found at Destination
2026/01/16 02:27:41 DEBUG : TestCopyFileMaxTransfer/file2: Uploading chunk 1/1
2026/01/16 02:27:41 DEBUG : pacer: low level retry 1/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/01/16 02:27:41 DEBUG : pacer: low level retry 2/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2026/01/16 02:27:41 DEBUG : pacer: low level retry 3/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2026/01/16 02:27:41 DEBUG : pacer: low level retry 4/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2026/01/16 02:27:41 DEBUG : pacer: low level retry 5/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2026/01/16 02:27:41 DEBUG : pacer: low level retry 6/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2026/01/16 02:27:41 DEBUG : pacer: low level retry 7/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:41 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2026/01/16 02:27:42 DEBUG : pacer: low level retry 8/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:42 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/01/16 02:27:43 DEBUG : pacer: low level retry 9/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:45 DEBUG : pacer: low level retry 10/10 (error Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer)
2026/01/16 02:27:45 DEBUG : TestCopyFileMaxTransfer/file2: Received error: upload failed: Post "https://content.dropboxapi.com/2/files/upload_session/append_v2": max transfer limit reached as set by --max-transfer - low level retry 0/10
2026/01/16 02:27:47 DEBUG : pacer: Reducing sleep to 1.5s
2026/01/16 02:27:50 DEBUG : pacer: Reducing sleep to 1.125s
2026/01/16 02:27:51 DEBUG : pacer: Reducing sleep to 843.75ms
2026/01/16 02:27:51 DEBUG : TestCopyFileMaxTransfer/file3: Need to transfer - File not found at Destination
2026/01/16 02:27:52 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/01/16 02:27:53 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/01/16 02:27:53 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/01/16 02:27:53 DEBUG : TestCopyFileMaxTransfer/file4: Need to transfer - File not found at Destination
2026/01/16 02:27:54 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/01/16 02:27:54 DEBUG : TestCopyFileMaxTransfer/file4: Uploading chunk 1/1
2026/01/16 02:27:54 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/01/16 02:27:54 DEBUG : TestCopyFileMaxTransfer/file4: Uploading chunk 2/1
2026/01/16 02:27:55 DEBUG : pacer: Reducing sleep to 150.169371ms
2026/01/16 02:27:55 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "TestCopyFileMaxTransfer/file4" to batch
2026/01/16 02:27:56 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:27:56 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: TestCopyFileMaxTransfer/file4
2026/01/16 02:27:57 DEBUG : pacer: Reducing sleep to 112.627028ms
2026/01/16 02:27:57 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: TestCopyFileMaxTransfer/file4
2026/01/16 02:27:57 DEBUG : TestCopyFileMaxTransfer/file4: size = 2062 OK
2026/01/16 02:27:57 DEBUG : TestCopyFileMaxTransfer/file4: dropbox = a5e74bd2eece1f7da88e61bd337d41d1d9db8287a21d9071aaef47a234d13595 OK
2026/01/16 02:27:57 INFO  : TestCopyFileMaxTransfer/file4: Copied (new)
2026/01/16 02:27:58 DEBUG : pacer: Reducing sleep to 84.470271ms
2026/01/16 02:27:58 DEBUG : pacer: Reducing sleep to 63.352703ms
2026/01/16 02:27:58 DEBUG : pacer: Reducing sleep to 47.514527ms
2026/01/16 02:27:58 DEBUG : pacer: Reducing sleep to 35.635895ms
2026/01/16 02:28:00 DEBUG : pacer: Reducing sleep to 26.726921ms
2026/01/16 02:28:01 DEBUG : pacer: Reducing sleep to 20.04519ms
2026/01/16 02:28:01 DEBUG : pacer: Reducing sleep to 15.033892ms
2026/01/16 02:28:01 DEBUG : pacer: Reducing sleep to 11.275419ms
2026/01/16 02:28:02 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestCopyFileMaxTransfer (25.31s)
=== RUN   TestLsWithFilesFrom
    run.go:185: Remote "Dropbox root 'rclone-test-fuvavew2lupo'", Local "Local file system at /tmp/rclone3459532720", Modify Window "1s"
2026/01/16 02:28:02 DEBUG : potato2: Uploading chunk 1/1
2026/01/16 02:28:03 DEBUG : potato2: Uploading chunk 2/1
2026/01/16 02:28:03 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "potato2" to batch
2026/01/16 02:28:04 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:28:04 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: potato2
2026/01/16 02:28:04 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: potato2
2026/01/16 02:28:05 DEBUG : empty space: Uploading chunk 1/1
2026/01/16 02:28:05 DEBUG : empty space: Uploading chunk 2/1
2026/01/16 02:28:06 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Adding "empty space" to batch
2026/01/16 02:28:06 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Batch idle for 500ms so committing
2026/01/16 02:28:06 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committing sync batch length 1 starting with: empty space
2026/01/16 02:28:07 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Committed sync batch length 1 starting with: empty space
2026/01/16 02:28:07 DEBUG : empty space: Excluded (FilesFrom Filter)
2026/01/16 02:28:07 DEBUG : empty space: Excluded
--- PASS: TestLsWithFilesFrom (6.87s)
PASS
2026/01/16 02:28:09 DEBUG : Dropbox root 'rclone-test-fuvavew2lupo': Purge remote
"./operations.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestCopyFileCopyDest|TestCopyFileMaxTransfer|TestLsWithFilesFrom)$'" - Finished OK in 1m14.914342521s (try 2/5)