"./sync.test -test.v -test.timeout 1h0m0s -remote TestB2: -list-retries 5 -verbose -test.run '^(TestMoveWithDeleteEmptySrcDirs|TestServerSideCopy|TestServerSideCopyOverSelf|TestServerSideMove|TestServerSideMoveDeleteEmptySourceDirs|TestServerSideMoveOverSelf|TestServerSideMoveWithFilter|TestSyncAfterChangingModtimeOnly|TestSyncWithTrackRenames|TestSyncWithTrackRenamesStrategyLeaf|TestSyncWithTrackRenamesStrategyModtime)$'" - Starting (try 4/5) 2025/11/01 02:16:18 DEBUG : Creating backend with remote "TestB2:rclone-test-yozubez8sulu" 2025/11/01 02:16:18 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/11/01 02:16:19 DEBUG : Creating backend with remote "/tmp/rclone1714971057" === RUN TestServerSideCopy run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:21 DEBUG : Creating backend with remote "TestB2:rclone-test-nacoxot9xoyi" sync_test.go:620: Server side copy (if possible) B2 bucket rclone-test-yozubez8sulu -> B2 bucket rclone-test-nacoxot9xoyi 2025/11/01 02:16:22 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/11/01 02:16:22 DEBUG : B2 bucket rclone-test-nacoxot9xoyi: Waiting for checks to finish 2025/11/01 02:16:22 DEBUG : B2 bucket rclone-test-nacoxot9xoyi: Waiting for transfers to finish 2025/11/01 02:16:22 ERROR : sub dir/hello world: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) sync_test.go:624: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:624 Error: Received unexpected error: expected a FileSseMode but found: '' (400 bad_request) Test: TestServerSideCopy 2025/11/01 02:16:22 DEBUG : B2 bucket rclone-test-nacoxot9xoyi: Purge remote 2025/11/01 02:16:22 INFO : B2 bucket rclone-test-nacoxot9xoyi: cleaning bucket "rclone-test-nacoxot9xoyi" of all files --- FAIL: TestServerSideCopy (4.77s) === RUN TestServerSideCopyOverSelf run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:24 DEBUG : Creating backend with remote "TestB2:rclone-test-diroxeh8luri" sync_test.go:656: Server side copy (if possible) B2 bucket rclone-test-yozubez8sulu -> B2 bucket rclone-test-diroxeh8luri 2025/11/01 02:16:25 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/11/01 02:16:25 DEBUG : B2 bucket rclone-test-diroxeh8luri: Waiting for checks to finish 2025/11/01 02:16:25 DEBUG : B2 bucket rclone-test-diroxeh8luri: Waiting for transfers to finish 2025/11/01 02:16:26 ERROR : sub dir/hello world: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) sync_test.go:660: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:660 Error: Received unexpected error: expected a FileSseMode but found: '' (400 bad_request) Test: TestServerSideCopyOverSelf 2025/11/01 02:16:26 DEBUG : B2 bucket rclone-test-diroxeh8luri: Purge remote 2025/11/01 02:16:26 INFO : B2 bucket rclone-test-diroxeh8luri: cleaning bucket "rclone-test-diroxeh8luri" of all files --- FAIL: TestServerSideCopyOverSelf (3.80s) === RUN TestServerSideMoveOverSelf run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:28 DEBUG : Creating backend with remote "TestB2:rclone-test-huheyeg3qote" 2025/11/01 02:16:29 DEBUG : pacer: low level retry 1/10 (error incident id 3894aee67876-50313fc1c9a15fb5 (500 internal_error)) 2025/11/01 02:16:29 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/11/01 02:16:29 DEBUG : pacer: low level retry 2/10 (error incident id 3894aee67876-d768b1aa667933dd (500 internal_error)) 2025/11/01 02:16:29 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/11/01 02:16:29 DEBUG : pacer: low level retry 3/10 (error incident id 3894aee67876-8707f7cf9c684896 (500 internal_error)) 2025/11/01 02:16:29 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/11/01 02:16:29 DEBUG : pacer: low level retry 4/10 (error incident id 3894aee67876-c43bdffdd5c89e70 (500 internal_error)) 2025/11/01 02:16:29 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/11/01 02:16:30 DEBUG : pacer: low level retry 5/10 (error incident id 3894aee67876-649a012567bc947b (500 internal_error)) 2025/11/01 02:16:30 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/11/01 02:16:30 DEBUG : pacer: low level retry 6/10 (error incident id 3894aee67876-d0ed71816742a9f6 (500 internal_error)) 2025/11/01 02:16:30 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/11/01 02:16:30 DEBUG : pacer: low level retry 7/10 (error incident id 3894aee67876-686ed38f3827de67 (500 internal_error)) 2025/11/01 02:16:30 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/11/01 02:16:31 DEBUG : pacer: low level retry 8/10 (error incident id 3894aee67876-2073a4ab6a6cf936 (500 internal_error)) 2025/11/01 02:16:31 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2025/11/01 02:16:32 DEBUG : pacer: low level retry 9/10 (error incident id 3894aee67876-f1d240a38eab4e03 (500 internal_error)) 2025/11/01 02:16:32 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2025/11/01 02:16:35 DEBUG : pacer: low level retry 10/10 (error incident id 3894aee67876-09db5fc2c36480cb (500 internal_error)) 2025/11/01 02:16:35 DEBUG : pacer: Rate limited, increasing sleep to 10.24s sync_test.go:699: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:699 Error: Received unexpected error: failed to authorize account: failed to authenticate: incident id 3894aee67876-09db5fc2c36480cb (500 internal_error) Test: TestServerSideMoveOverSelf --- FAIL: TestServerSideMoveOverSelf (8.10s) === RUN TestSyncAfterChangingModtimeOnly run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:37 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2025/11/01 02:16:37 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:37 DEBUG : empty space: sha1 = 3bc15c8aae3e4124dd409035f32ea2fd6835efc9 OK 2025/11/01 02:16:37 NOTICE: empty space: Skipped update modification time as --dry-run is set (size 1) 2025/11/01 02:16:37 DEBUG : empty space: Unchanged skipping 2025/11/01 02:16:37 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:37 DEBUG : Waiting for deletions to finish 2025/11/01 02:16:37 INFO : There was nothing to transfer 2025/11/01 02:16:37 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2025/11/01 02:16:37 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:37 DEBUG : empty space: sha1 = 3bc15c8aae3e4124dd409035f32ea2fd6835efc9 OK 2025/11/01 02:16:38 ERROR : empty space: Failed to set modification time: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:38 DEBUG : empty space: Unchanged skipping 2025/11/01 02:16:38 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:38 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting files as there were IO errors 2025/11/01 02:16:38 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting directories as there were IO errors sync_test.go:1033: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1033 Error: Received unexpected error: not deleting files as there were IO errors Test: TestSyncAfterChangingModtimeOnly --- FAIL: TestSyncAfterChangingModtimeOnly (2.67s) === RUN TestSyncWithTrackRenames run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" sync_test.go:1568: Can track renames: true 2025/11/01 02:16:38 INFO : B2 bucket rclone-test-yozubez8sulu: Making map for --track-renames 2025/11/01 02:16:38 INFO : B2 bucket rclone-test-yozubez8sulu: Finished making map for --track-renames 2025/11/01 02:16:38 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:38 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/11/01 02:16:38 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for renames to finish 2025/11/01 02:16:38 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/11/01 02:16:38 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:39 DEBUG : yam: sha1 = ad84b2fb6729688a5ee3225164a6d4d58465b33e OK 2025/11/01 02:16:39 INFO : yam: Copied (new) 2025/11/01 02:16:39 DEBUG : potato: Clearing upload URL because of error: CPU too busy (503 service_unavailable): trying again in 1s 2025/11/01 02:16:39 DEBUG : pacer: low level retry 1/1 (error CPU too busy (503 service_unavailable): trying again in 1s) 2025/11/01 02:16:39 DEBUG : pacer: Rate limited, increasing sleep to 1s 2025/11/01 02:16:39 DEBUG : potato: Received error: CPU too busy (503 service_unavailable): trying again in 1s - low level retry 0/10 2025/11/01 02:16:39 DEBUG : pacer: Reducing sleep to 500ms 2025/11/01 02:16:39 DEBUG : potato: sha1 = 1d1ac61cfffcfdd0a15cc9ae575fb06ca8c11fb5 OK 2025/11/01 02:16:39 INFO : potato: Copied (new) 2025/11/01 02:16:39 DEBUG : Waiting for deletions to finish 2025/11/01 02:16:40 DEBUG : pacer: Reducing sleep to 250ms 2025/11/01 02:16:41 DEBUG : pacer: Reducing sleep to 125ms 2025/11/01 02:16:41 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/11/01 02:16:41 INFO : B2 bucket rclone-test-yozubez8sulu: Making map for --track-renames 2025/11/01 02:16:41 INFO : B2 bucket rclone-test-yozubez8sulu: Finished making map for --track-renames 2025/11/01 02:16:41 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:41 DEBUG : potato: Unchanged skipping 2025/11/01 02:16:41 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for renames to finish 2025/11/01 02:16:41 DEBUG : pacer: Reducing sleep to 62.5ms 2025/11/01 02:16:41 DEBUG : pacer: Reducing sleep to 31.25ms 2025/11/01 02:16:41 ERROR : yam: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:41 ERROR : yam: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:41 DEBUG : yaml: Failed to rename to "yam": expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:41 DEBUG : yaml: Need to transfer - No matching file found at Destination 2025/11/01 02:16:41 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:42 DEBUG : pacer: Reducing sleep to 15.625ms 2025/11/01 02:16:42 DEBUG : yaml: sha1 = ad84b2fb6729688a5ee3225164a6d4d58465b33e OK 2025/11/01 02:16:42 INFO : yaml: Copied (new) 2025/11/01 02:16:42 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting files as there were IO errors 2025/11/01 02:16:42 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting directories as there were IO errors sync_test.go:1586: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1586 Error: Received unexpected error: not deleting files as there were IO errors Test: TestSyncWithTrackRenames 2025/11/01 02:16:42 DEBUG : pacer: Reducing sleep to 10ms --- FAIL: TestSyncWithTrackRenames (4.37s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" sync_test.go:1640: Can track renames: true 2025/11/01 02:16:43 INFO : B2 bucket rclone-test-yozubez8sulu: Making map for --track-renames 2025/11/01 02:16:43 INFO : B2 bucket rclone-test-yozubez8sulu: Finished making map for --track-renames 2025/11/01 02:16:43 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:43 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/11/01 02:16:43 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/11/01 02:16:43 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for renames to finish 2025/11/01 02:16:43 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:43 DEBUG : potato: sha1 = 1d1ac61cfffcfdd0a15cc9ae575fb06ca8c11fb5 OK 2025/11/01 02:16:43 INFO : potato: Copied (new) 2025/11/01 02:16:44 DEBUG : yam: sha1 = ad84b2fb6729688a5ee3225164a6d4d58465b33e OK 2025/11/01 02:16:44 INFO : yam: Copied (new) 2025/11/01 02:16:44 DEBUG : Waiting for deletions to finish 2025/11/01 02:16:44 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/11/01 02:16:44 INFO : B2 bucket rclone-test-yozubez8sulu: Making map for --track-renames 2025/11/01 02:16:44 INFO : B2 bucket rclone-test-yozubez8sulu: Finished making map for --track-renames 2025/11/01 02:16:44 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:44 DEBUG : potato: Unchanged skipping 2025/11/01 02:16:44 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for renames to finish 2025/11/01 02:16:44 ERROR : yam: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:44 ERROR : yam: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:44 DEBUG : yaml: Failed to rename to "yam": expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:44 DEBUG : yaml: Need to transfer - No matching file found at Destination 2025/11/01 02:16:44 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:45 DEBUG : yaml: sha1 = ad84b2fb6729688a5ee3225164a6d4d58465b33e OK 2025/11/01 02:16:45 INFO : yaml: Copied (new) 2025/11/01 02:16:45 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting files as there were IO errors 2025/11/01 02:16:45 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting directories as there were IO errors sync_test.go:1658: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1658 Error: Received unexpected error: not deleting files as there were IO errors Test: TestSyncWithTrackRenamesStrategyModtime --- FAIL: TestSyncWithTrackRenamesStrategyModtime (3.00s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" sync_test.go:1679: Can track renames: true 2025/11/01 02:16:46 INFO : B2 bucket rclone-test-yozubez8sulu: Making map for --track-renames 2025/11/01 02:16:46 INFO : B2 bucket rclone-test-yozubez8sulu: Finished making map for --track-renames 2025/11/01 02:16:46 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:46 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/11/01 02:16:46 DEBUG : sub/yam: Need to transfer - No matching file found at Destination 2025/11/01 02:16:46 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for renames to finish 2025/11/01 02:16:46 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:46 DEBUG : potato: sha1 = 1d1ac61cfffcfdd0a15cc9ae575fb06ca8c11fb5 OK 2025/11/01 02:16:46 INFO : potato: Copied (new) 2025/11/01 02:16:46 DEBUG : sub/yam: sha1 = ad84b2fb6729688a5ee3225164a6d4d58465b33e OK 2025/11/01 02:16:46 INFO : sub/yam: Copied (new) 2025/11/01 02:16:46 DEBUG : Waiting for deletions to finish 2025/11/01 02:16:47 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/11/01 02:16:47 DEBUG : potato: Unchanged skipping 2025/11/01 02:16:47 INFO : B2 bucket rclone-test-yozubez8sulu: Making map for --track-renames 2025/11/01 02:16:47 INFO : B2 bucket rclone-test-yozubez8sulu: Finished making map for --track-renames 2025/11/01 02:16:47 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:47 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for renames to finish 2025/11/01 02:16:47 ERROR : sub/yam: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:47 ERROR : sub/yam: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:47 DEBUG : yam: Failed to rename to "sub/yam": expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:47 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/11/01 02:16:47 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:47 DEBUG : yam: sha1 = ad84b2fb6729688a5ee3225164a6d4d58465b33e OK 2025/11/01 02:16:47 INFO : yam: Copied (new) 2025/11/01 02:16:47 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting files as there were IO errors 2025/11/01 02:16:47 ERROR : B2 bucket rclone-test-yozubez8sulu: not deleting directories as there were IO errors sync_test.go:1697: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1697 Error: Received unexpected error: not deleting files as there were IO errors Test: TestSyncWithTrackRenamesStrategyLeaf --- FAIL: TestSyncWithTrackRenamesStrategyLeaf (2.60s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:48 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/11/01 02:16:48 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/11/01 02:16:48 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for checks to finish 2025/11/01 02:16:48 DEBUG : B2 bucket rclone-test-yozubez8sulu: Waiting for transfers to finish 2025/11/01 02:16:49 DEBUG : nested/sub dir/file: sha1 = b4b3e0a278988bc15f2913af3f4153ccef74e465 OK 2025/11/01 02:16:49 INFO : nested/sub dir/file: Copied (new) 2025/11/01 02:16:49 INFO : nested/sub dir/file: Deleted 2025/11/01 02:16:49 DEBUG : sub dir/hello world: sha1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK 2025/11/01 02:16:49 INFO : sub dir/hello world: Copied (new) 2025/11/01 02:16:49 INFO : sub dir/hello world: Deleted 2025/11/01 02:16:49 ERROR : Local file system at /tmp/rclone1714971057: not deleting directories as there were IO errors sync_test.go:1818: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1818 Error: Received unexpected error: not deleting directories as there were IO errors Test: TestMoveWithDeleteEmptySrcDirs --- FAIL: TestMoveWithDeleteEmptySrcDirs (1.38s) === RUN TestServerSideMove run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:50 DEBUG : Creating backend with remote "TestB2:rclone-test-samegeq8tuxi" sync_test.go:1735: Server side move (if possible) B2 bucket rclone-test-yozubez8sulu -> B2 bucket rclone-test-samegeq8tuxi 2025/11/01 02:16:54 DEBUG : potato2: Need to transfer - File not found at Destination 2025/11/01 02:16:54 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2025/11/01 02:16:54 DEBUG : empty space: Unchanged skipping 2025/11/01 02:16:54 DEBUG : B2 bucket rclone-test-samegeq8tuxi: Waiting for checks to finish 2025/11/01 02:16:54 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/11/01 02:16:54 ERROR : potato2: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:54 ERROR : potato2: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:54 INFO : empty space: Deleted 2025/11/01 02:16:54 DEBUG : B2 bucket rclone-test-samegeq8tuxi: Waiting for transfers to finish 2025/11/01 02:16:54 ERROR : potato3: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:16:54 ERROR : potato3: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) sync_test.go:1746: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1746 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1911 Error: Received unexpected error: expected a FileSseMode but found: '' (400 bad_request) Test: TestServerSideMove 2025/11/01 02:16:54 DEBUG : B2 bucket rclone-test-samegeq8tuxi: Purge remote 2025/11/01 02:16:54 INFO : B2 bucket rclone-test-samegeq8tuxi: cleaning bucket "rclone-test-samegeq8tuxi" of all files 2025/11/01 02:16:54 DEBUG : empty space: Deleting (id "4_z0f620da3304d3bdb9fa80e1b_f101fe7aa9aa085ff_d20251101_m021652_c001_v0001109_t0012_u01761963412918") 2025/11/01 02:16:54 DEBUG : potato3: Deleting (id "4_z0f620da3304d3bdb9fa80e1b_f101fe7aa9aa08601_d20251101_m021653_c001_v0001109_t0027_u01761963413455") --- FAIL: TestServerSideMove (6.17s) === RUN TestServerSideMoveWithFilter run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:16:56 DEBUG : Creating backend with remote "TestB2:rclone-test-dureqel0fuge" 2025/11/01 02:16:56 DEBUG : pacer: low level retry 1/10 (error incident id 3894aee67876-63e314ef946c0742 (500 internal_error)) 2025/11/01 02:16:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/11/01 02:16:56 DEBUG : pacer: low level retry 2/10 (error incident id 3894aee67876-a47fb5261fd0184e (500 internal_error)) 2025/11/01 02:16:56 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/11/01 02:16:57 DEBUG : pacer: low level retry 3/10 (error incident id 3894aee67876-66ec59dc9d9f1542 (500 internal_error)) 2025/11/01 02:16:57 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/11/01 02:16:57 DEBUG : pacer: low level retry 4/10 (error incident id 3894aee67876-eaa67beb5bdc0bf9 (500 internal_error)) 2025/11/01 02:16:57 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/11/01 02:16:57 DEBUG : pacer: low level retry 5/10 (error incident id 3894aee67876-bc751a9ba6eb5ee4 (500 internal_error)) 2025/11/01 02:16:57 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/11/01 02:16:57 DEBUG : pacer: low level retry 6/10 (error incident id 3894aee67876-e066367ac7cf3d77 (500 internal_error)) 2025/11/01 02:16:57 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/11/01 02:16:58 DEBUG : pacer: low level retry 7/10 (error incident id 3894aee67876-de85ee0908a0dbe8 (500 internal_error)) 2025/11/01 02:16:58 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/11/01 02:16:58 DEBUG : pacer: low level retry 8/10 (error incident id 3894aee67876-de1e25928774aa7d (500 internal_error)) 2025/11/01 02:16:58 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2025/11/01 02:16:59 DEBUG : pacer: low level retry 9/10 (error incident id 3894aee67876-645623fe9bbda6e2 (500 internal_error)) 2025/11/01 02:16:59 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2025/11/01 02:17:02 DEBUG : pacer: low level retry 10/10 (error incident id 3894aee67876-6161a910e881c737 (500 internal_error)) 2025/11/01 02:17:02 DEBUG : pacer: Rate limited, increasing sleep to 10.24s sync_test.go:1721: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1721 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1924 Error: Received unexpected error: failed to authorize account: failed to authenticate: incident id 3894aee67876-6161a910e881c737 (500 internal_error) Test: TestServerSideMoveWithFilter --- FAIL: TestServerSideMoveWithFilter (7.06s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:185: Remote "B2 bucket rclone-test-yozubez8sulu", Local "Local file system at /tmp/rclone1714971057", Modify Window "1ms" 2025/11/01 02:17:03 DEBUG : Creating backend with remote "TestB2:rclone-test-docogoy8mayi" 2025/11/01 02:17:05 INFO : tomatoDir: Making directory sync_test.go:1735: Server side move (if possible) B2 bucket rclone-test-yozubez8sulu -> B2 bucket rclone-test-docogoy8mayi 2025/11/01 02:17:08 DEBUG : potato2: Need to transfer - File not found at Destination 2025/11/01 02:17:08 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2025/11/01 02:17:08 DEBUG : empty space: Unchanged skipping 2025/11/01 02:17:08 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/11/01 02:17:08 DEBUG : B2 bucket rclone-test-docogoy8mayi: Waiting for checks to finish 2025/11/01 02:17:08 ERROR : potato2: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:17:08 ERROR : potato2: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:17:08 INFO : empty space: Deleted 2025/11/01 02:17:08 DEBUG : B2 bucket rclone-test-docogoy8mayi: Waiting for transfers to finish 2025/11/01 02:17:08 ERROR : potato3: Failed to copy: expected a FileSseMode but found: '' (400 bad_request) 2025/11/01 02:17:08 ERROR : potato3: Not deleting source as copy failed: expected a FileSseMode but found: '' (400 bad_request) sync_test.go:1746: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1746 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1931 Error: Received unexpected error: expected a FileSseMode but found: '' (400 bad_request) Test: TestServerSideMoveDeleteEmptySourceDirs 2025/11/01 02:17:08 DEBUG : B2 bucket rclone-test-docogoy8mayi: Purge remote 2025/11/01 02:17:08 INFO : B2 bucket rclone-test-docogoy8mayi: cleaning bucket "rclone-test-docogoy8mayi" of all files 2025/11/01 02:17:08 DEBUG : empty space: Deleting (id "4_zdf824d13304d3bdb9fa80e1b_f102480e139a8254a_d20251101_m021707_c001_v0001042_t0049_u01761963427221") 2025/11/01 02:17:08 DEBUG : potato3: Deleting (id "4_zdf824d13304d3bdb9fa80e1b_f102480e139a8254c_d20251101_m021707_c001_v0001042_t0056_u01761963427598") --- FAIL: TestServerSideMoveDeleteEmptySourceDirs (6.94s) FAIL 2025/11/01 02:17:10 DEBUG : B2 bucket rclone-test-yozubez8sulu: Purge remote 2025/11/01 02:17:10 INFO : B2 bucket rclone-test-yozubez8sulu: cleaning bucket "rclone-test-yozubez8sulu" of all files 2025/11/01 02:17:10 DEBUG : empty space: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f41673bf139a838c1_d20251101_m021708_c001_v7007000_t0000_u01761963428395") 2025/11/01 02:17:10 DEBUG : empty space: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a466_d20251101_m021705_c001_v0001183_t0016_u01761963425037") 2025/11/01 02:17:10 DEBUG : empty space: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a3b_d20251101_m021654_c001_v7007000_t0000_u01761963414391") 2025/11/01 02:17:10 DEBUG : empty space: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0c5_d20251101_m021650_c001_v0001130_t0019_u01761963410890") 2025/11/01 02:17:10 DEBUG : empty space: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a29_d20251101_m021638_c001_v7007000_t0000_u01761963398416") 2025/11/01 02:17:10 DEBUG : empty space: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f08e_d20251101_m021636_c001_v0001130_t0025_u01761963396479") 2025/11/01 02:17:10 DEBUG : nested/sub dir/file: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a38_d20251101_m021649_c001_v7007000_t0000_u01761963409584") 2025/11/01 02:17:10 DEBUG : nested/sub dir/file: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a416_d20251101_m021648_c001_v0001183_t0054_u01761963408942") 2025/11/01 02:17:10 DEBUG : potato: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a34_d20251101_m021648_c001_v7007000_t0000_u01761963408024") 2025/11/01 02:17:10 DEBUG : potato: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a402_d20251101_m021646_c001_v0001183_t0051_u01761963406327") 2025/11/01 02:17:10 DEBUG : potato: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a2f_d20251101_m021645_c001_v7007000_t0000_u01761963405418") 2025/11/01 02:17:11 DEBUG : potato: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0ac_d20251101_m021643_c001_v0001130_t0000_u01761963403324") 2025/11/01 02:17:11 DEBUG : potato: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a2a_d20251101_m021642_c001_v7007000_t0000_u01761963402381") 2025/11/01 02:17:11 DEBUG : potato: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0a0_d20251101_m021639_c001_v0001130_t0018_u01761963399689") 2025/11/01 02:17:11 DEBUG : potato2: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f41673bf139a838c7_d20251101_m021709_c001_v7007000_t0000_u01761963429759") 2025/11/01 02:17:11 DEBUG : potato2: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0e1_d20251101_m021704_c001_v0001130_t0018_u01761963424288") 2025/11/01 02:17:11 DEBUG : potato2: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a3d_d20251101_m021655_c001_v7007000_t0000_u01761963415750") 2025/11/01 02:17:11 DEBUG : potato2: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a421_d20251101_m021650_c001_v0001183_t0021_u01761963410673") 2025/11/01 02:17:11 DEBUG : potato3: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f41673bf139a838c9_d20251101_m021709_c001_v7007000_t0000_u01761963429939") 2025/11/01 02:17:11 DEBUG : potato3: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0e3_d20251101_m021705_c001_v0001130_t0053_u01761963425243") 2025/11/01 02:17:11 DEBUG : potato3: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a3f_d20251101_m021655_c001_v7007000_t0000_u01761963415936") 2025/11/01 02:17:11 DEBUG : potato3: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a425_d20251101_m021651_c001_v0001183_t0010_u01761963411219") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a39_d20251101_m021649_c001_v7007000_t0000_u01761963409765") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0bf_d20251101_m021648_c001_v0001130_t0001_u01761963408929") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a25_d20251101_m021635_c001_v7007000_t0000_u01761963395749") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f07a_d20251101_m021628_c001_v0001130_t0010_u01761963388008") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f41816a065a339912_d20251101_m021627_c001_v7007000_t0000_u01761963387643") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f074_d20251101_m021624_c001_v0001130_t0026_u01761963384208") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f41816a065a33990f_d20251101_m021623_c001_v7007000_t0000_u01761963383835") 2025/11/01 02:17:11 DEBUG : sub dir/hello world: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f072_d20251101_m021620_c001_v0001130_t0048_u01761963380740") 2025/11/01 02:17:11 DEBUG : sub/yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a35_d20251101_m021648_c001_v7007000_t0000_u01761963408206") 2025/11/01 02:17:11 DEBUG : sub/yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0b7_d20251101_m021646_c001_v0001130_t0023_u01761963406335") 2025/11/01 02:17:11 DEBUG : yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a36_d20251101_m021648_c001_v7007000_t0000_u01761963408388") 2025/11/01 02:17:12 DEBUG : yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a40c_d20251101_m021647_c001_v0001183_t0003_u01761963407632") 2025/11/01 02:17:12 DEBUG : yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a30_d20251101_m021645_c001_v7007000_t0000_u01761963405602") 2025/11/01 02:17:12 DEBUG : yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f100aeaf7a570a3f1_d20251101_m021643_c001_v0001183_t0002_u01761963403883") 2025/11/01 02:17:12 DEBUG : yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a2b_d20251101_m021642_c001_v7007000_t0000_u01761963402583") 2025/11/01 02:17:12 DEBUG : yam: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f09a_d20251101_m021638_c001_v0001130_t0046_u01761963398956") 2025/11/01 02:17:12 DEBUG : yaml: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a31_d20251101_m021645_c001_v7007000_t0000_u01761963405783") 2025/11/01 02:17:12 DEBUG : yaml: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0b3_d20251101_m021644_c001_v0001130_t0007_u01761963404823") 2025/11/01 02:17:12 DEBUG : yaml: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f4116d128e05e8a2c_d20251101_m021642_c001_v7007000_t0000_u01761963402784") 2025/11/01 02:17:12 DEBUG : yaml: Deleting (id "4_z6fe28dc3303d3bdb9fa80e1b_f11699c692ae0f0aa_d20251101_m021641_c001_v0001130_t0049_u01761963401807") "./sync.test -test.v -test.timeout 1h0m0s -remote TestB2: -list-retries 5 -verbose -test.run '^(TestMoveWithDeleteEmptySrcDirs|TestServerSideCopy|TestServerSideCopyOverSelf|TestServerSideMove|TestServerSideMoveDeleteEmptySourceDirs|TestServerSideMoveOverSelf|TestServerSideMoveWithFilter|TestSyncAfterChangingModtimeOnly|TestSyncWithTrackRenames|TestSyncWithTrackRenamesStrategyLeaf|TestSyncWithTrackRenamesStrategyModtime)$'" - Finished ERROR in 54.516693965s (try 4/5): exit status 1: Failed [TestServerSideCopy TestServerSideCopyOverSelf TestServerSideMoveOverSelf TestSyncAfterChangingModtimeOnly TestSyncWithTrackRenames TestSyncWithTrackRenamesStrategyModtime TestSyncWithTrackRenamesStrategyLeaf TestMoveWithDeleteEmptySrcDirs TestServerSideMove TestServerSideMoveWithFilter TestServerSideMoveDeleteEmptySourceDirs]