"./sync.test -test.v -test.timeout 1h0m0s -remote TestHdfs: -verbose -test.run '^(TestCopy|TestCopyRedownload|TestSyncAfterChangingModtimeOnly|TestSyncBackupDirSuffixOnly|TestSyncConcurrentDelete|TestSyncConcurrentTruncate)$'" - Starting (try 4/5)
2022/05/21 06:39:45 DEBUG : Creating backend with remote "TestHdfs:rclone-test-jusegup5luqifiq7jetexah2"
2022/05/21 06:39:45 DEBUG : Setting type="hdfs" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_TYPE
2022/05/21 06:39:45 DEBUG : Setting namenode="127.0.0.1:8020" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_NAMENODE
2022/05/21 06:39:45 DEBUG : Setting username="root" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_USERNAME
2022/05/21 06:39:45 DEBUG : TestHdfs: detected overridden config - adding "{cNNQW}" suffix to name
2022/05/21 06:39:45 DEBUG : Setting namenode="127.0.0.1:8020" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_NAMENODE
2022/05/21 06:39:45 DEBUG : Setting username="root" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_USERNAME
2022/05/21 06:39:45 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/05/21 06:39:45 DEBUG : Creating backend with remote "/tmp/rclone607890603"
=== RUN   TestCopy
    run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone607890603", Modify Window "1s"
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: mkdir [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: Waiting for checks to finish
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: Waiting for transfers to finish
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/sub dir/hello world]
2022/05/21 06:39:45 ERROR : sub dir/hello world: Failed to copy: create /rclone-test-jusegup5luqifiq7jetexah2/sub dir/hello world: replication in progress
    sync_test.go:65: 
        	Error Trace:	sync_test.go:65
        	Error:      	Received unexpected error:
        	            	create /rclone-test-jusegup5luqifiq7jetexah2/sub dir/hello world: replication in progress
        	Test:       	TestCopy
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/sub dir]
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-jusegup5luqifiq7jetexah2/sub dir]
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
--- FAIL: TestCopy (0.63s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone607890603", Modify Window "1s"
2022/05/21 06:39:45 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/sub dir/hello world]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/sub dir]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/sub dir]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-jusegup5luqifiq7jetexah2/sub dir/hello world]
2022/05/21 06:39:46 DEBUG : Local file system at /tmp/rclone607890603: Waiting for checks to finish
2022/05/21 06:39:46 DEBUG : Local file system at /tmp/rclone607890603: Waiting for transfers to finish
2022/05/21 06:39:46 INFO  : sub dir/hello world: Copied (new)
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/sub dir]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/sub dir/hello world]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-jusegup5luqifiq7jetexah2/sub dir]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
--- PASS: TestCopyRedownload (0.24s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone607890603", Modify Window "1s"
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/empty space]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 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
2022/05/21 06:39:46 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for checks to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for transfers to finish
2022/05/21 06:39:46 DEBUG : Waiting for deletions to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 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
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/empty space]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for checks to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for transfers to finish
2022/05/21 06:39:46 INFO  : empty space: Copied (replaced existing)
2022/05/21 06:39:46 DEBUG : Waiting for deletions to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/empty space]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
--- PASS: TestSyncAfterChangingModtimeOnly (0.13s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone607890603", Modify Window "1s"
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/dst/one]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/dst/two]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : Creating backend with remote "TestHdfs:rclone-test-jusegup5luqifiq7jetexah2/dst"
2022/05/21 06:39:46 DEBUG : Setting type="hdfs" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_TYPE
2022/05/21 06:39:46 DEBUG : Setting namenode="127.0.0.1:8020" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_NAMENODE
2022/05/21 06:39:46 DEBUG : Setting username="root" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_USERNAME
2022/05/21 06:39:46 DEBUG : TestHdfs: detected overridden config - adding "{cNNQW}" suffix to name
2022/05/21 06:39:46 DEBUG : Setting namenode="127.0.0.1:8020" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_NAMENODE
2022/05/21 06:39:46 DEBUG : Setting username="root" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_USERNAME
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : one: Sizes differ (src 4 vs dst 3)
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-jusegup5luqifiq7jetexah2/dst/one.bak]
2022/05/21 06:39:46 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2022/05/21 06:39:46 DEBUG : two: Unchanged skipping
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for checks to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-jusegup5luqifiq7jetexah2/dst/one] to [/rclone-test-jusegup5luqifiq7jetexah2/dst/one.bak]
2022/05/21 06:39:46 INFO  : one: Moved (server-side) to: one.bak
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for transfers to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/dst/one]
2022/05/21 06:39:46 INFO  : one: Copied (new)
2022/05/21 06:39:46 DEBUG : Waiting for deletions to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt.bak]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt] to [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt.bak]
2022/05/21 06:39:46 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/05/21 06:39:46 INFO  : three.txt: Moved into backup dir
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : one.bak: Excluded
2022/05/21 06:39:46 DEBUG : three.txt.bak: Excluded
2022/05/21 06:39:46 DEBUG : one: Sizes differ (src 5 vs dst 4)
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-jusegup5luqifiq7jetexah2/dst/one.bak]
2022/05/21 06:39:46 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2022/05/21 06:39:46 DEBUG : two: Unchanged skipping
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for checks to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/dst/one.bak]
2022/05/21 06:39:46 INFO  : one.bak: Deleted
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-jusegup5luqifiq7jetexah2/dst/one] to [/rclone-test-jusegup5luqifiq7jetexah2/dst/one.bak]
2022/05/21 06:39:46 INFO  : one: Moved (server-side) to: one.bak
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Waiting for transfers to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/dst/one]
2022/05/21 06:39:46 INFO  : one: Copied (new)
2022/05/21 06:39:46 DEBUG : Waiting for deletions to finish
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt.bak]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt.bak]
2022/05/21 06:39:46 INFO  : three.txt.bak: Deleted
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt] to [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt.bak]
2022/05/21 06:39:46 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2022/05/21 06:39:46 INFO  : three.txt: Moved into backup dir
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/dst/one]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/dst/one.bak]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/dst/three.txt.bak]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/dst/two]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-jusegup5luqifiq7jetexah2/dst]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
--- PASS: TestSyncBackupDirSuffixOnly (0.25s)
=== RUN   TestSyncConcurrentDelete
    run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone607890603", Modify Window "1s"
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both1]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only1]
    run.go:287: Failed to put "only1" to "hdfs://127.0.0.1:8020": create /rclone-test-jusegup5luqifiq7jetexah2/only1: replication in progress
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both1]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/only0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
--- FAIL: TestSyncConcurrentDelete (0.08s)
=== RUN   TestSyncConcurrentTruncate
    run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone607890603", Modify Window "1s"
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both1]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only1]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both3]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only3]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/both4]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-jusegup5luqifiq7jetexah2/only4]
    run.go:287: Failed to put "only4" to "hdfs://127.0.0.1:8020": create /rclone-test-jusegup5luqifiq7jetexah2/only4: replication in progress
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both1]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both3]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/both4]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/only0]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/only1]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/only2]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-jusegup5luqifiq7jetexah2/only3]
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-jusegup5luqifiq7jetexah2]
--- FAIL: TestSyncConcurrentTruncate (0.25s)
FAIL
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: Purge remote
2022/05/21 06:39:46 DEBUG : hdfs://127.0.0.1:8020: purge [/rclone-test-jusegup5luqifiq7jetexah2]
"./sync.test -test.v -test.timeout 1h0m0s -remote TestHdfs: -verbose -test.run '^(TestCopy|TestCopyRedownload|TestSyncAfterChangingModtimeOnly|TestSyncBackupDirSuffixOnly|TestSyncConcurrentDelete|TestSyncConcurrentTruncate)$'" - Finished ERROR in 1.788074608s (try 4/5): exit status 1: Failed [TestCopy TestSyncConcurrentDelete TestSyncConcurrentTruncate]