"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Starting (try 1/5) 2024/04/12 05:04:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9" 2024/04/12 05:04:34 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/04/12 05:04:34 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc" 2024/04/12 05:04:35 DEBUG : Creating backend with remote "/tmp/rclone1145245598" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.03s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:36 NOTICE: sub dir: Skipped make directory as --dry-run is set 2024/04/12 05:04:36 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:04:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:04:36 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2024/04/12 05:04:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestCopyWithDryRun (2.63s) === RUN TestCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:38 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/12 05:04:38 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:04:39 INFO : sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:04:39 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:04:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:04:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:04:41 DEBUG : sub dir/hello world: md5 = 1a9f83a30ee0cda9f7bc510cb84f825b OK 2024/04/12 05:04:41 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:43 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (7.16s) === RUN TestCopyMetadata run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:45 DEBUG : metadata sub dir: Making directory with metadata 2024/04/12 05:04:45 INFO : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:04:45 DEBUG : Local file system at /tmp/rclone1145245598: File to upload is small (21 bytes), uploading instead of streaming 2024/04/12 05:04:45 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK 2024/04/12 05:04:45 DEBUG : metadata sub dir/hello metadata world.pehelub7.partial: renamed to: metadata sub dir/hello metadata world 2024/04/12 05:04:45 INFO : metadata sub dir/hello metadata world: Copied (new) 2024/04/12 05:04:45 INFO : metadata sub dir: Set directory modification time (using DirSetModTime) 2024/04/12 05:04:45 DEBUG : Google drive root 'crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc': Skipping btime metadata as can't update it on an existing file: 2024-04-12T05:04:45.406330572Z 2024/04/12 05:04:46 INFO : metadata sub dir: Updated directory metadata 2024/04/12 05:04:46 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination 2024/04/12 05:04:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:04:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:04:48 DEBUG : metadata sub dir/hello metadata world: md5 = 07722ca1290fbbb3dcc7a85b15706dde OK 2024/04/12 05:04:48 INFO : metadata sub dir/hello metadata world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:51 DEBUG : fg45q1rm3kh00nmmkk4m6ihmrcnel1p7551kqhjr9bk2gtd2gbf0: Rmdir: contains trashed file: "dmuvulfij81f693ur0f1vvbvq9v6iscp56daas3m51n9li5e3470" --- PASS: TestCopyMetadata (7.52s) === RUN TestCopyMissingDirectory run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:52 DEBUG : Creating backend with remote "/non-existing" 2024/04/12 05:04:53 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2024/04/12 05:04:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:04:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestCopyMissingDirectory (1.45s) === RUN TestCopyNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:54 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:04:55 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:04:54.378336067Z) 2024/04/12 05:04:55 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:04:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:04:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:04:57 DEBUG : sub dir/hello world: md5 = c71ec032ce2ba584a0aace1722b46552 OK 2024/04/12 05:04:57 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:04:59 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (6.58s) === RUN TestCopyCheckFirst run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:00 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Running all checks before starting transfers 2024/04/12 05:05:01 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:05:02 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:05:00.958340062Z) 2024/04/12 05:05:02 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:05:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:02 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Checks finished, now starting transfers 2024/04/12 05:05:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:04 DEBUG : sub dir/hello world: md5 = 88b68137164884f279c0e38eaa581f8f OK 2024/04/12 05:05:04 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:06 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (6.90s) === RUN TestSyncNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:07 ERROR : Ignoring --no-traverse with sync 2024/04/12 05:05:08 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:05:09 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:05:07.854344219Z) 2024/04/12 05:05:09 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:05:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:10 DEBUG : sub dir/hello world: md5 = d28c91559bad2fbd9a7ea00ec32b8279 OK 2024/04/12 05:05:10 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:05:10 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:12 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (6.53s) === RUN TestCopyWithDepth run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:14 DEBUG : hello world2: Need to transfer - File not found at Destination 2024/04/12 05:05:14 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:05:15 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:05:14.38634813Z) 2024/04/12 05:05:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:16 DEBUG : hello world2: md5 = 42c7aff0d397fbfe4b115effdc47a69f OK 2024/04/12 05:05:16 INFO : hello world2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestCopyWithDepth (6.15s) === RUN TestCopyWithFilesFrom run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:20 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:05:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:22 DEBUG : potato2: md5 = 9beac76013cf8e704edc7f3e489d9f27 OK 2024/04/12 05:05:22 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestCopyWithFilesFrom (4.25s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:25 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:05:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:26 DEBUG : potato2: md5 = 609e1235586ff75311ee4fe11787568f OK 2024/04/12 05:05:26 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestCopyWithFilesFromAndNoTraverse (4.15s) === RUN TestCopyEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:28 DEBUG : sub dir2: Making directory with metadata 2024/04/12 05:05:28 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:05:28 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/12 05:05:29 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:05:30 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2024/04/12 05:05:30 DEBUG : sub dir2: Making directory with metadata 2024/04/12 05:05:31 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:05:31 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:05:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:33 DEBUG : sub dir/hello world: md5 = 0beba40319178d73f365d85d6c414445 OK 2024/04/12 05:05:33 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:05:33 DEBUG : sub dir2: Making directory 2024/04/12 05:05:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': copied 1 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:37 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (9.95s) === RUN TestMoveEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:38 DEBUG : sub dir2: Making directory with metadata 2024/04/12 05:05:38 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:05:39 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:05:40 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:05:38.886362562Z) 2024/04/12 05:05:40 DEBUG : sub dir2: Making directory with metadata 2024/04/12 05:05:41 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:05:41 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:05:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:43 DEBUG : sub dir/hello world: md5 = 339c98084559b0e54d44bca2a1be3507 OK 2024/04/12 05:05:43 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:05:43 INFO : sub dir/hello world: Deleted 2024/04/12 05:05:43 DEBUG : sub dir: Making directory 2024/04/12 05:05:43 DEBUG : sub dir2: Making directory 2024/04/12 05:05:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': copied 2 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:47 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (9.96s) === RUN TestSyncNoUpdateDirModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:48 DEBUG : sub dir no update dir modtime: Making directory with metadata 2024/04/12 05:05:48 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2024/04/12 05:05:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:50 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncNoUpdateDirModtime (5.18s) === RUN TestSyncEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:05:54 DEBUG : sub dir2: Making directory with metadata 2024/04/12 05:05:54 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:05:54 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/12 05:05:54 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:05:55 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2024/04/12 05:05:55 DEBUG : sub dir2: Making directory with metadata 2024/04/12 05:05:56 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/12 05:05:56 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:05:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:05:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:05:58 DEBUG : sub dir/hello world: md5 = 3ef163bf4d6fbc5e8a07a06ef8e71eca OK 2024/04/12 05:05:58 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:05:58 DEBUG : sub dir2: Making directory 2024/04/12 05:05:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': copied 1 directories 2024/04/12 05:05:58 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:01 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (9.43s) === RUN TestSyncSetDelayedModTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:427: Backend doesn't have DirModTimeUpdatesOnWrite set --- SKIP: TestSyncSetDelayedModTimes (0.54s) === RUN TestServerSideCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:06 DEBUG : sub dir/hello world: md5 = 45f57c675fe99db3f64fcca1e0799cf6 OK 2024/04/12 05:06:07 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-kedeyed7yimayax3wubeheg4" 2024/04/12 05:06:07 DEBUG : Creating backend with remote "TestDrive:crypt/fd2qm72cjvgt8d1hdrbj33c74fqjvdf78l23md50tvj99k58d08vimadaioe07k3klc4pgal9cmrk" sync_test.go:487: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9' -> Encrypted drive 'TestCryptDrive:rclone-test-kedeyed7yimayax3wubeheg4' 2024/04/12 05:06:08 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:06:11 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:06:04.601Z) 2024/04/12 05:06:11 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:06:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kedeyed7yimayax3wubeheg4': Waiting for checks to finish 2024/04/12 05:06:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kedeyed7yimayax3wubeheg4': Waiting for transfers to finish 2024/04/12 05:06:12 INFO : sub dir/hello world: Copied (server-side copy) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kedeyed7yimayax3wubeheg4': Purge remote 2024/04/12 05:06:15 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (13.01s) === RUN TestCopyAfterDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:19 DEBUG : sub dir/hello world: md5 = 5e0cbda78e20f9e8e232100bfcc0da11 OK 2024/04/12 05:06:19 ERROR : : error listing: directory not found 2024/04/12 05:06:20 DEBUG : Local file system at /tmp/rclone1145245598: Making directory 2024/04/12 05:06:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:22 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (7.67s) === RUN TestCopyRedownload run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:27 DEBUG : sub dir/hello world: md5 = 5976022378f909f396ea17d69b84cc23 OK 2024/04/12 05:06:28 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:06:28 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:06:25.314Z) 2024/04/12 05:06:28 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2024/04/12 05:06:28 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:06:28 DEBUG : Local file system at /tmp/rclone1145245598: Waiting for checks to finish 2024/04/12 05:06:28 DEBUG : Local file system at /tmp/rclone1145245598: Waiting for transfers to finish 2024/04/12 05:06:29 DEBUG : sub dir/hello world.dufosoh4.partial: renamed to: sub dir/hello world 2024/04/12 05:06:29 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:06:29 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:31 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (8.28s) === RUN TestSyncBasedOnCheckSum run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:33 DEBUG : check sum: Need to transfer - File not found at Destination 2024/04/12 05:06:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:35 DEBUG : check sum: md5 = 0dfc36d9178e659e60f5c677d6ae4a18 OK 2024/04/12 05:06:35 INFO : check sum: Copied (new) 2024/04/12 05:06:35 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:35 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2024/04/12 05:06:35 DEBUG : check sum: Size of src and dst objects identical 2024/04/12 05:06:35 DEBUG : check sum: Unchanged skipping 2024/04/12 05:06:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:35 DEBUG : Waiting for deletions to finish 2024/04/12 05:06:35 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncBasedOnCheckSum (5.21s) === RUN TestSyncSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:38 DEBUG : sizeonly: Need to transfer - File not found at Destination 2024/04/12 05:06:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:40 DEBUG : sizeonly: md5 = 6736113b8b90a892452b32c846177467 OK 2024/04/12 05:06:40 INFO : sizeonly: Copied (new) 2024/04/12 05:06:40 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:40 DEBUG : sizeonly: Sizes identical 2024/04/12 05:06:40 DEBUG : sizeonly: Unchanged skipping 2024/04/12 05:06:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:40 DEBUG : Waiting for deletions to finish 2024/04/12 05:06:40 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncSizeOnly (5.32s) === RUN TestSyncIgnoreSize run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:43 DEBUG : ignore-size: Need to transfer - File not found at Destination 2024/04/12 05:06:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:45 DEBUG : ignore-size: md5 = 2d96b3ddf176b8cccedb25d5be0f5c36 OK 2024/04/12 05:06:45 INFO : ignore-size: Copied (new) 2024/04/12 05:06:45 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:45 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:06:45 DEBUG : ignore-size: Unchanged skipping 2024/04/12 05:06:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:45 DEBUG : Waiting for deletions to finish 2024/04/12 05:06:45 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncIgnoreSize (5.03s) === RUN TestSyncIgnoreTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:50 DEBUG : existing: md5 = 1d5dbb0a737ec4afb681fe9a6d3ab8a5 OK 2024/04/12 05:06:50 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:06:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:50 DEBUG : existing: Unchanged skipping 2024/04/12 05:06:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:50 DEBUG : Waiting for deletions to finish 2024/04/12 05:06:50 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:51 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2024/04/12 05:06:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:52 DEBUG : existing: md5 = d6e921f4671ea9e41ae167917686c8e9 OK 2024/04/12 05:06:52 INFO : existing: Copied (replaced existing) 2024/04/12 05:06:52 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncIgnoreTimes (6.66s) === RUN TestSyncIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:55 DEBUG : existing: Need to transfer - File not found at Destination 2024/04/12 05:06:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:57 DEBUG : existing: md5 = bdaa398d7ea60eb1a0637a8b2094fa48 OK 2024/04/12 05:06:57 INFO : existing: Copied (new) 2024/04/12 05:06:57 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:06:57 DEBUG : existing: Destination exists, skipping 2024/04/12 05:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:06:57 DEBUG : Waiting for deletions to finish 2024/04/12 05:06:57 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncIgnoreExisting (5.06s) === RUN TestSyncIgnoreErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:03 DEBUG : b/potato: md5 = 81a47efdb3bcd1bded3b5dda47b5bbd4 OK 2024/04/12 05:07:06 DEBUG : c/non empty space: md5 = fdfe8a76ae69ff155e5a8bbbe7964bd8 OK 2024/04/12 05:07:06 DEBUG : d: Making directory 2024/04/12 05:07:08 DEBUG : a: Making directory with metadata 2024/04/12 05:07:09 INFO : a: Made directory with metadata (mtime=2024-04-12T05:07:00.238408029Z) 2024/04/12 05:07:10 INFO : c: Set directory modification time (using SetModTime) 2024/04/12 05:07:10 DEBUG : a/potato2: Need to transfer - File not found at Destination 2024/04/12 05:07:10 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:07:10 DEBUG : c/non empty space: Unchanged skipping 2024/04/12 05:07:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:11 DEBUG : a/potato2: md5 = ba6d034cc77026f1e40f65c8d301b414 OK 2024/04/12 05:07:11 INFO : a/potato2: Copied (new) 2024/04/12 05:07:11 DEBUG : Waiting for deletions to finish 2024/04/12 05:07:12 INFO : b/potato: Deleted 2024/04/12 05:07:12 INFO : d: Removing directory 2024/04/12 05:07:13 INFO : b: Removing directory 2024/04/12 05:07:13 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2024/04/12 05:07:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': deleted 2 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:16 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2024/04/12 05:07:17 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (19.13s) === RUN TestSyncAfterChangingModtimeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:20 DEBUG : empty space: md5 = c81ff13efada9b977bc041c083a88c8f OK 2024/04/12 05:07:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:21 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 2024/04/12 05:07:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:21 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2024/04/12 05:07:21 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:22 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 2024/04/12 05:07:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:23 DEBUG : empty space: md5 = 33e9500ba85f65243ae123d05f28f374 OK 2024/04/12 05:07:23 INFO : empty space: Copied (replaced existing) 2024/04/12 05:07:23 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncAfterChangingModtimeOnly (6.89s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:811: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.54s) === RUN TestSyncDoesntUpdateModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:28 DEBUG : foo: md5 = da7fd0ee32582110a0a3e92cabd7acac OK 2024/04/12 05:07:29 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2024/04/12 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:30 DEBUG : foo: md5 = 9fdbefc79fdadfd43b07067bf5425576 OK 2024/04/12 05:07:30 INFO : foo: Copied (replaced existing) 2024/04/12 05:07:30 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncDoesntUpdateModtime (6.44s) === RUN TestSyncAfterAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:34 DEBUG : empty space: md5 = 85bb9e24a6900184763d13fbd8e6892c OK 2024/04/12 05:07:35 DEBUG : potato: Need to transfer - File not found at Destination 2024/04/12 05:07:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:35 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:07:35 DEBUG : empty space: Unchanged skipping 2024/04/12 05:07:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:37 DEBUG : potato: md5 = 71782a571a4974bbe693c210d1d8bb26 OK 2024/04/12 05:07:37 INFO : potato: Copied (new) 2024/04/12 05:07:37 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncAfterAddingAFile (6.81s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:41 DEBUG : potato: md5 = 518b78ed2cf086da4d6d47d8b476e95a OK 2024/04/12 05:07:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:42 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2024/04/12 05:07:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:43 DEBUG : potato: md5 = e6836ade82350f4a446eab8ed47b5a4a OK 2024/04/12 05:07:43 INFO : potato: Copied (replaced existing) 2024/04/12 05:07:43 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncAfterChangingFilesSizeOnly (5.98s) === RUN TestSyncAfterChangingContentsOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:48 DEBUG : potato: md5 = 0adbce3ac242168a0531892808edad91 OK 2024/04/12 05:07:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:48 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2024/04/12 05:07:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:50 DEBUG : potato: md5 = 876bc721d56f7bbd8de3589c1bbb0426 OK 2024/04/12 05:07:50 INFO : potato: Copied (replaced existing) 2024/04/12 05:07:50 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncAfterChangingContentsOnly (6.10s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:07:53 DEBUG : potato: md5 = 0b7641f2cf908beb30ccb1b5296d7647 OK 2024/04/12 05:07:55 DEBUG : empty space: md5 = 6357bdd22e363852cc18478d447e6cf6 OK 2024/04/12 05:07:55 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:07:55 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2024/04/12 05:07:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:07:55 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:07:55 DEBUG : empty space: Unchanged skipping 2024/04/12 05:07:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:07:55 DEBUG : Waiting for deletions to finish 2024/04/12 05:07:55 NOTICE: potato: Skipped delete as --dry-run is set (size 21) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (6.45s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:00 DEBUG : potato: md5 = 5225104a6c1db58e317714049acfbab5 OK 2024/04/12 05:08:01 DEBUG : empty space: md5 = e8837f7479dd8de01cf78fe518ab6483 OK 2024/04/12 05:08:03 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:08:03 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:08:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:08:03 DEBUG : empty space: Unchanged skipping 2024/04/12 05:08:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:08:04 DEBUG : potato2: md5 = 98f9ea17b462cbca30899d92593b53f1 OK 2024/04/12 05:08:04 INFO : potato2: Copied (new) 2024/04/12 05:08:04 DEBUG : Waiting for deletions to finish 2024/04/12 05:08:05 INFO : potato: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (9.70s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:11 DEBUG : b/potato: md5 = 856b1e07c75836bedfb483fec17882fc OK 2024/04/12 05:08:13 DEBUG : c/non empty space: md5 = 3001a53b38b779067a019de5ece3e97a OK 2024/04/12 05:08:13 DEBUG : d: Making directory 2024/04/12 05:08:15 DEBUG : d/e: Making directory 2024/04/12 05:08:17 DEBUG : a: Making directory with metadata 2024/04/12 05:08:18 INFO : a: Made directory with metadata (mtime=2024-04-12T05:08:08.274443491Z) 2024/04/12 05:08:19 INFO : c: Set directory modification time (using SetModTime) 2024/04/12 05:08:19 DEBUG : a/potato2: Need to transfer - File not found at Destination 2024/04/12 05:08:19 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:08:19 DEBUG : c/non empty space: Unchanged skipping 2024/04/12 05:08:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:08:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:08:20 DEBUG : a/potato2: md5 = 4e09e50c220d24540db782cf1614377b OK 2024/04/12 05:08:20 INFO : a/potato2: Copied (new) 2024/04/12 05:08:20 DEBUG : Waiting for deletions to finish 2024/04/12 05:08:21 INFO : b/potato: Deleted 2024/04/12 05:08:21 INFO : d/e: Removing directory 2024/04/12 05:08:22 INFO : d: Removing directory 2024/04/12 05:08:22 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2024/04/12 05:08:23 INFO : b: Removing directory 2024/04/12 05:08:23 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2024/04/12 05:08:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:27 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2024/04/12 05:08:28 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (21.52s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:32 DEBUG : b/potato: md5 = 2eb409db578f82c83d1356a0210fc099 OK 2024/04/12 05:08:35 DEBUG : c/non empty space: md5 = d4318e4d133a7fa8257608c0c0511e10 OK 2024/04/12 05:08:35 DEBUG : d: Making directory 2024/04/12 05:08:37 DEBUG : a: Making directory with metadata 2024/04/12 05:08:38 INFO : a: Made directory with metadata (mtime=2024-04-12T05:08:29.790454265Z) 2024/04/12 05:08:39 INFO : c: Set directory modification time (using SetModTime) 2024/04/12 05:08:39 DEBUG : a/potato2: Need to transfer - File not found at Destination 2024/04/12 05:08:39 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:08:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:08:39 DEBUG : c/non empty space: Unchanged skipping 2024/04/12 05:08:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:08:40 DEBUG : a/potato2: md5 = 55f733d62df593a6d181ac3ef5c02db2 OK 2024/04/12 05:08:40 INFO : a/potato2: Copied (new) 2024/04/12 05:08:40 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': not deleting files as there were IO errors 2024/04/12 05:08:40 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:45 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2024/04/12 05:08:46 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2024/04/12 05:08:47 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (19.49s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:50 DEBUG : potato: md5 = 9956273afddbe64e42e09a7d412e2194 OK 2024/04/12 05:08:52 DEBUG : empty space: md5 = 330be21f8d6df417e2ca4e4cb92168ec OK 2024/04/12 05:08:52 DEBUG : Waiting for deletions to finish 2024/04/12 05:08:53 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:08:53 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:08:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:08:53 DEBUG : empty space: Unchanged skipping 2024/04/12 05:08:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:08:53 INFO : potato: Deleted 2024/04/12 05:08:54 DEBUG : potato2: md5 = 5c403847d153b1f52e880989a850614f OK 2024/04/12 05:08:54 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncDeleteDuring (8.43s) === RUN TestSyncDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:08:59 DEBUG : potato: md5 = 68b95aed1b72acb201c8ead66635c1a7 OK 2024/04/12 05:09:01 DEBUG : empty space: md5 = 0377f600a13402494512b93f9643aab9 OK 2024/04/12 05:09:01 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:02 INFO : potato: Deleted 2024/04/12 05:09:02 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:09:02 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:09:02 DEBUG : empty space: Unchanged skipping 2024/04/12 05:09:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:04 DEBUG : potato2: md5 = 91f9b878744dc68093fcbacd2001093b OK 2024/04/12 05:09:04 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncDeleteBefore (9.56s) === RUN TestCopyDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:08 DEBUG : potato: md5 = cd121df30028d460c2d923210053bab8 OK 2024/04/12 05:09:09 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:11 DEBUG : potato2: md5 = cde98995699bdb1679cdf739e91c7533 OK 2024/04/12 05:09:11 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestCopyDeleteBefore (6.58s) === RUN TestSyncWithExclude run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:15 DEBUG : potato2: md5 = c3ff69252c5d24c894ab2f7f600d6640 OK 2024/04/12 05:09:17 DEBUG : empty space: md5 = b6ab94f75b0fd8f97abeb197d78bc79d OK 2024/04/12 05:09:17 DEBUG : enormous: Excluded (Size Filter) 2024/04/12 05:09:17 DEBUG : enormous: Excluded 2024/04/12 05:09:17 DEBUG : potato2: Excluded (Size Filter) 2024/04/12 05:09:17 DEBUG : potato2: Excluded 2024/04/12 05:09:17 DEBUG : potato2: Excluded (Size Filter) 2024/04/12 05:09:17 DEBUG : potato2: Excluded 2024/04/12 05:09:17 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:17 DEBUG : empty space: Unchanged skipping 2024/04/12 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:17 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:17 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:18 DEBUG : enormous: Excluded (Size Filter) 2024/04/12 05:09:18 DEBUG : enormous: Excluded 2024/04/12 05:09:18 DEBUG : potato2: Excluded (Size Filter) 2024/04/12 05:09:18 DEBUG : potato2: Excluded 2024/04/12 05:09:18 DEBUG : potato2: Excluded (Size Filter) 2024/04/12 05:09:18 DEBUG : potato2: Excluded 2024/04/12 05:09:18 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2024/04/12 05:09:18 DEBUG : empty space: Unchanged skipping 2024/04/12 05:09:18 DEBUG : Local file system at /tmp/rclone1145245598: Waiting for checks to finish 2024/04/12 05:09:18 DEBUG : Local file system at /tmp/rclone1145245598: Waiting for transfers to finish 2024/04/12 05:09:18 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:18 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncWithExclude (8.56s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:24 DEBUG : potato2: md5 = 475fd69261e9934b5f87286ed0e6a435 OK 2024/04/12 05:09:25 DEBUG : empty space: md5 = 79c6bbb6ad2de33b57cd1c8c253fc05e OK 2024/04/12 05:09:27 DEBUG : enormous: md5 = 9619578321b3ad3325a461f15d4f3981 OK 2024/04/12 05:09:27 DEBUG : enormous: Excluded (Size Filter) 2024/04/12 05:09:27 DEBUG : enormous: Excluded 2024/04/12 05:09:27 DEBUG : potato2: Excluded (Size Filter) 2024/04/12 05:09:27 DEBUG : potato2: Excluded 2024/04/12 05:09:28 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:09:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:28 DEBUG : empty space: Unchanged skipping 2024/04/12 05:09:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:28 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:28 INFO : potato2: Deleted 2024/04/12 05:09:28 INFO : enormous: Deleted 2024/04/12 05:09:28 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:29 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2024/04/12 05:09:29 DEBUG : Local file system at /tmp/rclone1145245598: Waiting for checks to finish 2024/04/12 05:09:29 DEBUG : empty space: Unchanged skipping 2024/04/12 05:09:29 DEBUG : Local file system at /tmp/rclone1145245598: Waiting for transfers to finish 2024/04/12 05:09:29 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:29 INFO : enormous: Deleted 2024/04/12 05:09:29 INFO : potato2: Deleted 2024/04/12 05:09:29 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncWithExcludeAndDeleteExcluded (9.48s) === RUN TestSyncWithUpdateOlder run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:33 DEBUG : one: md5 = 5dca6fd5a4a4c892ff77a325d0d92af9 OK 2024/04/12 05:09:35 DEBUG : two: md5 = 488806a02c207e641f6a15ef8877b23d OK 2024/04/12 05:09:37 DEBUG : three: md5 = 5a58b7686a716a76bc6c2e8e9a8a2c7e OK 2024/04/12 05:09:38 DEBUG : four: md5 = a48bd621dbf17954895e6768022a8c57 OK 2024/04/12 05:09:39 DEBUG : five: Need to transfer - File not found at Destination 2024/04/12 05:09:39 DEBUG : four: Sizes differ (src 4 vs dst 8) 2024/04/12 05:09:39 DEBUG : one: Destination is newer than source, skipping 2024/04/12 05:09:39 DEBUG : three: Sizes identical 2024/04/12 05:09:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:39 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2024/04/12 05:09:39 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2024/04/12 05:09:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:41 DEBUG : two: md5 = f70fb2a6554c0a28f368164d9d160622 OK 2024/04/12 05:09:41 INFO : two: Copied (replaced existing) 2024/04/12 05:09:41 DEBUG : four: md5 = 90c55adef89d9e9a3f4a02fa1a623707 OK 2024/04/12 05:09:41 INFO : four: Copied (replaced existing) 2024/04/12 05:09:41 DEBUG : five: md5 = b7340b73b1bfe0347aee947be1c3d858 OK 2024/04/12 05:09:41 INFO : five: Copied (new) 2024/04/12 05:09:41 DEBUG : Waiting for deletions to finish sync_test.go:1244: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (14.36s) === RUN TestSyncWithMaxDuration === RUN TestSyncWithMaxDuration/Hard sync_test.go:1261: Skipping test on non local remote === RUN TestSyncWithMaxDuration/Soft sync_test.go:1261: Skipping test on non local remote --- PASS: TestSyncWithMaxDuration (0.00s) --- SKIP: TestSyncWithMaxDuration/Hard (0.00s) --- SKIP: TestSyncWithMaxDuration/Soft (0.00s) === RUN TestSyncWithTrackRenames run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:1327: Can track renames: false 2024/04/12 05:09:46 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Ignoring --track-renames as the source and destination do not have a common hash 2024/04/12 05:09:46 DEBUG : potato: Need to transfer - File not found at Destination 2024/04/12 05:09:46 DEBUG : yam: Need to transfer - File not found at Destination 2024/04/12 05:09:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:48 DEBUG : potato: md5 = 0b515a00b633b3b057c7650f0e972c84 OK 2024/04/12 05:09:48 INFO : potato: Copied (new) 2024/04/12 05:09:48 DEBUG : yam: md5 = 71b073dbc415b9958742fd6bf25ca6c5 OK 2024/04/12 05:09:48 INFO : yam: Copied (new) 2024/04/12 05:09:48 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:48 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Ignoring --track-renames as the source and destination do not have a common hash 2024/04/12 05:09:49 DEBUG : yaml: Need to transfer - File not found at Destination 2024/04/12 05:09:49 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:09:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:49 DEBUG : potato: Unchanged skipping 2024/04/12 05:09:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:51 DEBUG : yaml: md5 = b7c22e9b067e7371896c84f1d75faee5 OK 2024/04/12 05:09:51 INFO : yaml: Copied (new) 2024/04/12 05:09:51 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:51 INFO : yam: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncWithTrackRenames (8.97s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:1399: Can track renames: true 2024/04/12 05:09:55 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Making map for --track-renames 2024/04/12 05:09:55 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Finished making map for --track-renames 2024/04/12 05:09:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:55 DEBUG : yam: Need to transfer - No matching file found at Destination 2024/04/12 05:09:55 DEBUG : potato: Need to transfer - No matching file found at Destination 2024/04/12 05:09:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for renames to finish 2024/04/12 05:09:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:57 DEBUG : potato: md5 = 64dc777222a65febfae0c6d6f3543493 OK 2024/04/12 05:09:57 INFO : potato: Copied (new) 2024/04/12 05:09:57 DEBUG : yam: md5 = fa2fe4408f391acc530658c62d2303ce OK 2024/04/12 05:09:57 INFO : yam: Copied (new) 2024/04/12 05:09:57 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:09:58 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:09:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Making map for --track-renames 2024/04/12 05:09:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Finished making map for --track-renames 2024/04/12 05:09:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:09:58 DEBUG : potato: Unchanged skipping 2024/04/12 05:09:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for renames to finish 2024/04/12 05:09:59 INFO : yam: Moved (server-side) to: yaml 2024/04/12 05:09:59 INFO : yaml: Renamed from "yam" 2024/04/12 05:09:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:09:59 DEBUG : Waiting for deletions to finish 2024/04/12 05:09:59 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyModtime (7.46s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:1438: Can track renames: true 2024/04/12 05:10:02 DEBUG : sub: Making directory with metadata 2024/04/12 05:10:04 INFO : sub: Made directory with metadata (mtime=2024-04-12T05:10:02.678498635Z) 2024/04/12 05:10:04 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Making map for --track-renames 2024/04/12 05:10:04 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Finished making map for --track-renames 2024/04/12 05:10:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:10:04 DEBUG : potato: Need to transfer - No matching file found at Destination 2024/04/12 05:10:04 DEBUG : sub/yam: Need to transfer - No matching file found at Destination 2024/04/12 05:10:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for renames to finish 2024/04/12 05:10:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:10:05 DEBUG : sub/yam: md5 = c89217b07deaeabe592382b0176b998d OK 2024/04/12 05:10:05 INFO : sub/yam: Copied (new) 2024/04/12 05:10:05 DEBUG : potato: md5 = 369f98bbffe075a5c812a523f407e8bd OK 2024/04/12 05:10:05 INFO : potato: Copied (new) 2024/04/12 05:10:05 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:06 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:10:06 DEBUG : potato: Unchanged skipping 2024/04/12 05:10:07 INFO : sub: Set directory modification time (using SetModTime) 2024/04/12 05:10:07 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Making map for --track-renames 2024/04/12 05:10:07 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Finished making map for --track-renames 2024/04/12 05:10:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:10:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for renames to finish 2024/04/12 05:10:08 INFO : sub/yam: Moved (server-side) to: yam 2024/04/12 05:10:08 INFO : yam: Renamed from "sub/yam" 2024/04/12 05:10:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:10:08 DEBUG : Waiting for deletions to finish 2024/04/12 05:10:08 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyLeaf (10.76s) === RUN TestServerSideMoveLocal run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:13 DEBUG : Creating backend with remote "/tmp/rclone1145245598/dir1" 2024/04/12 05:10:13 DEBUG : Creating backend with remote "/tmp/rclone1145245598/dir2" 2024/04/12 05:10:13 DEBUG : Local file system at /tmp/rclone1145245598/dir2: Using server-side directory move 2024/04/12 05:10:13 INFO : Local file system at /tmp/rclone1145245598/dir2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/04/12 05:10:13 DEBUG : file1.txt: Need to transfer - File not found at Destination 2024/04/12 05:10:13 DEBUG : Local file system at /tmp/rclone1145245598/dir2: Waiting for checks to finish 2024/04/12 05:10:13 DEBUG : Local file system at /tmp/rclone1145245598/dir2: Waiting for transfers to finish 2024/04/12 05:10:13 INFO : file1.txt: Moved (server-side) --- PASS: TestServerSideMoveLocal (0.52s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:14 DEBUG : nested: Making directory with metadata 2024/04/12 05:10:15 INFO : nested: Made directory with metadata (mtime=2024-04-12T05:10:13.958503803Z) 2024/04/12 05:10:15 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:10:16 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:10:13.954503801Z) 2024/04/12 05:10:16 DEBUG : nested/sub dir: Making directory with metadata 2024/04/12 05:10:16 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:10:17 INFO : nested/sub dir: Made directory with metadata (mtime=2024-04-12T05:10:13.958503803Z) 2024/04/12 05:10:17 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2024/04/12 05:10:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:10:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:10:18 DEBUG : sub dir/hello world: md5 = ea7ad27ea6b37ae2affe230396ba1785 OK 2024/04/12 05:10:18 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:10:18 INFO : sub dir/hello world: Deleted 2024/04/12 05:10:19 DEBUG : nested/sub dir/file: md5 = 41950c9a888f8faefc1bf6a1aad6519c OK 2024/04/12 05:10:19 INFO : nested/sub dir/file: Copied (new) 2024/04/12 05:10:19 INFO : nested/sub dir/file: Deleted 2024/04/12 05:10:19 INFO : sub dir: Removing directory 2024/04/12 05:10:19 INFO : nested/sub dir: Removing directory 2024/04/12 05:10:19 INFO : nested: Removing directory 2024/04/12 05:10:19 DEBUG : Local file system at /tmp/rclone1145245598: deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:22 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2024/04/12 05:10:23 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2024/04/12 05:10:24 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (12.24s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:26 DEBUG : nested: Making directory with metadata 2024/04/12 05:10:27 INFO : nested: Made directory with metadata (mtime=2024-04-12T05:10:26.194509361Z) 2024/04/12 05:10:27 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:10:28 INFO : sub dir: Made directory with metadata (mtime=2024-04-12T05:10:26.194509361Z) 2024/04/12 05:10:28 DEBUG : nested/sub dir: Making directory with metadata 2024/04/12 05:10:28 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/12 05:10:29 INFO : nested/sub dir: Made directory with metadata (mtime=2024-04-12T05:10:26.194509361Z) 2024/04/12 05:10:29 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2024/04/12 05:10:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:10:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:10:30 DEBUG : sub dir/hello world: md5 = 20a33d94948c859c6a0e4a25ec6d8b2c OK 2024/04/12 05:10:30 INFO : sub dir/hello world: Copied (new) 2024/04/12 05:10:30 INFO : sub dir/hello world: Deleted 2024/04/12 05:10:31 DEBUG : nested/sub dir/file: md5 = 1e65071415487262c33ec17c3ccfce4a OK 2024/04/12 05:10:31 INFO : nested/sub dir/file: Copied (new) 2024/04/12 05:10:31 INFO : nested/sub dir/file: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:34 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2024/04/12 05:10:35 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2024/04/12 05:10:36 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (11.79s) === RUN TestMoveWithIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:38 DEBUG : existing: Need to transfer - File not found at Destination 2024/04/12 05:10:38 DEBUG : existing-b: Need to transfer - File not found at Destination 2024/04/12 05:10:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:10:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:10:39 DEBUG : existing: md5 = 1ff8520f00663894387f4875b7ae1a69 OK 2024/04/12 05:10:39 INFO : existing: Copied (new) 2024/04/12 05:10:39 INFO : existing: Deleted 2024/04/12 05:10:40 DEBUG : existing-b: md5 = 4f87a66827092808d8ae62405334e3e1 OK 2024/04/12 05:10:40 INFO : existing-b: Copied (new) 2024/04/12 05:10:40 INFO : existing-b: Deleted 2024/04/12 05:10:40 DEBUG : existing: Destination exists, skipping 2024/04/12 05:10:40 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2024/04/12 05:10:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:10:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:10:40 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestMoveWithIgnoreExisting (5.70s) === RUN TestServerSideMove run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:10:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4" 2024/04/12 05:10:43 DEBUG : Creating backend with remote "TestDrive:crypt/tl0kq3v1egm28b5jrmvq4mp6pjg9bt89bea7vk7o6783hgsdqkk98oklvuk7s4tmdu693uvcltpr8" 2024/04/12 05:10:46 DEBUG : potato2: md5 = d6ca0e1bfac7bd4c4117c12af44ed181 OK 2024/04/12 05:10:48 DEBUG : empty space: md5 = 17df489fe03029ea1a22ddb64e5bd3d3 OK 2024/04/12 05:10:49 DEBUG : potato3: md5 = 7a03240db4724bb430cb5fd441f08127 OK sync_test.go:1494: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9' -> Encrypted drive 'TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4' 2024/04/12 05:10:53 DEBUG : empty space: md5 = 6c7a7228d5b816a25b47838b2cd744e2 OK 2024/04/12 05:10:54 DEBUG : potato3: md5 = 1b79774d7d9bac7ba4c96c64244450ee OK 2024/04/12 05:10:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4': Using server-side directory move 2024/04/12 05:10:55 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/04/12 05:10:55 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:10:55 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2024/04/12 05:10:55 DEBUG : empty space: Unchanged skipping 2024/04/12 05:10:55 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/04/12 05:10:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4': Waiting for checks to finish 2024/04/12 05:10:56 INFO : empty space: Deleted 2024/04/12 05:10:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4': Waiting for transfers to finish 2024/04/12 05:10:56 INFO : potato3: Deleted 2024/04/12 05:10:56 INFO : potato2: Moved (server-side) 2024/04/12 05:10:57 INFO : potato3: Moved (server-side) 2024/04/12 05:10:57 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-toyefag0jihozad0qimerus0" 2024/04/12 05:10:57 DEBUG : Creating backend with remote "TestDrive:crypt/ka3ntqb3vu4f9d9qgq1upoijjnfrscb69aap2pmueeuqpi6ntgclgva2sl1vmprkra0qjrlkhccqs" 2024/04/12 05:10:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-toyefag0jihozad0qimerus0': Using server-side directory move 2024/04/12 05:10:59 INFO : Encrypted drive 'TestCryptDrive:rclone-test-toyefag0jihozad0qimerus0': Server side directory move succeeded 2024/04/12 05:11:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-toyefag0jihozad0qimerus0': Purge remote 2024/04/12 05:11:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xopewuh8bolutad3rewamoc4': Purge remote 2024/04/12 05:11:01 purge failed: directory not found --- PASS: TestServerSideMove (18.78s) === RUN TestServerSideMoveWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:11:02 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cunoviy3bobacuh9waqelaw2" 2024/04/12 05:11:02 DEBUG : Creating backend with remote "TestDrive:crypt/o45p81cas7ghdekpkj05vir9o2uns4qsulkniget6irdc9tu5o42ngk7dtdahc0il46hejl0c3lk2" 2024/04/12 05:11:05 DEBUG : potato2: md5 = 979f00f5bab3ace60dfbfd889cdca5e9 OK 2024/04/12 05:11:07 DEBUG : empty space: md5 = 0897c6a92f3396376e979b0598926832 OK 2024/04/12 05:11:09 DEBUG : potato3: md5 = 21175fc4b2f20ff1b6b92f37234cd5d4 OK sync_test.go:1494: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9' -> Encrypted drive 'TestCryptDrive:rclone-test-cunoviy3bobacuh9waqelaw2' 2024/04/12 05:11:12 DEBUG : empty space: md5 = 1eacca35e382037d46872d5d92fb3f05 OK 2024/04/12 05:11:13 DEBUG : potato3: md5 = 9adb32df6cf6e5e143358a9cb73516d1 OK 2024/04/12 05:11:14 DEBUG : empty space: Excluded (Size Filter) 2024/04/12 05:11:14 DEBUG : empty space: Excluded 2024/04/12 05:11:14 DEBUG : empty space: Excluded (Size Filter) 2024/04/12 05:11:14 DEBUG : empty space: Excluded 2024/04/12 05:11:14 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:11:14 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/04/12 05:11:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cunoviy3bobacuh9waqelaw2': Waiting for checks to finish 2024/04/12 05:11:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cunoviy3bobacuh9waqelaw2': Waiting for transfers to finish 2024/04/12 05:11:15 INFO : potato3: Deleted 2024/04/12 05:11:15 INFO : potato2: Moved (server-side) 2024/04/12 05:11:16 INFO : potato3: Moved (server-side) 2024/04/12 05:11:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-lecefeh9jayuqab7xuleqam0" 2024/04/12 05:11:16 DEBUG : Creating backend with remote "TestDrive:crypt/9aoalklaibhtbj7kvi4f01v0brtac75egjm7dfbr3trtku7amrj442b4a49d46v0flv1tr5vvfotq" 2024/04/12 05:11:18 DEBUG : empty space: Excluded (Size Filter) 2024/04/12 05:11:18 DEBUG : empty space: Excluded 2024/04/12 05:11:18 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:11:18 DEBUG : potato3: Need to transfer - File not found at Destination 2024/04/12 05:11:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lecefeh9jayuqab7xuleqam0': Waiting for checks to finish 2024/04/12 05:11:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lecefeh9jayuqab7xuleqam0': Waiting for transfers to finish 2024/04/12 05:11:20 INFO : potato2: Moved (server-side) 2024/04/12 05:11:20 INFO : potato3: Moved (server-side) 2024/04/12 05:11:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lecefeh9jayuqab7xuleqam0': Purge remote 2024/04/12 05:11:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cunoviy3bobacuh9waqelaw2': Purge remote --- PASS: TestServerSideMoveWithFilter (21.52s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:11:23 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4" 2024/04/12 05:11:24 DEBUG : Creating backend with remote "TestDrive:crypt/59thvpmdhbtb92ao7tfq14nmnn2kvr4d87t37jrh8317prfc6o4lqcl289od3co2k4cqfo6tbiktg" 2024/04/12 05:11:26 DEBUG : potato2: md5 = 6b31af2f701e6850e5b91e7a7a15da04 OK 2024/04/12 05:11:28 DEBUG : empty space: md5 = f62ee1a41258f83c6d13ab03ca1e2e7e OK 2024/04/12 05:11:30 DEBUG : potato3: md5 = 7a59b6299cc6a00612ef6c906277a721 OK 2024/04/12 05:11:30 DEBUG : tomatoDir: Making directory sync_test.go:1494: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9' -> Encrypted drive 'TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4' 2024/04/12 05:11:34 DEBUG : empty space: md5 = 32ee8c5df9438862ee3f26cf6e6b61f9 OK 2024/04/12 05:11:36 DEBUG : potato3: md5 = a1a58def3f986ba1773a7b43ef5cda31 OK 2024/04/12 05:11:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4': Using server-side directory move 2024/04/12 05:11:36 INFO : Encrypted drive 'TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/04/12 05:11:36 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/12 05:11:36 DEBUG : tomatoDir: Making directory with metadata 2024/04/12 05:11:37 INFO : tomatoDir: Made directory with metadata (mtime=2024-04-12T05:11:30.386Z) 2024/04/12 05:11:37 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/04/12 05:11:37 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2024/04/12 05:11:37 DEBUG : empty space: Unchanged skipping 2024/04/12 05:11:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4': Waiting for checks to finish 2024/04/12 05:11:38 INFO : potato2: Moved (server-side) 2024/04/12 05:11:38 INFO : empty space: Deleted 2024/04/12 05:11:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4': Waiting for transfers to finish 2024/04/12 05:11:38 INFO : potato3: Deleted 2024/04/12 05:11:39 INFO : potato3: Moved (server-side) 2024/04/12 05:11:39 INFO : tomatoDir: Removing directory 2024/04/12 05:11:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': deleted 1 directories 2024/04/12 05:11:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-bobijes1nakulay0coqiziq7" 2024/04/12 05:11:41 DEBUG : Creating backend with remote "TestDrive:crypt/4me2g7avbj0aeusd2v2icmto1kjsv6anm2cm1g8e5lmb6entqf8meue9e5oiqipotgfspcoj0hpae" 2024/04/12 05:11:42 DEBUG : tomatoDir: Making directory 2024/04/12 05:11:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-bobijes1nakulay0coqiziq7': Using server-side directory move 2024/04/12 05:11:43 INFO : Encrypted drive 'TestCryptDrive:rclone-test-bobijes1nakulay0coqiziq7': Server side directory move succeeded 2024/04/12 05:11:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-bobijes1nakulay0coqiziq7': Purge remote 2024/04/12 05:11:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kizujuf4titiduj9nuzaxiq4': Purge remote 2024/04/12 05:11:46 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (23.05s) === RUN TestServerSideMoveOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:1699: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.50s) === RUN TestSyncOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:11:47 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test" 2024/04/12 05:11:47 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncOverlap (4.73s) === RUN TestSyncOverlapWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:11:52 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test" 2024/04/12 05:11:52 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" 2024/04/12 05:11:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test-include/layer2" 2024/04/12 05:11:55 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0/n01jpl9202nn9ec1rb75h0f1c4" 2024/04/12 05:11:59 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test-ignore-file" 2024/04/12 05:11:59 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg" 2024/04/12 05:12:04 DEBUG : rclone-sync-test-ignore-file/.ignore: md5 = 5383297aaf5ee5818a3cc9e52c0f4285 OK 2024/04/12 05:12:05 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/12 05:12:06 DEBUG : rclone-sync-test: Excluded 2024/04/12 05:12:06 DEBUG : rclone-sync-test-include: Making directory with metadata 2024/04/12 05:12:07 INFO : rclone-sync-test-include: Made directory with metadata (mtime=2024-04-12T05:11:57.539Z) 2024/04/12 05:12:08 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/12 05:12:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test': Waiting for checks to finish 2024/04/12 05:12:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test': Waiting for transfers to finish 2024/04/12 05:12:08 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:08 INFO : There was nothing to transfer 2024/04/12 05:12:09 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/12 05:12:09 DEBUG : rclone-sync-test: Excluded 2024/04/12 05:12:09 DEBUG : rclone-sync-test-include: Directory modification time the same (differ by 0s, within tolerance 1ms) 2024/04/12 05:12:10 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/12 05:12:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:12:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:12:10 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:10 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:12:11 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/12 05:12:11 DEBUG : rclone-sync-test: Excluded 2024/04/12 05:12:11 DEBUG : rclone-sync-test-include: Making directory with metadata 2024/04/12 05:12:12 INFO : rclone-sync-test-include: Made directory with metadata (mtime=2024-04-12T05:11:57.539Z) 2024/04/12 05:12:13 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/12 05:12:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test-include/layer2': Waiting for checks to finish 2024/04/12 05:12:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test-include/layer2': Waiting for transfers to finish 2024/04/12 05:12:13 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:13 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:12:14 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/12 05:12:14 DEBUG : rclone-sync-test: Excluded 2024/04/12 05:12:14 DEBUG : rclone-sync-test-include: Directory modification time the same (differ by 0s, within tolerance 1ms) 2024/04/12 05:12:15 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/12 05:12:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:12:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:12:15 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:15 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:12:15 DEBUG : : Excluded 2024/04/12 05:12:16 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/12 05:12:16 DEBUG : rclone-sync-test: Excluded 2024/04/12 05:12:16 DEBUG : rclone-sync-test-include: Making directory with metadata 2024/04/12 05:12:17 INFO : rclone-sync-test-include: Made directory with metadata (mtime=2024-04-12T05:11:57.539Z) 2024/04/12 05:12:18 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/12 05:12:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test-ignore-file': Waiting for checks to finish 2024/04/12 05:12:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/rclone-sync-test-ignore-file': Waiting for transfers to finish 2024/04/12 05:12:18 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:18 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:12:22 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0/n01jpl9202nn9ec1rb75h0f1c4: Rmdir: contains trashed file: "khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0" 2024/04/12 05:12:23 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains trashed file: "n01jpl9202nn9ec1rb75h0f1c4" 2024/04/12 05:12:25 DEBUG : kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg: Rmdir: contains trashed file: "khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0" 2024/04/12 05:12:25 DEBUG : kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg: Rmdir: contains trashed file: "i0t74httmdlljg425j6tg570d8" 2024/04/12 05:12:26 DEBUG : i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0: Rmdir: contains trashed file: "khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0" --- PASS: TestSyncOverlapWithFilter (44.27s) === RUN TestSyncCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:12:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:12:36 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:12:38 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/CompareDest" 2024/04/12 05:12:38 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/gveqi14airsml4bgu7krj116o8" 2024/04/12 05:12:40 DEBUG : one: Need to transfer - File not found at Destination 2024/04/12 05:12:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:12:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:12:43 DEBUG : one: md5 = 872bf4ca0e44312e863877c9a8b249ac OK 2024/04/12 05:12:43 INFO : one: Copied (new) 2024/04/12 05:12:43 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:45 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:12:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:12:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:12:46 DEBUG : one: md5 = 52f593af3fa402a6133e0e4d25ecd55e OK 2024/04/12 05:12:46 INFO : one: Copied (replaced existing) 2024/04/12 05:12:46 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:49 DEBUG : dst/one: md5 = c77f5dfb0a144055d67e30794cb0d78f OK 2024/04/12 05:12:51 DEBUG : CompareDest/one: md5 = 764bbe508d0c0e328a60b9f8eaa2820c OK 2024/04/12 05:12:52 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:12:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:12:53 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:12:53 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/12 05:12:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:12:53 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:53 INFO : There was nothing to transfer 2024/04/12 05:12:55 DEBUG : CompareDest/two: md5 = a99d2eaf10f6709af7119cb8792f44bc OK 2024/04/12 05:12:56 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:12:56 DEBUG : two: Destination found in --compare-dest, skipping 2024/04/12 05:12:56 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:12:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:12:57 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:12:57 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/12 05:12:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:12:57 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:57 INFO : There was nothing to transfer 2024/04/12 05:12:58 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:12:58 DEBUG : two: Destination found in --compare-dest, skipping 2024/04/12 05:12:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:12:58 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:12:58 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:12:58 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/12 05:12:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:12:58 DEBUG : Waiting for deletions to finish 2024/04/12 05:12:58 INFO : There was nothing to transfer sync_test.go:1964: No hash on uploaded file so skipping compare timestamp test 2024/04/12 05:13:00 DEBUG : two: Sizes differ (src 5 vs dst 3) 2024/04/12 05:13:00 DEBUG : two: Need to transfer - File not found at Destination 2024/04/12 05:13:00 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:13:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:13:01 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:13:01 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/12 05:13:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:13:02 DEBUG : two: md5 = af0c1991ac329fde315fef05767d4930 OK 2024/04/12 05:13:02 INFO : two: Copied (new) 2024/04/12 05:13:02 DEBUG : Waiting for deletions to finish 2024/04/12 05:13:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:13:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:13:07 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:13:07 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncCompareDest (32.29s) === RUN TestSyncMultipleCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:13:11 DEBUG : pre-dest1/1: md5 = f6176d20e7ccfb8fbb46b5dc6417aa7c OK 2024/04/12 05:13:14 DEBUG : pre-dest2/2: md5 = 92b9e955ab60524cad4691cb065aa14e OK 2024/04/12 05:13:15 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dest" 2024/04/12 05:13:15 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/rg03c1jvnehrrc617i0lnqjddc" 2024/04/12 05:13:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/pre-dest1" 2024/04/12 05:13:17 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/bbnblvh6k061ssopqrp18kd7gc" 2024/04/12 05:13:17 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/pre-dest2" 2024/04/12 05:13:18 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/dgicm1h6b5ejvlltm8eeif0bnk" 2024/04/12 05:13:20 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:13:20 DEBUG : 1: Destination found in --compare-dest, skipping 2024/04/12 05:13:20 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:13:20 DEBUG : 2: Destination found in --compare-dest, skipping 2024/04/12 05:13:21 DEBUG : 3: Need to transfer - File not found at Destination 2024/04/12 05:13:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dest': Waiting for checks to finish 2024/04/12 05:13:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dest': Waiting for transfers to finish 2024/04/12 05:13:24 DEBUG : 3: md5 = f9217be374b67459a566c70b3db62066 OK 2024/04/12 05:13:24 INFO : 3: Copied (new) 2024/04/12 05:13:24 DEBUG : Waiting for deletions to finish 2024/04/12 05:13:28 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2024/04/12 05:13:29 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2024/04/12 05:13:30 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (22.38s) === RUN TestSyncCopyDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:13:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:13:31 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:13:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/CopyDest" 2024/04/12 05:13:33 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/d09o6po3f7bm6ce32vdgs8h9ls" 2024/04/12 05:13:35 DEBUG : one: Need to transfer - File not found at Destination 2024/04/12 05:13:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:13:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:13:38 DEBUG : one: md5 = e3ebc49c9ed53b21809a541f3901394c OK 2024/04/12 05:13:38 INFO : one: Copied (new) 2024/04/12 05:13:38 DEBUG : Waiting for deletions to finish 2024/04/12 05:13:40 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:13:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:13:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:13:42 DEBUG : one: md5 = e1149ed021dcb20da78a49ec185d427f OK 2024/04/12 05:13:42 INFO : one: Copied (replaced existing) 2024/04/12 05:13:42 DEBUG : Waiting for deletions to finish 2024/04/12 05:13:44 DEBUG : dst/one: md5 = 3106006a8403ca0c56b34abb31050a0d OK 2024/04/12 05:13:47 DEBUG : CopyDest/one: md5 = d59d3b6243e4cb58a1a7107ba8d611ce OK 2024/04/12 05:13:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/BackupDir" 2024/04/12 05:13:48 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/s6dbk3lfi7c9kfvo6j7bla9m0g" 2024/04/12 05:13:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:13:50 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:13:50 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:13:50 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/12 05:13:52 INFO : one: Moved (server-side) 2024/04/12 05:13:54 INFO : one: Copied (server-side copy) 2024/04/12 05:13:54 DEBUG : one: Destination found in --copy-dest, using server-side copy 2024/04/12 05:13:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:13:54 DEBUG : Waiting for deletions to finish 2024/04/12 05:13:57 DEBUG : CopyDest/two: md5 = 490c08e79dbea425c659c610aba3daa2 OK 2024/04/12 05:13:58 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:14:00 INFO : two: Copied (server-side copy) 2024/04/12 05:14:00 DEBUG : two: Destination found in --copy-dest, using server-side copy 2024/04/12 05:14:00 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:14:00 DEBUG : one: Unchanged skipping 2024/04/12 05:14:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:14:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:14:00 DEBUG : Waiting for deletions to finish 2024/04/12 05:14:01 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:14:01 DEBUG : one: Unchanged skipping 2024/04/12 05:14:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:14:01 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:14:01 DEBUG : two: Unchanged skipping 2024/04/12 05:14:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:14:01 DEBUG : Waiting for deletions to finish 2024/04/12 05:14:01 INFO : There was nothing to transfer 2024/04/12 05:14:03 DEBUG : CopyDest/three: md5 = 13f3ed6f6f631185853da8d25b73ae01 OK 2024/04/12 05:14:04 DEBUG : three: Sizes differ (src 7 vs dst 5) 2024/04/12 05:14:04 DEBUG : three: Destination not found in --copy-dest 2024/04/12 05:14:04 DEBUG : three: Need to transfer - File not found at Destination 2024/04/12 05:14:04 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:14:04 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/12 05:14:04 DEBUG : one: Unchanged skipping 2024/04/12 05:14:04 DEBUG : two: Unchanged skipping 2024/04/12 05:14:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:14:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:14:06 DEBUG : three: md5 = 2ddcdacbb72c802c649ff1c2ef7ed4ef OK 2024/04/12 05:14:06 INFO : three: Copied (new) 2024/04/12 05:14:06 DEBUG : Waiting for deletions to finish 2024/04/12 05:14:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2024/04/12 05:14:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:14:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:14:14 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:14:14 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:14:14 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2024/04/12 05:14:15 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (44.75s) === RUN TestSyncBackupDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:14:18 DEBUG : dst/one: md5 = 291f05ee4ce3304d8a3eb72ee60ba4b3 OK 2024/04/12 05:14:20 DEBUG : dst/two: md5 = 4a2dc6f300e67566498de03ad6a921ec OK 2024/04/12 05:14:22 DEBUG : dst/three.txt: md5 = a3fc5098334c735c6c17d7c337e5fe05 OK 2024/04/12 05:14:23 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:14:23 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:14:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/backup" 2024/04/12 05:14:24 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/1nrff024r7pq65ecp72fc28jb0" 2024/04/12 05:14:26 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/12 05:14:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:14:26 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:14:26 DEBUG : two: Unchanged skipping 2024/04/12 05:14:28 INFO : one: Moved (server-side) 2024/04/12 05:14:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:14:30 DEBUG : one: md5 = 0d88ca408ae372100ed469a384a3a311 OK 2024/04/12 05:14:30 INFO : one: Copied (new) 2024/04/12 05:14:30 DEBUG : Waiting for deletions to finish 2024/04/12 05:14:31 INFO : three.txt: Moved (server-side) 2024/04/12 05:14:31 INFO : three.txt: Moved into backup dir 2024/04/12 05:14:33 DEBUG : dst/three.txt: md5 = b48b90537f0fe7435498affd8be3c4ba OK 2024/04/12 05:14:34 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/12 05:14:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:14:34 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:14:34 DEBUG : two: Unchanged skipping 2024/04/12 05:14:35 INFO : one: Deleted 2024/04/12 05:14:36 INFO : one: Moved (server-side) 2024/04/12 05:14:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:14:38 DEBUG : one: md5 = d75aa85d61fc9dfa5f12aa6af5cb457b OK 2024/04/12 05:14:38 INFO : one: Copied (new) 2024/04/12 05:14:38 DEBUG : Waiting for deletions to finish 2024/04/12 05:14:39 INFO : three.txt: Deleted 2024/04/12 05:14:40 INFO : three.txt: Moved (server-side) 2024/04/12 05:14:40 INFO : three.txt: Moved into backup dir 2024/04/12 05:14:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:14:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:14:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/12 05:14:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:14:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:14:45 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" --- PASS: TestSyncBackupDir (30.62s) === RUN TestSyncBackupDirWithSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:14:49 DEBUG : dst/one: md5 = 668bceaefa831c44e30acd2a44b450b4 OK 2024/04/12 05:14:51 DEBUG : dst/two: md5 = 3af03dc254ef543ae3c8fd43eb2efbf4 OK 2024/04/12 05:14:52 DEBUG : dst/three.txt: md5 = 550149b500fa6227b370e9207c7b3dc7 OK 2024/04/12 05:14:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:14:53 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:14:54 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/backup" 2024/04/12 05:14:54 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/1nrff024r7pq65ecp72fc28jb0" 2024/04/12 05:14:56 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/12 05:14:56 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:14:56 DEBUG : two: Unchanged skipping 2024/04/12 05:14:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:14:59 INFO : one: Moved (server-side) to: one.bak 2024/04/12 05:14:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:15:00 DEBUG : one: md5 = 1f16abfed8380c665b0fa9097fbed87a OK 2024/04/12 05:15:00 INFO : one: Copied (new) 2024/04/12 05:15:00 DEBUG : Waiting for deletions to finish 2024/04/12 05:15:01 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/12 05:15:01 INFO : three.txt: Moved into backup dir 2024/04/12 05:15:04 DEBUG : dst/three.txt: md5 = a35716de4a1c5962c69e5733cbbb967a OK 2024/04/12 05:15:05 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/12 05:15:05 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:15:05 DEBUG : two: Unchanged skipping 2024/04/12 05:15:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:15:06 INFO : one.bak: Deleted 2024/04/12 05:15:06 INFO : one: Moved (server-side) to: one.bak 2024/04/12 05:15:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:15:08 DEBUG : one: md5 = 54d2c6dbc2603ca58053b11bb3e9f21a OK 2024/04/12 05:15:08 INFO : one: Copied (new) 2024/04/12 05:15:08 DEBUG : Waiting for deletions to finish 2024/04/12 05:15:09 INFO : three.txt.bak: Deleted 2024/04/12 05:15:10 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/12 05:15:10 INFO : three.txt: Moved into backup dir 2024/04/12 05:15:14 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:15:14 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:15:15 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/12 05:15:15 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/12 05:15:15 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/12 05:15:15 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (30.32s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:15:19 DEBUG : dst/one: md5 = ddd5e0841715862c2758ff7ebde0c8fb OK 2024/04/12 05:15:21 DEBUG : dst/two: md5 = 8d0b1a5acae2a54d2126ef29a7192435 OK 2024/04/12 05:15:23 DEBUG : dst/three.txt: md5 = 3d3f1ffcc8b3f9cd499db2d48c7573ac OK 2024/04/12 05:15:23 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:15:23 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:15:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/backup" 2024/04/12 05:15:24 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/1nrff024r7pq65ecp72fc28jb0" 2024/04/12 05:15:27 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/12 05:15:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:15:27 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:15:27 DEBUG : two: Unchanged skipping 2024/04/12 05:15:29 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/12 05:15:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:15:30 DEBUG : one: md5 = 61f2cac7dbea973f1e4c5a55d68529c6 OK 2024/04/12 05:15:30 INFO : one: Copied (new) 2024/04/12 05:15:30 DEBUG : Waiting for deletions to finish 2024/04/12 05:15:31 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/12 05:15:31 INFO : three.txt: Moved into backup dir 2024/04/12 05:15:34 DEBUG : dst/three.txt: md5 = 71425ff2bf3a78b6dbc8bbd008248657 OK 2024/04/12 05:15:35 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/12 05:15:35 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:15:35 DEBUG : two: Unchanged skipping 2024/04/12 05:15:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:15:36 INFO : one-2019-01-01: Deleted 2024/04/12 05:15:37 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/12 05:15:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:15:38 DEBUG : one: md5 = 27addfaa9544df15f8c0b488ed96474a OK 2024/04/12 05:15:38 INFO : one: Copied (new) 2024/04/12 05:15:38 DEBUG : Waiting for deletions to finish 2024/04/12 05:15:39 INFO : three-2019-01-01.txt: Deleted 2024/04/12 05:15:40 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/12 05:15:40 INFO : three.txt: Moved into backup dir 2024/04/12 05:15:45 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:15:45 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:15:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2024/04/12 05:15:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/12 05:15:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/12 05:15:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (30.23s) === RUN TestSyncBackupDirSuffixOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:15:49 DEBUG : dst/one: md5 = ed697c48c26a18e0a16bf08911032b24 OK 2024/04/12 05:15:51 DEBUG : dst/two: md5 = 2fd9c354f4df0b320e97a029dea60f63 OK 2024/04/12 05:15:53 DEBUG : dst/three.txt: md5 = ff6afbdd8e6e35ca99f171b68e9c6440 OK 2024/04/12 05:15:54 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:15:54 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:15:55 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/12 05:15:55 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:15:55 DEBUG : two: Unchanged skipping 2024/04/12 05:15:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:15:56 INFO : one: Moved (server-side) to: one.bak 2024/04/12 05:15:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:15:58 DEBUG : one: md5 = db65cfae2e1a284a75ffbf6de59c0be0 OK 2024/04/12 05:15:58 INFO : one: Copied (new) 2024/04/12 05:15:58 DEBUG : Waiting for deletions to finish 2024/04/12 05:15:59 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/12 05:15:59 INFO : three.txt: Moved into backup dir 2024/04/12 05:16:01 DEBUG : dst/three.txt: md5 = 54d79c5728568c7aed605c1be979f133 OK 2024/04/12 05:16:02 DEBUG : three.txt.bak: Excluded (Path Filter) 2024/04/12 05:16:02 DEBUG : three.txt.bak: Excluded 2024/04/12 05:16:02 DEBUG : one.bak: Excluded (Path Filter) 2024/04/12 05:16:02 DEBUG : one.bak: Excluded 2024/04/12 05:16:02 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/12 05:16:02 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:16:02 DEBUG : two: Unchanged skipping 2024/04/12 05:16:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for checks to finish 2024/04/12 05:16:03 INFO : one.bak: Deleted 2024/04/12 05:16:04 INFO : one: Moved (server-side) to: one.bak 2024/04/12 05:16:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst': Waiting for transfers to finish 2024/04/12 05:16:05 DEBUG : one: md5 = 1de5845aad04fc8b27b9dad5b69ac960 OK 2024/04/12 05:16:05 INFO : one: Copied (new) 2024/04/12 05:16:05 DEBUG : Waiting for deletions to finish 2024/04/12 05:16:06 INFO : three.txt.bak: Deleted 2024/04/12 05:16:07 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/12 05:16:07 INFO : three.txt: Moved into backup dir 2024/04/12 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/12 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/12 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/12 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirSuffixOnly (25.56s) === RUN TestSyncSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:16:15 DEBUG : dst/one: md5 = 6c59369ea4d4d206eedc1ac706d3e41c OK 2024/04/12 05:16:17 DEBUG : dst/two: md5 = bbecb8528eafa0bc39b6090506a45914 OK 2024/04/12 05:16:19 DEBUG : dst/three.txt: md5 = a60a8d6e1116811cb161682f80c90c79 OK 2024/04/12 05:16:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:16:19 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:16:21 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/12 05:16:22 INFO : one: Moved (server-side) to: one.bak 2024/04/12 05:16:23 DEBUG : one: md5 = b0918aa672b09bd2e010e32c835a9608 OK 2024/04/12 05:16:23 INFO : one: Copied (new) 2024/04/12 05:16:24 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:16:24 DEBUG : two: Unchanged skipping 2024/04/12 05:16:24 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2024/04/12 05:16:25 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/12 05:16:27 DEBUG : three.txt: md5 = f77c87d970ea532ad71fe6490dca2425 OK 2024/04/12 05:16:27 INFO : three.txt: Copied (new) 2024/04/12 05:16:29 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/12 05:16:30 INFO : one.bak: Deleted 2024/04/12 05:16:30 INFO : one: Moved (server-side) to: one.bak 2024/04/12 05:16:32 DEBUG : one: md5 = ff09a698da03f3146644325f4fbd16e6 OK 2024/04/12 05:16:32 INFO : one: Copied (new) 2024/04/12 05:16:32 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:16:32 DEBUG : two: Unchanged skipping 2024/04/12 05:16:33 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2024/04/12 05:16:34 INFO : three.txt.bak: Deleted 2024/04/12 05:16:34 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/12 05:16:36 DEBUG : three.txt: md5 = 322053d3139a71d2f2abc4c326b4a3c3 OK 2024/04/12 05:16:36 INFO : three.txt: Copied (new) 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/12 05:16:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncSuffix (29.83s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:16:45 DEBUG : dst/one: md5 = cb55415ffc8027dbb5c42c8294065bde OK 2024/04/12 05:16:47 DEBUG : dst/two: md5 = 26c6c45d6515ca39552c687b7f20a33c OK 2024/04/12 05:16:48 DEBUG : dst/three.txt: md5 = 4f3ce009407ec696b35cda6ef47634d0 OK 2024/04/12 05:16:49 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9/dst" 2024/04/12 05:16:49 DEBUG : Creating backend with remote "TestDrive:crypt/s0d0aiueq5s819cvvgmmimnmo6gsov1rtgfha16h2q0ln5atgo3kgn3kd3gnd0ouslaiuuk3volrc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/12 05:16:50 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/12 05:16:51 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/12 05:16:53 DEBUG : one: md5 = 13f42887a4d393c9427f7f60ada360d8 OK 2024/04/12 05:16:53 INFO : one: Copied (new) 2024/04/12 05:16:53 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:16:53 DEBUG : two: Unchanged skipping 2024/04/12 05:16:54 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2024/04/12 05:16:54 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/12 05:16:56 DEBUG : three.txt: md5 = ba43251b1627ead28a70771ae54e6a68 OK 2024/04/12 05:16:56 INFO : three.txt: Copied (new) 2024/04/12 05:16:58 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/12 05:16:59 INFO : one-2019-01-01: Deleted 2024/04/12 05:16:59 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/12 05:17:01 DEBUG : one: md5 = 95f5277f114fbeb4980636c03b3a82c9 OK 2024/04/12 05:17:01 INFO : one: Copied (new) 2024/04/12 05:17:01 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:17:01 DEBUG : two: Unchanged skipping 2024/04/12 05:17:02 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2024/04/12 05:17:02 INFO : three-2019-01-01.txt: Deleted 2024/04/12 05:17:03 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/12 05:17:05 DEBUG : three.txt: md5 = 8191d948c885f402e79c8f82315f582b OK 2024/04/12 05:17:05 INFO : three.txt: Copied (new) 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/12 05:17:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" --- PASS: TestSyncSuffixKeepExtension (28.65s) === RUN TestSyncUTFNorm run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:17:12 DEBUG : Testêé: md5 = 2defb4bbb677764ccba57bb410c8bc1f OK 2024/04/12 05:17:13 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2024/04/12 05:17:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:17:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:17:15 DEBUG : Testêé: md5 = ab0a946a38a0428c942192510ae7154e OK 2024/04/12 05:17:15 INFO : Testêé: Copied (replaced existing) to: Testêé 2024/04/12 05:17:15 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (5.57s) === RUN TestSyncImmutable run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:17:17 DEBUG : existing: Need to transfer - File not found at Destination 2024/04/12 05:17:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:17:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:17:19 DEBUG : existing: md5 = 82a50e06523879567c7637c0b25c868d OK 2024/04/12 05:17:19 INFO : existing: Copied (new) 2024/04/12 05:17:19 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:17:20 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2024/04/12 05:17:20 ERROR : existing: Source and destination exist but do not match: immutable file modified 2024/04/12 05:17:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:17:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:17:20 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': not deleting files as there were IO errors 2024/04/12 05:17:20 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncImmutable (5.92s) === RUN TestSyncIgnoreCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:17:24 DEBUG : EXISTING: md5 = b5ac0f609f2c80e1fb53424ca76951ec OK 2024/04/12 05:17:25 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:17:25 DEBUG : existing: Unchanged skipping 2024/04/12 05:17:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:17:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:17:25 DEBUG : Waiting for deletions to finish 2024/04/12 05:17:25 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (4.04s) === RUN TestFixCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:2420: Skipping test as local or remote are case-sensitive --- SKIP: TestFixCase (0.53s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:2459: This test only runs on local === RUN TestMaxTransfer/Soft run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:2459: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" sync_test.go:2459: This test only runs on local --- PASS: TestMaxTransfer (1.72s) --- SKIP: TestMaxTransfer/Hard (0.51s) --- SKIP: TestMaxTransfer/Soft (0.54s) --- SKIP: TestMaxTransfer/Cautious (0.67s) === RUN TestSyncConcurrentDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:17:30 DEBUG : both0: md5 = 0a423c0d578c97337f55936fa5af6b31 OK 2024/04/12 05:17:32 DEBUG : only0: md5 = 0e3fd37508266d053dc909700c272d58 OK 2024/04/12 05:17:34 DEBUG : both1: md5 = e156e99c3eb50a590d731e8a5920bd09 OK 2024/04/12 05:17:35 DEBUG : only1: md5 = cc3b5a95c3a0df2a634038ff59c0810e OK 2024/04/12 05:17:37 DEBUG : both2: md5 = 36611eb961faec5610e9861383c557d3 OK 2024/04/12 05:17:39 DEBUG : only2: md5 = e1c4cc91f25a56e75633f03d47c69207 OK 2024/04/12 05:17:41 DEBUG : both3: md5 = 9c87c2ed5c92d7a5ed2444bc1620c601 OK 2024/04/12 05:17:42 DEBUG : only3: md5 = 33b9667319b78e2a1311b9ffcfcabec1 OK 2024/04/12 05:17:44 DEBUG : both4: md5 = ab3df063ddb58cfdac180c74b9145970 OK 2024/04/12 05:17:46 DEBUG : only4: md5 = d8ab3ab6a61a117aa8560837ee245d6e OK 2024/04/12 05:17:47 DEBUG : both5: md5 = ead09ae46fed518988cdf28cd103f3f8 OK 2024/04/12 05:17:50 DEBUG : only5: md5 = 702f454ebf9fd17a594f36ef176afec6 OK 2024/04/12 05:17:51 DEBUG : both6: md5 = dcc5d1d9af08a63c2ef5546ab5254fa6 OK 2024/04/12 05:17:53 DEBUG : only6: md5 = 463643b6eee8a13743080ffcba5bb041 OK 2024/04/12 05:17:55 DEBUG : both7: md5 = 6ee33acbed2be005aec818ab4721c5dc OK 2024/04/12 05:17:57 DEBUG : only7: md5 = 51c26877530a733e1d538f26e44b6750 OK 2024/04/12 05:17:59 DEBUG : both8: md5 = 70bb7493a7977a3ecfbfc94347d8f63e OK 2024/04/12 05:18:01 DEBUG : only8: md5 = 98a0a878d2dd5db486c5fb4575185d77 OK 2024/04/12 05:18:02 DEBUG : both9: md5 = 402ca7d49b283bdc09ea69d2deac1f30 OK 2024/04/12 05:18:04 DEBUG : only9: md5 = 345951ae8232a8715c40bbf810005423 OK 2024/04/12 05:18:06 DEBUG : both10: md5 = 90eb013c69cd8681e03db09f7d81fc18 OK 2024/04/12 05:18:08 DEBUG : only10: md5 = 2676bb5d45f17f4d9df819b7bb551ca7 OK 2024/04/12 05:18:09 DEBUG : both11: md5 = 873de9833c2365d7a17dea9fdc7e25de OK 2024/04/12 05:18:11 DEBUG : only11: md5 = af1f730ee1c2c58fa94ecbe3df86a326 OK 2024/04/12 05:18:13 DEBUG : both12: md5 = 41002413018e41b09951f939489bc7bc OK 2024/04/12 05:18:15 DEBUG : only12: md5 = 28af6c5adc176250f0986e295738dda5 OK 2024/04/12 05:18:17 DEBUG : both13: md5 = 33c17456225d6245ce73eb3cc635a0fa OK 2024/04/12 05:18:18 DEBUG : only13: md5 = 60decda486ac35b800613ac2ebce97c6 OK 2024/04/12 05:18:20 DEBUG : both14: md5 = 9b5af4cad2249bc390c31551afa3ddcb OK 2024/04/12 05:18:22 DEBUG : only14: md5 = ab7d961e70b95339c52c8d4715795fa4 OK 2024/04/12 05:18:24 DEBUG : both15: md5 = 5a3828bd84af5622b4b927c4f6e4947e OK 2024/04/12 05:18:26 DEBUG : only15: md5 = f00c5f1eaa9b2f311373896a7cc38875 OK 2024/04/12 05:18:27 DEBUG : both16: md5 = ff236c26d48c5c91bbc8a314c82cb965 OK 2024/04/12 05:18:29 DEBUG : only16: md5 = e895864f42c7d49e431e3e02167bd8c9 OK 2024/04/12 05:18:31 DEBUG : both17: md5 = fa28b5c656139e8852c51ff18ff30f4b OK 2024/04/12 05:18:32 DEBUG : only17: md5 = e9db42a08707a5a5b73bb6c7973be3d0 OK 2024/04/12 05:18:34 DEBUG : both18: md5 = 075e7495ecb3c3e1433eafbe4366d60b OK 2024/04/12 05:18:36 DEBUG : only18: md5 = 3f6c1dedf33c2173748c840d54289d95 OK 2024/04/12 05:18:38 DEBUG : both19: md5 = 5680c06836aef785f892dca729a0f036 OK 2024/04/12 05:18:40 DEBUG : only19: md5 = c002e1b2eef5af8c92ad5db011ff159b OK 2024/04/12 05:18:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:18:41 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both0: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both12: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both11: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both13: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both1: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both16: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both17: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both18: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both10: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both14: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both2: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both4: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both5: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both15: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both7: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both19: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:18:41 DEBUG : both9: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both3: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both6: Unchanged skipping 2024/04/12 05:18:41 DEBUG : both8: Unchanged skipping 2024/04/12 05:18:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:18:41 DEBUG : Waiting for deletions to finish 2024/04/12 05:18:42 INFO : only14: Deleted 2024/04/12 05:18:42 INFO : only11: Deleted 2024/04/12 05:18:42 INFO : only2: Deleted 2024/04/12 05:18:42 INFO : only17: Deleted 2024/04/12 05:18:42 INFO : only8: Deleted 2024/04/12 05:18:42 INFO : only4: Deleted 2024/04/12 05:18:42 INFO : only1: Deleted 2024/04/12 05:18:42 INFO : only10: Deleted 2024/04/12 05:18:43 INFO : only13: Deleted 2024/04/12 05:18:43 INFO : only6: Deleted 2024/04/12 05:18:43 INFO : only18: Deleted 2024/04/12 05:18:43 INFO : only16: Deleted 2024/04/12 05:18:44 INFO : only5: Deleted 2024/04/12 05:18:44 INFO : only15: Deleted 2024/04/12 05:18:44 INFO : only12: Deleted 2024/04/12 05:18:44 INFO : only7: Deleted 2024/04/12 05:18:45 INFO : only9: Deleted 2024/04/12 05:18:45 INFO : only3: Deleted 2024/04/12 05:18:45 INFO : only19: Deleted 2024/04/12 05:18:45 INFO : only0: Deleted 2024/04/12 05:18:45 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncConcurrentDelete (94.70s) === RUN TestSyncConcurrentTruncate run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:19:05 DEBUG : both0: md5 = d57b338a551a6071f207898a3dd0a561 OK 2024/04/12 05:19:07 DEBUG : only0: md5 = c6885c8b116dfd7fd3342148fc4da3a5 OK 2024/04/12 05:19:08 DEBUG : both1: md5 = 9574795dc592bfd72a393991f54a686e OK 2024/04/12 05:19:10 DEBUG : only1: md5 = 78d69803e9bdbcf71babce536f408c73 OK 2024/04/12 05:19:12 DEBUG : both2: md5 = 9862209035cff7566e94dbe373e8d92f OK 2024/04/12 05:19:14 DEBUG : only2: md5 = 7ba470c6f1eb9dbb34c6ba199d108725 OK 2024/04/12 05:19:15 DEBUG : both3: md5 = 7988dc708807e25b628209cc5b385221 OK 2024/04/12 05:19:17 DEBUG : only3: md5 = fba6d782a5f287b22372267082e321ce OK 2024/04/12 05:19:19 DEBUG : both4: md5 = 63271c10fcffb0c84c298128ecfd26b3 OK 2024/04/12 05:19:20 DEBUG : only4: md5 = 56ccabb6127ecd25b13a1e4b47e399a0 OK 2024/04/12 05:19:22 DEBUG : both5: md5 = 734b0a6f5a389a6b379a5ea80027ec78 OK 2024/04/12 05:19:24 DEBUG : only5: md5 = f3262045e687d12df83c49560404e017 OK 2024/04/12 05:19:26 DEBUG : both6: md5 = 18fcbe4240f844f40753dc01fdf92df9 OK 2024/04/12 05:19:27 DEBUG : only6: md5 = 733afe656993307f321d2d97c4d152ee OK 2024/04/12 05:19:29 DEBUG : both7: md5 = b35abc655d645f9c02f0a9e576a228f1 OK 2024/04/12 05:19:31 DEBUG : only7: md5 = 9b11c197038a82e98d51bc0e46bb265a OK 2024/04/12 05:19:33 DEBUG : both8: md5 = 3a17d475d28a88a834ba1272bce53a39 OK 2024/04/12 05:19:34 DEBUG : only8: md5 = b1b55a644055f9beb3e6fa329c2c56df OK 2024/04/12 05:19:36 DEBUG : both9: md5 = 787600175a085c843fa570d8eb801442 OK 2024/04/12 05:19:38 DEBUG : only9: md5 = a282c55b0c80d19181491ba3916701bb OK 2024/04/12 05:19:39 DEBUG : both10: md5 = 4d2c8602a5f1046d02f3f0cb2fa0e44c OK 2024/04/12 05:19:41 DEBUG : only10: md5 = d986ef42c20f2415cfd9d7bad14c31ab OK 2024/04/12 05:19:43 DEBUG : both11: md5 = bae5f229f7184125e5c8912f71ceb84b OK 2024/04/12 05:19:45 DEBUG : only11: md5 = bb11ab66381987c3daa1bb674052ad2c OK 2024/04/12 05:19:47 DEBUG : both12: md5 = 0d9dd3648c255e2cfd2409bfb866549f OK 2024/04/12 05:19:48 DEBUG : only12: md5 = c899a94511c6d9c418e7348944fc4366 OK 2024/04/12 05:19:50 DEBUG : both13: md5 = d3e7e02ac5892fec2fba8159f96f2272 OK 2024/04/12 05:19:52 DEBUG : only13: md5 = 9120df4f7c51d74ebf94c97b18fab6ac OK 2024/04/12 05:19:53 DEBUG : both14: md5 = 8370053f2ca173a2f082be851c3f295e OK 2024/04/12 05:19:55 DEBUG : only14: md5 = 57573412543c478ec57857a2fdc3abf3 OK 2024/04/12 05:19:57 DEBUG : both15: md5 = c620d781dd764f399a7bdc96197ca0c8 OK 2024/04/12 05:19:58 DEBUG : only15: md5 = 1c5d3ab106de6a70adb3c2cbbbcee247 OK 2024/04/12 05:20:00 DEBUG : both16: md5 = 9195b798d4dcfd9f7efed70226e0a144 OK 2024/04/12 05:20:02 DEBUG : only16: md5 = 169f4b8956228f0d2fa917ffb42a4a23 OK 2024/04/12 05:20:04 DEBUG : both17: md5 = 31c7fb393f2ed30c8b117f3ef20a13e0 OK 2024/04/12 05:20:05 DEBUG : only17: md5 = 0ff190d27950595630cc33c513005095 OK 2024/04/12 05:20:07 DEBUG : both18: md5 = 39a564fea8a3eed0b28b14f4ed769f77 OK 2024/04/12 05:20:09 DEBUG : only18: md5 = 89d583e5a2094891acae34a26ec4555c OK 2024/04/12 05:20:11 DEBUG : both19: md5 = 02c27b2b698283f56c4641bad8f64409 OK 2024/04/12 05:20:12 DEBUG : only19: md5 = 72529d64e40b5063558b9c467f88e3b4 OK 2024/04/12 05:20:13 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for checks to finish 2024/04/12 05:20:13 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both0: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both12: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both1: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both14: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both15: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both16: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both17: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both18: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both19: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both2: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both3: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both4: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both5: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both6: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both7: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both8: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/12 05:20:13 DEBUG : both9: Unchanged skipping 2024/04/12 05:20:13 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2024/04/12 05:20:13 DEBUG : both11: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both10: Unchanged skipping 2024/04/12 05:20:13 DEBUG : both13: Unchanged skipping 2024/04/12 05:20:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Waiting for transfers to finish 2024/04/12 05:20:15 DEBUG : only1: md5 = a8c0574fb06d44a10c8505661d0a1aba OK 2024/04/12 05:20:15 INFO : only1: Copied (replaced existing) 2024/04/12 05:20:15 DEBUG : only0: md5 = d9bd6994a6f1420dbfcf4e4528110572 OK 2024/04/12 05:20:15 INFO : only0: Copied (replaced existing) 2024/04/12 05:20:15 DEBUG : only10: md5 = 32dead467124e6b696ae667cd4d4e9e0 OK 2024/04/12 05:20:15 INFO : only10: Copied (replaced existing) 2024/04/12 05:20:15 DEBUG : only11: md5 = 08c5e67cf3e53ca6dae7ceddf44616d3 OK 2024/04/12 05:20:15 INFO : only11: Copied (replaced existing) 2024/04/12 05:20:16 DEBUG : only12: md5 = 3cd5eaedde541e8815e52ed3652c97ac OK 2024/04/12 05:20:16 INFO : only12: Copied (replaced existing) 2024/04/12 05:20:16 DEBUG : only13: md5 = 54f8af26f07ffb13bcedcf45bcac1950 OK 2024/04/12 05:20:16 INFO : only13: Copied (replaced existing) 2024/04/12 05:20:17 DEBUG : only15: md5 = d00835f2886058394ac8c33c484fcea2 OK 2024/04/12 05:20:17 INFO : only15: Copied (replaced existing) 2024/04/12 05:20:17 DEBUG : only14: md5 = 26ab3e7b00174d5c3a5a917f71b79241 OK 2024/04/12 05:20:17 INFO : only14: Copied (replaced existing) 2024/04/12 05:20:18 DEBUG : only16: md5 = e5e4a31007ebaeb208ed2c7e5c71d95e OK 2024/04/12 05:20:18 INFO : only16: Copied (replaced existing) 2024/04/12 05:20:18 DEBUG : only17: md5 = 157fe84cd3a8d7be1e56025debdf8012 OK 2024/04/12 05:20:18 INFO : only17: Copied (replaced existing) 2024/04/12 05:20:18 DEBUG : only18: md5 = aafa361e164e99deb8690e4504a6c0f6 OK 2024/04/12 05:20:18 INFO : only18: Copied (replaced existing) 2024/04/12 05:20:18 DEBUG : only19: md5 = b1296b365756e42c4d6aa555acdeff36 OK 2024/04/12 05:20:18 INFO : only19: Copied (replaced existing) 2024/04/12 05:20:19 DEBUG : only2: md5 = e9c36e7da498f96bd62fb08708d1fac0 OK 2024/04/12 05:20:19 INFO : only2: Copied (replaced existing) 2024/04/12 05:20:19 DEBUG : only3: md5 = 4cfa269b69111f0e084d19364d505600 OK 2024/04/12 05:20:19 INFO : only3: Copied (replaced existing) 2024/04/12 05:20:20 DEBUG : only4: md5 = 57b1cc35cab24da47a1ce3b07d88ecbe OK 2024/04/12 05:20:20 INFO : only4: Copied (replaced existing) 2024/04/12 05:20:20 DEBUG : only5: md5 = bb343cd244e085be8704fecaaa0c5958 OK 2024/04/12 05:20:20 INFO : only5: Copied (replaced existing) 2024/04/12 05:20:21 DEBUG : only7: md5 = 40fcec4ad8a1d21cb03345715a15a945 OK 2024/04/12 05:20:21 INFO : only7: Copied (replaced existing) 2024/04/12 05:20:21 DEBUG : only6: md5 = 1a2a27cf31740a4b1a2dbd997b7a661e OK 2024/04/12 05:20:21 INFO : only6: Copied (replaced existing) 2024/04/12 05:20:21 DEBUG : only9: md5 = b45eb8aa8c2ae0ab3adacbae9072c384 OK 2024/04/12 05:20:21 INFO : only9: Copied (replaced existing) 2024/04/12 05:20:21 DEBUG : only8: md5 = 18fca5b1fd3812e17cae1b01b0d7c485 OK 2024/04/12 05:20:21 INFO : only8: Copied (replaced existing) 2024/04/12 05:20:21 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" --- PASS: TestSyncConcurrentTruncate (109.78s) === RUN TestNothingToTransfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:20:53 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/12 05:20:53 DEBUG : sub dir: Making directory with metadata 2024/04/12 05:20:54 INFO : sub dir: Made directory with metadata (mtime=2011-12-30T12:59:59Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9'", Local "Local file system at /tmp/rclone1145245598", Modify Window "1ms" 2024/04/12 05:21:21 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8/i24n0ln37pa2hv8pctddeuh73o: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2024/04/12 05:21:21 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "i24n0ln37pa2hv8pctddeuh73o" 2024/04/12 05:21:22 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "37qp6d1gohacv723ij3brofbu8" 2024/04/12 05:21:23 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/12 05:21:25 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/12 05:21:26 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/12 05:21:27 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/12 05:21:28 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/12 05:21:29 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestNothingToTransfer (37.73s) PASS 2024/04/12 05:21:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wumodez2dorakem0weyenul9': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Finished OK in 16m57.564674451s (try 1/5)