"./vfs.test -test.v -test.timeout 1h0m0s -remote TestHdfs: -verbose -test.run '^(TestDirForgetPath|TestDirOpen|TestDirRemoveName|TestDirWalk|TestFileRename|TestFileSetModTime|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleReleaseWrite|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestVFSNew|TestVFSStatParent)$/^(cache=full,open=true,write=true|cache=off,open=false,write=false|cache=off,open=true,write=false|off,forceCache=false)$'" - Starting (try 2/5) 2022/06/12 05:28:20 DEBUG : Creating backend with remote "TestHdfs:rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:20 DEBUG : Setting type="hdfs" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_TYPE 2022/06/12 05:28:20 DEBUG : Setting namenode="127.0.0.1:8020" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_NAMENODE 2022/06/12 05:28:20 DEBUG : Setting username="root" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_USERNAME 2022/06/12 05:28:20 DEBUG : TestHdfs: detected overridden config - adding "{cNNQW}" suffix to name 2022/06/12 05:28:20 DEBUG : Setting namenode="127.0.0.1:8020" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_NAMENODE 2022/06/12 05:28:20 DEBUG : Setting username="root" for "TestHdfs" from environment variable RCLONE_CONFIG_TESTHDFS_USERNAME 2022/06/12 05:28:20 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/06/12 05:28:20 DEBUG : Creating backend with remote "/tmp/rclone571626698" === RUN TestDirForgetPath run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:20 INFO : hdfs://127.0.0.1:8020: poll-interval is not supported by this remote 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: mkdir [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] run.go:287: Failed to put "dir/file1" to "hdfs://127.0.0.1:8020": create /rclone-test-meyiwov9mubehik1mequron8/dir/file1: replication in progress --- FAIL: TestDirForgetPath (0.21s) === RUN TestDirWalk run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/fil/a/b/c] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil/a] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil/a/b] 2022/06/12 05:28:20 DEBUG : : forgetting directory cache 2022/06/12 05:28:20 DEBUG : dir: forgetting directory cache 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil/a] 2022/06/12 05:28:20 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:20 DEBUG : dir: Looking for writers 2022/06/12 05:28:20 DEBUG : fil/a/b: Looking for writers 2022/06/12 05:28:20 DEBUG : fil/a: Looking for writers 2022/06/12 05:28:20 DEBUG : b: reading active writers 2022/06/12 05:28:20 DEBUG : fil: Looking for writers 2022/06/12 05:28:20 DEBUG : a: reading active writers 2022/06/12 05:28:20 DEBUG : : Looking for writers 2022/06/12 05:28:20 DEBUG : dir: reading active writers 2022/06/12 05:28:20 DEBUG : fil: reading active writers 2022/06/12 05:28:20 DEBUG : >WaitForWriters: 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil/a] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/fil/a/b] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/fil/a/b/c] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/fil/a/b] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/fil/a] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/fil] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestDirWalk (0.10s) === RUN TestDirOpen run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:20 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 ERROR : dir/: Can only open directories read only 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : fil/a/b: Looking for writers 2022/06/12 05:28:21 DEBUG : fil/a: Looking for writers 2022/06/12 05:28:21 DEBUG : b: reading active writers 2022/06/12 05:28:21 DEBUG : fil: Looking for writers 2022/06/12 05:28:21 DEBUG : a: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : fil: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestDirOpen (0.03s) === RUN TestDirRemoveName run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] run.go:287: Failed to put "dir/file1" to "hdfs://127.0.0.1:8020": create /rclone-test-meyiwov9mubehik1mequron8/dir/file1: replication in progress --- FAIL: TestDirRemoveName (0.01s) === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=false,write=false run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 INFO : hdfs://127.0.0.1:8020: poll-interval is not supported by this remote 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/time_test] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-meyiwov9mubehik1mequron8/time_test] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/time_test] 2022/06/12 05:28:21 DEBUG : Can set mod time: true 2022/06/12 05:28:21 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] === RUN TestFileSetModTime/cache=off,open=true,write=false run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 INFO : hdfs://127.0.0.1:8020: poll-interval is not supported by this remote 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2022/06/12 05:28:21 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: File to upload is small (0 bytes), uploading instead of streaming 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 INFO : dir/file1: Copied (new) 2022/06/12 05:28:21 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] === RUN TestFileSetModTime/cache=full,open=true,write=true run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 INFO : hdfs://127.0.0.1:8020: poll-interval is not supported by this remote 2022/06/12 05:28:21 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2022/06/12 05:28:21 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfsMeta/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: Open: flags=O_WRONLY 2022/06/12 05:28:21 DEBUG : dir/file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : dir/file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000658600): _writeAt: size=5, off=0 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000658600): openPending: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: truncate to size=14 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000658600): >openPending: err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000658600): >_writeAt: n=5, err= 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: setting modification time to 2011-12-25 12:59:59.123456789 +0000 UTC 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000658600): close: 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:5}] - present false 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: setting modification time to 2011-12-25 12:59:59.123456789 +0000 UTC 2022/06/12 05:28:21 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000658600): >close: err= 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: starting upload 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 INFO : dir/file1: Copied (replaced existing) 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: fingerprint now "14,2011-12-25 12:59:59.123456789 +0000 UTC" 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2022/06/12 05:28:21 DEBUG : dir/file1: Not setting pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC as it is already set 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 INFO : dir/file1: vfs cache: upload succeeded try #1 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : vfs cache: cleaner exiting 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestFileSetModTime (0.32s) --- PASS: TestFileSetModTime/cache=off,open=false,write=false (0.05s) --- PASS: TestFileSetModTime/cache=off,open=true,write=false (0.04s) --- PASS: TestFileSetModTime/cache=full,open=true,write=true (0.22s) === RUN TestFileRename === RUN TestFileRename/off,forceCache=false run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 INFO : hdfs://127.0.0.1:8020: poll-interval is not supported by this remote 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-meyiwov9mubehik1mequron8/newLeaf] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] to [/rclone-test-meyiwov9mubehik1mequron8/newLeaf] 2022/06/12 05:28:21 INFO : dir/file1: Moved (server-side) to: newLeaf 2022/06/12 05:28:21 DEBUG : newLeaf: Updating file with newLeaf 0xc00027a9c0 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vDel: "file1" 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-meyiwov9mubehik1mequron8/newLeaf] to [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 INFO : newLeaf: Moved (server-side) to: dir/file1 2022/06/12 05:28:21 DEBUG : dir/file1: Updating file with dir/file1 0xc00027a9c0 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2022/06/12 05:28:21 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : dir/file1: File is currently open, delaying rename 0xc00027a9c0 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vDel: "file1" 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: File to upload is small (25 bytes), uploading instead of streaming 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 INFO : dir/file1: Copied (new) 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2022/06/12 05:28:21 DEBUG : newLeaf: Running delayed rename now 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: new [/rclone-test-meyiwov9mubehik1mequron8/newLeaf] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rename [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] to [/rclone-test-meyiwov9mubehik1mequron8/newLeaf] 2022/06/12 05:28:21 INFO : dir/file1: Moved (server-side) to: newLeaf 2022/06/12 05:28:21 DEBUG : newLeaf: Updating file with newLeaf 0xc00027a9c0 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : newLeaf: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : newLeaf: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/newLeaf] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestFileRename (0.08s) --- PASS: TestFileRename/off,forceCache=false (0.08s) === RUN TestRcGetVFS rc_test.go:28: Error Trace: rc_test.go:28 Error: An error is expected but got nil. Test: TestRcGetVFS --- FAIL: TestRcGetVFS (0.00s) === RUN TestRWFileHandleMethodsRead run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 INFO : hdfs://127.0.0.1:8020: poll-interval is not supported by this remote 2022/06/12 05:28:21 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2022/06/12 05:28:21 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfsMeta/TestHdfs{cNNQW}/rclone-test-meyiwov9mubehik1mequron8" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:287: Failed to put "dir/file1" to "hdfs://127.0.0.1:8020": create /rclone-test-meyiwov9mubehik1mequron8/dir/file1: replication in progress --- FAIL: TestRWFileHandleMethodsRead (0.01s) === RUN TestRWFileHandleSeek run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: Open: flags=O_RDONLY 2022/06/12 05:28:21 DEBUG : dir/file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : dir/file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): _readAt: size=1, off=0 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): openPending: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: truncate to size=16 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >openPending: err= 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): _readAt: size=1, off=5 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): _readAt: size=1, off=3 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:3 Size:1} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): _readAt: size=1, off=13 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:13 Size:1} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): _readAt: size=16, off=100 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >_readAt: n=0, err=EOF 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): close: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00049f340): >close: err= 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestRWFileHandleSeek (0.04s) === RUN TestRWFileHandleReadAt run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : dir/file1: Open: flags=O_RDONLY 2022/06/12 05:28:21 DEBUG : dir/file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : dir/file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=1, off=0 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): openPending: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "16,2001-02-03 04:05:06 +0000 UTC" 2022/06/12 05:28:21 ERROR : dir/file1: vfs cache: detected external removal of cache file 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: truncate to size=16 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >openPending: err= 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=1, off=5 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=1, off=1 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:1 Size:1} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=1, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=6, off=10 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=6, err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=256, off=10 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=6, err=EOF 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=256, off=100 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=0, err=EOF 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): close: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >close: err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): _readAt: size=256, off=100 2022/06/12 05:28:21 DEBUG : dir/file1(0xc000343600): >_readAt: n=0, err=file already closed 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestRWFileHandleReadAt (0.03s) === RUN TestRWFileHandleFlushRead run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] run.go:287: Failed to put "dir/file1" to "hdfs://127.0.0.1:8020": create /rclone-test-meyiwov9mubehik1mequron8/dir/file1: replication in progress --- FAIL: TestRWFileHandleFlushRead (0.01s) === RUN TestRWFileHandleReleaseRead run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : dir/file1: Open: flags=O_RDONLY 2022/06/12 05:28:21 DEBUG : dir/file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : dir/file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): _readAt: size=256, off=0 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): openPending: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "16,2001-02-03 04:05:06 +0000 UTC" 2022/06/12 05:28:21 ERROR : dir/file1: vfs cache: detected external removal of cache file 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: truncate to size=16 2022/06/12 05:28:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): >openPending: err= 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2022/06/12 05:28:21 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): >_readAt: n=16, err=EOF 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): RWFileHandle.Release 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): close: 2022/06/12 05:28:21 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): >close: err= 2022/06/12 05:28:21 DEBUG : dir/file1(0xc00062c480): RWFileHandle.Release 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestRWFileHandleReleaseRead (0.02s) === RUN TestRWFileHandleMethodsWrite run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:21 DEBUG : file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): openPending: 2022/06/12 05:28:21 DEBUG : file1: vfs cache: truncate to size=0 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): >openPending: err= 2022/06/12 05:28:21 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:28:21 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): _writeAt: size=5, off=0 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): >_writeAt: n=5, err= 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): _writeAt: size=7, off=5 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): >_writeAt: n=7, err= 2022/06/12 05:28:21 DEBUG : file1: vfs cache: truncate to size=11 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): close: 2022/06/12 05:28:21 DEBUG : file1: vfs cache: setting modification time to 2022-06-12 05:28:21.549894619 +0000 UTC m=+1.009099471 2022/06/12 05:28:21 INFO : file1: vfs cache: queuing for upload in 100ms 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): >close: err= 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): close: 2022/06/12 05:28:21 DEBUG : file1(0xc0005cca40): >close: err=file already closed dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:339 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestRWFileHandleMethodsWrite 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:21 DEBUG : file1: vfs cache: starting upload 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:21 INFO : file1: Copied (new) 2022/06/12 05:28:21 DEBUG : file1: vfs cache: fingerprint now "11,2022-06-12 05:28:21.549894619 +0000 UTC" 2022/06/12 05:28:21 DEBUG : file1: vfs cache: writeback object to VFS layer 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 INFO : file1: vfs cache: upload succeeded try #1 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleMethodsWrite (0.16s) === RUN TestRWFileHandleWriteAt run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:21 DEBUG : file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:28:21 DEBUG : file1: >OpenFile: fd=file1 (rw), err= read_write_test.go:359: Error Trace: read_write_test.go:359 Error: Should be true Test: TestRWFileHandleWriteAt 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): _writeAt: size=7, off=0 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): openPending: 2022/06/12 05:28:21 DEBUG : file1: vfs cache: checking remote fingerprint "11,2022-06-12 05:28:21.549894619 +0000 UTC" against cached fingerprint "11,2022-06-12 05:28:21.549894619 +0000 UTC" 2022/06/12 05:28:21 ERROR : file1: vfs cache: detected external removal of cache file 2022/06/12 05:28:21 DEBUG : file1: vfs cache: truncate to size=11 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): >openPending: err= 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): >_writeAt: n=7, err= 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): _writeAt: size=6, off=5 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): >_writeAt: n=6, err= 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): close: 2022/06/12 05:28:21 DEBUG : vfs cache: looking for range={Pos:0 Size:11} in [{Pos:0 Size:11}] - present true 2022/06/12 05:28:21 DEBUG : file1: vfs cache: setting modification time to 2022-06-12 05:28:21.709289264 +0000 UTC m=+1.168494125 2022/06/12 05:28:21 INFO : file1: vfs cache: queuing for upload in 100ms 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): >close: err= 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): _writeAt: size=5, off=0 2022/06/12 05:28:21 DEBUG : file1(0xc0008f67c0): >_writeAt: n=0, err=file already closed dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:387 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestRWFileHandleWriteAt 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:21 DEBUG : file1: vfs cache: starting upload 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:21 INFO : file1: Copied (replaced existing) 2022/06/12 05:28:21 DEBUG : file1: vfs cache: fingerprint now "11,2022-06-12 05:28:21.709289264 +0000 UTC" 2022/06/12 05:28:21 DEBUG : file1: vfs cache: writeback object to VFS layer 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 INFO : file1: vfs cache: upload succeeded try #1 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : >WaitForWriters: 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleWriteAt (0.16s) === RUN TestRWFileHandleWriteNoWrite run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:21 DEBUG : file1: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:21 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:28:21 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/06/12 05:28:21 DEBUG : file1(0xc0008f6940): close: 2022/06/12 05:28:21 DEBUG : file1(0xc0008f6940): >close: err= 2022/06/12 05:28:21 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2022/06/12 05:28:21 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2022/06/12 05:28:21 DEBUG : file2: newRWFileHandle: 2022/06/12 05:28:21 DEBUG : file2(0xc0008f6a40): openPending: 2022/06/12 05:28:21 DEBUG : file2: vfs cache: truncate to size=0 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file2" 2022/06/12 05:28:21 DEBUG : file2(0xc0008f6a40): >openPending: err= 2022/06/12 05:28:21 DEBUG : file2: >newRWFileHandle: err= 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file2" 2022/06/12 05:28:21 DEBUG : file2: >Open: fd=file2 (rw), err= 2022/06/12 05:28:21 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2022/06/12 05:28:21 DEBUG : file2(0xc0008f6a40): RWFileHandle.Flush 2022/06/12 05:28:21 DEBUG : file2(0xc0008f6a40): RWFileHandle.Release 2022/06/12 05:28:21 DEBUG : file2(0xc0008f6a40): close: 2022/06/12 05:28:21 DEBUG : file2: vfs cache: setting modification time to 2022-06-12 05:28:21.86803032 +0000 UTC m=+1.327235181 2022/06/12 05:28:21 INFO : file2: vfs cache: queuing for upload in 100ms 2022/06/12 05:28:21 DEBUG : file2(0xc0008f6a40): >close: err= dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:420 Error: Not equal: expected: []string{"file1,0,false", "file2,0,false"} actual : []string{"dir,0,true", "file1,11,false", "file2,0,false"} Diff: --- Expected +++ Actual @@ -1,3 +1,4 @@ -([]string) (len=2) { - (string) (len=13) "file1,0,false", +([]string) (len=3) { + (string) (len=10) "dir,0,true", + (string) (len=14) "file1,11,false", (string) (len=13) "file2,0,false" Test: TestRWFileHandleWriteNoWrite 2022/06/12 05:28:21 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : file2: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : file2: reading active writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : file2: reading active writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:21 DEBUG : dir: Looking for writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : : Looking for writers 2022/06/12 05:28:21 DEBUG : dir: reading active writers 2022/06/12 05:28:21 DEBUG : file1: reading active writers 2022/06/12 05:28:21 DEBUG : file2: reading active writers 2022/06/12 05:28:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:21 DEBUG : file2: vfs cache: starting upload 2022/06/12 05:28:21 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/file2] 2022/06/12 05:28:21 INFO : file2: Copied (new) 2022/06/12 05:28:21 DEBUG : file2: vfs cache: fingerprint now "0,2022-06-12 05:28:21.86803032 +0000 UTC" 2022/06/12 05:28:21 DEBUG : file2: vfs cache: writeback object to VFS layer 2022/06/12 05:28:21 DEBUG : : Added virtual directory entry vAddFile: "file2" 2022/06/12 05:28:21 INFO : file2: vfs cache: upload succeeded try #1 2022/06/12 05:28:22 DEBUG : dir: Looking for writers 2022/06/12 05:28:22 DEBUG : file1: reading active writers 2022/06/12 05:28:22 DEBUG : : Looking for writers 2022/06/12 05:28:22 DEBUG : dir: reading active writers 2022/06/12 05:28:22 DEBUG : file1: reading active writers 2022/06/12 05:28:22 DEBUG : file2: reading active writers 2022/06/12 05:28:22 DEBUG : >WaitForWriters: 2022/06/12 05:28:22 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 2022/06/12 05:28:23 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 2022/06/12 05:28:25 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 read_write_test.go:426 Error: Should be true Test: TestRWFileHandleWriteNoWrite Messages: listing wrong, want file1 (0), file2 (0) got file2 (0) fstest.go:204: Not found "file1" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 read_write_test.go:426 Error: Not equal: expected: 0 actual : 1 Test: TestRWFileHandleWriteNoWrite Messages: 1 objects not found 2022/06/12 05:28:29 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : >WaitForWriters: 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/file2] 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleWriteNoWrite (7.17s) === RUN TestRWFileHandleFlushWrite run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:29 DEBUG : file1: newRWFileHandle: 2022/06/12 05:28:29 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:28:29 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:29 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:28:29 DEBUG : file1: >OpenFile: fd=file1 (rw), err= read_write_test.go:434: Error Trace: read_write_test.go:434 Error: Should be true Test: TestRWFileHandleFlushWrite 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): _writeAt: size=5, off=0 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): openPending: 2022/06/12 05:28:29 DEBUG : file1: vfs cache: checking remote fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" against cached fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" 2022/06/12 05:28:29 ERROR : file1: vfs cache: detected external removal of cache file 2022/06/12 05:28:29 DEBUG : file1: vfs cache: truncate to size=11 2022/06/12 05:28:29 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): >openPending: err= 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): >_writeAt: n=5, err= 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): RWFileHandle.Flush 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): RWFileHandle.Flush 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): close: 2022/06/12 05:28:29 DEBUG : vfs cache: looking for range={Pos:0 Size:11} in [{Pos:0 Size:5}] - present false 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 1: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 2: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 3: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 4: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 5: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 6: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 7: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 8: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 9: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 10: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 11: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:29 ERROR : file1: vfs cache: too many errors 11/10: last error: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to kick waiters: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : file1(0xc0005cda40): >close: err=vfs cache: failed to download missing parts of cache file: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist read_write_test.go:454: Error Trace: read_write_test.go:454 Error: Received unexpected error: vfs cache: failed to download missing parts of cache file: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist Test: TestRWFileHandleFlushWrite 2022/06/12 05:28:29 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:29 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:29 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:29 INFO : file1: vfs cache: downloader: error count now 12: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2022/06/12 05:28:29 DEBUG : dir: Looking for writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : : Looking for writers 2022/06/12 05:28:29 DEBUG : dir: reading active writers 2022/06/12 05:28:29 DEBUG : file1: reading active writers 2022/06/12 05:28:29 DEBUG : file2: reading active writers 2022/06/12 05:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2022/06/12 05:28:30 DEBUG : dir: Looking for writers 2022/06/12 05:28:30 DEBUG : file1: reading active writers 2022/06/12 05:28:30 DEBUG : : Looking for writers 2022/06/12 05:28:30 DEBUG : dir: reading active writers 2022/06/12 05:28:30 DEBUG : file1: reading active writers 2022/06/12 05:28:30 DEBUG : file2: reading active writers 2022/06/12 05:28:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:31 DEBUG : dir: Looking for writers 2022/06/12 05:28:31 DEBUG : file1: reading active writers 2022/06/12 05:28:31 DEBUG : : Looking for writers 2022/06/12 05:28:31 DEBUG : dir: reading active writers 2022/06/12 05:28:31 DEBUG : file1: reading active writers 2022/06/12 05:28:31 DEBUG : file2: reading active writers 2022/06/12 05:28:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:32 DEBUG : dir: Looking for writers 2022/06/12 05:28:32 DEBUG : file1: reading active writers 2022/06/12 05:28:32 DEBUG : : Looking for writers 2022/06/12 05:28:32 DEBUG : dir: reading active writers 2022/06/12 05:28:32 DEBUG : file1: reading active writers 2022/06/12 05:28:32 DEBUG : file2: reading active writers 2022/06/12 05:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:33 DEBUG : dir: Looking for writers 2022/06/12 05:28:33 DEBUG : file1: reading active writers 2022/06/12 05:28:33 DEBUG : : Looking for writers 2022/06/12 05:28:33 DEBUG : dir: reading active writers 2022/06/12 05:28:33 DEBUG : file1: reading active writers 2022/06/12 05:28:33 DEBUG : file2: reading active writers 2022/06/12 05:28:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:34 DEBUG : dir: Looking for writers 2022/06/12 05:28:34 DEBUG : file1: reading active writers 2022/06/12 05:28:34 DEBUG : : Looking for writers 2022/06/12 05:28:34 DEBUG : dir: reading active writers 2022/06/12 05:28:34 DEBUG : file1: reading active writers 2022/06/12 05:28:34 DEBUG : file2: reading active writers 2022/06/12 05:28:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:35 DEBUG : dir: Looking for writers 2022/06/12 05:28:35 DEBUG : file1: reading active writers 2022/06/12 05:28:35 DEBUG : : Looking for writers 2022/06/12 05:28:35 DEBUG : dir: reading active writers 2022/06/12 05:28:35 DEBUG : file1: reading active writers 2022/06/12 05:28:35 DEBUG : file2: reading active writers 2022/06/12 05:28:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:36 DEBUG : dir: Looking for writers 2022/06/12 05:28:36 DEBUG : file1: reading active writers 2022/06/12 05:28:36 DEBUG : : Looking for writers 2022/06/12 05:28:36 DEBUG : file2: reading active writers 2022/06/12 05:28:36 DEBUG : dir: reading active writers 2022/06/12 05:28:36 DEBUG : file1: reading active writers 2022/06/12 05:28:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:37 DEBUG : dir: Looking for writers 2022/06/12 05:28:37 DEBUG : file1: reading active writers 2022/06/12 05:28:37 DEBUG : : Looking for writers 2022/06/12 05:28:37 DEBUG : dir: reading active writers 2022/06/12 05:28:37 DEBUG : file1: reading active writers 2022/06/12 05:28:37 DEBUG : file2: reading active writers 2022/06/12 05:28:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:38 DEBUG : dir: Looking for writers 2022/06/12 05:28:38 DEBUG : file1: reading active writers 2022/06/12 05:28:38 DEBUG : : Looking for writers 2022/06/12 05:28:38 DEBUG : file1: reading active writers 2022/06/12 05:28:38 DEBUG : file2: reading active writers 2022/06/12 05:28:38 DEBUG : dir: reading active writers 2022/06/12 05:28:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:39 DEBUG : dir: Looking for writers 2022/06/12 05:28:39 DEBUG : file1: reading active writers 2022/06/12 05:28:39 DEBUG : : Looking for writers 2022/06/12 05:28:39 DEBUG : dir: reading active writers 2022/06/12 05:28:39 DEBUG : file1: reading active writers 2022/06/12 05:28:39 DEBUG : file2: reading active writers 2022/06/12 05:28:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:40 DEBUG : dir: Looking for writers 2022/06/12 05:28:40 DEBUG : file1: reading active writers 2022/06/12 05:28:40 DEBUG : : Looking for writers 2022/06/12 05:28:40 DEBUG : dir: reading active writers 2022/06/12 05:28:40 DEBUG : file1: reading active writers 2022/06/12 05:28:40 DEBUG : file2: reading active writers 2022/06/12 05:28:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:41 DEBUG : dir: Looking for writers 2022/06/12 05:28:41 DEBUG : file1: reading active writers 2022/06/12 05:28:41 DEBUG : : Looking for writers 2022/06/12 05:28:41 DEBUG : file1: reading active writers 2022/06/12 05:28:41 DEBUG : file2: reading active writers 2022/06/12 05:28:41 DEBUG : dir: reading active writers 2022/06/12 05:28:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:42 DEBUG : dir: Looking for writers 2022/06/12 05:28:42 DEBUG : file1: reading active writers 2022/06/12 05:28:42 DEBUG : : Looking for writers 2022/06/12 05:28:42 DEBUG : dir: reading active writers 2022/06/12 05:28:42 DEBUG : file1: reading active writers 2022/06/12 05:28:42 DEBUG : file2: reading active writers 2022/06/12 05:28:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:43 DEBUG : dir: Looking for writers 2022/06/12 05:28:43 DEBUG : file1: reading active writers 2022/06/12 05:28:43 DEBUG : : Looking for writers 2022/06/12 05:28:43 DEBUG : file1: reading active writers 2022/06/12 05:28:43 DEBUG : file2: reading active writers 2022/06/12 05:28:43 DEBUG : dir: reading active writers 2022/06/12 05:28:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:44 DEBUG : dir: Looking for writers 2022/06/12 05:28:44 DEBUG : file1: reading active writers 2022/06/12 05:28:44 DEBUG : : Looking for writers 2022/06/12 05:28:44 DEBUG : file1: reading active writers 2022/06/12 05:28:44 DEBUG : file2: reading active writers 2022/06/12 05:28:44 DEBUG : dir: reading active writers 2022/06/12 05:28:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:45 DEBUG : dir: Looking for writers 2022/06/12 05:28:45 DEBUG : file1: reading active writers 2022/06/12 05:28:45 DEBUG : : Looking for writers 2022/06/12 05:28:45 DEBUG : dir: reading active writers 2022/06/12 05:28:45 DEBUG : file1: reading active writers 2022/06/12 05:28:45 DEBUG : file2: reading active writers 2022/06/12 05:28:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:46 DEBUG : dir: Looking for writers 2022/06/12 05:28:46 DEBUG : file1: reading active writers 2022/06/12 05:28:46 DEBUG : : Looking for writers 2022/06/12 05:28:46 DEBUG : dir: reading active writers 2022/06/12 05:28:46 DEBUG : file1: reading active writers 2022/06/12 05:28:46 DEBUG : file2: reading active writers 2022/06/12 05:28:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:47 DEBUG : dir: Looking for writers 2022/06/12 05:28:47 DEBUG : file1: reading active writers 2022/06/12 05:28:47 DEBUG : : Looking for writers 2022/06/12 05:28:47 DEBUG : dir: reading active writers 2022/06/12 05:28:47 DEBUG : file1: reading active writers 2022/06/12 05:28:47 DEBUG : file2: reading active writers 2022/06/12 05:28:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:48 DEBUG : dir: Looking for writers 2022/06/12 05:28:48 DEBUG : file1: reading active writers 2022/06/12 05:28:48 DEBUG : : Looking for writers 2022/06/12 05:28:48 DEBUG : dir: reading active writers 2022/06/12 05:28:48 DEBUG : file1: reading active writers 2022/06/12 05:28:48 DEBUG : file2: reading active writers 2022/06/12 05:28:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:49 DEBUG : dir: Looking for writers 2022/06/12 05:28:49 DEBUG : file1: reading active writers 2022/06/12 05:28:49 DEBUG : : Looking for writers 2022/06/12 05:28:49 DEBUG : dir: reading active writers 2022/06/12 05:28:49 DEBUG : file1: reading active writers 2022/06/12 05:28:49 DEBUG : file2: reading active writers 2022/06/12 05:28:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:50 DEBUG : dir: Looking for writers 2022/06/12 05:28:50 DEBUG : file1: reading active writers 2022/06/12 05:28:50 DEBUG : : Looking for writers 2022/06/12 05:28:50 DEBUG : dir: reading active writers 2022/06/12 05:28:50 DEBUG : file1: reading active writers 2022/06/12 05:28:50 DEBUG : file2: reading active writers 2022/06/12 05:28:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:51 DEBUG : dir: Looking for writers 2022/06/12 05:28:51 DEBUG : file1: reading active writers 2022/06/12 05:28:51 DEBUG : : Looking for writers 2022/06/12 05:28:51 DEBUG : dir: reading active writers 2022/06/12 05:28:51 DEBUG : file1: reading active writers 2022/06/12 05:28:51 DEBUG : file2: reading active writers 2022/06/12 05:28:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:52 DEBUG : dir: Looking for writers 2022/06/12 05:28:52 DEBUG : file1: reading active writers 2022/06/12 05:28:52 DEBUG : : Looking for writers 2022/06/12 05:28:52 DEBUG : dir: reading active writers 2022/06/12 05:28:52 DEBUG : file1: reading active writers 2022/06/12 05:28:52 DEBUG : file2: reading active writers 2022/06/12 05:28:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:53 DEBUG : dir: Looking for writers 2022/06/12 05:28:53 DEBUG : file1: reading active writers 2022/06/12 05:28:53 DEBUG : : Looking for writers 2022/06/12 05:28:53 DEBUG : dir: reading active writers 2022/06/12 05:28:53 DEBUG : file1: reading active writers 2022/06/12 05:28:53 DEBUG : file2: reading active writers 2022/06/12 05:28:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:54 DEBUG : dir: Looking for writers 2022/06/12 05:28:54 DEBUG : file1: reading active writers 2022/06/12 05:28:54 DEBUG : : Looking for writers 2022/06/12 05:28:54 DEBUG : dir: reading active writers 2022/06/12 05:28:54 DEBUG : file1: reading active writers 2022/06/12 05:28:54 DEBUG : file2: reading active writers 2022/06/12 05:28:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:55 DEBUG : dir: Looking for writers 2022/06/12 05:28:55 DEBUG : file1: reading active writers 2022/06/12 05:28:55 DEBUG : : Looking for writers 2022/06/12 05:28:55 DEBUG : file1: reading active writers 2022/06/12 05:28:55 DEBUG : file2: reading active writers 2022/06/12 05:28:55 DEBUG : dir: reading active writers 2022/06/12 05:28:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:56 DEBUG : dir: Looking for writers 2022/06/12 05:28:56 DEBUG : file1: reading active writers 2022/06/12 05:28:56 DEBUG : : Looking for writers 2022/06/12 05:28:56 DEBUG : dir: reading active writers 2022/06/12 05:28:56 DEBUG : file1: reading active writers 2022/06/12 05:28:56 DEBUG : file2: reading active writers 2022/06/12 05:28:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:57 DEBUG : dir: Looking for writers 2022/06/12 05:28:57 DEBUG : file1: reading active writers 2022/06/12 05:28:57 DEBUG : : Looking for writers 2022/06/12 05:28:57 DEBUG : dir: reading active writers 2022/06/12 05:28:57 DEBUG : file1: reading active writers 2022/06/12 05:28:57 DEBUG : file2: reading active writers 2022/06/12 05:28:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:58 DEBUG : dir: Looking for writers 2022/06/12 05:28:58 DEBUG : file1: reading active writers 2022/06/12 05:28:58 DEBUG : : Looking for writers 2022/06/12 05:28:58 DEBUG : file1: reading active writers 2022/06/12 05:28:58 DEBUG : file2: reading active writers 2022/06/12 05:28:58 DEBUG : dir: reading active writers 2022/06/12 05:28:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:28:59 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc0005cca00 name:file1 opens:0 downloaders:0xc000900580 o:0xc0005ccbc0 fd:0xc000203ea8 modified:true info:{ModTime:{wall:13880512137666358665 ext:8494458502 loc:0x2be8a40} ATime:{wall:13880512137666450296 ext:8494550133 loc:0x2be8a40} Size:11 Rs:[{Pos:0 Size:5}] Fingerprint:11,2022-06-12 05:28:21.709289264 +0000 UTC Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, "file2": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc0008f6a00 name:file2 opens:0 downloaders: o:0xc0008f6b80 fd: modified:false info:{ModTime:{wall:13880512129909200752 ext:1327235181 loc:0x2be8a40} ATime:{wall:13880512129909322949 ext:1327357378 loc:0x2be8a40} Size:0 Rs:[] Fingerprint:0,2022-06-12 05:28:21.86803032 +0000 UTC Dirty:false} writeBackID:2 pendingAccesses:0 beingReset:false}, "dir/file1": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc00049f300 name:dir/file1 opens:0 downloaders: o:0xc00049f2c0 fd: modified:false info:{ModTime:{wall:13880512129499964683 ext:917999102 loc:0x2be8a40} ATime:{wall:13880512129582614684 ext:1000649103 loc:0x2be8a40} Size:16 Rs:[{Pos:0 Size:16}] Fingerprint:16,2001-02-03 04:05:06 +0000 UTC Dirty:false} writeBackID:0 pendingAccesses:0 beingReset:false}, } 2022/06/12 05:28:59 DEBUG : >WaitForWriters: 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleFlushWrite (30.01s) === RUN TestRWFileHandleReleaseWrite run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:59 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:59 DEBUG : file1: newRWFileHandle: 2022/06/12 05:28:59 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:28:59 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:28:59 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): _writeAt: size=5, off=0 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): openPending: 2022/06/12 05:28:59 DEBUG : file1: vfs cache: checking remote fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" against cached fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" 2022/06/12 05:28:59 DEBUG : file1: vfs cache: truncate to size=11 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to open item: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file 2022/06/12 05:28:59 ERROR : file1: Non-out-of-space error encountered during open 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): >openPending: err=open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): >_writeAt: n=0, err=open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file read_write_test.go:464: Error Trace: read_write_test.go:464 Error: Received unexpected error: open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file Test: TestRWFileHandleReleaseWrite read_write_test.go:465: Error Trace: read_write_test.go:465 Error: Not equal: expected: 5 actual : 0 Test: TestRWFileHandleReleaseWrite 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): RWFileHandle.Release 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): close: 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): >close: err= 2022/06/12 05:28:59 DEBUG : file1(0xc00062cbc0): RWFileHandle.Release 2022/06/12 05:28:59 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : >WaitForWriters: 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleReleaseWrite (0.00s) === RUN TestRWFileHandleSizeTruncateExisting run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:59 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2022/06/12 05:28:59 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2022/06/12 05:28:59 DEBUG : dir/file1: newRWFileHandle: 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7700): openPending: 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "16,2001-02-03 04:05:06 +0000 UTC" 2022/06/12 05:28:59 ERROR : dir/file1: vfs cache: detected external removal of cache file 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: truncate to size=16 2022/06/12 05:28:59 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7700): >openPending: err= 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: truncate to size=0 2022/06/12 05:28:59 DEBUG : dir/file1: >newRWFileHandle: err= 2022/06/12 05:28:59 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2022/06/12 05:28:59 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7700): _writeAt: size=5, off=0 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7700): >_writeAt: n=5, err= 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7700): close: 2022/06/12 05:28:59 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: setting modification time to 2022-06-12 05:28:59.06792531 +0000 UTC m=+38.527130162 2022/06/12 05:28:59 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7700): >close: err= 2022/06/12 05:28:59 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: starting upload 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:59 INFO : dir/file1: Copied (replaced existing) 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: fingerprint now "5,2022-06-12 05:28:59.06792531 +0000 UTC" 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2022/06/12 05:28:59 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 INFO : dir/file1: vfs cache: upload succeeded try #1 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : >WaitForWriters: 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- PASS: TestRWFileHandleSizeTruncateExisting (0.18s) === RUN TestRWFileHandleSizeCreateExisting run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:59 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:59 DEBUG : dir/file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:59 DEBUG : dir/file1: newRWFileHandle: 2022/06/12 05:28:59 DEBUG : dir/file1: >newRWFileHandle: err= 2022/06/12 05:28:59 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2022/06/12 05:28:59 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= read_write_test.go:481: Error Trace: read_write_test.go:481 read_write_test.go:515 Error: Not equal: expected: 16 actual : 5 Test: TestRWFileHandleSizeCreateExisting read_write_test.go:485: Error Trace: read_write_test.go:485 read_write_test.go:515 Error: Not equal: expected: 16 actual : 5 Test: TestRWFileHandleSizeCreateExisting 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): _writeAt: size=5, off=0 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): openPending: 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: checking remote fingerprint "5,2022-06-12 05:28:59.06792531 +0000 UTC" against cached fingerprint "5,2022-06-12 05:28:59.06792531 +0000 UTC" 2022/06/12 05:28:59 ERROR : dir/file1: vfs cache: detected external removal of cache file 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: truncate to size=5 2022/06/12 05:28:59 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): >openPending: err= 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): >_writeAt: n=5, err= read_write_test.go:481: Error Trace: read_write_test.go:481 read_write_test.go:523 Error: Not equal: expected: 16 actual : 5 Test: TestRWFileHandleSizeCreateExisting read_write_test.go:485: Error Trace: read_write_test.go:485 read_write_test.go:523 Error: Not equal: expected: 16 actual : 5 Test: TestRWFileHandleSizeCreateExisting 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): _writeAt: size=15, off=5 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): >_writeAt: n=15, err= 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): close: 2022/06/12 05:28:59 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [{Pos:0 Size:20}] - present true 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: setting modification time to 2022-06-12 05:28:59.242970231 +0000 UTC m=+38.702175092 2022/06/12 05:28:59 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2022/06/12 05:28:59 DEBUG : dir/file1(0xc0008f7f80): >close: err= 2022/06/12 05:28:59 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: starting upload 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:59 INFO : dir/file1: Copied (replaced existing) 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: fingerprint now "20,2022-06-12 05:28:59.242970231 +0000 UTC" 2022/06/12 05:28:59 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2022/06/12 05:28:59 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 INFO : dir/file1: vfs cache: upload succeeded try #1 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : >WaitForWriters: 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: remove [/rclone-test-meyiwov9mubehik1mequron8/dir/file1] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: rmdir [/rclone-test-meyiwov9mubehik1mequron8/dir] 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleSizeCreateExisting (0.17s) === RUN TestRWFileHandleSizeCreateNew run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:28:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:28:59 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:28:59 DEBUG : file1: newRWFileHandle: 2022/06/12 05:28:59 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:28:59 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:28:59 DEBUG : file1: >OpenFile: fd=file1 (rw), err= read_write_test.go:481: Error Trace: read_write_test.go:481 read_write_test.go:545 Error: Not equal: expected: 0 actual : 11 Test: TestRWFileHandleSizeCreateNew read_write_test.go:485: Error Trace: read_write_test.go:485 read_write_test.go:545 Error: Not equal: expected: 0 actual : 11 Test: TestRWFileHandleSizeCreateNew 2022/06/12 05:28:59 DEBUG : file1(0xc000b85000): _writeAt: size=5, off=0 2022/06/12 05:28:59 DEBUG : file1(0xc000b85000): openPending: 2022/06/12 05:28:59 DEBUG : file1: vfs cache: checking remote fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" against cached fingerprint "" 2022/06/12 05:28:59 DEBUG : file1: vfs cache: truncate to size=11 2022/06/12 05:28:59 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:28:59 DEBUG : file1(0xc000b85000): >openPending: err= 2022/06/12 05:28:59 DEBUG : file1(0xc000b85000): >_writeAt: n=5, err= read_write_test.go:481: Error Trace: read_write_test.go:481 read_write_test.go:553 Error: Not equal: expected: 5 actual : 11 Test: TestRWFileHandleSizeCreateNew read_write_test.go:485: Error Trace: read_write_test.go:485 read_write_test.go:553 Error: Not equal: expected: 5 actual : 11 Test: TestRWFileHandleSizeCreateNew read_write_test.go:481: Error Trace: read_write_test.go:481 read_write_test.go:556 Error: Not equal: expected: 5 actual : 11 Test: TestRWFileHandleSizeCreateNew read_write_test.go:485: Error Trace: read_write_test.go:485 read_write_test.go:556 Error: Not equal: expected: 5 actual : 11 Test: TestRWFileHandleSizeCreateNew 2022/06/12 05:28:59 DEBUG : file1(0xc000b85000): close: 2022/06/12 05:28:59 DEBUG : vfs cache: looking for range={Pos:0 Size:11} in [{Pos:0 Size:5}] - present false 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 1: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 2: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 3: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 4: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 5: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 6: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 7: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 8: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 9: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 10: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 11: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.RangeSeek from -1 to 5 length -1 2022/06/12 05:28:59 ERROR : file1: vfs cache: too many errors 11/10: last error: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to kick waiters: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1(0xc000b85000): >close: err=vfs cache: failed to download missing parts of cache file: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728 read_write_test.go:559: Error Trace: read_write_test.go:559 Error: Received unexpected error: vfs cache: failed to download missing parts of cache file: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist Test: TestRWFileHandleSizeCreateNew 2022/06/12 05:28:59 DEBUG : file1: ChunkedReader.openRange at 5 length 134217728 2022/06/12 05:28:59 DEBUG : hdfs://127.0.0.1:8020: open [/rclone-test-meyiwov9mubehik1mequron8/file1] read_write_test.go:485: Error Trace: read_write_test.go:485 read_write_test.go:562 Error: Not equal: expected: 5 actual : 11 Test: TestRWFileHandleSizeCreateNew 2022/06/12 05:28:59 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/06/12 05:28:59 INFO : file1: vfs cache: downloader: error count now 12: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 ERROR : file1: vfs cache: failed to download: vfs reader: failed to write to cache file: open /rclone-test-meyiwov9mubehik1mequron8/file1: file does not exist 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2022/06/12 05:28:59 DEBUG : dir: Looking for writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : : Looking for writers 2022/06/12 05:28:59 DEBUG : dir: reading active writers 2022/06/12 05:28:59 DEBUG : file1: reading active writers 2022/06/12 05:28:59 DEBUG : file2: reading active writers 2022/06/12 05:28:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2022/06/12 05:29:00 DEBUG : dir: Looking for writers 2022/06/12 05:29:00 DEBUG : file1: reading active writers 2022/06/12 05:29:00 DEBUG : : Looking for writers 2022/06/12 05:29:00 DEBUG : dir: reading active writers 2022/06/12 05:29:00 DEBUG : file1: reading active writers 2022/06/12 05:29:00 DEBUG : file2: reading active writers 2022/06/12 05:29:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2022/06/12 05:29:00 DEBUG : dir: Looking for writers 2022/06/12 05:29:00 DEBUG : file1: reading active writers 2022/06/12 05:29:00 DEBUG : : Looking for writers 2022/06/12 05:29:00 DEBUG : dir: reading active writers 2022/06/12 05:29:00 DEBUG : file1: reading active writers 2022/06/12 05:29:00 DEBUG : file2: reading active writers 2022/06/12 05:29:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:01 DEBUG : dir: Looking for writers 2022/06/12 05:29:01 DEBUG : file1: reading active writers 2022/06/12 05:29:01 DEBUG : : Looking for writers 2022/06/12 05:29:01 DEBUG : dir: reading active writers 2022/06/12 05:29:01 DEBUG : file1: reading active writers 2022/06/12 05:29:01 DEBUG : file2: reading active writers 2022/06/12 05:29:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:02 DEBUG : dir: Looking for writers 2022/06/12 05:29:02 DEBUG : file1: reading active writers 2022/06/12 05:29:02 DEBUG : : Looking for writers 2022/06/12 05:29:02 DEBUG : dir: reading active writers 2022/06/12 05:29:02 DEBUG : file1: reading active writers 2022/06/12 05:29:02 DEBUG : file2: reading active writers 2022/06/12 05:29:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:03 DEBUG : dir: Looking for writers 2022/06/12 05:29:03 DEBUG : file1: reading active writers 2022/06/12 05:29:03 DEBUG : : Looking for writers 2022/06/12 05:29:03 DEBUG : dir: reading active writers 2022/06/12 05:29:03 DEBUG : file1: reading active writers 2022/06/12 05:29:03 DEBUG : file2: reading active writers 2022/06/12 05:29:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:04 DEBUG : dir: Looking for writers 2022/06/12 05:29:04 DEBUG : file1: reading active writers 2022/06/12 05:29:04 DEBUG : : Looking for writers 2022/06/12 05:29:04 DEBUG : dir: reading active writers 2022/06/12 05:29:04 DEBUG : file1: reading active writers 2022/06/12 05:29:04 DEBUG : file2: reading active writers 2022/06/12 05:29:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:05 DEBUG : dir: Looking for writers 2022/06/12 05:29:05 DEBUG : file1: reading active writers 2022/06/12 05:29:05 DEBUG : : Looking for writers 2022/06/12 05:29:05 DEBUG : dir: reading active writers 2022/06/12 05:29:05 DEBUG : file1: reading active writers 2022/06/12 05:29:05 DEBUG : file2: reading active writers 2022/06/12 05:29:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:06 DEBUG : dir: Looking for writers 2022/06/12 05:29:06 DEBUG : file1: reading active writers 2022/06/12 05:29:06 DEBUG : : Looking for writers 2022/06/12 05:29:06 DEBUG : dir: reading active writers 2022/06/12 05:29:06 DEBUG : file1: reading active writers 2022/06/12 05:29:06 DEBUG : file2: reading active writers 2022/06/12 05:29:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:07 DEBUG : dir: Looking for writers 2022/06/12 05:29:07 DEBUG : file1: reading active writers 2022/06/12 05:29:07 DEBUG : : Looking for writers 2022/06/12 05:29:07 DEBUG : file1: reading active writers 2022/06/12 05:29:07 DEBUG : file2: reading active writers 2022/06/12 05:29:07 DEBUG : dir: reading active writers 2022/06/12 05:29:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:08 DEBUG : dir: Looking for writers 2022/06/12 05:29:08 DEBUG : file1: reading active writers 2022/06/12 05:29:08 DEBUG : : Looking for writers 2022/06/12 05:29:08 DEBUG : dir: reading active writers 2022/06/12 05:29:08 DEBUG : file1: reading active writers 2022/06/12 05:29:08 DEBUG : file2: reading active writers 2022/06/12 05:29:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:09 DEBUG : dir: Looking for writers 2022/06/12 05:29:09 DEBUG : file1: reading active writers 2022/06/12 05:29:09 DEBUG : : Looking for writers 2022/06/12 05:29:09 DEBUG : dir: reading active writers 2022/06/12 05:29:09 DEBUG : file1: reading active writers 2022/06/12 05:29:09 DEBUG : file2: reading active writers 2022/06/12 05:29:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:10 DEBUG : dir: Looking for writers 2022/06/12 05:29:10 DEBUG : file1: reading active writers 2022/06/12 05:29:10 DEBUG : : Looking for writers 2022/06/12 05:29:10 DEBUG : dir: reading active writers 2022/06/12 05:29:10 DEBUG : file1: reading active writers 2022/06/12 05:29:10 DEBUG : file2: reading active writers 2022/06/12 05:29:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:11 DEBUG : dir: Looking for writers 2022/06/12 05:29:11 DEBUG : file1: reading active writers 2022/06/12 05:29:11 DEBUG : : Looking for writers 2022/06/12 05:29:11 DEBUG : dir: reading active writers 2022/06/12 05:29:11 DEBUG : file1: reading active writers 2022/06/12 05:29:11 DEBUG : file2: reading active writers 2022/06/12 05:29:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:12 DEBUG : dir: Looking for writers 2022/06/12 05:29:12 DEBUG : file1: reading active writers 2022/06/12 05:29:12 DEBUG : : Looking for writers 2022/06/12 05:29:12 DEBUG : dir: reading active writers 2022/06/12 05:29:12 DEBUG : file1: reading active writers 2022/06/12 05:29:12 DEBUG : file2: reading active writers 2022/06/12 05:29:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:13 DEBUG : dir: Looking for writers 2022/06/12 05:29:13 DEBUG : file1: reading active writers 2022/06/12 05:29:13 DEBUG : : Looking for writers 2022/06/12 05:29:13 DEBUG : dir: reading active writers 2022/06/12 05:29:13 DEBUG : file1: reading active writers 2022/06/12 05:29:13 DEBUG : file2: reading active writers 2022/06/12 05:29:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:14 DEBUG : dir: Looking for writers 2022/06/12 05:29:14 DEBUG : file1: reading active writers 2022/06/12 05:29:14 DEBUG : : Looking for writers 2022/06/12 05:29:14 DEBUG : dir: reading active writers 2022/06/12 05:29:14 DEBUG : file1: reading active writers 2022/06/12 05:29:14 DEBUG : file2: reading active writers 2022/06/12 05:29:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:15 DEBUG : dir: Looking for writers 2022/06/12 05:29:15 DEBUG : file1: reading active writers 2022/06/12 05:29:15 DEBUG : : Looking for writers 2022/06/12 05:29:15 DEBUG : file2: reading active writers 2022/06/12 05:29:15 DEBUG : dir: reading active writers 2022/06/12 05:29:15 DEBUG : file1: reading active writers 2022/06/12 05:29:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:16 DEBUG : dir: Looking for writers 2022/06/12 05:29:16 DEBUG : file1: reading active writers 2022/06/12 05:29:16 DEBUG : : Looking for writers 2022/06/12 05:29:16 DEBUG : dir: reading active writers 2022/06/12 05:29:16 DEBUG : file1: reading active writers 2022/06/12 05:29:16 DEBUG : file2: reading active writers 2022/06/12 05:29:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:17 DEBUG : dir: Looking for writers 2022/06/12 05:29:17 DEBUG : file1: reading active writers 2022/06/12 05:29:17 DEBUG : : Looking for writers 2022/06/12 05:29:17 DEBUG : dir: reading active writers 2022/06/12 05:29:17 DEBUG : file1: reading active writers 2022/06/12 05:29:17 DEBUG : file2: reading active writers 2022/06/12 05:29:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:18 DEBUG : dir: Looking for writers 2022/06/12 05:29:18 DEBUG : file1: reading active writers 2022/06/12 05:29:18 DEBUG : : Looking for writers 2022/06/12 05:29:18 DEBUG : dir: reading active writers 2022/06/12 05:29:18 DEBUG : file1: reading active writers 2022/06/12 05:29:18 DEBUG : file2: reading active writers 2022/06/12 05:29:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:19 DEBUG : dir: Looking for writers 2022/06/12 05:29:19 DEBUG : file1: reading active writers 2022/06/12 05:29:19 DEBUG : : Looking for writers 2022/06/12 05:29:19 DEBUG : dir: reading active writers 2022/06/12 05:29:19 DEBUG : file1: reading active writers 2022/06/12 05:29:19 DEBUG : file2: reading active writers 2022/06/12 05:29:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:20 DEBUG : dir: Looking for writers 2022/06/12 05:29:20 DEBUG : file1: reading active writers 2022/06/12 05:29:20 DEBUG : : Looking for writers 2022/06/12 05:29:20 DEBUG : dir: reading active writers 2022/06/12 05:29:20 DEBUG : file1: reading active writers 2022/06/12 05:29:20 DEBUG : file2: reading active writers 2022/06/12 05:29:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:21 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2022/06/12 05:29:21 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2022/06/12 05:29:21 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2022/06/12 05:29:21 INFO : vfs cache: cleaned: objects 3 (was 3) in use 1, to upload 0, uploading 0, total size 25 (was 25) 2022/06/12 05:29:21 DEBUG : dir: Looking for writers 2022/06/12 05:29:21 DEBUG : file1: reading active writers 2022/06/12 05:29:21 DEBUG : : Looking for writers 2022/06/12 05:29:21 DEBUG : dir: reading active writers 2022/06/12 05:29:21 DEBUG : file1: reading active writers 2022/06/12 05:29:21 DEBUG : file2: reading active writers 2022/06/12 05:29:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:22 DEBUG : dir: Looking for writers 2022/06/12 05:29:22 DEBUG : file1: reading active writers 2022/06/12 05:29:22 DEBUG : : Looking for writers 2022/06/12 05:29:22 DEBUG : dir: reading active writers 2022/06/12 05:29:22 DEBUG : file1: reading active writers 2022/06/12 05:29:22 DEBUG : file2: reading active writers 2022/06/12 05:29:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:23 DEBUG : dir: Looking for writers 2022/06/12 05:29:23 DEBUG : file1: reading active writers 2022/06/12 05:29:23 DEBUG : : Looking for writers 2022/06/12 05:29:23 DEBUG : dir: reading active writers 2022/06/12 05:29:23 DEBUG : file1: reading active writers 2022/06/12 05:29:23 DEBUG : file2: reading active writers 2022/06/12 05:29:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:24 DEBUG : dir: Looking for writers 2022/06/12 05:29:24 DEBUG : file1: reading active writers 2022/06/12 05:29:24 DEBUG : : Looking for writers 2022/06/12 05:29:24 DEBUG : file2: reading active writers 2022/06/12 05:29:24 DEBUG : dir: reading active writers 2022/06/12 05:29:24 DEBUG : file1: reading active writers 2022/06/12 05:29:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:25 DEBUG : dir: Looking for writers 2022/06/12 05:29:25 DEBUG : file1: reading active writers 2022/06/12 05:29:25 DEBUG : : Looking for writers 2022/06/12 05:29:25 DEBUG : dir: reading active writers 2022/06/12 05:29:25 DEBUG : file1: reading active writers 2022/06/12 05:29:25 DEBUG : file2: reading active writers 2022/06/12 05:29:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:26 DEBUG : dir: Looking for writers 2022/06/12 05:29:26 DEBUG : file1: reading active writers 2022/06/12 05:29:26 DEBUG : : Looking for writers 2022/06/12 05:29:26 DEBUG : dir: reading active writers 2022/06/12 05:29:26 DEBUG : file1: reading active writers 2022/06/12 05:29:26 DEBUG : file2: reading active writers 2022/06/12 05:29:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:27 DEBUG : dir: Looking for writers 2022/06/12 05:29:27 DEBUG : file1: reading active writers 2022/06/12 05:29:27 DEBUG : : Looking for writers 2022/06/12 05:29:27 DEBUG : dir: reading active writers 2022/06/12 05:29:27 DEBUG : file1: reading active writers 2022/06/12 05:29:27 DEBUG : file2: reading active writers 2022/06/12 05:29:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:28 DEBUG : dir: Looking for writers 2022/06/12 05:29:28 DEBUG : file1: reading active writers 2022/06/12 05:29:28 DEBUG : : Looking for writers 2022/06/12 05:29:28 DEBUG : file1: reading active writers 2022/06/12 05:29:28 DEBUG : file2: reading active writers 2022/06/12 05:29:28 DEBUG : dir: reading active writers 2022/06/12 05:29:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/06/12 05:29:29 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "dir/file1": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc00049f300 name:dir/file1 opens:0 downloaders: o:0xc00049f2c0 fd: modified:false info:{ModTime:{wall:13880512170086329975 ext:38702175092 loc:0x2be8a40} ATime:{wall:13880512170086348350 ext:38702193456 loc:0x2be8a40} Size:20 Rs:[{Pos:0 Size:20}] Fingerprint:20,2022-06-12 05:28:59.242970231 +0000 UTC Dirty:false} writeBackID:3 pendingAccesses:0 beingReset:false}, "file1": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc0005cca00 name:file1 opens:0 downloaders:0xc000900c60 o:0xc0005ccbc0 fd:0xc000203fa0 modified:true info:{ModTime:{wall:13880512170246850847 ext:38862695964 loc:0x2be8a40} ATime:{wall:13880512170247140516 ext:38862985633 loc:0x2be8a40} Size:11 Rs:[{Pos:0 Size:5}] Fingerprint:11,2022-06-12 05:28:21.709289264 +0000 UTC Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, "file2": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc0008f6a00 name:file2 opens:0 downloaders: o:0xc0008f6b80 fd: modified:false info:{ModTime:{wall:13880512129909200752 ext:1327235181 loc:0x2be8a40} ATime:{wall:13880512129909322949 ext:1327357378 loc:0x2be8a40} Size:0 Rs:[] Fingerprint:0,2022-06-12 05:28:21.86803032 +0000 UTC Dirty:false} writeBackID:2 pendingAccesses:0 beingReset:false}, } 2022/06/12 05:29:29 DEBUG : >WaitForWriters: 2022/06/12 05:29:29 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:29:29 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileHandleSizeCreateNew (30.01s) === RUN TestRWFileModTimeWithOpenWriters run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:29:29 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:29:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/06/12 05:29:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/06/12 05:29:29 DEBUG : file1: newRWFileHandle: 2022/06/12 05:29:29 DEBUG : file1: >newRWFileHandle: err= 2022/06/12 05:29:29 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/06/12 05:29:29 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/06/12 05:29:29 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/06/12 05:29:29 DEBUG : file1(0xc000c8e440): _writeAt: size=2, off=0 2022/06/12 05:29:29 DEBUG : file1(0xc000c8e440): openPending: 2022/06/12 05:29:29 DEBUG : file1: vfs cache: checking remote fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" against cached fingerprint "11,2022-06-12 05:28:21.709289264 +0000 UTC" 2022/06/12 05:29:29 DEBUG : file1: vfs cache: truncate to size=11 2022/06/12 05:29:29 ERROR : file1: vfs cache: failed to open item: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file 2022/06/12 05:29:29 ERROR : file1: Non-out-of-space error encountered during open 2022/06/12 05:29:29 DEBUG : file1(0xc000c8e440): >openPending: err=open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file 2022/06/12 05:29:29 DEBUG : file1(0xc000c8e440): >_writeAt: n=0, err=open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file read_write_test.go:670: Error Trace: read_write_test.go:670 Error: Received unexpected error: open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file Test: TestRWFileModTimeWithOpenWriters 2022/06/12 05:29:29 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:29:29 DEBUG : dir: Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : : Looking for writers 2022/06/12 05:29:29 DEBUG : dir: reading active writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : file1: active writers 1 2022/06/12 05:29:29 DEBUG : file2: reading active writers 2022/06/12 05:29:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/06/12 05:29:29 DEBUG : dir: Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : : Looking for writers 2022/06/12 05:29:29 DEBUG : dir: reading active writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : file1: active writers 1 2022/06/12 05:29:29 DEBUG : file2: reading active writers 2022/06/12 05:29:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/06/12 05:29:29 DEBUG : dir: Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : : Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : file1: active writers 1 2022/06/12 05:29:29 DEBUG : file2: reading active writers 2022/06/12 05:29:29 DEBUG : dir: reading active writers 2022/06/12 05:29:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/06/12 05:29:29 DEBUG : dir: Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : : Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : file1: active writers 1 2022/06/12 05:29:29 DEBUG : file2: reading active writers 2022/06/12 05:29:29 DEBUG : dir: reading active writers 2022/06/12 05:29:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/06/12 05:29:29 DEBUG : dir: Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : : Looking for writers 2022/06/12 05:29:29 DEBUG : dir: reading active writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : file1: active writers 1 2022/06/12 05:29:29 DEBUG : file2: reading active writers 2022/06/12 05:29:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/06/12 05:29:29 DEBUG : dir: Looking for writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : : Looking for writers 2022/06/12 05:29:29 DEBUG : dir: reading active writers 2022/06/12 05:29:29 DEBUG : file1: reading active writers 2022/06/12 05:29:29 DEBUG : file1: active writers 1 2022/06/12 05:29:29 DEBUG : file2: reading active writers 2022/06/12 05:29:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/06/12 05:29:30 DEBUG : dir: Looking for writers 2022/06/12 05:29:30 DEBUG : file1: reading active writers 2022/06/12 05:29:30 DEBUG : : Looking for writers 2022/06/12 05:29:30 DEBUG : dir: reading active writers 2022/06/12 05:29:30 DEBUG : file1: reading active writers 2022/06/12 05:29:30 DEBUG : file1: active writers 1 2022/06/12 05:29:30 DEBUG : file2: reading active writers 2022/06/12 05:29:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/06/12 05:29:30 DEBUG : dir: Looking for writers 2022/06/12 05:29:30 DEBUG : file1: reading active writers 2022/06/12 05:29:30 DEBUG : : Looking for writers 2022/06/12 05:29:30 DEBUG : file2: reading active writers 2022/06/12 05:29:30 DEBUG : dir: reading active writers 2022/06/12 05:29:30 DEBUG : file1: reading active writers 2022/06/12 05:29:30 DEBUG : file1: active writers 1 2022/06/12 05:29:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:31 DEBUG : dir: Looking for writers 2022/06/12 05:29:31 DEBUG : file1: reading active writers 2022/06/12 05:29:31 DEBUG : : Looking for writers 2022/06/12 05:29:31 DEBUG : file2: reading active writers 2022/06/12 05:29:31 DEBUG : dir: reading active writers 2022/06/12 05:29:31 DEBUG : file1: reading active writers 2022/06/12 05:29:31 DEBUG : file1: active writers 1 2022/06/12 05:29:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:32 DEBUG : dir: Looking for writers 2022/06/12 05:29:32 DEBUG : file1: reading active writers 2022/06/12 05:29:32 DEBUG : : Looking for writers 2022/06/12 05:29:32 DEBUG : file2: reading active writers 2022/06/12 05:29:32 DEBUG : dir: reading active writers 2022/06/12 05:29:32 DEBUG : file1: reading active writers 2022/06/12 05:29:32 DEBUG : file1: active writers 1 2022/06/12 05:29:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:33 DEBUG : dir: Looking for writers 2022/06/12 05:29:33 DEBUG : file1: reading active writers 2022/06/12 05:29:33 DEBUG : : Looking for writers 2022/06/12 05:29:33 DEBUG : dir: reading active writers 2022/06/12 05:29:33 DEBUG : file1: reading active writers 2022/06/12 05:29:33 DEBUG : file1: active writers 1 2022/06/12 05:29:33 DEBUG : file2: reading active writers 2022/06/12 05:29:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:34 DEBUG : dir: Looking for writers 2022/06/12 05:29:34 DEBUG : file1: reading active writers 2022/06/12 05:29:34 DEBUG : : Looking for writers 2022/06/12 05:29:34 DEBUG : file1: reading active writers 2022/06/12 05:29:34 DEBUG : file1: active writers 1 2022/06/12 05:29:34 DEBUG : file2: reading active writers 2022/06/12 05:29:34 DEBUG : dir: reading active writers 2022/06/12 05:29:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:35 DEBUG : dir: Looking for writers 2022/06/12 05:29:35 DEBUG : file1: reading active writers 2022/06/12 05:29:35 DEBUG : : Looking for writers 2022/06/12 05:29:35 DEBUG : dir: reading active writers 2022/06/12 05:29:35 DEBUG : file1: reading active writers 2022/06/12 05:29:35 DEBUG : file1: active writers 1 2022/06/12 05:29:35 DEBUG : file2: reading active writers 2022/06/12 05:29:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:36 DEBUG : dir: Looking for writers 2022/06/12 05:29:36 DEBUG : file1: reading active writers 2022/06/12 05:29:36 DEBUG : : Looking for writers 2022/06/12 05:29:36 DEBUG : file2: reading active writers 2022/06/12 05:29:36 DEBUG : dir: reading active writers 2022/06/12 05:29:36 DEBUG : file1: reading active writers 2022/06/12 05:29:36 DEBUG : file1: active writers 1 2022/06/12 05:29:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:37 DEBUG : dir: Looking for writers 2022/06/12 05:29:37 DEBUG : file1: reading active writers 2022/06/12 05:29:37 DEBUG : : Looking for writers 2022/06/12 05:29:37 DEBUG : dir: reading active writers 2022/06/12 05:29:37 DEBUG : file1: reading active writers 2022/06/12 05:29:37 DEBUG : file1: active writers 1 2022/06/12 05:29:37 DEBUG : file2: reading active writers 2022/06/12 05:29:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:38 DEBUG : dir: Looking for writers 2022/06/12 05:29:38 DEBUG : file1: reading active writers 2022/06/12 05:29:38 DEBUG : : Looking for writers 2022/06/12 05:29:38 DEBUG : dir: reading active writers 2022/06/12 05:29:38 DEBUG : file1: reading active writers 2022/06/12 05:29:38 DEBUG : file1: active writers 1 2022/06/12 05:29:38 DEBUG : file2: reading active writers 2022/06/12 05:29:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:39 DEBUG : dir: Looking for writers 2022/06/12 05:29:39 DEBUG : file1: reading active writers 2022/06/12 05:29:39 DEBUG : : Looking for writers 2022/06/12 05:29:39 DEBUG : file2: reading active writers 2022/06/12 05:29:39 DEBUG : dir: reading active writers 2022/06/12 05:29:39 DEBUG : file1: reading active writers 2022/06/12 05:29:39 DEBUG : file1: active writers 1 2022/06/12 05:29:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:40 DEBUG : dir: Looking for writers 2022/06/12 05:29:40 DEBUG : file1: reading active writers 2022/06/12 05:29:40 DEBUG : : Looking for writers 2022/06/12 05:29:40 DEBUG : dir: reading active writers 2022/06/12 05:29:40 DEBUG : file1: reading active writers 2022/06/12 05:29:40 DEBUG : file1: active writers 1 2022/06/12 05:29:40 DEBUG : file2: reading active writers 2022/06/12 05:29:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:41 DEBUG : dir: Looking for writers 2022/06/12 05:29:41 DEBUG : file1: reading active writers 2022/06/12 05:29:41 DEBUG : : Looking for writers 2022/06/12 05:29:41 DEBUG : dir: reading active writers 2022/06/12 05:29:41 DEBUG : file1: reading active writers 2022/06/12 05:29:41 DEBUG : file1: active writers 1 2022/06/12 05:29:41 DEBUG : file2: reading active writers 2022/06/12 05:29:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:42 DEBUG : dir: Looking for writers 2022/06/12 05:29:42 DEBUG : file1: reading active writers 2022/06/12 05:29:42 DEBUG : : Looking for writers 2022/06/12 05:29:42 DEBUG : dir: reading active writers 2022/06/12 05:29:42 DEBUG : file1: reading active writers 2022/06/12 05:29:42 DEBUG : file1: active writers 1 2022/06/12 05:29:42 DEBUG : file2: reading active writers 2022/06/12 05:29:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:43 DEBUG : dir: Looking for writers 2022/06/12 05:29:43 DEBUG : file1: reading active writers 2022/06/12 05:29:43 DEBUG : : Looking for writers 2022/06/12 05:29:43 DEBUG : file2: reading active writers 2022/06/12 05:29:43 DEBUG : dir: reading active writers 2022/06/12 05:29:43 DEBUG : file1: reading active writers 2022/06/12 05:29:43 DEBUG : file1: active writers 1 2022/06/12 05:29:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:44 DEBUG : dir: Looking for writers 2022/06/12 05:29:44 DEBUG : file1: reading active writers 2022/06/12 05:29:44 DEBUG : : Looking for writers 2022/06/12 05:29:44 DEBUG : dir: reading active writers 2022/06/12 05:29:44 DEBUG : file1: reading active writers 2022/06/12 05:29:44 DEBUG : file1: active writers 1 2022/06/12 05:29:44 DEBUG : file2: reading active writers 2022/06/12 05:29:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:45 DEBUG : dir: Looking for writers 2022/06/12 05:29:45 DEBUG : file1: reading active writers 2022/06/12 05:29:45 DEBUG : : Looking for writers 2022/06/12 05:29:45 DEBUG : file2: reading active writers 2022/06/12 05:29:45 DEBUG : dir: reading active writers 2022/06/12 05:29:45 DEBUG : file1: reading active writers 2022/06/12 05:29:45 DEBUG : file1: active writers 1 2022/06/12 05:29:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:46 DEBUG : dir: Looking for writers 2022/06/12 05:29:46 DEBUG : file1: reading active writers 2022/06/12 05:29:46 DEBUG : : Looking for writers 2022/06/12 05:29:46 DEBUG : dir: reading active writers 2022/06/12 05:29:46 DEBUG : file1: reading active writers 2022/06/12 05:29:46 DEBUG : file1: active writers 1 2022/06/12 05:29:46 DEBUG : file2: reading active writers 2022/06/12 05:29:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:47 DEBUG : dir: Looking for writers 2022/06/12 05:29:47 DEBUG : file1: reading active writers 2022/06/12 05:29:47 DEBUG : : Looking for writers 2022/06/12 05:29:47 DEBUG : dir: reading active writers 2022/06/12 05:29:47 DEBUG : file1: reading active writers 2022/06/12 05:29:47 DEBUG : file1: active writers 1 2022/06/12 05:29:47 DEBUG : file2: reading active writers 2022/06/12 05:29:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:48 DEBUG : dir: Looking for writers 2022/06/12 05:29:48 DEBUG : file1: reading active writers 2022/06/12 05:29:48 DEBUG : : Looking for writers 2022/06/12 05:29:48 DEBUG : dir: reading active writers 2022/06/12 05:29:48 DEBUG : file1: reading active writers 2022/06/12 05:29:48 DEBUG : file1: active writers 1 2022/06/12 05:29:48 DEBUG : file2: reading active writers 2022/06/12 05:29:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:49 DEBUG : dir: Looking for writers 2022/06/12 05:29:49 DEBUG : file1: reading active writers 2022/06/12 05:29:49 DEBUG : : Looking for writers 2022/06/12 05:29:49 DEBUG : file2: reading active writers 2022/06/12 05:29:49 DEBUG : dir: reading active writers 2022/06/12 05:29:49 DEBUG : file1: reading active writers 2022/06/12 05:29:49 DEBUG : file1: active writers 1 2022/06/12 05:29:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:50 DEBUG : dir: Looking for writers 2022/06/12 05:29:50 DEBUG : file1: reading active writers 2022/06/12 05:29:50 DEBUG : : Looking for writers 2022/06/12 05:29:50 DEBUG : dir: reading active writers 2022/06/12 05:29:50 DEBUG : file1: reading active writers 2022/06/12 05:29:50 DEBUG : file1: active writers 1 2022/06/12 05:29:50 DEBUG : file2: reading active writers 2022/06/12 05:29:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:51 DEBUG : dir: Looking for writers 2022/06/12 05:29:51 DEBUG : file1: reading active writers 2022/06/12 05:29:51 DEBUG : : Looking for writers 2022/06/12 05:29:51 DEBUG : dir: reading active writers 2022/06/12 05:29:51 DEBUG : file1: reading active writers 2022/06/12 05:29:51 DEBUG : file1: active writers 1 2022/06/12 05:29:51 DEBUG : file2: reading active writers 2022/06/12 05:29:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:52 DEBUG : dir: Looking for writers 2022/06/12 05:29:52 DEBUG : file1: reading active writers 2022/06/12 05:29:52 DEBUG : : Looking for writers 2022/06/12 05:29:52 DEBUG : dir: reading active writers 2022/06/12 05:29:52 DEBUG : file1: reading active writers 2022/06/12 05:29:52 DEBUG : file1: active writers 1 2022/06/12 05:29:52 DEBUG : file2: reading active writers 2022/06/12 05:29:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:53 DEBUG : dir: Looking for writers 2022/06/12 05:29:53 DEBUG : file1: reading active writers 2022/06/12 05:29:53 DEBUG : : Looking for writers 2022/06/12 05:29:53 DEBUG : dir: reading active writers 2022/06/12 05:29:53 DEBUG : file1: reading active writers 2022/06/12 05:29:53 DEBUG : file1: active writers 1 2022/06/12 05:29:53 DEBUG : file2: reading active writers 2022/06/12 05:29:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:54 DEBUG : dir: Looking for writers 2022/06/12 05:29:54 DEBUG : file1: reading active writers 2022/06/12 05:29:54 DEBUG : : Looking for writers 2022/06/12 05:29:54 DEBUG : file2: reading active writers 2022/06/12 05:29:54 DEBUG : dir: reading active writers 2022/06/12 05:29:54 DEBUG : file1: reading active writers 2022/06/12 05:29:54 DEBUG : file1: active writers 1 2022/06/12 05:29:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:55 DEBUG : dir: Looking for writers 2022/06/12 05:29:55 DEBUG : file1: reading active writers 2022/06/12 05:29:55 DEBUG : : Looking for writers 2022/06/12 05:29:55 DEBUG : dir: reading active writers 2022/06/12 05:29:55 DEBUG : file1: reading active writers 2022/06/12 05:29:55 DEBUG : file1: active writers 1 2022/06/12 05:29:55 DEBUG : file2: reading active writers 2022/06/12 05:29:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:56 DEBUG : dir: Looking for writers 2022/06/12 05:29:56 DEBUG : file1: reading active writers 2022/06/12 05:29:56 DEBUG : : Looking for writers 2022/06/12 05:29:56 DEBUG : file2: reading active writers 2022/06/12 05:29:56 DEBUG : dir: reading active writers 2022/06/12 05:29:56 DEBUG : file1: reading active writers 2022/06/12 05:29:56 DEBUG : file1: active writers 1 2022/06/12 05:29:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:57 DEBUG : dir: Looking for writers 2022/06/12 05:29:57 DEBUG : file1: reading active writers 2022/06/12 05:29:57 DEBUG : : Looking for writers 2022/06/12 05:29:57 DEBUG : file2: reading active writers 2022/06/12 05:29:57 DEBUG : dir: reading active writers 2022/06/12 05:29:57 DEBUG : file1: reading active writers 2022/06/12 05:29:57 DEBUG : file1: active writers 1 2022/06/12 05:29:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:58 DEBUG : dir: Looking for writers 2022/06/12 05:29:58 DEBUG : file1: reading active writers 2022/06/12 05:29:58 DEBUG : : Looking for writers 2022/06/12 05:29:58 DEBUG : file1: reading active writers 2022/06/12 05:29:58 DEBUG : file1: active writers 1 2022/06/12 05:29:58 DEBUG : file2: reading active writers 2022/06/12 05:29:58 DEBUG : dir: reading active writers 2022/06/12 05:29:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/06/12 05:29:59 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache{ "dir/file1": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc00049f300 name:dir/file1 opens:0 downloaders: o:0xc00049f2c0 fd: modified:false info:{ModTime:{wall:13880512170086329975 ext:38702175092 loc:0x2be8a40} ATime:{wall:13880512170086348350 ext:38702193456 loc:0x2be8a40} Size:20 Rs:[{Pos:0 Size:20}] Fingerprint:20,2022-06-12 05:28:59.242970231 +0000 UTC Dirty:false} writeBackID:3 pendingAccesses:0 beingReset:false}, "file1": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc0005cca00 name:file1 opens:0 downloaders:0xc000900c60 o:0xc0005ccbc0 fd: modified:true info:{ModTime:{wall:13880512202470861335 ext:68874451723 loc:0x2be8a40} ATime:{wall:13880512202470861335 ext:68874451723 loc:0x2be8a40} Size:0 Rs:[] Fingerprint: Dirty:false} writeBackID:1 pendingAccesses:0 beingReset:false}, "file2": &{c:0xc00017f2c0 mu:{state:0 sema:0} cond:0xc0008f6a00 name:file2 opens:0 downloaders: o:0xc0008f6b80 fd: modified:false info:{ModTime:{wall:13880512129909200752 ext:1327235181 loc:0x2be8a40} ATime:{wall:13880512129909322949 ext:1327357378 loc:0x2be8a40} Size:0 Rs:[] Fingerprint:0,2022-06-12 05:28:21.86803032 +0000 UTC Dirty:false} writeBackID:2 pendingAccesses:0 beingReset:false}, } 2022/06/12 05:29:59 DEBUG : >WaitForWriters: 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestRWFileModTimeWithOpenWriters (30.00s) === RUN TestVFSNew vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:137 Error: Not equal: expected: 0 actual : 2 Test: TestVFSNew run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:147 Error: Not equal: expected: 1 actual : 2 Test: TestVFSNew 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:154 Error: Not equal: expected: 1 actual : 2 Test: TestVFSNew vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:159 Error: Not equal: expected: 1 actual : 2 Test: TestVFSNew 2022/06/12 05:29:59 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:29:59 DEBUG : fil/a/b: Looking for writers 2022/06/12 05:29:59 DEBUG : fil/a: Looking for writers 2022/06/12 05:29:59 DEBUG : b: reading active writers 2022/06/12 05:29:59 DEBUG : fil: Looking for writers 2022/06/12 05:29:59 DEBUG : a: reading active writers 2022/06/12 05:29:59 DEBUG : dir: Looking for writers 2022/06/12 05:29:59 DEBUG : : Looking for writers 2022/06/12 05:29:59 DEBUG : dir: reading active writers 2022/06/12 05:29:59 DEBUG : fil: reading active writers 2022/06/12 05:29:59 DEBUG : >WaitForWriters: 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:163 Error: Not equal: expected: 0 actual : 2 Test: TestVFSNew --- FAIL: TestVFSNew (0.01s) === RUN TestVFSStatParent run.go:181: Remote "hdfs://127.0.0.1:8020", Local "Local file system at /tmp/rclone571626698", Modify Window "1s" 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: Re-using VFS from active cache 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: update [/rclone-test-meyiwov9mubehik1mequron8/file1] run.go:287: Failed to put "file1" to "hdfs://127.0.0.1:8020": create /rclone-test-meyiwov9mubehik1mequron8/file1: replication in progress 2022/06/12 05:29:59 DEBUG : WaitForWriters: timeout=30s 2022/06/12 05:29:59 DEBUG : fil/a/b: Looking for writers 2022/06/12 05:29:59 DEBUG : fil/a: Looking for writers 2022/06/12 05:29:59 DEBUG : b: reading active writers 2022/06/12 05:29:59 DEBUG : fil: Looking for writers 2022/06/12 05:29:59 DEBUG : a: reading active writers 2022/06/12 05:29:59 DEBUG : dir: Looking for writers 2022/06/12 05:29:59 DEBUG : : Looking for writers 2022/06/12 05:29:59 DEBUG : dir: reading active writers 2022/06/12 05:29:59 DEBUG : fil: reading active writers 2022/06/12 05:29:59 DEBUG : >WaitForWriters: 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: list [/rclone-test-meyiwov9mubehik1mequron8] --- FAIL: TestVFSStatParent (0.03s) FAIL 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: Purge remote 2022/06/12 05:29:59 DEBUG : hdfs://127.0.0.1:8020: purge [/rclone-test-meyiwov9mubehik1mequron8] "./vfs.test -test.v -test.timeout 1h0m0s -remote TestHdfs: -verbose -test.run '^(TestDirForgetPath|TestDirOpen|TestDirRemoveName|TestDirWalk|TestFileRename|TestFileSetModTime|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleReleaseWrite|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestVFSNew|TestVFSStatParent)$/^(cache=full,open=true,write=true|cache=off,open=false,write=false|cache=off,open=true,write=false|off,forceCache=false)$'" - Finished ERROR in 1m38.927737871s (try 2/5): exit status 1: Failed [TestDirForgetPath TestDirRemoveName TestRcGetVFS TestRWFileHandleMethodsRead TestRWFileHandleFlushRead TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestRWFileHandleFlushWrite TestRWFileHandleReleaseWrite TestRWFileHandleSizeCreateExisting TestRWFileHandleSizeCreateNew TestRWFileModTimeWithOpenWriters TestVFSNew TestVFSStatParent]