"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestBase64|TestManualTransformFile|TestServerSideMoveOverSelf|TestTransformFile)$'" - Starting (try 2/5) 2025/08/23 02:16:45 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-qamazij5quza" 2025/08/23 02:16:45 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/08/23 02:16:45 DEBUG : Creating backend with remote "/tmp/rclone3415168480" === RUN TestServerSideMoveOverSelf run.go:180: Remote "files root 'rclone-test-qamazij5quza'", Local "Local file system at /tmp/rclone3415168480", Modify Window "1s" 2025/08/23 02:16:48 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-luriduh7newi" sync_test.go:701: Server side copy (if possible) files root 'rclone-test-qamazij5quza' -> files root 'rclone-test-luriduh7newi' 2025/08/23 02:16:49 DEBUG : Added delayed dir = "sub dir", newDst= 2025/08/23 02:16:49 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/08/23 02:16:49 DEBUG : files root 'rclone-test-luriduh7newi': Waiting for checks to finish 2025/08/23 02:16:49 DEBUG : files root 'rclone-test-luriduh7newi': Waiting for transfers to finish 2025/08/23 02:16:50 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/08/23 02:16:50 INFO : sub dir/hello world: Copied (server-side copy) 2025/08/23 02:16:51 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/08/23 02:16:52 DEBUG : files root 'rclone-test-luriduh7newi': Using server-side directory move 2025/08/23 02:16:53 INFO : files root 'rclone-test-luriduh7newi': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/08/23 02:16:53 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/08/23 02:16:53 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/08/23 02:16:53 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/08/23 02:16:53 DEBUG : files root 'rclone-test-luriduh7newi': Waiting for checks to finish 2025/08/23 02:16:53 DEBUG : files root 'rclone-test-luriduh7newi': Waiting for transfers to finish 2025/08/23 02:16:53 INFO : sub dir/hello world: Deleted 2025/08/23 02:16:54 INFO : sub dir/hello world: Moved (server-side) 2025/08/23 02:16:54 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/08/23 02:16:56 DEBUG : testing file moves 2025/08/23 02:16:56 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/08/23 02:16:56 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/08/23 02:16:56 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17) 2025/08/23 02:16:56 DEBUG : files root 'rclone-test-luriduh7newi': Waiting for checks to finish 2025/08/23 02:16:56 DEBUG : files root 'rclone-test-luriduh7newi': Waiting for transfers to finish 2025/08/23 02:16:56 INFO : sub dir/hello world: Deleted 2025/08/23 02:16:57 INFO : sub dir/hello world: Moved (server-side) 2025/08/23 02:16:57 INFO : sub dir: Set directory modification time (using DirSetModTime) Diff of "logger" and "lsf" 2c2 < 2011-12-30 12:59:59;;24;sub dir/hello world --- > 2011-12-30 12:59:59;c0e6b00e2b2068ef74d2ed582114e376;24;sub dir/hello world sync_test.go:3104: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:3104 /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;;24;sub dir/hello world lsf: 2011-12-30 12:59:59;c0e6b00e2b2068ef74d2ed582114e376;24;sub dir/hello world Test: TestServerSideMoveOverSelf 2025/08/23 02:16:57 DEBUG : files root 'rclone-test-luriduh7newi': Purge remote --- FAIL: TestServerSideMoveOverSelf (12.86s) === RUN TestTransformFile run.go:180: Remote "files root 'rclone-test-qamazij5quza'", Local "Local file system at /tmp/rclone3415168480", Modify Window "1s" 2025/08/23 02:16:58 DEBUG : empty_dir: Making directory with metadata 2025/08/23 02:16:58 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/08/23 02:16:58 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:16:58 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:16:58 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:16:58 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:16:58 INFO : tictacempty_dir: Making directory 2025/08/23 02:16:59 INFO : tictacempty_dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/08/23 02:16:59 DEBUG : Added delayed dir = "tictacempty_dir", newDst= 2025/08/23 02:16:59 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:16:59 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:16:59 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:16:59 INFO : tictactoe: Making directory 2025/08/23 02:16:59 INFO : tictactoe: Made directory with modification time 2025-08-23 02:16:58.581116317 +0000 UTC 2025/08/23 02:16:59 DEBUG : Added delayed dir = "tictactoe", newDst= 2025/08/23 02:16:59 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:16:59 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:16:59 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/23 02:16:59 INFO : tictactoe/tictactoe: Making directory 2025/08/23 02:16:59 INFO : tictactoe/tictactoe: Made directory with modification time 2025-08-23 02:16:58.581116317 +0000 UTC 2025/08/23 02:16:59 DEBUG : Added delayed dir = "tictactoe/tictactoe", newDst= 2025/08/23 02:16:59 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/23 02:16:59 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/08/23 02:16:59 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:16:59 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/08/23 02:16:59 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:16:59 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:16:59 DEBUG : files root 'rclone-test-qamazij5quza': Waiting for checks to finish 2025/08/23 02:16:59 DEBUG : files root 'rclone-test-qamazij5quza': Waiting for transfers to finish 2025/08/23 02:17:00 DEBUG : tictactoe/tictactoe/tictactoe.txt: Dst hash empty - aborting Src hash check 2025/08/23 02:17:00 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:17:00 INFO : toe/toe/toe.txt: Deleted 2025/08/23 02:17:00 INFO : tictactoe/tictactoe: Set directory modification time (using DirSetModTime) 2025/08/23 02:17:00 INFO : tictactoe: Set directory modification time (using DirSetModTime) 2025/08/23 02:17:00 INFO : tictacempty_dir: Set directory modification time (using DirSetModTime) 2025/08/23 02:17:00 INFO : toe/toe: Removing directory 2025/08/23 02:17:00 INFO : toe: Removing directory 2025/08/23 02:17:00 INFO : empty_dir: Removing directory 2025/08/23 02:17:00 DEBUG : Local file system at /tmp/rclone3415168480: deleted 3 directories 2025/08/23 02:17:01 DEBUG : tictactoe/tictactoe/tictactoe.txt: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/08/23 02:17:01 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/23 02:17:01 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/23 02:17:01 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/08/23 02:17:02 INFO : tictactoe/tictactoe/tictactoe.txt: Moved (server-side) to: toe/toe/toe.txt --- PASS: TestTransformFile (5.58s) === RUN TestManualTransformFile run.go:180: Remote "files root 'rclone-test-qamazij5quza'", Local "Local file system at /tmp/rclone3415168480", Modify Window "1s" 2025/08/23 02:17:04 DEBUG : Reset feature "Copy" 2025/08/23 02:17:04 DEBUG : Reset feature "Move" 2025/08/23 02:17:04 DEBUG : Reset feature "Copy" 2025/08/23 02:17:04 DEBUG : Reset feature "Move" 2025/08/23 02:17:04 DEBUG : empty_dir: Making directory with metadata 2025/08/23 02:17:04 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/08/23 02:17:04 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:17:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:17:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:17:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:17:04 INFO : tictacempty_dir: Making directory 2025/08/23 02:17:04 INFO : tictacempty_dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/08/23 02:17:04 DEBUG : Added delayed dir = "tictacempty_dir", newDst= 2025/08/23 02:17:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/08/23 02:17:04 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:17:04 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:17:04 INFO : tictactoe: Making directory 2025/08/23 02:17:04 INFO : tictactoe: Made directory with modification time 2025-08-23 02:17:04.164133136 +0000 UTC 2025/08/23 02:17:04 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:17:04 DEBUG : toe: transformed to: tictactoe 2025/08/23 02:17:04 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/23 02:17:04 INFO : tictactoe/tictactoe: Making directory 2025/08/23 02:17:05 INFO : tictactoe/tictactoe: Made directory with modification time 2025-08-23 02:17:04.164133136 +0000 UTC 2025/08/23 02:17:05 DEBUG : Added delayed dir = "tictactoe/tictactoe", newDst= 2025/08/23 02:17:05 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/08/23 02:17:05 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/08/23 02:17:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:17:05 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/08/23 02:17:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:17:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:17:05 DEBUG : files root 'rclone-test-qamazij5quza': Waiting for checks to finish 2025/08/23 02:17:05 DEBUG : files root 'rclone-test-qamazij5quza': Waiting for transfers to finish 2025/08/23 02:17:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: Dst hash empty - aborting Src hash check 2025/08/23 02:17:06 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/08/23 02:17:06 INFO : toe/toe/toe.txt: Deleted 2025/08/23 02:17:06 INFO : tictactoe/tictactoe: Set directory modification time (using DirSetModTime) 2025/08/23 02:17:06 ERROR : tictacempty_dir: Failed to update directory timestamp or metadata: Not Found - `Not Found. This may be related to your permissions.` 2025/08/23 02:17:06 ERROR : Local file system at /tmp/rclone3415168480: 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 (3.20s) === RUN TestBase64 run.go:180: Remote "files root 'rclone-test-qamazij5quza'", Local "Local file system at /tmp/rclone3415168480", Modify Window "1s" 2025/08/23 02:17:07 DEBUG : toe: transformed to: dG9l 2025/08/23 02:17:07 DEBUG : toe: transformed to: dG9l 2025/08/23 02:17:07 INFO : dG9l: Making directory 2025/08/23 02:17:07 INFO : dG9l: Made directory with modification time 2025-08-23 02:17:07.362142769 +0000 UTC 2025/08/23 02:17:07 DEBUG : Added delayed dir = "dG9l", newDst= 2025/08/23 02:17:07 DEBUG : toe: transformed to: dG9l 2025/08/23 02:17:07 DEBUG : toe: transformed to: dG9l 2025/08/23 02:17:07 DEBUG : toe/toe: transformed to: dG9l/dG9l 2025/08/23 02:17:07 INFO : dG9l/dG9l: Making directory 2025/08/23 02:17:08 INFO : dG9l/dG9l: Made directory with modification time 2025-08-23 02:17:07.362142769 +0000 UTC 2025/08/23 02:17:08 DEBUG : Added delayed dir = "dG9l/dG9l", newDst= 2025/08/23 02:17:08 DEBUG : toe/toe: transformed to: dG9l/dG9l 2025/08/23 02:17:08 DEBUG : toe.txt: transformed to: dG9lLnR4dA== 2025/08/23 02:17:08 DEBUG : toe/toe/toe.txt: transformed to: dG9l/dG9l/dG9lLnR4dA== 2025/08/23 02:17:08 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/08/23 02:17:08 DEBUG : toe/toe/toe.txt: transformed to: dG9l/dG9l/dG9lLnR4dA== 2025/08/23 02:17:08 DEBUG : files root 'rclone-test-qamazij5quza': Waiting for checks to finish 2025/08/23 02:17:08 DEBUG : files root 'rclone-test-qamazij5quza': Waiting for transfers to finish 2025/08/23 02:17:09 DEBUG : dG9l/dG9l/dG9lLnR4dA==: Dst hash empty - aborting Src hash check 2025/08/23 02:17:09 INFO : toe/toe/toe.txt: Copied (new) to: dG9l/dG9l/dG9lLnR4dA== 2025/08/23 02:17:09 ERROR : files root 'rclone-test-qamazij5quza': not deleting files as there were IO errors 2025/08/23 02:17:09 INFO : dG9l/dG9l: Set directory modification time (using DirSetModTime) 2025/08/23 02:17:09 INFO : dG9l: Set directory modification time (using DirSetModTime) 2025/08/23 02:17:09 ERROR : files root 'rclone-test-qamazij5quza': 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 2025/08/23 02:17:10 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-qamazij5quza/dG9l not empty`) 2025/08/23 02:17:10 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/08/23 02:17:10 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-qamazij5quza/dG9l not empty`) 2025/08/23 02:17:10 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/08/23 02:17:10 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-qamazij5quza/dG9l not empty`) 2025/08/23 02:17:10 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/08/23 02:17:10 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-qamazij5quza/dG9l not empty`) 2025/08/23 02:17:10 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/08/23 02:17:10 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-qamazij5quza/dG9l not empty`) 2025/08/23 02:17:10 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/08/23 02:17:10 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-qamazij5quza/dG9l not empty`) 2025/08/23 02:17:10 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/08/23 02:17:11 DEBUG : pacer: Reducing sleep to 480ms 2025/08/23 02:17:11 DEBUG : pacer: Reducing sleep to 360ms --- FAIL: TestBase64 (4.50s) FAIL 2025/08/23 02:17:11 DEBUG : files root 'rclone-test-qamazij5quza': Purge remote 2025/08/23 02:17:12 DEBUG : pacer: Reducing sleep to 270ms "./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestBase64|TestManualTransformFile|TestServerSideMoveOverSelf|TestTransformFile)$'" - Finished ERROR in 27.390417526s (try 2/5): exit status 1: Failed [TestServerSideMoveOverSelf TestManualTransformFile TestBase64]