"./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestCopyAfterDelete|TestCopyNoEmptyDirectories|TestCopyOverSelf|TestCopyRedownload|TestMoveEmptyDirectories|TestMoveNoEmptyDirectories|TestMoveOverSelf|TestServerSideCopy|TestServerSideCopyOverSelf|TestServerSideMoveDeleteEmptySourceDirs|TestServerSideMoveOverSelf|TestSyncAfterRemovingAFileAndAddingAFileSubDir|TestSyncBackupDir|TestSyncBackupDirSuffixOnly|TestSyncEmptyDirectories|TestSyncIgnoreTimes|TestSyncImmutable|TestSyncNoEmptyDirectories)$'" - Starting (try 2/5)
2024/11/20 02:24:37 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-ledarir2nulu"
2024/11/20 02:24:37 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/11/20 02:24:37 DEBUG : Starting OpenDrive session with ID: a8f87cc14ce13041cfb88af6dd0985c099a1787ae95bc40f9b567b3199de01a2
2024/11/20 02:24:38 DEBUG : Creating backend with remote "/tmp/rclone3436590420"
=== RUN   TestCopyNoEmptyDirectories
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:24:38 DEBUG : sub dir2: Making directory
2024/11/20 02:24:38 DEBUG : sub dir2/sub sub dir2: Making directory with metadata
2024/11/20 02:24:38 INFO  : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2024/11/20 02:24:38 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:24:38 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:24:38 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:24:40 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:24:40 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/11/20 02:24:40 INFO  : sub dir/hello world: Copied (new)
    run.go:125: removing dir "sub dir" failed - try 1/3: folder not empty
--- PASS: TestCopyNoEmptyDirectories (5.08s)
=== RUN   TestMoveEmptyDirectories
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:24:43 DEBUG : sub dir2: Making directory with metadata
2024/11/20 02:24:43 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2024/11/20 02:24:43 DEBUG : sub dir: Making directory
2024/11/20 02:24:43 DEBUG : sub dir2: Making directory
2024/11/20 02:24:44 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:24:44 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:24:44 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:24:45 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:24:45 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/11/20 02:24:45 INFO  : sub dir/hello world: Copied (new)
2024/11/20 02:24:45 INFO  : sub dir/hello world: Deleted
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:24:46 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Skipping modtime test as remote does not support DirSetModTime or MkdirMetadata
2024/11/20 02:24:46 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Skipping modtime test as remote does not support DirSetModTime or MkdirMetadata
    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: TestMoveEmptyDirectories (12.40s)
=== RUN   TestMoveNoEmptyDirectories
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:24:55 DEBUG : sub dir2: Making directory
2024/11/20 02:24:55 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:24:55 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:24:55 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:24:57 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:24:58 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/11/20 02:24:58 INFO  : sub dir/hello world: Copied (new)
2024/11/20 02:24:58 INFO  : sub dir/hello world: Deleted
--- PASS: TestMoveNoEmptyDirectories (3.66s)
=== RUN   TestSyncEmptyDirectories
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:24:59 DEBUG : sub dir2: Making directory with metadata
2024/11/20 02:24:59 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2024/11/20 02:24:59 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2024/11/20 02:24:59 DEBUG : sub dir: Making directory
2024/11/20 02:24:59 DEBUG : sub dir2: Making directory
2024/11/20 02:25:00 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:25:00 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:25:00 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:25:01 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:25:02 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/11/20 02:25:02 INFO  : sub dir/hello world: Copied (new)
2024/11/20 02:25:02 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:02 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Skipping modtime test as remote does not support DirSetModTime or MkdirMetadata
--- PASS: TestSyncEmptyDirectories (4.83s)
=== RUN   TestSyncNoEmptyDirectories
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:04 DEBUG : sub dir2: Making directory
2024/11/20 02:25:04 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:25:04 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:25:04 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:25:05 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:25:06 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/11/20 02:25:06 INFO  : sub dir/hello world: Copied (new)
2024/11/20 02:25:06 DEBUG : Waiting for deletions to finish
    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: TestSyncNoEmptyDirectories (11.12s)
=== RUN   TestServerSideCopy
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:16 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:25:17 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-comiqed2havi"
2024/11/20 02:25:17 DEBUG : Config file has changed externally - reloading
2024/11/20 02:25:18 DEBUG : Starting OpenDrive session with ID: 2d8768d0f0b5151eabfbe80ac2bc22fd04633acbc8e0f357a15f4158763a0218
    sync_test.go:590: Server side copy (if possible) OpenDrive root 'rclone-test-ledarir2nulu' -> OpenDrive root 'rclone-test-comiqed2havi'
2024/11/20 02:25:19 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:25:19 DEBUG : OpenDrive root 'rclone-test-comiqed2havi': Waiting for checks to finish
2024/11/20 02:25:19 DEBUG : OpenDrive root 'rclone-test-comiqed2havi': Waiting for transfers to finish
2024/11/20 02:25:20 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2024/11/20 02:25:20 INFO  : sub dir/hello world: Copied (server-side copy)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:20 DEBUG : OpenDrive root 'rclone-test-comiqed2havi': Purge remote
--- PASS: TestServerSideCopy (6.87s)
=== RUN   TestCopyOverSelf
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:23 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:25:25 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2024/11/20 02:25:25 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:25:25 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:25:25 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0
2024/11/20 02:25:26 DEBUG : sub dir/hello world: md5 = 00321a507bdb420dbbd4f53c733b1505 OK
2024/11/20 02:25:26 INFO  : sub dir/hello world: Copied (replaced existing)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
--- PASS: TestCopyOverSelf (6.28s)
=== RUN   TestServerSideCopyOverSelf
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:29 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:25:31 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-niyabem1zamo"
2024/11/20 02:25:31 DEBUG : Starting OpenDrive session with ID: a7952a1c4d850dfb0b78d9f68ea5ee02e62a46c5d53caa4e67cabb885111ac5b
    sync_test.go:626: Server side copy (if possible) OpenDrive root 'rclone-test-ledarir2nulu' -> OpenDrive root 'rclone-test-niyabem1zamo'
2024/11/20 02:25:32 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:25:32 DEBUG : OpenDrive root 'rclone-test-niyabem1zamo': Waiting for checks to finish
2024/11/20 02:25:32 DEBUG : OpenDrive root 'rclone-test-niyabem1zamo': Waiting for transfers to finish
2024/11/20 02:25:33 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2024/11/20 02:25:33 INFO  : sub dir/hello world: Copied (server-side copy)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:34 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0
2024/11/20 02:25:36 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2024/11/20 02:25:36 DEBUG : OpenDrive root 'rclone-test-niyabem1zamo': Waiting for checks to finish
2024/11/20 02:25:36 DEBUG : OpenDrive root 'rclone-test-niyabem1zamo': Waiting for transfers to finish
2024/11/20 02:25:36 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2024/11/20 02:25:36 INFO  : sub dir/hello world: Copied (server-side copy)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:36 DEBUG : OpenDrive root 'rclone-test-niyabem1zamo': Purge remote
--- PASS: TestServerSideCopyOverSelf (10.32s)
=== RUN   TestMoveOverSelf
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:39 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
    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
2024/11/20 02:25:49 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2024/11/20 02:25:49 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:25:49 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:25:49 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0
2024/11/20 02:25:50 DEBUG : sub dir/hello world: md5 = 00321a507bdb420dbbd4f53c733b1505 OK
2024/11/20 02:25:50 INFO  : sub dir/hello world: Copied (replaced existing)
2024/11/20 02:25:50 INFO  : sub dir/hello world: Deleted
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
--- PASS: TestMoveOverSelf (13.12s)
=== RUN   TestServerSideMoveOverSelf
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:53 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:25:54 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-zecubih5wayi"
2024/11/20 02:25:54 DEBUG : Config file has changed externally - reloading
2024/11/20 02:25:54 DEBUG : Starting OpenDrive session with ID: f6d89cde7c9284f196145332a8a8c78ef502954ed1858b2953cf3cd475a98df4
    sync_test.go:671: Server side copy (if possible) OpenDrive root 'rclone-test-ledarir2nulu' -> OpenDrive root 'rclone-test-zecubih5wayi'
2024/11/20 02:25:55 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:25:55 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Waiting for checks to finish
2024/11/20 02:25:55 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Waiting for transfers to finish
2024/11/20 02:25:56 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2024/11/20 02:25:56 INFO  : sub dir/hello world: Copied (server-side copy)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:25:57 DEBUG : sub dir/hello world: Uploading chunk 0, size=17, remain=0
2024/11/20 02:25:58 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Using server-side directory move
2024/11/20 02:25:58 INFO  : OpenDrive root 'rclone-test-zecubih5wayi': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2024/11/20 02:25:59 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2024/11/20 02:25:59 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Waiting for checks to finish
2024/11/20 02:25:59 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Waiting for transfers to finish
2024/11/20 02:25:59 INFO  : sub dir/hello world: Deleted
2024/11/20 02:25:59 INFO  : sub dir/hello world: Moved (server-side)
2024/11/20 02:26:01 DEBUG : sub dir/hello world: Uploading chunk 0, size=24, remain=0
2024/11/20 02:26:02 DEBUG : testing file moves
2024/11/20 02:26:02 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17)
2024/11/20 02:26:02 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Waiting for checks to finish
2024/11/20 02:26:02 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Waiting for transfers to finish
2024/11/20 02:26:03 INFO  : sub dir/hello world: Deleted
2024/11/20 02:26:03 INFO  : sub dir/hello world: Moved (server-side)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:04 DEBUG : OpenDrive root 'rclone-test-zecubih5wayi': Purge remote
--- PASS: TestServerSideMoveOverSelf (14.03s)
=== RUN   TestCopyAfterDelete
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:07 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:26:08 ERROR : : error listing: directory not found
2024/11/20 02:26:08 DEBUG : Local file system at /tmp/rclone3436590420: Making directory
2024/11/20 02:26:09 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:26:09 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
--- PASS: TestCopyAfterDelete (4.71s)
=== RUN   TestCopyRedownload
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:11 DEBUG : sub dir/hello world: Uploading chunk 0, size=11, remain=0
2024/11/20 02:26:13 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2024/11/20 02:26:13 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/11/20 02:26:13 DEBUG : Local file system at /tmp/rclone3436590420: Waiting for checks to finish
2024/11/20 02:26:13 DEBUG : Local file system at /tmp/rclone3436590420: Waiting for transfers to finish
2024/11/20 02:26:14 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2024/11/20 02:26:14 DEBUG : sub dir/hello world.87ffde68.partial: renamed to: sub dir/hello world
2024/11/20 02:26:14 INFO  : sub dir/hello world: Copied (new)
2024/11/20 02:26:14 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
--- PASS: TestCopyRedownload (4.71s)
=== RUN   TestSyncIgnoreTimes
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:16 DEBUG : existing: Uploading chunk 0, size=6, remain=0
2024/11/20 02:26:17 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/11/20 02:26:17 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:26:17 DEBUG : existing: Unchanged skipping
2024/11/20 02:26:17 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:26:17 DEBUG : Waiting for deletions to finish
2024/11/20 02:26:17 INFO  : There was nothing to transfer
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:17 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:26:17 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2024/11/20 02:26:17 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:26:18 DEBUG : existing: Uploading chunk 0, size=6, remain=0
2024/11/20 02:26:19 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK
2024/11/20 02:26:19 INFO  : existing: Copied (replaced existing)
2024/11/20 02:26:19 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
--- PASS: TestSyncIgnoreTimes (5.09s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:21 DEBUG : b/potato: Uploading chunk 0, size=21, remain=0
2024/11/20 02:26:23 DEBUG : c/non empty space: Uploading chunk 0, size=5, remain=0
2024/11/20 02:26:24 DEBUG : d: Making directory
2024/11/20 02:26:24 DEBUG : d/e: Making directory
2024/11/20 02:26:25 DEBUG : a/potato2: Need to transfer - File not found at Destination
2024/11/20 02:26:26 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2024/11/20 02:26:26 DEBUG : c/non empty space: Unchanged skipping
2024/11/20 02:26:26 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:26:26 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:26:27 DEBUG : a/potato2: Uploading chunk 0, size=60, remain=0
2024/11/20 02:26:28 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK
2024/11/20 02:26:28 INFO  : a/potato2: Copied (new)
2024/11/20 02:26:28 DEBUG : Waiting for deletions to finish
2024/11/20 02:26:28 INFO  : b/potato: Deleted
2024/11/20 02:26:28 INFO  : d/e: Removing directory
2024/11/20 02:26:28 INFO  : d: Removing directory
2024/11/20 02:26:28 INFO  : b: Removing directory
2024/11/20 02:26:29 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': deleted 3 directories
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (10.90s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:31 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-cedirof2cemo"
2024/11/20 02:26:31 DEBUG : Starting OpenDrive session with ID: 2cf09a1e1819cc60a08c90da4fefe4657efb9dcf02ce4e09d986d0fb765ee4f1
2024/11/20 02:26:33 DEBUG : potato2: Uploading chunk 0, size=60, remain=0
2024/11/20 02:26:34 DEBUG : empty space: Uploading chunk 0, size=1, remain=0
2024/11/20 02:26:36 DEBUG : potato3: Uploading chunk 0, size=68, remain=0
2024/11/20 02:26:37 DEBUG : tomatoDir: Making directory
    sync_test.go:1705: Server side move (if possible) OpenDrive root 'rclone-test-ledarir2nulu' -> OpenDrive root 'rclone-test-cedirof2cemo'
2024/11/20 02:26:39 DEBUG : empty space: Uploading chunk 0, size=1, remain=0
2024/11/20 02:26:40 DEBUG : potato3: Uploading chunk 0, size=60, remain=0
2024/11/20 02:26:42 DEBUG : OpenDrive root 'rclone-test-cedirof2cemo': Using server-side directory move
2024/11/20 02:26:42 INFO  : OpenDrive root 'rclone-test-cedirof2cemo': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2024/11/20 02:26:42 DEBUG : potato2: Need to transfer - File not found at Destination
2024/11/20 02:26:42 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s)
2024/11/20 02:26:42 DEBUG : empty space: Unchanged skipping
2024/11/20 02:26:42 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2024/11/20 02:26:42 INFO  : potato3: Deleted
2024/11/20 02:26:42 DEBUG : OpenDrive root 'rclone-test-cedirof2cemo': Waiting for checks to finish
2024/11/20 02:26:43 INFO  : empty space: Deleted
2024/11/20 02:26:43 DEBUG : OpenDrive root 'rclone-test-cedirof2cemo': Waiting for transfers to finish
2024/11/20 02:26:43 INFO  : potato2: Moved (server-side)
2024/11/20 02:26:43 INFO  : potato3: Moved (server-side)
2024/11/20 02:26:43 INFO  : tomatoDir: Removing directory
2024/11/20 02:26:43 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': deleted 1 directories
    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
2024/11/20 02:26:51 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-mowerar1beji"
2024/11/20 02:26:52 DEBUG : Starting OpenDrive session with ID: 4482fc0ff6afb80c8dc5b040c87b4c0917e06f41fc3799e962b52b0e95d20169
2024/11/20 02:26:52 DEBUG : tomatoDir: Making directory
2024/11/20 02:26:52 DEBUG : OpenDrive root 'rclone-test-mowerar1beji': Using server-side directory move
2024/11/20 02:26:53 DEBUG : : same parent dir (0) - using folder/rename instead of move_copy
2024/11/20 02:26:53 INFO  : OpenDrive root 'rclone-test-mowerar1beji': Server side directory move succeeded
2024/11/20 02:26:54 ERROR : : error listing: directory not found
2024/11/20 02:26:54 ERROR : : error listing: directory not found
2024/11/20 02:26:54 DEBUG : OpenDrive root 'rclone-test-mowerar1beji': Purge remote
2024/11/20 02:26:54 DEBUG : OpenDrive root 'rclone-test-cedirof2cemo': Purge remote
2024/11/20 02:26:54 NOTICE: purge failed: directory not found
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (23.76s)
=== RUN   TestSyncBackupDir
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:26:56 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0
2024/11/20 02:26:58 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0
2024/11/20 02:26:59 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0
2024/11/20 02:27:00 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-ledarir2nulu/dst"
2024/11/20 02:27:01 DEBUG : Starting OpenDrive session with ID: f67fd31610b8f8609b511e26534b49f9aefdb73605f49dd184186c73cc399936
2024/11/20 02:27:01 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-ledarir2nulu/backup"
2024/11/20 02:27:02 DEBUG : Starting OpenDrive session with ID: 8edd0e0ff326a92b19581e91972bda1df349c8bf0da3b7b9dd87097c4880e37a
2024/11/20 02:27:03 DEBUG : one: Sizes differ (src 4 vs dst 3)
2024/11/20 02:27:03 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for checks to finish
2024/11/20 02:27:03 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/11/20 02:27:03 DEBUG : two: Unchanged skipping
2024/11/20 02:27:04 INFO  : one: Moved (server-side)
2024/11/20 02:27:04 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for transfers to finish
2024/11/20 02:27:05 DEBUG : one: Uploading chunk 0, size=4, remain=0
2024/11/20 02:27:05 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK
2024/11/20 02:27:05 INFO  : one: Copied (new)
2024/11/20 02:27:05 DEBUG : Waiting for deletions to finish
2024/11/20 02:27:06 INFO  : three.txt: Moved (server-side)
2024/11/20 02:27:06 INFO  : three.txt: Moved into backup dir
2024/11/20 02:27:07 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0
2024/11/20 02:27:09 DEBUG : one: Sizes differ (src 5 vs dst 4)
2024/11/20 02:27:09 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/11/20 02:27:09 DEBUG : two: Unchanged skipping
2024/11/20 02:27:09 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for checks to finish
2024/11/20 02:27:09 INFO  : one: Deleted
2024/11/20 02:27:09 INFO  : one: Moved (server-side)
2024/11/20 02:27:09 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for transfers to finish
2024/11/20 02:27:10 DEBUG : one: Uploading chunk 0, size=5, remain=0
2024/11/20 02:27:11 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK
2024/11/20 02:27:11 INFO  : one: Copied (new)
2024/11/20 02:27:11 DEBUG : Waiting for deletions to finish
2024/11/20 02:27:11 INFO  : three.txt: Deleted
2024/11/20 02:27:12 INFO  : three.txt: Moved (server-side)
2024/11/20 02:27:12 INFO  : three.txt: Moved into backup dir
    run.go:125: removing dir "dst" failed - try 1/3: folder not empty
--- PASS: TestSyncBackupDir (20.53s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:27:16 DEBUG : dst/one: Uploading chunk 0, size=3, remain=0
2024/11/20 02:27:18 DEBUG : dst/two: Uploading chunk 0, size=3, remain=0
2024/11/20 02:27:20 DEBUG : dst/three.txt: Uploading chunk 0, size=5, remain=0
2024/11/20 02:27:21 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-ledarir2nulu/dst"
2024/11/20 02:27:21 DEBUG : Config file has changed externally - reloading
2024/11/20 02:27:21 DEBUG : Starting OpenDrive session with ID: 553cc667d767a8b506f4f72ca15ddcc5658a386a3417f3a7519fc44e6f88202e
2024/11/20 02:27:22 DEBUG : one: Sizes differ (src 4 vs dst 3)
2024/11/20 02:27:22 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for checks to finish
2024/11/20 02:27:22 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/11/20 02:27:22 DEBUG : two: Unchanged skipping
2024/11/20 02:27:22 DEBUG : one: same parent dir (ODFfNzA2Njk1Ml9kVHJ1Sw) - using file/rename instead of move_copy for one.bak
2024/11/20 02:27:23 INFO  : one: Moved (server-side) to: one.bak
2024/11/20 02:27:23 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for transfers to finish
2024/11/20 02:27:23 DEBUG : one: Uploading chunk 0, size=4, remain=0
2024/11/20 02:27:24 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK
2024/11/20 02:27:24 INFO  : one: Copied (new)
2024/11/20 02:27:24 DEBUG : Waiting for deletions to finish
2024/11/20 02:27:25 DEBUG : three.txt: same parent dir (ODFfNzA2Njk1Ml9kVHJ1Sw) - using file/rename instead of move_copy for three.txt.bak
2024/11/20 02:27:25 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2024/11/20 02:27:25 INFO  : three.txt: Moved into backup dir
2024/11/20 02:27:26 DEBUG : dst/three.txt: Uploading chunk 0, size=6, remain=0
2024/11/20 02:27:27 DEBUG : one.bak: Excluded (Path Filter)
2024/11/20 02:27:27 DEBUG : one.bak: Excluded
2024/11/20 02:27:27 DEBUG : three.txt.bak: Excluded (Path Filter)
2024/11/20 02:27:27 DEBUG : three.txt.bak: Excluded
2024/11/20 02:27:27 DEBUG : one: Sizes differ (src 5 vs dst 4)
2024/11/20 02:27:27 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2024/11/20 02:27:27 DEBUG : two: Unchanged skipping
2024/11/20 02:27:27 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for checks to finish
2024/11/20 02:27:28 INFO  : one.bak: Deleted
2024/11/20 02:27:28 DEBUG : one: same parent dir (ODFfNzA2Njk1Ml9kVHJ1Sw) - using file/rename instead of move_copy for one.bak
2024/11/20 02:27:28 INFO  : one: Moved (server-side) to: one.bak
2024/11/20 02:27:28 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu/dst': Waiting for transfers to finish
2024/11/20 02:27:29 DEBUG : one: Uploading chunk 0, size=5, remain=0
2024/11/20 02:27:30 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK
2024/11/20 02:27:30 INFO  : one: Copied (new)
2024/11/20 02:27:30 DEBUG : Waiting for deletions to finish
2024/11/20 02:27:30 INFO  : three.txt.bak: Deleted
2024/11/20 02:27:31 DEBUG : three.txt: same parent dir (ODFfNzA2Njk1Ml9kVHJ1Sw) - using file/rename instead of move_copy for three.txt.bak
2024/11/20 02:27:31 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2024/11/20 02:27:31 INFO  : three.txt: Moved into backup dir
    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: TestSyncBackupDirSuffixOnly (24.91s)
=== RUN   TestSyncImmutable
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:27:40 DEBUG : existing: Need to transfer - File not found at Destination
2024/11/20 02:27:40 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:27:40 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:27:41 DEBUG : existing: Uploading chunk 0, size=6, remain=0
2024/11/20 02:27:42 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK
2024/11/20 02:27:42 INFO  : existing: Copied (new)
2024/11/20 02:27:42 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", Modify Window "1s"
2024/11/20 02:27:43 DEBUG : existing: Sizes differ (src 8 vs dst 6)
2024/11/20 02:27:43 ERROR : existing: Source and destination exist but do not match: immutable file modified
2024/11/20 02:27:43 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for checks to finish
2024/11/20 02:27:43 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Waiting for transfers to finish
2024/11/20 02:27:43 ERROR : OpenDrive root 'rclone-test-ledarir2nulu': not deleting files as there were IO errors
2024/11/20 02:27:43 ERROR : OpenDrive root 'rclone-test-ledarir2nulu': not deleting directories as there were IO errors
    run.go:180: Remote "OpenDrive root 'rclone-test-ledarir2nulu'", Local "Local file system at /tmp/rclone3436590420", 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: TestSyncImmutable (11.57s)
PASS
2024/11/20 02:27:52 DEBUG : OpenDrive root 'rclone-test-ledarir2nulu': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestCopyAfterDelete|TestCopyNoEmptyDirectories|TestCopyOverSelf|TestCopyRedownload|TestMoveEmptyDirectories|TestMoveNoEmptyDirectories|TestMoveOverSelf|TestServerSideCopy|TestServerSideCopyOverSelf|TestServerSideMoveDeleteEmptySourceDirs|TestServerSideMoveOverSelf|TestSyncAfterRemovingAFileAndAddingAFileSubDir|TestSyncBackupDir|TestSyncBackupDirSuffixOnly|TestSyncEmptyDirectories|TestSyncIgnoreTimes|TestSyncImmutable|TestSyncNoEmptyDirectories)$'" - Finished OK in 3m15.362228659s (try 2/5)