"./sync.test -test.v -test.timeout 30m0s -remote TestOpenDrive: -verbose" - Starting (try 1/5) 2019/10/12 05:27:13 DEBUG : Starting OpenDrive session with ID: 260fa60a30beb5165a5ede6176742bec6540f80dbb29641a673bf3b71e75c603 === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.07s) === RUN TestRcCopy --- SKIP: TestRcCopy (0.00s) rc_test.go:16: Skipping test on non local remote === RUN TestRcMove --- SKIP: TestRcMove (0.00s) rc_test.go:16: Skipping test on non local remote === RUN TestRcSync --- SKIP: TestRcSync (0.00s) rc_test.go:16: Skipping test on non local remote === RUN TestCopyWithDryRun 2019/10/12 05:27:16 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:27:16 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:27:16 NOTICE: sub dir/hello world: Not copying as --dry-run --- PASS: TestCopyWithDryRun (3.39s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopy 2019/10/12 05:27:18 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:27:18 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:27:21 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:27:25 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopy (11.76s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyMissingDirectory 2019/10/12 05:27:30 ERROR : : error reading source directory: directory not found 2019/10/12 05:27:30 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:27:30 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (1.63s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyNoTraverse 2019/10/12 05:27:31 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:27:31 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:27:34 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:27:37 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopyNoTraverse (10.82s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncNoTraverse 2019/10/12 05:27:42 ERROR : Ignoring --no-traverse with sync 2019/10/12 05:27:42 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:27:42 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:27:45 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:27:48 INFO : sub dir/hello world: Copied (new) 2019/10/12 05:27:48 INFO : Waiting for deletions to finish --- PASS: TestSyncNoTraverse (10.56s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyWithDepth 2019/10/12 05:27:53 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:27:53 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:27:55 DEBUG : hello world2: Uploading chunk 0, size=12, remain=0 2019/10/12 05:27:58 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (7.51s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyWithFilesFrom 2019/10/12 05:28:00 DEBUG : hello world2: Excluded 2019/10/12 05:28:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:28:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:28:02 DEBUG : potato2: Uploading chunk 0, size=11, remain=0 2019/10/12 05:28:05 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (7.32s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyWithFilesFromAndNoTraverse 2019/10/12 05:28:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:28:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:28:10 DEBUG : potato2: Uploading chunk 0, size=11, remain=0 2019/10/12 05:28:13 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (7.66s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyEmptyDirectories 2019/10/12 05:28:15 DEBUG : sub dir2: Making directory 2019/10/12 05:28:15 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:28:15 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:28:18 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:28:21 INFO : sub dir/hello world: Copied (new) 2019/10/12 05:28:21 DEBUG : sub dir2: Making directory 2019/10/12 05:28:22 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': copied 1 directories --- PASS: TestCopyEmptyDirectories (12.92s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestMoveEmptyDirectories 2019/10/12 05:28:28 DEBUG : sub dir2: Making directory 2019/10/12 05:28:28 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:28:28 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:28:31 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:28:34 INFO : sub dir/hello world: Copied (new) 2019/10/12 05:28:34 INFO : sub dir/hello world: Deleted 2019/10/12 05:28:34 DEBUG : sub dir: Making directory 2019/10/12 05:28:34 DEBUG : sub dir2: Making directory 2019/10/12 05:28:35 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': copied 2 directories --- PASS: TestMoveEmptyDirectories (12.65s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncEmptyDirectories 2019/10/12 05:28:40 DEBUG : sub dir2: Making directory 2019/10/12 05:28:41 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:28:41 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:28:44 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:28:46 INFO : sub dir/hello world: Copied (new) 2019/10/12 05:28:46 DEBUG : sub dir2: Making directory 2019/10/12 05:28:48 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': copied 1 directories 2019/10/12 05:28:48 INFO : Waiting for deletions to finish --- PASS: TestSyncEmptyDirectories (12.82s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestServerSideCopy 2019/10/12 05:28:56 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:29:01 DEBUG : Starting OpenDrive session with ID: 09a4120f5789367eb9b3ee861e6fe04d864dcc9f31fdd94320ab19eb8d3fc099 2019/10/12 05:29:03 INFO : OpenDrive root 'rclone-test-monibid7qoqalus4jocopex1': Waiting for checks to finish 2019/10/12 05:29:03 INFO : OpenDrive root 'rclone-test-monibid7qoqalus4jocopex1': Waiting for transfers to finish 2019/10/12 05:29:07 INFO : sub dir/hello world: Copied (server side copy) 2019/10/12 05:29:08 DEBUG : OpenDrive root 'rclone-test-monibid7qoqalus4jocopex1': Purge remote --- PASS: TestServerSideCopy (19.49s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:257: Server side copy (if possible) OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7' -> OpenDrive root 'rclone-test-monibid7qoqalus4jocopex1' === RUN TestCopyAfterDelete 2019/10/12 05:29:15 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:29:18 ERROR : : error listing: directory not found 2019/10/12 05:29:19 DEBUG : Local file system at /tmp/rclone676390312: Making directory 2019/10/12 05:29:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:29:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish --- PASS: TestCopyAfterDelete (11.51s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyRedownload 2019/10/12 05:29:27 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:29:32 INFO : Local file system at /tmp/rclone676390312: Waiting for checks to finish 2019/10/12 05:29:32 INFO : Local file system at /tmp/rclone676390312: Waiting for transfers to finish 2019/10/12 05:29:32 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/12 05:29:32 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopyRedownload (11.32s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncBasedOnCheckSum 2019/10/12 05:29:36 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:29:36 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:29:38 DEBUG : check sum: Uploading chunk 0, size=1, remain=0 2019/10/12 05:29:41 INFO : check sum: Copied (new) 2019/10/12 05:29:41 INFO : Waiting for deletions to finish 2019/10/12 05:29:42 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:29:42 DEBUG : check sum: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/12 05:29:42 DEBUG : check sum: Size and MD5 of src and dst objects identical 2019/10/12 05:29:42 DEBUG : check sum: Unchanged skipping 2019/10/12 05:29:42 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:29:42 INFO : Waiting for deletions to finish --- PASS: TestSyncBasedOnCheckSum (8.75s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncSizeOnly 2019/10/12 05:29:45 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:29:45 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:29:46 DEBUG : sizeonly: Uploading chunk 0, size=6, remain=0 2019/10/12 05:29:51 INFO : sizeonly: Copied (new) 2019/10/12 05:29:51 INFO : Waiting for deletions to finish 2019/10/12 05:29:52 DEBUG : sizeonly: Sizes identical 2019/10/12 05:29:52 DEBUG : sizeonly: Unchanged skipping 2019/10/12 05:29:52 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:29:52 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:29:52 INFO : Waiting for deletions to finish --- PASS: TestSyncSizeOnly (9.70s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncIgnoreSize 2019/10/12 05:29:54 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:29:54 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:29:56 DEBUG : ignore-size: Uploading chunk 0, size=8, remain=0 2019/10/12 05:29:59 INFO : ignore-size: Copied (new) 2019/10/12 05:29:59 INFO : Waiting for deletions to finish 2019/10/12 05:30:00 DEBUG : ignore-size: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:30:00 DEBUG : ignore-size: Unchanged skipping 2019/10/12 05:30:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:00 INFO : Waiting for deletions to finish --- PASS: TestSyncIgnoreSize (8.47s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncIgnoreTimes 2019/10/12 05:30:04 DEBUG : existing: Uploading chunk 0, size=6, remain=0 2019/10/12 05:30:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:08 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:30:08 DEBUG : existing: Unchanged skipping 2019/10/12 05:30:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:08 INFO : Waiting for deletions to finish 2019/10/12 05:30:09 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2019/10/12 05:30:09 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:09 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:09 DEBUG : existing: Uploading chunk 0, size=6, remain=0 2019/10/12 05:30:12 INFO : existing: Copied (replaced existing) 2019/10/12 05:30:12 INFO : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (11.76s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncIgnoreExisting 2019/10/12 05:30:15 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:15 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:17 DEBUG : existing: Uploading chunk 0, size=6, remain=0 2019/10/12 05:30:19 INFO : existing: Copied (new) 2019/10/12 05:30:19 INFO : Waiting for deletions to finish 2019/10/12 05:30:20 DEBUG : existing: Destination exists, skipping 2019/10/12 05:30:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:20 INFO : Waiting for deletions to finish --- PASS: TestSyncIgnoreExisting (8.45s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncIgnoreErrors 2019/10/12 05:30:25 DEBUG : b/potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:30:32 DEBUG : c/non empty space: Uploading chunk 0, size=5, remain=0 2019/10/12 05:30:35 DEBUG : d: Making directory 2019/10/12 05:30:38 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:30:38 DEBUG : c/non empty space: Unchanged skipping 2019/10/12 05:30:38 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:38 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:41 DEBUG : a/potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:30:44 INFO : a/potato2: Copied (new) 2019/10/12 05:30:44 INFO : Waiting for deletions to finish 2019/10/12 05:30:44 INFO : b/potato: Deleted 2019/10/12 05:30:44 DEBUG : d: Removing directory 2019/10/12 05:30:46 DEBUG : b: Removing directory 2019/10/12 05:30:47 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': deleted 2 directories --- PASS: TestSyncIgnoreErrors (30.02s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterChangingModtimeOnly 2019/10/12 05:30:54 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:30:58 DEBUG : empty space: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC 2019/10/12 05:30:58 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:58 DEBUG : empty space: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/12 05:30:58 NOTICE: empty space: Not updating modification time as --dry-run 2019/10/12 05:30:58 DEBUG : empty space: Unchanged skipping 2019/10/12 05:30:58 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:30:58 INFO : Waiting for deletions to finish 2019/10/12 05:30:59 DEBUG : empty space: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC 2019/10/12 05:30:59 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:30:59 DEBUG : empty space: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/12 05:31:00 INFO : empty space: Updated modification time in destination 2019/10/12 05:31:00 DEBUG : empty space: Unchanged skipping 2019/10/12 05:31:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:31:00 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (9.46s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime 2019/10/12 05:31:04 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:31:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:31:08 DEBUG : empty space: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC 2019/10/12 05:31:08 DEBUG : empty space: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/12 05:31:08 DEBUG : empty space: Unchanged skipping 2019/10/12 05:31:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:31:08 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (7.71s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncDoesntUpdateModtime 2019/10/12 05:31:12 DEBUG : foo: Uploading chunk 0, size=3, remain=0 2019/10/12 05:31:16 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:31:16 DEBUG : foo: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC 2019/10/12 05:31:16 DEBUG : foo: MD5 = acbd18db4cc2f85cedef654fccc4a4d8 (Local file system at /tmp/rclone676390312) 2019/10/12 05:31:16 DEBUG : foo: MD5 = 37b51d194a7513e45b56f6524f2d51f2 (OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7') 2019/10/12 05:31:16 DEBUG : foo: MD5 differ 2019/10/12 05:31:16 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:31:16 DEBUG : foo: Uploading chunk 0, size=3, remain=0 2019/10/12 05:31:20 INFO : foo: Copied (replaced existing) 2019/10/12 05:31:20 INFO : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (12.00s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterAddingAFile 2019/10/12 05:31:24 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:31:28 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:31:28 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:31:28 DEBUG : empty space: Unchanged skipping 2019/10/12 05:31:28 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:31:30 DEBUG : potato: Uploading chunk 0, size=60, remain=0 2019/10/12 05:31:33 INFO : potato: Copied (new) 2019/10/12 05:31:33 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (13.93s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterChangingFilesSizeOnly 2019/10/12 05:31:37 DEBUG : potato: Uploading chunk 0, size=60, remain=0 2019/10/12 05:31:41 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:31:41 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2019/10/12 05:31:41 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:31:42 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:31:45 INFO : potato: Copied (replaced existing) 2019/10/12 05:31:45 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (11.60s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterChangingContentsOnly 2019/10/12 05:31:49 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:31:53 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 2019/10/12 05:31:53 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:31:53 DEBUG : potato: MD5 = e4cb6955d9106df6263c45fcfc10f163 (Local file system at /tmp/rclone676390312) 2019/10/12 05:31:53 DEBUG : potato: MD5 = 100defcf18c42a1e0dc42a789b107cd2 (OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7') 2019/10/12 05:31:53 DEBUG : potato: MD5 differ 2019/10/12 05:31:53 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:31:54 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:31:57 INFO : potato: Copied (replaced existing) 2019/10/12 05:31:57 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (11.53s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun 2019/10/12 05:32:00 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:32:05 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:32:08 NOTICE: potato2: Not copying as --dry-run 2019/10/12 05:32:08 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:32:08 DEBUG : empty space: Unchanged skipping 2019/10/12 05:32:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:32:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:32:08 INFO : Waiting for deletions to finish 2019/10/12 05:32:08 NOTICE: potato: Not deleting as --dry-run --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (12.18s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFile 2019/10/12 05:32:13 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:32:18 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:32:21 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:32:21 DEBUG : empty space: Unchanged skipping 2019/10/12 05:32:21 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:32:21 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:32:24 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:32:26 INFO : potato2: Copied (new) 2019/10/12 05:32:26 INFO : Waiting for deletions to finish 2019/10/12 05:32:27 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (18.58s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir 2019/10/12 05:32:33 DEBUG : b/potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:32:43 DEBUG : c/non empty space: Uploading chunk 0, size=5, remain=0 2019/10/12 05:32:47 DEBUG : d: Making directory 2019/10/12 05:32:48 DEBUG : d/e: Making directory 2019/10/12 05:32:53 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:32:53 DEBUG : c/non empty space: Unchanged skipping 2019/10/12 05:32:54 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:32:54 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:32:55 DEBUG : a/potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:32:58 INFO : a/potato2: Copied (new) 2019/10/12 05:32:58 INFO : Waiting for deletions to finish 2019/10/12 05:32:58 INFO : b/potato: Deleted 2019/10/12 05:32:58 DEBUG : d/e: Removing directory 2019/10/12 05:32:59 DEBUG : d: Removing directory 2019/10/12 05:33:00 DEBUG : b: Removing directory 2019/10/12 05:33:02 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': deleted 3 directories --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (37.93s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors 2019/10/12 05:33:10 DEBUG : b/potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:33:16 DEBUG : c/non empty space: Uploading chunk 0, size=5, remain=0 2019/10/12 05:33:19 DEBUG : d: Making directory 2019/10/12 05:33:22 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:33:22 DEBUG : c/non empty space: Unchanged skipping 2019/10/12 05:33:22 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:33:22 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:33:25 DEBUG : a/potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:33:28 INFO : a/potato2: Copied (new) 2019/10/12 05:33:28 ERROR : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': not deleting files as there were IO errors 2019/10/12 05:33:28 ERROR : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': not deleting directories as there were IO errors --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (28.69s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring 2019/10/12 05:33:38 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:33:43 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:33:46 INFO : Waiting for deletions to finish 2019/10/12 05:33:47 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:33:47 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:33:47 DEBUG : empty space: Unchanged skipping 2019/10/12 05:33:47 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:33:47 INFO : potato: Deleted 2019/10/12 05:33:48 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:33:51 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (17.64s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncDeleteBefore 2019/10/12 05:33:56 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:34:00 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:34:03 INFO : Waiting for deletions to finish 2019/10/12 05:34:04 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:34:04 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:34:04 INFO : potato: Deleted 2019/10/12 05:34:05 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:34:05 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:34:05 DEBUG : empty space: Unchanged skipping 2019/10/12 05:34:05 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:34:07 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:34:09 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (18.29s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestCopyDeleteBefore 2019/10/12 05:34:14 DEBUG : potato: Uploading chunk 0, size=21, remain=0 2019/10/12 05:34:18 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:34:18 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:34:20 DEBUG : potato2: Uploading chunk 0, size=19, remain=0 2019/10/12 05:34:23 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (13.37s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncWithExclude 2019/10/12 05:34:28 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:34:33 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:34:37 DEBUG : potato2: Excluded 2019/10/12 05:34:37 DEBUG : enormous: Excluded 2019/10/12 05:34:37 DEBUG : potato2: Excluded 2019/10/12 05:34:37 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:34:37 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:34:37 DEBUG : empty space: Unchanged skipping 2019/10/12 05:34:37 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:34:37 INFO : Waiting for deletions to finish 2019/10/12 05:34:38 DEBUG : potato2: Excluded 2019/10/12 05:34:38 DEBUG : enormous: Excluded 2019/10/12 05:34:38 DEBUG : potato2: Excluded 2019/10/12 05:34:38 INFO : Local file system at /tmp/rclone676390312: Waiting for checks to finish 2019/10/12 05:34:38 DEBUG : empty space: Size and modification time the same (differ by 123.456789ms, within tolerance 1s) 2019/10/12 05:34:38 DEBUG : empty space: Unchanged skipping 2019/10/12 05:34:38 INFO : Local file system at /tmp/rclone676390312: Waiting for transfers to finish 2019/10/12 05:34:38 INFO : Waiting for deletions to finish --- PASS: TestSyncWithExclude (14.94s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncWithExcludeAndDeleteExcluded 2019/10/12 05:34:42 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:34:47 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:34:52 DEBUG : enormous: Uploading chunk 0, size=100, remain=0 2019/10/12 05:34:56 DEBUG : potato2: Excluded 2019/10/12 05:34:56 DEBUG : enormous: Excluded 2019/10/12 05:34:56 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:34:56 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:34:56 DEBUG : empty space: Unchanged skipping 2019/10/12 05:34:56 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:34:56 INFO : Waiting for deletions to finish 2019/10/12 05:34:57 INFO : enormous: Deleted 2019/10/12 05:34:57 INFO : potato2: Deleted 2019/10/12 05:34:58 INFO : Local file system at /tmp/rclone676390312: Waiting for checks to finish 2019/10/12 05:34:58 DEBUG : empty space: Size and modification time the same (differ by 123.456789ms, within tolerance 1s) 2019/10/12 05:34:58 DEBUG : empty space: Unchanged skipping 2019/10/12 05:34:58 INFO : Local file system at /tmp/rclone676390312: Waiting for transfers to finish 2019/10/12 05:34:58 INFO : Waiting for deletions to finish 2019/10/12 05:34:58 INFO : potato2: Deleted 2019/10/12 05:34:58 INFO : enormous: Deleted --- PASS: TestSyncWithExcludeAndDeleteExcluded (19.11s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncWithUpdateOlder 2019/10/12 05:35:01 DEBUG : one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:35:06 DEBUG : two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:35:11 DEBUG : three: Uploading chunk 0, size=5, remain=0 2019/10/12 05:35:15 DEBUG : four: Uploading chunk 0, size=8, remain=0 2019/10/12 05:35:19 DEBUG : four: Destination mod time is within 1s of source but sizes differ, transferring 2019/10/12 05:35:19 DEBUG : one: Destination is newer than source, skipping 2019/10/12 05:35:19 DEBUG : three: Destination mod time is within 1s of source and sizes identical, skipping 2019/10/12 05:35:19 DEBUG : two: Destination is older than source, transferring 2019/10/12 05:35:19 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:35:19 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:35:20 DEBUG : four: Uploading chunk 0, size=4, remain=0 2019/10/12 05:35:20 DEBUG : two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:35:21 DEBUG : five: Uploading chunk 0, size=4, remain=0 2019/10/12 05:35:23 INFO : two: Copied (replaced existing) 2019/10/12 05:35:24 INFO : four: Copied (replaced existing) 2019/10/12 05:35:24 INFO : five: Copied (new) 2019/10/12 05:35:24 INFO : Waiting for deletions to finish --- PASS: TestSyncWithUpdateOlder (28.58s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncWithTrackRenames 2019/10/12 05:35:29 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Making map for --track-renames 2019/10/12 05:35:29 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Finished making map for --track-renames 2019/10/12 05:35:29 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:35:29 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for renames to finish 2019/10/12 05:35:29 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:35:30 DEBUG : yam: Uploading chunk 0, size=11, remain=0 2019/10/12 05:35:31 DEBUG : potato: Uploading chunk 0, size=14, remain=0 2019/10/12 05:35:33 INFO : yam: Copied (new) 2019/10/12 05:35:34 INFO : potato: Copied (new) 2019/10/12 05:35:34 INFO : Waiting for deletions to finish 2019/10/12 05:35:35 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:35:35 DEBUG : potato: Unchanged skipping 2019/10/12 05:35:35 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Making map for --track-renames 2019/10/12 05:35:35 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Finished making map for --track-renames 2019/10/12 05:35:35 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:35:35 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for renames to finish 2019/10/12 05:35:48 INFO : yam: Moved (server side) 2019/10/12 05:35:48 INFO : yaml: Renamed from "yam" 2019/10/12 05:35:48 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:35:48 INFO : Waiting for deletions to finish --- PASS: TestSyncWithTrackRenames (22.42s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:993: Can track renames: true === RUN TestMoveWithDeleteEmptySrcDirs 2019/10/12 05:35:51 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:35:51 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:35:54 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:35:56 DEBUG : nested/sub dir/file: Uploading chunk 0, size=6, remain=0 2019/10/12 05:35:57 INFO : sub dir/hello world: Copied (new) 2019/10/12 05:35:57 INFO : sub dir/hello world: Deleted 2019/10/12 05:35:59 INFO : nested/sub dir/file: Copied (new) 2019/10/12 05:35:59 INFO : nested/sub dir/file: Deleted 2019/10/12 05:35:59 DEBUG : sub dir: Removing directory 2019/10/12 05:35:59 DEBUG : nested/sub dir: Removing directory 2019/10/12 05:35:59 DEBUG : nested: Removing directory 2019/10/12 05:35:59 DEBUG : Local file system at /tmp/rclone676390312: deleted 3 directories --- PASS: TestMoveWithDeleteEmptySrcDirs (16.70s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestMoveWithoutDeleteEmptySrcDirs 2019/10/12 05:36:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:36:08 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:36:11 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0 2019/10/12 05:36:13 DEBUG : nested/sub dir/file: Uploading chunk 0, size=6, remain=0 2019/10/12 05:36:13 INFO : sub dir/hello world: Copied (new) 2019/10/12 05:36:13 INFO : sub dir/hello world: Deleted 2019/10/12 05:36:16 INFO : nested/sub dir/file: Copied (new) 2019/10/12 05:36:16 INFO : nested/sub dir/file: Deleted --- PASS: TestMoveWithoutDeleteEmptySrcDirs (16.40s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestServerSideMove 2019/10/12 05:36:24 DEBUG : Starting OpenDrive session with ID: 31f87009f93bf44f0dda5ba1a25ea0cf16f16b8d5246e0b255d25856bf147730 2019/10/12 05:36:27 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:36:32 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:36:37 DEBUG : potato3: Uploading chunk 0, size=68, remain=0 2019/10/12 05:36:43 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:36:48 DEBUG : potato3: Uploading chunk 0, size=60, remain=0 2019/10/12 05:36:51 DEBUG : OpenDrive root 'rclone-test-gipabak5cajuwol3gisiwot2': Using server side directory move 2019/10/12 05:36:51 INFO : OpenDrive root 'rclone-test-gipabak5cajuwol3gisiwot2': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2019/10/12 05:36:51 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2019/10/12 05:36:51 DEBUG : empty space: Unchanged skipping 2019/10/12 05:36:51 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2019/10/12 05:36:51 INFO : OpenDrive root 'rclone-test-gipabak5cajuwol3gisiwot2': Waiting for checks to finish 2019/10/12 05:36:52 INFO : potato3: Deleted 2019/10/12 05:36:52 INFO : empty space: Deleted 2019/10/12 05:36:52 INFO : OpenDrive root 'rclone-test-gipabak5cajuwol3gisiwot2': Waiting for transfers to finish 2019/10/12 05:36:53 INFO : potato2: Moved (server side) 2019/10/12 05:36:53 INFO : potato3: Moved (server side) 2019/10/12 05:36:55 DEBUG : Starting OpenDrive session with ID: dce34b75a36aa6b9357a2551c7bec0746f05e90814ec92334c605f39a29c0e21 2019/10/12 05:36:56 DEBUG : OpenDrive root 'rclone-test-yutajaz4cugosec1kobosaq7': Using server side directory move 2019/10/12 05:36:57 INFO : OpenDrive root 'rclone-test-yutajaz4cugosec1kobosaq7': Server side directory move succeeded 2019/10/12 05:36:58 ERROR : : error listing: directory not found 2019/10/12 05:36:58 DEBUG : OpenDrive root 'rclone-test-yutajaz4cugosec1kobosaq7': Purge remote 2019/10/12 05:37:00 DEBUG : OpenDrive root 'rclone-test-gipabak5cajuwol3gisiwot2': Purge remote 2019/10/12 05:37:00 purge failed: directory not found --- PASS: TestServerSideMove (37.67s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:1098: Server side move (if possible) OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7' -> OpenDrive root 'rclone-test-gipabak5cajuwol3gisiwot2' === RUN TestServerSideMoveWithFilter 2019/10/12 05:37:02 DEBUG : Starting OpenDrive session with ID: 3f434ef8ef33d9aa0f2e5d0515d24ed45a6601d8177021f303a551d69933c18c 2019/10/12 05:37:05 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:37:10 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:37:15 DEBUG : potato3: Uploading chunk 0, size=68, remain=0 2019/10/12 05:37:21 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:37:26 DEBUG : potato3: Uploading chunk 0, size=60, remain=0 2019/10/12 05:37:30 DEBUG : empty space: Excluded 2019/10/12 05:37:30 DEBUG : empty space: Excluded 2019/10/12 05:37:30 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2019/10/12 05:37:30 INFO : OpenDrive root 'rclone-test-feditaq3xayijuv2cudivap0': Waiting for checks to finish 2019/10/12 05:37:30 INFO : OpenDrive root 'rclone-test-feditaq3xayijuv2cudivap0': Waiting for transfers to finish 2019/10/12 05:37:31 INFO : potato3: Deleted 2019/10/12 05:37:32 INFO : potato2: Moved (server side) 2019/10/12 05:37:32 INFO : potato3: Moved (server side) 2019/10/12 05:37:34 DEBUG : Starting OpenDrive session with ID: a8567d9d794377a2658daf71c86cd605331b5792748738096d110b058388411f 2019/10/12 05:37:35 DEBUG : empty space: Excluded 2019/10/12 05:37:36 INFO : OpenDrive root 'rclone-test-gebuzar3donicib3yovuted6': Waiting for checks to finish 2019/10/12 05:37:36 INFO : OpenDrive root 'rclone-test-gebuzar3donicib3yovuted6': Waiting for transfers to finish 2019/10/12 05:37:38 INFO : potato2: Moved (server side) 2019/10/12 05:37:38 INFO : potato3: Moved (server side) 2019/10/12 05:37:39 DEBUG : OpenDrive root 'rclone-test-gebuzar3donicib3yovuted6': Purge remote 2019/10/12 05:37:40 DEBUG : OpenDrive root 'rclone-test-feditaq3xayijuv2cudivap0': Purge remote --- PASS: TestServerSideMoveWithFilter (41.53s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:1098: Server side move (if possible) OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7' -> OpenDrive root 'rclone-test-feditaq3xayijuv2cudivap0' === RUN TestServerSideMoveDeleteEmptySourceDirs 2019/10/12 05:37:43 DEBUG : Starting OpenDrive session with ID: d03e1e72889d0a22597c9811ba75fd33481f6d3ca14897e1da14315a5c92e9b3 2019/10/12 05:37:46 DEBUG : potato2: Uploading chunk 0, size=60, remain=0 2019/10/12 05:37:51 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:37:55 DEBUG : potato3: Uploading chunk 0, size=68, remain=0 2019/10/12 05:37:58 DEBUG : tomatoDir: Making directory 2019/10/12 05:38:04 DEBUG : empty space: Uploading chunk 0, size=1, remain=0 2019/10/12 05:38:08 DEBUG : potato3: Uploading chunk 0, size=60, remain=0 2019/10/12 05:38:11 DEBUG : OpenDrive root 'rclone-test-yuhiqal6fupesuv8qadosoh0': Using server side directory move 2019/10/12 05:38:11 INFO : OpenDrive root 'rclone-test-yuhiqal6fupesuv8qadosoh0': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2019/10/12 05:38:12 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2019/10/12 05:38:12 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2019/10/12 05:38:12 DEBUG : empty space: Unchanged skipping 2019/10/12 05:38:12 INFO : OpenDrive root 'rclone-test-yuhiqal6fupesuv8qadosoh0': Waiting for checks to finish 2019/10/12 05:38:12 INFO : potato3: Deleted 2019/10/12 05:38:12 INFO : empty space: Deleted 2019/10/12 05:38:12 INFO : OpenDrive root 'rclone-test-yuhiqal6fupesuv8qadosoh0': Waiting for transfers to finish 2019/10/12 05:38:13 INFO : potato2: Moved (server side) 2019/10/12 05:38:14 INFO : potato3: Moved (server side) 2019/10/12 05:38:14 DEBUG : tomatoDir: Removing directory 2019/10/12 05:38:15 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': deleted 1 directories 2019/10/12 05:38:17 DEBUG : Starting OpenDrive session with ID: ec5c55bad22a33f5325342a273060c88d8017b0a67a0e9bf31402e3c20ff8165 2019/10/12 05:38:18 DEBUG : tomatoDir: Making directory 2019/10/12 05:38:19 DEBUG : OpenDrive root 'rclone-test-xafupev5kovucet1bulasox0': Using server side directory move 2019/10/12 05:38:20 INFO : OpenDrive root 'rclone-test-xafupev5kovucet1bulasox0': Server side directory move succeeded 2019/10/12 05:38:22 ERROR : : error listing: directory not found 2019/10/12 05:38:23 ERROR : : error listing: directory not found 2019/10/12 05:38:23 DEBUG : OpenDrive root 'rclone-test-xafupev5kovucet1bulasox0': Purge remote 2019/10/12 05:38:24 DEBUG : OpenDrive root 'rclone-test-yuhiqal6fupesuv8qadosoh0': Purge remote 2019/10/12 05:38:25 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (42.99s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:1098: Server side move (if possible) OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7' -> OpenDrive root 'rclone-test-yuhiqal6fupesuv8qadosoh0' === RUN TestServerSideMoveOverlap --- SKIP: TestServerSideMoveOverlap (1.07s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:1229: Skipping test as remote supports DirMove === RUN TestSyncOverlap 2019/10/12 05:38:27 DEBUG : Starting OpenDrive session with ID: 534f897bd164cadcce42512f06d2f9e08796fe9151220e1c7ebf6ea12ddaf84e --- PASS: TestSyncOverlap (4.09s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncCompareDest 2019/10/12 05:38:32 DEBUG : Starting OpenDrive session with ID: 375a7099f14130e925bf9e5de28f44d7e12da800ad5697309abca3d2e4b05330 2019/10/12 05:38:35 DEBUG : Starting OpenDrive session with ID: f2861f27eb994df82fa73bc866d5974dabb54179caaa3444b39fe8d48fb0b4f4 2019/10/12 05:38:38 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:38:38 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:38:41 DEBUG : one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:38:44 INFO : one: Copied (new) 2019/10/12 05:38:44 INFO : Waiting for deletions to finish 2019/10/12 05:38:47 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:38:47 DEBUG : one: Sizes differ (src 5 vs dst 3) 2019/10/12 05:38:47 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:38:48 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:38:51 INFO : one: Copied (replaced existing) 2019/10/12 05:38:51 INFO : Waiting for deletions to finish 2019/10/12 05:38:53 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:38:59 DEBUG : CompareDest/one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:39:04 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:39:05 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:39:05 DEBUG : one: Destination found in --compare-dest, skipping 2019/10/12 05:39:05 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:39:05 INFO : Waiting for deletions to finish 2019/10/12 05:39:07 DEBUG : CompareDest/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:39:13 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:39:13 DEBUG : two: Destination found in --compare-dest, skipping 2019/10/12 05:39:13 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:39:13 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:39:13 DEBUG : one: Destination found in --compare-dest, skipping 2019/10/12 05:39:13 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:39:13 INFO : Waiting for deletions to finish 2019/10/12 05:39:15 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:39:15 DEBUG : two: Destination found in --compare-dest, skipping 2019/10/12 05:39:15 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:39:16 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:39:16 DEBUG : one: Destination found in --compare-dest, skipping 2019/10/12 05:39:16 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:39:16 INFO : Waiting for deletions to finish 2019/10/12 05:39:19 DEBUG : two: Sizes differ (src 5 vs dst 3) 2019/10/12 05:39:19 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:39:20 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:39:20 DEBUG : one: Destination found in --compare-dest, skipping 2019/10/12 05:39:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:39:21 DEBUG : two: Uploading chunk 0, size=5, remain=0 2019/10/12 05:39:24 INFO : two: Copied (new) 2019/10/12 05:39:24 INFO : Waiting for deletions to finish --- PASS: TestSyncCompareDest (59.60s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncCopyDest 2019/10/12 05:39:31 DEBUG : Starting OpenDrive session with ID: 58ba378807f24693b186fb1b793cbb48488406029bda23f4b7c472241941c7c3 2019/10/12 05:39:34 DEBUG : Starting OpenDrive session with ID: a7d8f7a6b44563f0987cbaeaaf96e9170c24ca40e9d43f7d479cc47c0483f280 2019/10/12 05:39:38 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:39:38 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:39:41 DEBUG : one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:39:43 INFO : one: Copied (new) 2019/10/12 05:39:43 INFO : Waiting for deletions to finish 2019/10/12 05:39:46 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:39:47 DEBUG : one: Sizes differ (src 5 vs dst 3) 2019/10/12 05:39:47 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:39:47 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:39:50 INFO : one: Copied (replaced existing) 2019/10/12 05:39:50 INFO : Waiting for deletions to finish 2019/10/12 05:39:52 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:39:58 DEBUG : CopyDest/one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:40:02 DEBUG : Starting OpenDrive session with ID: a7155ca558030b2590444ccfa6cd737236e39a25b455c4ab3d701b408bd53d20 2019/10/12 05:40:05 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:40:07 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:07 DEBUG : one: Sizes differ (src 5 vs dst 3) 2019/10/12 05:40:09 INFO : one: Moved (server side) 2019/10/12 05:40:10 INFO : one: Copied (server side copy) 2019/10/12 05:40:10 DEBUG : one: Destination found in --copy-dest, using server side copy 2019/10/12 05:40:10 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:40:10 INFO : Waiting for deletions to finish 2019/10/12 05:40:13 DEBUG : CopyDest/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:40:18 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:19 INFO : two: Copied (server side copy) 2019/10/12 05:40:19 DEBUG : two: Destination found in --copy-dest, using server side copy 2019/10/12 05:40:19 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:40:20 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:20 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:20 DEBUG : one: Unchanged skipping 2019/10/12 05:40:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:40:20 INFO : Waiting for deletions to finish 2019/10/12 05:40:22 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:40:22 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:22 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:22 DEBUG : two: Unchanged skipping 2019/10/12 05:40:22 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:22 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:22 DEBUG : one: Unchanged skipping 2019/10/12 05:40:22 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:40:22 INFO : Waiting for deletions to finish 2019/10/12 05:40:25 DEBUG : CopyDest/three: Uploading chunk 0, size=5, remain=0 2019/10/12 05:40:30 DEBUG : three: Sizes differ (src 7 vs dst 5) 2019/10/12 05:40:30 DEBUG : three: Destination not found in --copy-dest 2019/10/12 05:40:30 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:40:30 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:30 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:30 DEBUG : one: Unchanged skipping 2019/10/12 05:40:30 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:30 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2019/10/12 05:40:30 DEBUG : two: Unchanged skipping 2019/10/12 05:40:30 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:40:32 DEBUG : three: Uploading chunk 0, size=7, remain=0 2019/10/12 05:40:35 INFO : three: Copied (new) 2019/10/12 05:40:35 INFO : Waiting for deletions to finish --- PASS: TestSyncCopyDest (73.78s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncBackupDir 2019/10/12 05:40:48 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:40:52 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:40:57 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 2019/10/12 05:41:01 DEBUG : Starting OpenDrive session with ID: 96a89725b2467373937b6fff2067ac155eb75bac275f9ebb56becd68ad866848 2019/10/12 05:41:03 DEBUG : Starting OpenDrive session with ID: bb5ac4135c934437ea886cec07aa72f997b1715f646f6209c49eb797f5fc59be 2019/10/12 05:41:06 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:41:06 DEBUG : one: Sizes differ (src 4 vs dst 3) 2019/10/12 05:41:06 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:41:06 DEBUG : two: Unchanged skipping 2019/10/12 05:41:09 INFO : one: Moved (server side) 2019/10/12 05:41:09 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:41:11 DEBUG : one: Uploading chunk 0, size=4, remain=0 2019/10/12 05:41:14 INFO : one: Copied (new) 2019/10/12 05:41:14 INFO : Waiting for deletions to finish 2019/10/12 05:41:15 INFO : three.txt: Moved (server side) 2019/10/12 05:41:15 INFO : three.txt: Moved into backup dir 2019/10/12 05:41:18 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0 2019/10/12 05:41:23 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:41:23 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:41:23 DEBUG : two: Unchanged skipping 2019/10/12 05:41:23 DEBUG : one: Sizes differ (src 5 vs dst 4) 2019/10/12 05:41:24 INFO : one: Deleted 2019/10/12 05:41:25 INFO : one: Moved (server side) 2019/10/12 05:41:25 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:41:26 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:41:29 INFO : one: Copied (new) 2019/10/12 05:41:29 INFO : Waiting for deletions to finish 2019/10/12 05:41:30 INFO : three.txt: Deleted 2019/10/12 05:41:31 INFO : three.txt: Moved (server side) 2019/10/12 05:41:31 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDir (54.07s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncBackupDirWithSuffix 2019/10/12 05:41:41 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:41:46 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:41:51 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 2019/10/12 05:41:55 DEBUG : Starting OpenDrive session with ID: 99ae185422e42ae24ea71c84be1b921113dd6e1b3ff7ceba5a32fbe695864357 2019/10/12 05:41:57 DEBUG : Starting OpenDrive session with ID: b1d406f2cd4c26117c48a46c7b3465063d98a97ecae8e61a8edf421d5cc9b7a1 2019/10/12 05:42:00 DEBUG : one: Sizes differ (src 4 vs dst 3) 2019/10/12 05:42:00 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:42:00 DEBUG : two: Unchanged skipping 2019/10/12 05:42:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:42:03 INFO : one: Moved (server side) 2019/10/12 05:42:03 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:42:08 DEBUG : one: Uploading chunk 0, size=4, remain=0 2019/10/12 05:42:11 INFO : one: Copied (new) 2019/10/12 05:42:11 INFO : Waiting for deletions to finish 2019/10/12 05:42:13 INFO : three.txt: Moved (server side) 2019/10/12 05:42:13 INFO : three.txt: Moved into backup dir 2019/10/12 05:42:15 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0 2019/10/12 05:42:20 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:42:20 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:42:20 DEBUG : two: Unchanged skipping 2019/10/12 05:42:20 DEBUG : one: Sizes differ (src 5 vs dst 4) 2019/10/12 05:42:21 INFO : one.bak: Deleted 2019/10/12 05:42:22 INFO : one: Moved (server side) 2019/10/12 05:42:22 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:42:24 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:42:27 INFO : one: Copied (new) 2019/10/12 05:42:27 INFO : Waiting for deletions to finish 2019/10/12 05:42:28 INFO : three.txt.bak: Deleted 2019/10/12 05:42:29 INFO : three.txt: Moved (server side) 2019/10/12 05:42:29 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDirWithSuffix (57.80s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncBackupDirWithSuffixKeepExtension 2019/10/12 05:42:39 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:42:43 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:42:48 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 2019/10/12 05:42:52 DEBUG : Starting OpenDrive session with ID: 7e9747b3ad997847a73713fa7a9b2b45819b32d9e568dbeed52f3771ff291150 2019/10/12 05:42:54 DEBUG : Starting OpenDrive session with ID: 8878cae491edd7a95cb77c89b637560c15037f19a1221e77750764219f4c4de1 2019/10/12 05:42:57 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:42:57 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:42:57 DEBUG : two: Unchanged skipping 2019/10/12 05:42:57 DEBUG : one: Sizes differ (src 4 vs dst 3) 2019/10/12 05:43:00 INFO : one: Moved (server side) 2019/10/12 05:43:00 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:43:02 DEBUG : one: Uploading chunk 0, size=4, remain=0 2019/10/12 05:43:06 INFO : one: Copied (new) 2019/10/12 05:43:06 INFO : Waiting for deletions to finish 2019/10/12 05:43:07 INFO : three.txt: Moved (server side) 2019/10/12 05:43:07 INFO : three.txt: Moved into backup dir 2019/10/12 05:43:10 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0 2019/10/12 05:43:14 DEBUG : one: Sizes differ (src 5 vs dst 4) 2019/10/12 05:43:14 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:43:14 DEBUG : two: Unchanged skipping 2019/10/12 05:43:14 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for checks to finish 2019/10/12 05:43:16 INFO : one-2019-01-01: Deleted 2019/10/12 05:43:17 INFO : one: Moved (server side) 2019/10/12 05:43:17 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7/dst': Waiting for transfers to finish 2019/10/12 05:43:18 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:43:21 INFO : one: Copied (new) 2019/10/12 05:43:21 INFO : Waiting for deletions to finish 2019/10/12 05:43:22 INFO : three-2019-01-01.txt: Deleted 2019/10/12 05:43:23 INFO : three.txt: Moved (server side) 2019/10/12 05:43:23 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDirWithSuffixKeepExtension (54.04s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncSuffix 2019/10/12 05:43:38 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:43:48 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:43:58 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 2019/10/12 05:44:02 DEBUG : Starting OpenDrive session with ID: 83b55906b3a8216ebe7e250e19d34223e5794098afddc99faf11c77287399ff8 2019/10/12 05:44:04 DEBUG : one: Sizes differ (src 4 vs dst 3) 2019/10/12 05:44:17 INFO : one: Moved (server side) 2019/10/12 05:44:21 DEBUG : one: Uploading chunk 0, size=4, remain=0 2019/10/12 05:44:26 INFO : one: Copied (new) 2019/10/12 05:44:27 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:44:27 DEBUG : two: Unchanged skipping 2019/10/12 05:44:28 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2019/10/12 05:44:40 INFO : three.txt: Moved (server side) 2019/10/12 05:44:48 DEBUG : three.txt: Uploading chunk 0, size=6, remain=0 2019/10/12 05:44:51 INFO : three.txt: Copied (new) 2019/10/12 05:44:55 DEBUG : one: Sizes differ (src 5 vs dst 4) 2019/10/12 05:44:56 INFO : one.bak: Deleted 2019/10/12 05:45:10 INFO : one: Moved (server side) 2019/10/12 05:45:11 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:45:14 INFO : one: Copied (new) 2019/10/12 05:45:15 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:45:15 DEBUG : two: Unchanged skipping 2019/10/12 05:45:15 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2019/10/12 05:45:16 INFO : three.txt.bak: Deleted 2019/10/12 05:45:29 INFO : three.txt: Moved (server side) 2019/10/12 05:45:30 DEBUG : three.txt: Uploading chunk 0, size=19, remain=0 2019/10/12 05:45:33 INFO : three.txt: Copied (new) --- PASS: TestSyncSuffix (129.45s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncSuffixKeepExtension 2019/10/12 05:45:43 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0 2019/10/12 05:45:47 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0 2019/10/12 05:45:52 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0 2019/10/12 05:45:56 DEBUG : Starting OpenDrive session with ID: ee396289f82fe29067e6d892332a04bbfce16ee905b9fec011eb3cc74d13de35 2019/10/12 05:45:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2019/10/12 05:46:11 INFO : one: Moved (server side) 2019/10/12 05:46:12 DEBUG : one: Uploading chunk 0, size=4, remain=0 2019/10/12 05:46:15 INFO : one: Copied (new) 2019/10/12 05:46:16 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:46:16 DEBUG : two: Unchanged skipping 2019/10/12 05:46:16 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2019/10/12 05:46:29 INFO : three.txt: Moved (server side) 2019/10/12 05:46:31 DEBUG : three.txt: Uploading chunk 0, size=6, remain=0 2019/10/12 05:46:33 INFO : three.txt: Copied (new) 2019/10/12 05:46:36 DEBUG : one: Sizes differ (src 5 vs dst 4) 2019/10/12 05:46:37 INFO : one-2019-01-01: Deleted 2019/10/12 05:46:49 INFO : one: Moved (server side) 2019/10/12 05:46:52 DEBUG : one: Uploading chunk 0, size=5, remain=0 2019/10/12 05:46:55 INFO : one: Copied (new) 2019/10/12 05:46:55 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2019/10/12 05:46:55 DEBUG : two: Unchanged skipping 2019/10/12 05:46:56 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2019/10/12 05:46:57 INFO : three-2019-01-01.txt: Deleted 2019/10/12 05:47:10 INFO : three.txt: Moved (server side) 2019/10/12 05:47:15 DEBUG : three.txt: Uploading chunk 0, size=19, remain=0 2019/10/12 05:47:18 INFO : three.txt: Copied (new) --- PASS: TestSyncSuffixKeepExtension (104.55s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncUTFNorm 2019/10/12 05:47:26 DEBUG : Testêé: Uploading chunk 0, size=18, remain=0 2019/10/12 05:47:30 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2019/10/12 05:47:30 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:47:30 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:47:31 DEBUG : Testêé: Uploading chunk 0, size=14, remain=0 2019/10/12 05:47:33 INFO : Testêé: Copied (replaced existing) 2019/10/12 05:47:33 INFO : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (11.27s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncImmutable 2019/10/12 05:47:37 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:47:37 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:47:38 DEBUG : existing: Uploading chunk 0, size=6, remain=0 2019/10/12 05:47:41 INFO : existing: Copied (new) 2019/10/12 05:47:41 INFO : Waiting for deletions to finish 2019/10/12 05:47:43 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for checks to finish 2019/10/12 05:47:43 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2019/10/12 05:47:43 ERROR : existing: Source and destination exist but do not match: immutable file modified 2019/10/12 05:47:43 INFO : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Waiting for transfers to finish 2019/10/12 05:47:43 ERROR : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': not deleting files as there were IO errors 2019/10/12 05:47:43 ERROR : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': not deleting directories as there were IO errors --- PASS: TestSyncImmutable (9.49s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" === RUN TestSyncIgnoreCase --- SKIP: TestSyncIgnoreCase (1.08s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:1703: Skipping test as local or remote are case-insensitive === RUN TestAbort --- SKIP: TestAbort (1.08s) run.go:176: Remote "OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7'", Local "Local file system at /tmp/rclone676390312", Modify Window "1s" sync_test.go:1729: This test only runs on local PASS 2019/10/12 05:47:47 DEBUG : OpenDrive root 'rclone-test-jixexax9zevimed5yukojot7': Purge remote "./sync.test -test.v -test.timeout 30m0s -remote TestOpenDrive: -verbose" - Finished OK in 20m36.589287072s (try 1/5)