"./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestMoveWithoutDeleteEmptySrcDirs|TestSyncAfterChangingModtimeOnly|TestSyncBackupDir|TestSyncBackupDirWithSuffix|TestSyncIgnoreErrors|TestSyncIgnoreSize)$'" - Starting (try 2/5)
2024/10/29 04:52:38 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-xezajuc5kero"
2024/10/29 04:52:38 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/10/29 04:52:39 DEBUG : Starting OpenDrive session with ID: b75a5eb2d87c1b27c0d44106ea2bf7f4f07faf95b9fd14b08c8fd8deef7e9e40
2024/10/29 04:52:40 DEBUG : Creating backend with remote "/tmp/rclone55566031"
=== RUN   TestSyncIgnoreSize
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:52:40 DEBUG : ignore-size: Need to transfer - File not found at Destination
2024/10/29 04:52:40 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for checks to finish
2024/10/29 04:52:40 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for transfers to finish
2024/10/29 04:52:41 DEBUG : ignore-size: Uploading chunk 0, size=8, remain=0
2024/10/29 04:52:42 DEBUG : ignore-size: md5 = 98bf7d8c15784f0a3d63204441e1e2aa OK
2024/10/29 04:52:42 INFO  : ignore-size: Copied (new)
2024/10/29 04:52:42 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:52:42 DEBUG : ignore-size: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/10/29 04:52:42 DEBUG : ignore-size: Unchanged skipping
2024/10/29 04:52:42 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for checks to finish
2024/10/29 04:52:42 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for transfers to finish
2024/10/29 04:52:42 DEBUG : Waiting for deletions to finish
2024/10/29 04:52:42 INFO  : There was nothing to transfer
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
--- PASS: TestSyncIgnoreSize (4.09s)
=== RUN   TestSyncIgnoreErrors
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:52:45 DEBUG : b/potato: Uploading chunk 0, size=21, remain=0
2024/10/29 04:52:47 DEBUG : c/non empty space: Uploading chunk 0, size=5, remain=0
2024/10/29 04:52:48 DEBUG : d: Making directory
2024/10/29 04:52:49 DEBUG : a/potato2: Need to transfer - File not found at Destination
2024/10/29 04:52:49 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2024/10/29 04:52:49 DEBUG : c/non empty space: Unchanged skipping
2024/10/29 04:52:49 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for checks to finish
2024/10/29 04:52:49 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for transfers to finish
2024/10/29 04:52:50 DEBUG : a/potato2: Uploading chunk 0, size=60, remain=0
2024/10/29 04:52:51 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK
2024/10/29 04:52:51 INFO  : a/potato2: Copied (new)
2024/10/29 04:52:51 DEBUG : Waiting for deletions to finish
2024/10/29 04:52:51 INFO  : b/potato: Deleted
2024/10/29 04:52:51 INFO  : d: Removing directory
2024/10/29 04:52:52 INFO  : b: Removing directory
2024/10/29 04:52:52 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': deleted 2 directories
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
    fstest.go:292: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Flushing the directory cache
    fstest.go:286: Sleeping for 6s just to make sure
--- PASS: TestSyncIgnoreErrors (18.30s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:53:03 DEBUG : empty space: Uploading chunk 0, size=1, remain=0
2024/10/29 04:53:04 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for checks to finish
2024/10/29 04:53:04 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
2024/10/29 04:53:04 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK
2024/10/29 04:53:04 NOTICE: empty space: Skipped update modification time as --dry-run is set (size 1)
2024/10/29 04:53:04 DEBUG : empty space: Unchanged skipping
2024/10/29 04:53:04 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for transfers to finish
2024/10/29 04:53:04 DEBUG : Waiting for deletions to finish
2024/10/29 04:53:04 INFO  : There was nothing to transfer
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:53:04 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for checks to finish
2024/10/29 04:53:04 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
2024/10/29 04:53:04 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK
2024/10/29 04:53:05 INFO  : empty space: Updated modification time in destination
2024/10/29 04:53:05 DEBUG : empty space: Unchanged skipping
2024/10/29 04:53:05 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for transfers to finish
2024/10/29 04:53:05 DEBUG : Waiting for deletions to finish
2024/10/29 04:53:05 INFO  : There was nothing to transfer
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
--- PASS: TestSyncAfterChangingModtimeOnly (3.94s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:53:06 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/10/29 04:53:06 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination
2024/10/29 04:53:06 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for checks to finish
2024/10/29 04:53:06 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Waiting for transfers to finish
2024/10/29 04:53:07 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/10/29 04:53:08 DEBUG : nested/sub dir/file: Uploading chunk 0, size=6, remain=0
2024/10/29 04:53:08 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/10/29 04:53:08 INFO  : sub dir/hello world: Copied (new)
2024/10/29 04:53:08 INFO  : sub dir/hello world: Deleted
2024/10/29 04:53:09 DEBUG : nested/sub dir/file: md5 = 83d3784ea62518eafc60e98d84f877ad OK
2024/10/29 04:53:09 INFO  : nested/sub dir/file: Copied (new)
2024/10/29 04:53:09 INFO  : nested/sub dir/file: Deleted
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (5.98s)
=== RUN   TestSyncBackupDir
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:53:13 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0
2024/10/29 04:53:15 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0
2024/10/29 04:53:16 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0
2024/10/29 04:53:18 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-xezajuc5kero/dst"
2024/10/29 04:53:18 DEBUG : Config file has changed externally - reloading
2024/10/29 04:53:18 DEBUG : Starting OpenDrive session with ID: 1438df03205fc06daeadb94e3f2e7918acb992bb83408e31b10c361f7821adb4
2024/10/29 04:53:19 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-xezajuc5kero/backup"
2024/10/29 04:53:19 DEBUG : Starting OpenDrive session with ID: c520eaddecdf99b96c834617acb6eb0b27a5bd6819c0ecc845935d63eff9773e
2024/10/29 04:53:20 DEBUG : one: Sizes differ (src 4 vs dst 3)
2024/10/29 04:53:20 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for checks to finish
2024/10/29 04:53:20 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/10/29 04:53:20 DEBUG : two: Unchanged skipping
2024/10/29 04:53:21 INFO  : one: Moved (server-side)
2024/10/29 04:53:21 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for transfers to finish
2024/10/29 04:53:22 DEBUG : one: Uploading chunk 0, size=4, remain=0
2024/10/29 04:53:23 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK
2024/10/29 04:53:23 INFO  : one: Copied (new)
2024/10/29 04:53:23 DEBUG : Waiting for deletions to finish
2024/10/29 04:53:23 INFO  : three.txt: Moved (server-side)
2024/10/29 04:53:23 INFO  : three.txt: Moved into backup dir
2024/10/29 04:53:24 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0
2024/10/29 04:53:26 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for checks to finish
2024/10/29 04:53:26 DEBUG : one: Sizes differ (src 5 vs dst 4)
2024/10/29 04:53:26 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/10/29 04:53:26 DEBUG : two: Unchanged skipping
2024/10/29 04:53:26 INFO  : one: Deleted
2024/10/29 04:53:27 INFO  : one: Moved (server-side)
2024/10/29 04:53:27 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for transfers to finish
2024/10/29 04:53:27 DEBUG : one: Uploading chunk 0, size=5, remain=0
2024/10/29 04:53:28 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK
2024/10/29 04:53:28 INFO  : one: Copied (new)
2024/10/29 04:53:28 DEBUG : Waiting for deletions to finish
2024/10/29 04:53:29 INFO  : three.txt: Deleted
2024/10/29 04:53:29 INFO  : three.txt: Moved (server-side)
2024/10/29 04:53:29 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDir (19.33s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:180: Remote "OpenDrive root 'rclone-test-xezajuc5kero'", Local "Local file system at /tmp/rclone55566031", Modify Window "1s"
2024/10/29 04:53:32 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0
2024/10/29 04:53:34 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0
2024/10/29 04:53:36 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0
2024/10/29 04:53:37 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-xezajuc5kero/dst"
2024/10/29 04:53:37 DEBUG : Config file has changed externally - reloading
2024/10/29 04:53:37 DEBUG : Starting OpenDrive session with ID: 1801daa8825588957c1748d43ac19d743f83521121c8a09170edd5ab3663c268
2024/10/29 04:53:38 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-xezajuc5kero/backup"
2024/10/29 04:53:38 DEBUG : Starting OpenDrive session with ID: 7e120e4a12abb2ecbc7e42b5e8251ec4b9964669c09326aee667542558da4a3b
2024/10/29 04:53:39 DEBUG : one: Sizes differ (src 4 vs dst 3)
2024/10/29 04:53:39 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/10/29 04:53:39 DEBUG : two: Unchanged skipping
2024/10/29 04:53:39 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for checks to finish
2024/10/29 04:53:40 INFO  : one: Moved (server-side) to: one.bak
2024/10/29 04:53:40 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for transfers to finish
2024/10/29 04:53:41 DEBUG : one: Uploading chunk 0, size=4, remain=0
2024/10/29 04:53:42 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK
2024/10/29 04:53:42 INFO  : one: Copied (new)
2024/10/29 04:53:42 DEBUG : Waiting for deletions to finish
2024/10/29 04:53:42 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2024/10/29 04:53:42 INFO  : three.txt: Moved into backup dir
2024/10/29 04:53:44 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0
2024/10/29 04:53:45 DEBUG : one: Sizes differ (src 5 vs dst 4)
2024/10/29 04:53:45 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/10/29 04:53:45 DEBUG : two: Unchanged skipping
2024/10/29 04:53:45 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for checks to finish
2024/10/29 04:53:45 INFO  : one.bak: Deleted
2024/10/29 04:53:46 INFO  : one: Moved (server-side) to: one.bak
2024/10/29 04:53:46 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero/dst': Waiting for transfers to finish
2024/10/29 04:53:47 DEBUG : one: Uploading chunk 0, size=5, remain=0
2024/10/29 04:53:48 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK
2024/10/29 04:53:48 INFO  : one: Copied (new)
2024/10/29 04:53:48 DEBUG : Waiting for deletions to finish
2024/10/29 04:53:48 INFO  : three.txt.bak: Deleted
2024/10/29 04:53:48 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2024/10/29 04:53:48 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDirWithSuffix (19.22s)
PASS
2024/10/29 04:53:50 DEBUG : OpenDrive root 'rclone-test-xezajuc5kero': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestMoveWithoutDeleteEmptySrcDirs|TestSyncAfterChangingModtimeOnly|TestSyncBackupDir|TestSyncBackupDirWithSuffix|TestSyncIgnoreErrors|TestSyncIgnoreSize)$'" - Finished OK in 1m12.946059679s (try 2/5)