"./sync.test -test.v -test.timeout 1h0m0s -remote TestSFTPRclone: -verbose -test.run '^TestSyncBackupDirWithSuffixKeepExtension$'" - Starting (try 3/5)
2021/03/23 05:54:33 DEBUG : Creating backend with remote "TestSFTPRclone:rclone-test-muxaqow5niqozoq2lulekel7"
2021/03/23 05:54:33 DEBUG : TestSFTPRclone: detected overridden config - adding "{yyBzY}" suffix to name
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7: New connection 127.0.0.1:37426->127.0.0.1:28621 to "SSH-2.0-rclone/v1.55.0-beta.5328.1fe2460e3"
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7: Using absolute root directory "/rclone-test-muxaqow5niqozoq2lulekel7"
2021/03/23 05:54:33 DEBUG : Creating backend with remote "/tmp/rclone784797018"
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:176: Remote "sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7", Local "Local file system at /tmp/rclone784797018", Modify Window "1s"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "f97c5d29941bfb1b2fdab0874906ab82  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "f97c5d29941bfb1b2fdab0874906ab82"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "fe05bcdcdc4928012781a5f1a2a77cbb5398e106  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "fe05bcdcdc4928012781a5f1a2a77cbb5398e106"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt
2021/03/23 05:54:33 DEBUG : sftp output = "35d6d33467aae9a2e3dccb4b6b027878  /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "35d6d33467aae9a2e3dccb4b6b027878"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt
2021/03/23 05:54:33 DEBUG : sftp output = "b802f384302cb24fbab0a44997e820bf2e8507bb  /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b802f384302cb24fbab0a44997e820bf2e8507bb"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "b8a9f715dbb64fd5c56e7783c6820a61  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b8a9f715dbb64fd5c56e7783c6820a61"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b"
2021/03/23 05:54:33 DEBUG : Creating backend with remote "TestSFTPRclone:rclone-test-muxaqow5niqozoq2lulekel7/dst"
2021/03/23 05:54:33 DEBUG : TestSFTPRclone: detected overridden config - adding "{yyBzY}" suffix to name
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/dst: New connection 127.0.0.1:37428->127.0.0.1:28621 to "SSH-2.0-rclone/v1.55.0-beta.5328.1fe2460e3"
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/dst: Using absolute root directory "/rclone-test-muxaqow5niqozoq2lulekel7/dst"
2021/03/23 05:54:33 DEBUG : Creating backend with remote "TestSFTPRclone:rclone-test-muxaqow5niqozoq2lulekel7/backup"
2021/03/23 05:54:33 DEBUG : TestSFTPRclone: detected overridden config - adding "{yyBzY}" suffix to name
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/backup: New connection 127.0.0.1:37430->127.0.0.1:28621 to "SSH-2.0-rclone/v1.55.0-beta.5328.1fe2460e3"
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/backup: Using absolute root directory "/rclone-test-muxaqow5niqozoq2lulekel7/backup"
2021/03/23 05:54:33 DEBUG : fs cache: renaming cache item "TestSFTPRclone:rclone-test-muxaqow5niqozoq2lulekel7/backup" to be canonical "TestSFTPRclone{yyBzY}:rclone-test-muxaqow5niqozoq2lulekel7/backup"
2021/03/23 05:54:33 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/dst: Waiting for checks to finish
2021/03/23 05:54:33 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/03/23 05:54:33 DEBUG : two: Unchanged skipping
2021/03/23 05:54:33 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/dst: Waiting for transfers to finish
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "c7957179c41f69d44f217a108c7915d8  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "c7957179c41f69d44f217a108c7915d8"
2021/03/23 05:54:33 DEBUG : one: MD5 = c7957179c41f69d44f217a108c7915d8 OK
2021/03/23 05:54:33 INFO  : one: Copied (new)
2021/03/23 05:54:33 DEBUG : Waiting for deletions to finish
2021/03/23 05:54:33 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/03/23 05:54:33 INFO  : three.txt: Moved into backup dir
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7: New connection 127.0.0.1:37432->127.0.0.1:28621 to "SSH-2.0-rclone/v1.55.0-beta.5328.1fe2460e3"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "c7957179c41f69d44f217a108c7915d8  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "c7957179c41f69d44f217a108c7915d8"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "d63a9910ed57f038b76549c070df6196b2102f42  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "d63a9910ed57f038b76549c070df6196b2102f42"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "b8a9f715dbb64fd5c56e7783c6820a61  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b8a9f715dbb64fd5c56e7783c6820a61"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp output = "f97c5d29941bfb1b2fdab0874906ab82  /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "f97c5d29941bfb1b2fdab0874906ab82"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp output = "fe05bcdcdc4928012781a5f1a2a77cbb5398e106  /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "fe05bcdcdc4928012781a5f1a2a77cbb5398e106"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt
2021/03/23 05:54:33 DEBUG : sftp output = "35d6d33467aae9a2e3dccb4b6b027878  /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "35d6d33467aae9a2e3dccb4b6b027878"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt
2021/03/23 05:54:33 DEBUG : sftp output = "b802f384302cb24fbab0a44997e820bf2e8507bb  /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b802f384302cb24fbab0a44997e820bf2e8507bb"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp output = "f97c5d29941bfb1b2fdab0874906ab82  /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "f97c5d29941bfb1b2fdab0874906ab82"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp output = "fe05bcdcdc4928012781a5f1a2a77cbb5398e106  /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "fe05bcdcdc4928012781a5f1a2a77cbb5398e106"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt
2021/03/23 05:54:33 DEBUG : sftp output = "35d6d33467aae9a2e3dccb4b6b027878  /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "35d6d33467aae9a2e3dccb4b6b027878"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt
2021/03/23 05:54:33 DEBUG : sftp output = "b802f384302cb24fbab0a44997e820bf2e8507bb  /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b802f384302cb24fbab0a44997e820bf2e8507bb"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "c7957179c41f69d44f217a108c7915d8  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "c7957179c41f69d44f217a108c7915d8"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "d63a9910ed57f038b76549c070df6196b2102f42  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "d63a9910ed57f038b76549c070df6196b2102f42"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt
2021/03/23 05:54:33 DEBUG : sftp output = "91341eed84691a83caea73aa785736d5  /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "91341eed84691a83caea73aa785736d5"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt
2021/03/23 05:54:33 DEBUG : sftp output = "92e0258fe3c7456f15dff78d509f6e3c9166c254  /rclone-test-muxaqow5niqozoq2lulekel7/dst/three.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "92e0258fe3c7456f15dff78d509f6e3c9166c254"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "b8a9f715dbb64fd5c56e7783c6820a61  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b8a9f715dbb64fd5c56e7783c6820a61"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b"
2021/03/23 05:54:33 DEBUG : fs cache: switching user supplied name "TestSFTPRclone:rclone-test-muxaqow5niqozoq2lulekel7/backup" for canonical name "TestSFTPRclone{yyBzY}:rclone-test-muxaqow5niqozoq2lulekel7/backup"
2021/03/23 05:54:33 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/03/23 05:54:33 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/03/23 05:54:33 DEBUG : two: Unchanged skipping
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/dst: Waiting for checks to finish
2021/03/23 05:54:33 INFO  : one-2019-01-01: Deleted
2021/03/23 05:54:33 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7/dst: Waiting for transfers to finish
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "0f93e81041f0cab37c37a05ae998b219  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "0f93e81041f0cab37c37a05ae998b219"
2021/03/23 05:54:33 DEBUG : one: MD5 = 0f93e81041f0cab37c37a05ae998b219 OK
2021/03/23 05:54:33 INFO  : one: Copied (new)
2021/03/23 05:54:33 DEBUG : Waiting for deletions to finish
2021/03/23 05:54:33 INFO  : three-2019-01-01.txt: Deleted
2021/03/23 05:54:33 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/03/23 05:54:33 INFO  : three.txt: Moved into backup dir
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "0f93e81041f0cab37c37a05ae998b219  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "0f93e81041f0cab37c37a05ae998b219"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/one
2021/03/23 05:54:33 DEBUG : sftp output = "88a8c2880f555638f990d1ec4c8359b25caa20c7  /rclone-test-muxaqow5niqozoq2lulekel7/dst/one\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "88a8c2880f555638f990d1ec4c8359b25caa20c7"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "b8a9f715dbb64fd5c56e7783c6820a61  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "b8a9f715dbb64fd5c56e7783c6820a61"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/dst/two
2021/03/23 05:54:33 DEBUG : sftp output = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b  /rclone-test-muxaqow5niqozoq2lulekel7/dst/two\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "ad782ecdac770fc6eb9a62e44f90873fb97fb26b"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp output = "c7957179c41f69d44f217a108c7915d8  /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "c7957179c41f69d44f217a108c7915d8"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01
2021/03/23 05:54:33 DEBUG : sftp output = "d63a9910ed57f038b76549c070df6196b2102f42  /rclone-test-muxaqow5niqozoq2lulekel7/backup/one-2019-01-01\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "d63a9910ed57f038b76549c070df6196b2102f42"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt
2021/03/23 05:54:33 DEBUG : sftp output = "91341eed84691a83caea73aa785736d5  /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "91341eed84691a83caea73aa785736d5"
2021/03/23 05:54:33 DEBUG : sftp cmd = /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt
2021/03/23 05:54:33 DEBUG : sftp output = "92e0258fe3c7456f15dff78d509f6e3c9166c254  /rclone-test-muxaqow5niqozoq2lulekel7/backup/three-2019-01-01.txt\n"
2021/03/23 05:54:33 DEBUG : sftp hash = "92e0258fe3c7456f15dff78d509f6e3c9166c254"
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (0.28s)
PASS
2021/03/23 05:54:33 DEBUG : sftp://rclone@127.0.0.1:28621/rclone-test-muxaqow5niqozoq2lulekel7: Purge dir ""
"./sync.test -test.v -test.timeout 1h0m0s -remote TestSFTPRclone: -verbose -test.run '^TestSyncBackupDirWithSuffixKeepExtension$'" - Finished OK in 449.413097ms (try 3/5)