"./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestBase64|TestConflicting|TestCopyAfterDelete|TestCopyOverSelf|TestCopyRedownload|TestFixCase|TestManualTransformFile|TestMove|TestMoveOverSelf|TestNothingToTransferWithEmptyDirs|TestRunTwice|TestServerSideCopy|TestServerSideCopyOverSelf|TestServerSideMove|TestServerSideMoveOverSelf|TestSyncBackupDirSuffixOnly|TestSyncConcurrentDelete|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncOverlapWithFilter|TestSyncReplaceDirModTimeWithEmptyDirs|TestTransformFile)$'" - Starting (try 2/5) 2025/07/15 01:32:27 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-humejat7metu" 2025/07/15 01:32:27 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/07/15 01:32:27 DEBUG : Starting OpenDrive session with ID: b8ee681a369dad8d5df3b04d31a361aaacdac4f274ebd08e2c7acf641ee2c6c5 2025/07/15 01:32:28 DEBUG : Creating backend with remote "/tmp/rclone2676751357" === RUN TestSyncEmptyDirectories run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:32:28 DEBUG : sub dir2: Making directory with metadata 2025/07/15 01:32:28 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/07/15 01:32:28 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/07/15 01:32:28 INFO : sub dir2: Making directory 2025/07/15 01:32:29 INFO : sub dir: Making directory 2025/07/15 01:32:29 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/07/15 01:32:29 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:32:29 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:32:30 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:32:31 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:32:31 INFO : sub dir/hello world: Copied (new) 2025/07/15 01:32:31 DEBUG : Waiting for deletions to finish 2025/07/15 01:32:31 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Skipping modtime test as remote does not support DirSetModTime or MkdirMetadata fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:289: Sleeping for 6s just to make sure --- PASS: TestSyncEmptyDirectories (12.58s) === RUN TestSyncNoEmptyDirectories run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:32:40 INFO : sub dir2: Making directory 2025/07/15 01:32:41 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/07/15 01:32:41 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:32:41 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:32:42 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:32:43 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:32:43 INFO : sub dir/hello world: Copied (new) 2025/07/15 01:32:43 DEBUG : Waiting for deletions to finish --- PASS: TestSyncNoEmptyDirectories (3.77s) === RUN TestServerSideCopy run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:32:45 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:32:47 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-yiyupad5bipo" 2025/07/15 01:32:47 DEBUG : Starting OpenDrive session with ID: 526436f2db989e0365ff28bc8126ffc0b8aab416f1af760e0336e2b529c1ec68 sync_test.go:620: Server side copy (if possible) OpenDrive root 'rclone-test-humejat7metu' -> OpenDrive root 'rclone-test-yiyupad5bipo' 2025/07/15 01:32:48 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/07/15 01:32:48 DEBUG : OpenDrive root 'rclone-test-yiyupad5bipo': Waiting for checks to finish 2025/07/15 01:32:48 DEBUG : OpenDrive root 'rclone-test-yiyupad5bipo': Waiting for transfers to finish 2025/07/15 01:32:49 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/07/15 01:32:49 INFO : sub dir/hello world: Copied (server-side copy) fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:289: Sleeping for 6s just to make sure 2025/07/15 01:32:57 DEBUG : OpenDrive root 'rclone-test-yiyupad5bipo': Purge remote --- PASS: TestServerSideCopy (14.06s) === RUN TestCopyOverSelf run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:32:59 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:33:01 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/07/15 01:33:01 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:33:01 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:33:01 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0 2025/07/15 01:33:02 DEBUG : sub dir/hello world: md5 = 00321a507bdb420dbbd4f53c733b1505 OK 2025/07/15 01:33:02 INFO : sub dir/hello world: Copied (replaced existing) --- PASS: TestCopyOverSelf (5.51s) === RUN TestServerSideCopyOverSelf run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:33:05 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:33:06 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-woyicid2giqe" 2025/07/15 01:33:07 DEBUG : Starting OpenDrive session with ID: 176ae4a4e3cff702c1374dfd58dcae74fbe100b4772d02e21f2657f771deb153 sync_test.go:656: Server side copy (if possible) OpenDrive root 'rclone-test-humejat7metu' -> OpenDrive root 'rclone-test-woyicid2giqe' 2025/07/15 01:33:07 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/07/15 01:33:07 DEBUG : OpenDrive root 'rclone-test-woyicid2giqe': Waiting for checks to finish 2025/07/15 01:33:07 DEBUG : OpenDrive root 'rclone-test-woyicid2giqe': Waiting for transfers to finish 2025/07/15 01:33:08 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/07/15 01:33:08 INFO : sub dir/hello world: Copied (server-side copy) 2025/07/15 01:33:09 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0 2025/07/15 01:33:11 DEBUG : OpenDrive root 'rclone-test-woyicid2giqe': Waiting for checks to finish 2025/07/15 01:33:11 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/07/15 01:33:11 DEBUG : OpenDrive root 'rclone-test-woyicid2giqe': Waiting for transfers to finish 2025/07/15 01:33:11 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/07/15 01:33:11 INFO : sub dir/hello world: Copied (server-side copy) 2025/07/15 01:33:12 DEBUG : OpenDrive root 'rclone-test-woyicid2giqe': Purge remote --- PASS: TestServerSideCopyOverSelf (9.35s) === RUN TestMoveOverSelf run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:33:14 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:33:16 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/07/15 01:33:16 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:33:16 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:33:16 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0 2025/07/15 01:33:17 DEBUG : sub dir/hello world: md5 = 00321a507bdb420dbbd4f53c733b1505 OK 2025/07/15 01:33:17 INFO : sub dir/hello world: Copied (replaced existing) 2025/07/15 01:33:17 INFO : sub dir/hello world: Deleted fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:289: Sleeping for 6s just to make sure --- PASS: TestMoveOverSelf (12.83s) === RUN TestServerSideMoveOverSelf run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:33:27 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:33:28 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-fokaqav3fita" 2025/07/15 01:33:29 DEBUG : Starting OpenDrive session with ID: 0ab477dd72b1755e1cf0d2a862d1cc9bd15adf1fb7a76e0b435320bd35f4471e sync_test.go:701: Server side copy (if possible) OpenDrive root 'rclone-test-humejat7metu' -> OpenDrive root 'rclone-test-fokaqav3fita' 2025/07/15 01:33:29 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/07/15 01:33:29 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Waiting for checks to finish 2025/07/15 01:33:29 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Waiting for transfers to finish 2025/07/15 01:33:30 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/07/15 01:33:30 INFO : sub dir/hello world: Copied (server-side copy) 2025/07/15 01:33:31 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0 2025/07/15 01:33:33 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Using server-side directory move 2025/07/15 01:33:33 INFO : OpenDrive root 'rclone-test-fokaqav3fita': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/07/15 01:33:33 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/07/15 01:33:33 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Waiting for checks to finish 2025/07/15 01:33:33 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Waiting for transfers to finish 2025/07/15 01:33:33 INFO : sub dir/hello world: Deleted 2025/07/15 01:33:33 INFO : sub dir/hello world: Moved (server-side) 2025/07/15 01:33:35 DEBUG : sub dir/hello world: Uploading chunk 0, size=24, remain=0 2025/07/15 01:33:36 DEBUG : testing file moves 2025/07/15 01:33:37 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17) 2025/07/15 01:33:37 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Waiting for checks to finish 2025/07/15 01:33:37 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Waiting for transfers to finish 2025/07/15 01:33:37 INFO : sub dir/hello world: Deleted 2025/07/15 01:33:37 INFO : sub dir/hello world: Moved (server-side) Diff of "logger" and "lsf" 2d1 < 2011-12-30 12:59:59;c0e6b00e2b2068ef74d2ed582114e376;24;sub dir/hello world sync_test.go:3101: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:3101 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:727 Error: Received unexpected error: logger does not match lsf! logger: 2011-12-30 12:59:59;c0e6b00e2b2068ef74d2ed582114e376;24;sub dir/hello world lsf: Test: TestServerSideMoveOverSelf 2025/07/15 01:33:38 DEBUG : OpenDrive root 'rclone-test-fokaqav3fita': Purge remote --- FAIL: TestServerSideMoveOverSelf (12.81s) === RUN TestCopyAfterDelete run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:33:40 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:33:41 ERROR : error listing: directory not found 2025/07/15 01:33:41 INFO : Local file system at /tmp/rclone2676751357: Making directory 2025/07/15 01:33:42 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:33:42 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish --- PASS: TestCopyAfterDelete (4.26s) === RUN TestCopyRedownload run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:33:44 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2025/07/15 01:33:46 DEBUG : Added delayed dir = "sub dir", newDst= 2025/07/15 01:33:46 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/07/15 01:33:46 DEBUG : Local file system at /tmp/rclone2676751357: Waiting for checks to finish 2025/07/15 01:33:46 DEBUG : Local file system at /tmp/rclone2676751357: Waiting for transfers to finish 2025/07/15 01:33:46 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:33:46 DEBUG : sub dir/hello world.87ffde68.partial: renamed to: sub dir/hello world 2025/07/15 01:33:46 INFO : sub dir/hello world: Copied (new) 2025/07/15 01:33:46 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestCopyRedownload (4.23s) === RUN TestServerSideMove run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:33:47 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-cuxubix4paca" 2025/07/15 01:33:48 DEBUG : Starting OpenDrive session with ID: 3a095444df37cf7267e3cf31430e901bd2e9b53b5d455cdf044daf45ab3ec947 2025/07/15 01:33:49 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2025/07/15 01:33:51 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2025/07/15 01:33:52 DEBUG : potato3: Uploading chunk 0, size=68, remain=0 sync_test.go:1735: Server side move (if possible) OpenDrive root 'rclone-test-humejat7metu' -> OpenDrive root 'rclone-test-cuxubix4paca' 2025/07/15 01:33:55 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2025/07/15 01:33:56 DEBUG : potato3: Uploading chunk 0, size=60, remain=0 2025/07/15 01:33:57 DEBUG : OpenDrive root 'rclone-test-cuxubix4paca': Using server-side directory move 2025/07/15 01:33:57 INFO : OpenDrive root 'rclone-test-cuxubix4paca': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/07/15 01:33:58 DEBUG : potato2: Need to transfer - File not found at Destination 2025/07/15 01:33:58 DEBUG : potato3: Need to transfer - File not found at Destination 2025/07/15 01:33:58 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/07/15 01:33:58 DEBUG : empty space: Unchanged skipping 2025/07/15 01:33:58 DEBUG : OpenDrive root 'rclone-test-cuxubix4paca': Waiting for checks to finish 2025/07/15 01:33:58 INFO : empty space: Deleted 2025/07/15 01:33:58 DEBUG : OpenDrive root 'rclone-test-cuxubix4paca': Waiting for transfers to finish 2025/07/15 01:33:58 INFO : potato2: Moved (server-side) 2025/07/15 01:33:58 INFO : potato3: Moved (server-side) 2025/07/15 01:33:59 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-nojufuz9cage" 2025/07/15 01:34:00 DEBUG : Starting OpenDrive session with ID: 5d11b1350cb66d51387657801d29ab2750c52bff887fef78000bae0d11fd4c01 2025/07/15 01:34:01 DEBUG : OpenDrive root 'rclone-test-nojufuz9cage': Using server-side directory move 2025/07/15 01:34:01 DEBUG : same parent dir (0) - using folder/rename instead of move_copy 2025/07/15 01:34:01 INFO : OpenDrive root 'rclone-test-nojufuz9cage': Server side directory move succeeded 2025/07/15 01:34:02 ERROR : error listing: directory not found 2025/07/15 01:34:02 DEBUG : OpenDrive root 'rclone-test-nojufuz9cage': Purge remote 2025/07/15 01:34:02 DEBUG : OpenDrive root 'rclone-test-cuxubix4paca': Purge remote 2025/07/15 01:34:02 NOTICE: purge failed: directory not found --- PASS: TestServerSideMove (15.20s) === RUN TestSyncOverlapWithFilter run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:34:02 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-humejat7metu/rclone-sync-test" 2025/07/15 01:34:03 DEBUG : Starting OpenDrive session with ID: 1c20724552667c143a26dc7fabde2442c600640755ae22e499766fdd138de11c 2025/07/15 01:34:04 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-humejat7metu/rclone-sync-test-include/layer2" 2025/07/15 01:34:04 DEBUG : Starting OpenDrive session with ID: 7a0aae7bdaedc42c6e51848062390070d884786d681e1afec0701a9d19305e7d 2025/07/15 01:34:06 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-humejat7metu/rclone-sync-test-ignore-file" 2025/07/15 01:34:06 DEBUG : Starting OpenDrive session with ID: 65bac42ab151cf39667241eb4d980860c07da5a5743c778093f8e7d3806ad6f3 2025/07/15 01:34:08 DEBUG : rclone-sync-test-ignore-file/.ignore: Uploading chunk 0, size=1, remain=0 2025/07/15 01:34:10 DEBUG : rclone-sync-test: Excluded 2025/07/15 01:34:10 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/07/15 01:34:11 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/07/15 01:34:11 DEBUG : OpenDrive root 'rclone-test-humejat7metu/rclone-sync-test': Waiting for checks to finish 2025/07/15 01:34:11 DEBUG : OpenDrive root 'rclone-test-humejat7metu/rclone-sync-test': Waiting for transfers to finish 2025/07/15 01:34:11 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:11 INFO : There was nothing to transfer 2025/07/15 01:34:11 DEBUG : rclone-sync-test: Excluded 2025/07/15 01:34:11 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/07/15 01:34:12 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/07/15 01:34:12 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:34:12 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:34:12 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:12 INFO : rclone-sync-test-include: Removing directory 2025/07/15 01:34:12 DEBUG : OpenDrive root 'rclone-test-humejat7metu': deleted 1 directories 2025/07/15 01:34:12 INFO : There was nothing to transfer 2025/07/15 01:34:13 DEBUG : rclone-sync-test: Excluded 2025/07/15 01:34:13 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/07/15 01:34:13 DEBUG : OpenDrive root 'rclone-test-humejat7metu/rclone-sync-test-include/layer2': Waiting for checks to finish 2025/07/15 01:34:13 DEBUG : OpenDrive root 'rclone-test-humejat7metu/rclone-sync-test-include/layer2': Waiting for transfers to finish 2025/07/15 01:34:13 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:13 INFO : There was nothing to transfer 2025/07/15 01:34:13 DEBUG : rclone-sync-test: Excluded 2025/07/15 01:34:14 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/07/15 01:34:14 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:34:14 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:34:14 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:14 INFO : There was nothing to transfer 2025/07/15 01:34:14 DEBUG : Excluded 2025/07/15 01:34:14 DEBUG : rclone-sync-test: Excluded 2025/07/15 01:34:14 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/07/15 01:34:14 DEBUG : OpenDrive root 'rclone-test-humejat7metu/rclone-sync-test-ignore-file': Waiting for checks to finish 2025/07/15 01:34:14 DEBUG : OpenDrive root 'rclone-test-humejat7metu/rclone-sync-test-ignore-file': Waiting for transfers to finish 2025/07/15 01:34:14 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:14 INFO : There was nothing to transfer --- PASS: TestSyncOverlapWithFilter (13.22s) === RUN TestSyncBackupDirSuffixOnly run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:34:17 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2025/07/15 01:34:19 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2025/07/15 01:34:21 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:289: Sleeping for 6s just to make sure fstest.go:124: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:124 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:129 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:148 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:192 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2407 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2469 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: dst/three.txt: Modification time difference too big |-214269h29m14.500000001s| > 1s (want 2001-02-03 04:05:06.499999999 +0000 UTC vs got 2025-07-15 01:34:21 +0000 UTC) (precision 1s) 2025/07/15 01:34:30 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-humejat7metu/dst" 2025/07/15 01:34:31 DEBUG : Starting OpenDrive session with ID: 294c89bbd0c3d994f70972e4ded8c8eec8f676f5d08215025583017deae30d62 2025/07/15 01:34:31 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/07/15 01:34:31 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:34:31 DEBUG : two: Unchanged skipping 2025/07/15 01:34:31 DEBUG : OpenDrive root 'rclone-test-humejat7metu/dst': Waiting for checks to finish 2025/07/15 01:34:31 DEBUG : one: same parent dir (ODFfOTE5MDUwOF9YY1hmWQ) - using file/rename instead of move_copy for one.bak 2025/07/15 01:34:32 INFO : one: Moved (server-side) to: one.bak 2025/07/15 01:34:32 DEBUG : OpenDrive root 'rclone-test-humejat7metu/dst': Waiting for transfers to finish 2025/07/15 01:34:32 DEBUG : one: Uploading chunk 0, size=4, remain=0 2025/07/15 01:34:33 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2025/07/15 01:34:33 INFO : one: Copied (new) 2025/07/15 01:34:33 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:34 DEBUG : three.txt: same parent dir (ODFfOTE5MDUwOF9YY1hmWQ) - using file/rename instead of move_copy for three.txt.bak 2025/07/15 01:34:34 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/07/15 01:34:34 INFO : three.txt: Moved into backup dir 2025/07/15 01:34:35 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0 2025/07/15 01:34:37 DEBUG : one.bak: Excluded (Path Filter) 2025/07/15 01:34:37 DEBUG : one.bak: Excluded 2025/07/15 01:34:37 DEBUG : three.txt.bak: Excluded (Path Filter) 2025/07/15 01:34:37 DEBUG : three.txt.bak: Excluded 2025/07/15 01:34:37 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/07/15 01:34:37 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:34:37 DEBUG : two: Unchanged skipping 2025/07/15 01:34:37 DEBUG : OpenDrive root 'rclone-test-humejat7metu/dst': Waiting for checks to finish 2025/07/15 01:34:37 INFO : one.bak: Deleted 2025/07/15 01:34:37 DEBUG : one: same parent dir (ODFfOTE5MDUwOF9YY1hmWQ) - using file/rename instead of move_copy for one.bak 2025/07/15 01:34:37 INFO : one: Moved (server-side) to: one.bak 2025/07/15 01:34:37 DEBUG : OpenDrive root 'rclone-test-humejat7metu/dst': Waiting for transfers to finish 2025/07/15 01:34:38 DEBUG : one: Uploading chunk 0, size=5, remain=0 2025/07/15 01:34:39 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2025/07/15 01:34:39 INFO : one: Copied (new) 2025/07/15 01:34:39 DEBUG : Waiting for deletions to finish 2025/07/15 01:34:40 INFO : three.txt.bak: Deleted 2025/07/15 01:34:40 DEBUG : three.txt: same parent dir (ODFfOTE5MDUwOF9YY1hmWQ) - using file/rename instead of move_copy for three.txt.bak 2025/07/15 01:34:40 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/07/15 01:34:40 INFO : three.txt: Moved into backup dir --- FAIL: TestSyncBackupDirSuffixOnly (26.27s) === RUN TestFixCase run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:34:43 DEBUG : EXISTING: Uploading chunk 0, size=6, remain=0 2025/07/15 01:34:45 DEBUG : EXISTINGBUTDIFFERENT: Uploading chunk 0, size=8, remain=0 2025/07/15 01:34:48 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: Uploading chunk 0, size=8, remain=0 2025/07/15 01:34:50 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Uploading chunk 0, size=8, remain=0 2025/07/15 01:34:52 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:34:52 DEBUG : existing: Unchanged skipping 2025/07/15 01:34:52 DEBUG : existingbutdifferent: Sizes differ (src 5 vs dst 8) 2025/07/15 01:34:52 DEBUG : subdira-rclone-move-werifab2: same parent dir (ODFfOTE5MDQ1OF93OXF1OA) - using folder/rename instead of move_copy 2025/07/15 01:34:52 DEBUG : EXISTING: moving to existing-rclone-move-lobuguw0 2025/07/15 01:34:52 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent-rclone-move-hasafen7 2025/07/15 01:34:52 INFO : OpenDrive root 'rclone-test-humejat7metu': Can't DirMove - falling back to file moves: can't copy directory - destination already exists 2025/07/15 01:34:53 DEBUG : EXISTINGBUTDIFFERENT: same parent dir (ODFfOTE5MDQ1OF93OXF1OA) - using file/rename instead of move_copy for existingbutdifferent-rclone-move-hasafen7 2025/07/15 01:34:53 DEBUG : EXISTING: same parent dir (ODFfOTE5MDQ1OF93OXF1OA) - using file/rename instead of move_copy for existing-rclone-move-lobuguw0 2025/07/15 01:34:53 INFO : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent-rclone-move-hasafen7 2025/07/15 01:34:53 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent 2025/07/15 01:34:53 INFO : EXISTING: Moved (server-side) to: existing-rclone-move-lobuguw0 2025/07/15 01:34:53 DEBUG : EXISTING: moving to existing 2025/07/15 01:34:53 DEBUG : existingbutdifferent-rclone-move-hasafen7: same parent dir (ODFfOTE5MDQ1OF93OXF1OA) - using file/rename instead of move_copy for existingbutdifferent 2025/07/15 01:34:53 DEBUG : existing-rclone-move-lobuguw0: same parent dir (ODFfOTE5MDQ1OF93OXF1OA) - using file/rename instead of move_copy for existing 2025/07/15 01:34:53 INFO : existingbutdifferent-rclone-move-hasafen7: Moved (server-side) to: existingbutdifferent 2025/07/15 01:34:53 INFO : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent 2025/07/15 01:34:53 INFO : EXISTINGBUTDIFFERENT: Fixed case by renaming to: existingbutdifferent 2025/07/15 01:34:53 INFO : existing-rclone-move-lobuguw0: Moved (server-side) to: existing 2025/07/15 01:34:53 INFO : EXISTING: Moved (server-side) to: existing 2025/07/15 01:34:53 INFO : EXISTING: Fixed case by renaming to: existing 2025/07/15 01:34:53 DEBUG : existingbutdifferent: Uploading chunk 0, size=5, remain=0 2025/07/15 01:34:54 INFO : subdira/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Deleted 2025/07/15 01:34:54 INFO : subdira/subdirb/SUBDIRC/HELLO: Deleted 2025/07/15 01:34:54 ERROR : subdira-rclone-move-werifab2/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Couldn't move: failed to get fileinfo: File is deleted (Error 404) 2025/07/15 01:34:54 ERROR : subdira-rclone-move-werifab2/subdirb/SUBDIRC/HELLO: Couldn't move: failed to get fileinfo: Get "https://dev.opendrive.com/api/v1/file/info.json/ODFfMTAyMjQzMDQxX3dTbDhn?session_id=b8ee681a369dad8d5df3b04d31a361aaacdac4f274ebd08e2c7acf641ee2c6c5": failed to get fileinfo: File is deleted (Error 404) 2025/07/15 01:34:54 ERROR : SUBDIRA: Error while attempting to rename to subdira: RenameDir renames: failed to get fileinfo: File is deleted (Error 404) 2025/07/15 01:34:55 DEBUG : subdira/subdirb/subdirc/hello: Need to transfer - File not found at Destination 2025/07/15 01:34:55 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Need to transfer - File not found at Destination 2025/07/15 01:34:55 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:34:55 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:34:55 DEBUG : existingbutdifferent: md5 = 81bdd90fd4bc5a1c9b7b603014ff1388 OK 2025/07/15 01:34:55 INFO : existingbutdifferent: Copied (replaced existing) 2025/07/15 01:34:56 DEBUG : subdira/subdirb/subdirc/hello: Uploading chunk 0, size=5, remain=0 2025/07/15 01:34:56 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Uploading chunk 0, size=5, remain=0 2025/07/15 01:34:56 DEBUG : subdira/subdirb/subdirc/hello: md5 = 81bdd90fd4bc5a1c9b7b603014ff1388 OK 2025/07/15 01:34:56 INFO : subdira/subdirb/subdirc/hello: Copied (new) 2025/07/15 01:34:57 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: md5 = 81bdd90fd4bc5a1c9b7b603014ff1388 OK 2025/07/15 01:34:57 INFO : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Copied (new) 2025/07/15 01:34:57 ERROR : OpenDrive root 'rclone-test-humejat7metu': not deleting files as there were IO errors 2025/07/15 01:34:57 ERROR : OpenDrive root 'rclone-test-humejat7metu': not deleting directories as there were IO errors sync_test.go:2685: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2685 Error: Received unexpected error: RenameDir renames: failed to get fileinfo: File is deleted (Error 404) Test: TestFixCase --- FAIL: TestFixCase (18.16s) === RUN TestSyncConcurrentDelete run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:35:01 DEBUG : both0: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:03 DEBUG : only0: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:04 DEBUG : both1: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:06 DEBUG : only1: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:08 DEBUG : both2: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:10 DEBUG : only2: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:11 DEBUG : both3: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:13 DEBUG : only3: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:15 DEBUG : both4: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:17 DEBUG : only4: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:19 DEBUG : both5: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:20 DEBUG : only5: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:22 DEBUG : both6: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:24 DEBUG : only6: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:25 DEBUG : both7: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:27 DEBUG : only7: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:29 DEBUG : both8: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:30 DEBUG : only8: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:32 DEBUG : both9: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:34 DEBUG : only9: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:36 DEBUG : both10: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:38 DEBUG : only10: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:39 DEBUG : both11: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:41 DEBUG : only11: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:43 DEBUG : both12: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:45 DEBUG : only12: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:46 DEBUG : both13: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:48 DEBUG : only13: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:50 DEBUG : both14: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:52 DEBUG : only14: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:53 DEBUG : both15: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:55 DEBUG : only15: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:57 DEBUG : both16: Uploading chunk 0, size=6, remain=0 2025/07/15 01:35:59 DEBUG : only16: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:01 DEBUG : both17: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:02 DEBUG : only17: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:04 DEBUG : both18: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:06 DEBUG : only18: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:08 DEBUG : both19: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:09 DEBUG : only19: Uploading chunk 0, size=6, remain=0 2025/07/15 01:36:11 DEBUG : both0: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both0: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both10: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both11: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both12: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both13: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both14: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both15: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both16: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both17: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both18: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both19: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both1: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:36:11 DEBUG : both3: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both6: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both7: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both8: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:11 DEBUG : both9: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both4: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both5: Unchanged skipping 2025/07/15 01:36:11 DEBUG : both2: Unchanged skipping 2025/07/15 01:36:11 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:36:11 DEBUG : Waiting for deletions to finish 2025/07/15 01:36:11 INFO : only10: Deleted 2025/07/15 01:36:11 INFO : only11: Deleted 2025/07/15 01:36:11 INFO : only13: Deleted 2025/07/15 01:36:11 INFO : only4: Deleted 2025/07/15 01:36:11 INFO : only5: Deleted 2025/07/15 01:36:12 INFO : only19: Deleted 2025/07/15 01:36:12 INFO : only1: Deleted 2025/07/15 01:36:12 INFO : only2: Deleted 2025/07/15 01:36:12 INFO : only6: Deleted 2025/07/15 01:36:12 INFO : only9: Deleted 2025/07/15 01:36:12 INFO : only12: Deleted 2025/07/15 01:36:12 INFO : only14: Deleted 2025/07/15 01:36:12 INFO : only15: Deleted 2025/07/15 01:36:12 INFO : only16: Deleted 2025/07/15 01:36:12 INFO : only17: Deleted 2025/07/15 01:36:12 INFO : only3: Deleted 2025/07/15 01:36:12 INFO : only7: Deleted 2025/07/15 01:36:12 INFO : only8: Deleted 2025/07/15 01:36:12 INFO : only0: Deleted 2025/07/15 01:36:13 INFO : only18: Deleted fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:289: Sleeping for 6s just to make sure --- PASS: TestSyncConcurrentDelete (84.44s) === RUN TestSyncReplaceDirModTimeWithEmptyDirs run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:36:25 DEBUG : empty_dir: Making directory with metadata 2025/07/15 01:36:25 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/07/15 01:36:25 DEBUG : empty_on_remote: Making directory with metadata 2025/07/15 01:36:25 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/07/15 01:36:25 INFO : empty_on_remote: Making directory 2025/07/15 01:36:25 INFO : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC sync_test.go:2827: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2827 /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bilib/output.go:22 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2825 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2867 Error: Received unexpected error: failed to get folder list: Directory doesn't exist (Error 404) Test: TestSyncReplaceDirModTimeWithEmptyDirs --- FAIL: TestSyncReplaceDirModTimeWithEmptyDirs (7.05s) === RUN TestNothingToTransferWithEmptyDirs run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:36:32 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/07/15 01:36:32 INFO : sub dir: Making directory 2025/07/15 01:36:32 INFO : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC --- PASS: TestNothingToTransferWithEmptyDirs (15.73s) === RUN TestRunTwice run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:36:47 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:47 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:47 INFO : tictactoe: Making directory 2025/07/15 01:36:48 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:48 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:48 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:36:48 INFO : tictactoe/tictactoe: Making directory 2025/07/15 01:36:48 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:36:48 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/toe.txt 2025/07/15 01:36:48 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/07/15 01:36:48 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:36:48 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/toe.txt 2025/07/15 01:36:48 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:36:49 DEBUG : tictactoe/tictactoe/toe.txt: Uploading chunk 0, size=11, remain=0 2025/07/15 01:36:50 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:36:50 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/toe.txt 2025/07/15 01:36:50 DEBUG : Waiting for deletions to finish 2025/07/15 01:36:51 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:51 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:51 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:51 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:36:51 DEBUG : toe/toe/toe.txt: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/07/15 01:36:51 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:36:51 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/toe.txt 2025/07/15 01:36:51 DEBUG : toe/toe/toe.txt: Unchanged skipping 2025/07/15 01:36:51 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:36:51 DEBUG : Waiting for deletions to finish --- PASS: TestRunTwice (6.07s) === RUN TestConflicting run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:36:54 INFO : toe: Making directory 2025/07/15 01:36:54 INFO : toe/toe: Making directory 2025/07/15 01:36:54 DEBUG : toe/toe/toe: Need to transfer - File not found at Destination 2025/07/15 01:36:54 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:36:54 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:36:55 DEBUG : toe/toe/toe: Uploading chunk 0, size=11, remain=0 2025/07/15 01:36:56 DEBUG : toe/toe/toe: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:36:56 INFO : toe/toe/toe: Copied (new) 2025/07/15 01:36:56 DEBUG : Waiting for deletions to finish --- PASS: TestConflicting (4.83s) === RUN TestMove run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:36:58 DEBUG : empty_dir: Making directory with metadata 2025/07/15 01:36:58 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/07/15 01:36:58 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:58 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:36:58 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:36:58 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:36:58 INFO : tictacempty_dir: Making directory 2025/07/15 01:36:59 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:36:59 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:59 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:59 INFO : tictactoe: Making directory 2025/07/15 01:36:59 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:59 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:36:59 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:36:59 INFO : tictactoe/tictactoe: Making directory 2025/07/15 01:36:59 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:36:59 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/07/15 01:36:59 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:36:59 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/07/15 01:36:59 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:36:59 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:36:59 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:36:59 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:37:00 DEBUG : tictactoe/tictactoe/tictactoe.txt: Uploading chunk 0, size=11, remain=0 2025/07/15 01:37:01 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:37:01 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:01 INFO : toe/toe/toe.txt: Deleted 2025/07/15 01:37:01 INFO : toe/toe: Removing directory 2025/07/15 01:37:01 INFO : toe: Removing directory 2025/07/15 01:37:01 INFO : empty_dir: Removing directory 2025/07/15 01:37:01 DEBUG : Local file system at /tmp/rclone2676751357: deleted 3 directories --- PASS: TestMove (5.63s) === RUN TestTransformFile run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:37:04 DEBUG : empty_dir: Making directory with metadata 2025/07/15 01:37:04 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/07/15 01:37:04 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:04 INFO : tictacempty_dir: Making directory 2025/07/15 01:37:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:04 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:04 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:04 INFO : tictactoe: Making directory 2025/07/15 01:37:05 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:05 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:05 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:37:05 INFO : tictactoe/tictactoe: Making directory 2025/07/15 01:37:05 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:37:05 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/07/15 01:37:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:05 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/07/15 01:37:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:05 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:37:05 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:37:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: Uploading chunk 0, size=11, remain=0 2025/07/15 01:37:07 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:37:07 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:07 INFO : toe/toe/toe.txt: Deleted 2025/07/15 01:37:07 INFO : toe/toe: Removing directory 2025/07/15 01:37:07 INFO : toe: Removing directory 2025/07/15 01:37:07 INFO : empty_dir: Removing directory 2025/07/15 01:37:07 DEBUG : Local file system at /tmp/rclone2676751357: deleted 3 directories 2025/07/15 01:37:08 DEBUG : tictactoe/tictactoe/tictactoe.txt: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/07/15 01:37:08 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/07/15 01:37:08 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/07/15 01:37:08 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/07/15 01:37:08 ERROR : tictactoe/tictactoe/tictactoe.txt: Couldn't move: failed to get folder list: Directory doesn't exist (Error 404) sync_transform_test.go:435: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_transform_test.go:435 Error: Received unexpected error: failed to get folder list: Directory doesn't exist (Error 404) Test: TestTransformFile run.go:125: removing dir "tictactoe/tictactoe" failed - try 1/3: folder not empty run.go:125: removing dir "tictactoe/tictactoe" failed - try 2/3: folder not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Flushing the directory cache fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:298: Flushing the directory cache fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:298: Flushing the directory cache fstest.go:324: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:324 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:173 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:388 /usr/local/go/src/testing/testing.go:1211 /usr/local/go/src/testing/testing.go:1445 /usr/local/go/src/testing/testing.go:1786 /usr/local/go/src/runtime/panic.go:636 /usr/local/go/src/testing/testing.go:1041 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_transform_test.go:435 Error: Not equal: expected: []string{} actual : []string{"toe"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "toe" } Test: TestTransformFile Messages: directories --- FAIL: TestTransformFile (17.22s) === RUN TestManualTransformFile run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:37:21 DEBUG : Reset feature "Copy" 2025/07/15 01:37:21 DEBUG : Reset feature "Move" 2025/07/15 01:37:21 DEBUG : Reset feature "Copy" 2025/07/15 01:37:21 DEBUG : Reset feature "Move" 2025/07/15 01:37:21 DEBUG : empty_dir: Making directory with metadata 2025/07/15 01:37:21 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/07/15 01:37:21 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:21 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:21 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:21 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:21 INFO : tictacempty_dir: Making directory 2025/07/15 01:37:22 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/07/15 01:37:22 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:22 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:22 INFO : tictactoe: Making directory 2025/07/15 01:37:22 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:22 DEBUG : toe: transformed to: tictactoe 2025/07/15 01:37:22 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:37:22 INFO : tictactoe/tictactoe: Making directory 2025/07/15 01:37:22 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/07/15 01:37:22 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/07/15 01:37:22 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:22 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/07/15 01:37:22 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:22 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:22 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:37:22 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:37:23 DEBUG : tictactoe/tictactoe/tictactoe.txt: Uploading chunk 0, size=11, remain=0 2025/07/15 01:37:24 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:37:24 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/07/15 01:37:24 INFO : toe/toe/toe.txt: Deleted 2025/07/15 01:37:24 ERROR : Local file system at /tmp/rclone2676751357: not deleting directories as there were IO errors sync_transform_test.go:457: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_transform_test.go:457 Error: Received unexpected error: not deleting directories as there were IO errors Test: TestManualTransformFile --- FAIL: TestManualTransformFile (5.60s) === RUN TestBase64 run.go:180: Remote "OpenDrive root 'rclone-test-humejat7metu'", Local "Local file system at /tmp/rclone2676751357", Modify Window "1s" 2025/07/15 01:37:27 DEBUG : toe: transformed to: dG9l 2025/07/15 01:37:27 DEBUG : toe: transformed to: dG9l 2025/07/15 01:37:27 INFO : dG9l: Making directory 2025/07/15 01:37:27 DEBUG : toe: transformed to: dG9l 2025/07/15 01:37:27 DEBUG : toe: transformed to: dG9l 2025/07/15 01:37:27 DEBUG : toe/toe: transformed to: dG9l/dG9l 2025/07/15 01:37:27 INFO : dG9l/dG9l: Making directory 2025/07/15 01:37:28 DEBUG : toe/toe: transformed to: dG9l/dG9l 2025/07/15 01:37:28 DEBUG : toe.txt: transformed to: dG9lLnR4dA== 2025/07/15 01:37:28 DEBUG : toe/toe/toe.txt: transformed to: dG9l/dG9l/dG9lLnR4dA== 2025/07/15 01:37:28 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/07/15 01:37:28 DEBUG : toe/toe/toe.txt: transformed to: dG9l/dG9l/dG9lLnR4dA== 2025/07/15 01:37:28 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for checks to finish 2025/07/15 01:37:28 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Waiting for transfers to finish 2025/07/15 01:37:28 DEBUG : dG9l/dG9l/dG9lLnR4dA==: Uploading chunk 0, size=11, remain=0 2025/07/15 01:37:29 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/07/15 01:37:29 INFO : toe/toe/toe.txt: Copied (new) to: dG9l/dG9l/dG9lLnR4dA== 2025/07/15 01:37:29 ERROR : OpenDrive root 'rclone-test-humejat7metu': not deleting files as there were IO errors 2025/07/15 01:37:29 ERROR : OpenDrive root 'rclone-test-humejat7metu': not deleting directories as there were IO errors sync_transform_test.go:481: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_transform_test.go:481 Error: Received unexpected error: not deleting files as there were IO errors Test: TestBase64 run.go:125: removing dir "dG9l/dG9l" failed - try 1/3: folder not empty --- FAIL: TestBase64 (5.35s) FAIL 2025/07/15 01:37:32 DEBUG : OpenDrive root 'rclone-test-humejat7metu': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestBase64|TestConflicting|TestCopyAfterDelete|TestCopyOverSelf|TestCopyRedownload|TestFixCase|TestManualTransformFile|TestMove|TestMoveOverSelf|TestNothingToTransferWithEmptyDirs|TestRunTwice|TestServerSideCopy|TestServerSideCopyOverSelf|TestServerSideMove|TestServerSideMoveOverSelf|TestSyncBackupDirSuffixOnly|TestSyncConcurrentDelete|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncOverlapWithFilter|TestSyncReplaceDirModTimeWithEmptyDirs|TestTransformFile)$'" - Finished ERROR in 5m5.985588255s (try 2/5): exit status 1: Failed [TestServerSideMoveOverSelf TestSyncBackupDirSuffixOnly TestFixCase TestSyncReplaceDirModTimeWithEmptyDirs TestTransformFile TestManualTransformFile TestBase64]