"./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestBase64|TestCopyWithFilesFrom|TestManualTransformFile|TestSyncSuffixKeepExtension|TestTransformFile)$'" - Starting (try 2/5) 2025/08/13 01:26:32 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-sonirik4gebi" 2025/08/13 01:26:32 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/08/13 01:26:33 DEBUG : Starting OpenDrive session with ID: 5168587c1ae2b576365fd4f7a14dafdaca62a51d89c60367f3ab0e990b5bba8f 2025/08/13 01:26:34 DEBUG : Creating backend with remote "/tmp/rclone2989201582" === RUN TestCopyWithFilesFrom run.go:180: Remote "OpenDrive root 'rclone-test-sonirik4gebi'", Local "Local file system at /tmp/rclone2989201582", Modify Window "1s" 2025/08/13 01:26:34 DEBUG : potato2: Need to transfer - File not found at Destination 2025/08/13 01:26:34 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for checks to finish 2025/08/13 01:26:34 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for transfers to finish 2025/08/13 01:26:36 DEBUG : potato2: Uploading chunk 0, size=11, remain=0 2025/08/13 01:26:37 DEBUG : potato2: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/08/13 01:26:37 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (4.89s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "OpenDrive root 'rclone-test-sonirik4gebi'", Local "Local file system at /tmp/rclone2989201582", Modify Window "1s" 2025/08/13 01:26:41 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2025/08/13 01:26:44 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2025/08/13 01:26:46 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 2025/08/13 01:26:48 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-sonirik4gebi/dst" 2025/08/13 01:26:48 DEBUG : Starting OpenDrive session with ID: e2ea8908f4bd8a4b78d7db415ec5c1ba3b103d867b04046fd1f95cf0c75de776 2025/08/13 01:26:49 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/08/13 01:26:49 DEBUG : one: same parent dir (ODFfOTM4MTg4NF9sbHc0Yw) - using file/rename instead of move_copy for one-2019-01-01 2025/08/13 01:26:49 INFO : one: Moved (server-side) to: one-2019-01-01 2025/08/13 01:26:50 DEBUG : one: Uploading chunk 0, size=4, remain=0 2025/08/13 01:26:51 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2025/08/13 01:26:51 INFO : one: Copied (new) 2025/08/13 01:26:51 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/08/13 01:26:51 DEBUG : two: Unchanged skipping 2025/08/13 01:26:51 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/08/13 01:26:52 DEBUG : three.txt: same parent dir (ODFfOTM4MTg4NF9sbHc0Yw) - using file/rename instead of move_copy for three-2019-01-01.txt 2025/08/13 01:26:52 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/08/13 01:26:53 DEBUG : three.txt: Uploading chunk 0, size=6, remain=0 2025/08/13 01:26:54 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2025/08/13 01:26:54 INFO : three.txt: Copied (new) 2025/08/13 01:26:55 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/08/13 01:26:56 INFO : one-2019-01-01: Deleted 2025/08/13 01:26:56 DEBUG : one: same parent dir (ODFfOTM4MTg4NF9sbHc0Yw) - using file/rename instead of move_copy for one-2019-01-01 2025/08/13 01:26:56 INFO : one: Moved (server-side) to: one-2019-01-01 2025/08/13 01:26:57 DEBUG : one: Uploading chunk 0, size=5, remain=0 2025/08/13 01:26:58 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2025/08/13 01:26:58 INFO : one: Copied (new) 2025/08/13 01:26:58 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/08/13 01:26:58 DEBUG : two: Unchanged skipping 2025/08/13 01:26:58 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/08/13 01:26:59 INFO : three-2019-01-01.txt: Deleted 2025/08/13 01:26:59 DEBUG : three.txt: same parent dir (ODFfOTM4MTg4NF9sbHc0Yw) - using file/rename instead of move_copy for three-2019-01-01.txt 2025/08/13 01:26:59 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/08/13 01:26:59 DEBUG : three.txt: Uploading chunk 0, size=19, remain=0 2025/08/13 01:27:00 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2025/08/13 01:27:00 INFO : three.txt: Copied (new) 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:302: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:302 /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:2551 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2554 Error: Should be true Test: TestSyncSuffixKeepExtension Messages: listing wrong, want dst/one (5), dst/one-2019-01-01 (4), dst/three-2019-01-01.txt (6), dst/three.txt (19), dst/two (3) got dst/one (5), dst/one-2019-01-01 (4), dst/three-2019-01-01.txt (19), dst/two (3) fstest.go:140: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:140 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:146 /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:2551 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2554 Error: Should be true Test: TestSyncSuffixKeepExtension Messages: OpenDrive root 'rclone-test-sonirik4gebi'/dst/three-2019-01-01.txt: md5 hash incorrect - expecting "91341eed84691a83caea73aa785736d5" got "423e01c5e84a30d129b97aedb6e219a9" fstest.go:147: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:147 /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:2551 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2554 Error: Not equal: expected: 6 actual : 19 Test: TestSyncSuffixKeepExtension Messages: dst/three-2019-01-01.txt: size incorrect file=6 vs obj=19 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:2551 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2554 Error: Should be true Test: TestSyncSuffixKeepExtension Messages: dst/three-2019-01-01.txt: Modification time difference too big |-95576h54m52.500000001s| > 1s (want 2001-02-03 04:05:06.499999999 +0000 UTC vs got 2011-12-30 12:59:59 +0000 UTC) (precision 1s) fstest.go:200: Not found "dst/three.txt" fstest.go:203: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:203 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:307 /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:2551 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2554 Error: Not equal: expected: 0 actual : 1 Test: TestSyncSuffixKeepExtension Messages: 1 objects not found --- FAIL: TestSyncSuffixKeepExtension (33.64s) === RUN TestTransformFile run.go:180: Remote "OpenDrive root 'rclone-test-sonirik4gebi'", Local "Local file system at /tmp/rclone2989201582", Modify Window "1s" 2025/08/13 01:27:12 DEBUG : empty_dir: Making directory with metadata 2025/08/13 01:27:12 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/08/13 01:27:12 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:12 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:12 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:13 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:13 INFO : tictacempty_dir: Making directory 2025/08/13 01:27:13 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:13 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:13 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:13 INFO : tictactoe: Making directory 2025/08/13 01:27:14 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:14 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:14 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/13 01:27:14 INFO : tictactoe/tictactoe: Making directory 2025/08/13 01:27:14 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/13 01:27:14 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/08/13 01:27:14 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:14 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/08/13 01:27:14 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:14 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:14 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for checks to finish 2025/08/13 01:27:14 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for transfers to finish 2025/08/13 01:27:15 DEBUG : tictactoe/tictactoe/tictactoe.txt: Uploading chunk 0, size=11, remain=0 2025/08/13 01:27:17 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/08/13 01:27:17 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:17 INFO : toe/toe/toe.txt: Deleted 2025/08/13 01:27:17 INFO : toe/toe: Removing directory 2025/08/13 01:27:17 INFO : toe: Removing directory 2025/08/13 01:27:17 INFO : empty_dir: Removing directory 2025/08/13 01:27:17 DEBUG : Local file system at /tmp/rclone2989201582: deleted 3 directories 2025/08/13 01:27:18 DEBUG : tictactoe/tictactoe/tictactoe.txt: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/08/13 01:27:18 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/13 01:27:18 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/13 01:27:18 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/13 01:27:19 INFO : tictactoe/tictactoe/tictactoe.txt: Moved (server-side) to: toe/toe/toe.txt --- PASS: TestTransformFile (10.97s) === RUN TestManualTransformFile run.go:180: Remote "OpenDrive root 'rclone-test-sonirik4gebi'", Local "Local file system at /tmp/rclone2989201582", Modify Window "1s" 2025/08/13 01:27:23 DEBUG : Reset feature "Copy" 2025/08/13 01:27:23 DEBUG : Reset feature "Move" 2025/08/13 01:27:23 DEBUG : Reset feature "Copy" 2025/08/13 01:27:23 DEBUG : Reset feature "Move" 2025/08/13 01:27:23 DEBUG : empty_dir: Making directory with metadata 2025/08/13 01:27:23 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/08/13 01:27:23 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:23 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:23 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:24 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:24 INFO : tictacempty_dir: Making directory 2025/08/13 01:27:24 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/13 01:27:24 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:24 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:24 INFO : tictactoe: Making directory 2025/08/13 01:27:25 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:25 DEBUG : toe: transformed to: tictactoe 2025/08/13 01:27:25 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/13 01:27:25 INFO : tictactoe/tictactoe: Making directory 2025/08/13 01:27:25 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/13 01:27:25 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/08/13 01:27:25 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:25 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/08/13 01:27:25 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:25 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:25 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for checks to finish 2025/08/13 01:27:25 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for transfers to finish 2025/08/13 01:27:26 DEBUG : tictactoe/tictactoe/tictactoe.txt: Uploading chunk 0, size=11, remain=0 2025/08/13 01:27:27 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/08/13 01:27:27 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/08/13 01:27:27 INFO : toe/toe/toe.txt: Deleted 2025/08/13 01:27:27 INFO : toe/toe: Removing directory 2025/08/13 01:27:27 INFO : toe: Removing directory 2025/08/13 01:27:27 INFO : empty_dir: Removing directory 2025/08/13 01:27:27 DEBUG : Local file system at /tmp/rclone2989201582: deleted 3 directories 2025/08/13 01:27:29 DEBUG : tictactoe/tictactoe/tictactoe.txt: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/08/13 01:27:29 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/13 01:27:29 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/13 01:27:29 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/13 01:27:30 DEBUG : toe/toe/toe.txt: Uploading chunk 0, size=11, remain=0 2025/08/13 01:27:31 DEBUG : tictactoe/tictactoe/tictactoe.txt: Src hash empty - aborting Dst hash check 2025/08/13 01:27:31 INFO : tictactoe/tictactoe/tictactoe.txt: Copied (new) to: toe/toe/toe.txt 2025/08/13 01:27:32 INFO : tictactoe/tictactoe/tictactoe.txt: Deleted --- PASS: TestManualTransformFile (16.40s) === RUN TestBase64 run.go:180: Remote "OpenDrive root 'rclone-test-sonirik4gebi'", Local "Local file system at /tmp/rclone2989201582", Modify Window "1s" 2025/08/13 01:27:40 DEBUG : toe: transformed to: dG9l 2025/08/13 01:27:40 DEBUG : toe: transformed to: dG9l 2025/08/13 01:27:40 INFO : dG9l: Making directory 2025/08/13 01:27:40 DEBUG : toe: transformed to: dG9l 2025/08/13 01:27:40 DEBUG : toe: transformed to: dG9l 2025/08/13 01:27:40 DEBUG : toe/toe: transformed to: dG9l/dG9l 2025/08/13 01:27:40 INFO : dG9l/dG9l: Making directory 2025/08/13 01:27:41 DEBUG : toe/toe: transformed to: dG9l/dG9l 2025/08/13 01:27:41 DEBUG : toe.txt: transformed to: dG9lLnR4dA== 2025/08/13 01:27:41 DEBUG : toe/toe/toe.txt: transformed to: dG9l/dG9l/dG9lLnR4dA== 2025/08/13 01:27:41 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/08/13 01:27:41 DEBUG : toe/toe/toe.txt: transformed to: dG9l/dG9l/dG9lLnR4dA== 2025/08/13 01:27:41 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for checks to finish 2025/08/13 01:27:41 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Waiting for transfers to finish 2025/08/13 01:27:42 DEBUG : dG9l/dG9l/dG9lLnR4dA==: Uploading chunk 0, size=11, remain=0 2025/08/13 01:27:43 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/08/13 01:27:43 INFO : toe/toe/toe.txt: Copied (new) to: dG9l/dG9l/dG9lLnR4dA== 2025/08/13 01:27:43 DEBUG : Waiting for deletions to finish 2025/08/13 01:27:44 DEBUG : dG9l: transformed to: toe 2025/08/13 01:27:44 DEBUG : dG9l: transformed to: toe 2025/08/13 01:27:44 DEBUG : toe: Directory modification time the same (differ by -800.141791ms, within tolerance 1s) 2025/08/13 01:27:44 DEBUG : Added delayed dir = "toe", newDst=toe 2025/08/13 01:27:44 DEBUG : dG9l: transformed to: toe 2025/08/13 01:27:44 DEBUG : dG9l/dG9l: transformed to: toe/toe 2025/08/13 01:27:44 INFO : toe/toe: Set directory modification time (using SetModTime) 2025/08/13 01:27:44 DEBUG : Added delayed dir = "toe/toe", newDst=toe/toe 2025/08/13 01:27:45 DEBUG : dG9lLnR4dA==: transformed to: toe.txt 2025/08/13 01:27:45 DEBUG : Local file system at /tmp/rclone2989201582: Waiting for checks to finish 2025/08/13 01:27:45 DEBUG : dG9l/dG9l/dG9lLnR4dA==: Size and modification time the same (differ by 499.999999ms, within tolerance 1s) 2025/08/13 01:27:45 DEBUG : dG9l/dG9l/dG9lLnR4dA==: transformed to: toe/toe/toe.txt 2025/08/13 01:27:45 DEBUG : dG9l/dG9l/dG9lLnR4dA==: Unchanged skipping 2025/08/13 01:27:45 DEBUG : Local file system at /tmp/rclone2989201582: Waiting for transfers to finish 2025/08/13 01:27:45 DEBUG : Waiting for deletions to finish --- PASS: TestBase64 (10.22s) FAIL 2025/08/13 01:27:50 DEBUG : OpenDrive root 'rclone-test-sonirik4gebi': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestBase64|TestCopyWithFilesFrom|TestManualTransformFile|TestSyncSuffixKeepExtension|TestTransformFile)$'" - Finished ERROR in 1m19.605066354s (try 2/5): exit status 1: Failed [TestSyncSuffixKeepExtension]