"./vfs.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^(TestDirHandleMethods|TestRWFileHandleSizeCreateNew)$'" - Starting (try 2/5)
2024/11/10 04:39:09 DEBUG : Creating backend with remote "TestGoFile:rclone-test-ruvuqid9kagu"
2024/11/10 04:39:09 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/11/10 04:39:09 DEBUG : Creating backend with remote "/tmp/rclone3094945913"
=== RUN   TestDirHandleMethods
    run.go:180: Remote "gofile root 'rclone-test-ruvuqid9kagu'", Local "Local file system at /tmp/rclone3094945913", Modify Window "1s"
2024/11/10 04:39:09 INFO  : gofile root 'rclone-test-ruvuqid9kagu': poll-interval is not supported by this remote
2024/11/10 04:39:12 DEBUG : Upload server store1 (eu) responded in 123.202698ms
2024/11/10 04:39:12 DEBUG : Upload server store4 (eu) responded in 126.633239ms
2024/11/10 04:39:12 DEBUG : dir/file1: Using upload server store4 (eu)
2024/11/10 04:39:12 DEBUG : WaitForWriters: timeout=30s
2024/11/10 04:39:12 DEBUG : dir: Looking for writers
2024/11/10 04:39:12 DEBUG : : Looking for writers
2024/11/10 04:39:12 DEBUG : dir: reading active writers
2024/11/10 04:39:12 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (3.86s)
=== RUN   TestRWFileHandleSizeCreateNew
    run.go:180: Remote "gofile root 'rclone-test-ruvuqid9kagu'", Local "Local file system at /tmp/rclone3094945913", Modify Window "1s"
2024/11/10 04:39:13 INFO  : gofile root 'rclone-test-ruvuqid9kagu': poll-interval is not supported by this remote
2024/11/10 04:39:13 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/11/10 04:39:13 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestGoFile/rclone-test-ruvuqid9kagu"
2024/11/10 04:39:13 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestGoFile/rclone-test-ruvuqid9kagu"
2024/11/10 04:39:13 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestGoFile/rclone-test-ruvuqid9kagu"
2024/11/10 04:39:13 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/11/10 04:39:13 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestGoFile/rclone-test-ruvuqid9kagu" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestGoFile/rclone-test-ruvuqid9kagu"
2024/11/10 04:39:13 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestGoFile/rclone-test-ruvuqid9kagu"
2024/11/10 04:39:13 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/11/10 04:39:13 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestGoFile/rclone-test-ruvuqid9kagu" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestGoFile/rclone-test-ruvuqid9kagu"
2024/11/10 04:39:13 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2024/11/10 04:39:13 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/11/10 04:39:13 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2024/11/10 04:39:13 DEBUG : file1: newRWFileHandle: 
2024/11/10 04:39:13 DEBUG : file1(0xc00075c340): openPending: 
2024/11/10 04:39:13 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct)
2024/11/10 04:39:13 DEBUG : : Added virtual directory entry vAddFile: "file1"
2024/11/10 04:39:13 DEBUG : file1(0xc00075c340): >openPending: err=<nil>
2024/11/10 04:39:13 DEBUG : file1: >newRWFileHandle: err=<nil>
2024/11/10 04:39:13 DEBUG : : Added virtual directory entry vAddFile: "file1"
2024/11/10 04:39:13 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2024/11/10 04:39:13 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2024/11/10 04:39:13 DEBUG : file1(0xc00075c340): _writeAt: size=5, off=0
2024/11/10 04:39:13 DEBUG : file1(0xc00075c340): >_writeAt: n=5, err=<nil>
2024/11/10 04:39:13 DEBUG : file1(0xc00075c340): close: 
2024/11/10 04:39:13 DEBUG : file1: vfs cache: setting modification time to 2024-11-10 04:39:13.868076555 +0000 UTC m=+4.801476324
2024/11/10 04:39:13 INFO  : file1: vfs cache: queuing for upload in 100ms
2024/11/10 04:39:13 DEBUG : file1(0xc00075c340): >close: err=<nil>
2024/11/10 04:39:13 DEBUG : WaitForWriters: timeout=30s
2024/11/10 04:39:13 DEBUG : : Looking for writers
2024/11/10 04:39:13 DEBUG : file1: reading active writers
2024/11/10 04:39:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/11/10 04:39:13 DEBUG : : Looking for writers
2024/11/10 04:39:13 DEBUG : file1: reading active writers
2024/11/10 04:39:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/11/10 04:39:13 DEBUG : : Looking for writers
2024/11/10 04:39:13 DEBUG : file1: reading active writers
2024/11/10 04:39:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/11/10 04:39:13 DEBUG : : Looking for writers
2024/11/10 04:39:13 DEBUG : file1: reading active writers
2024/11/10 04:39:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/11/10 04:39:13 DEBUG : file1: vfs cache: starting upload
2024/11/10 04:39:14 DEBUG : : Looking for writers
2024/11/10 04:39:14 DEBUG : file1: reading active writers
2024/11/10 04:39:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/11/10 04:39:14 DEBUG : file1: Using upload server store1 (eu)
2024/11/10 04:39:14 DEBUG : : Looking for writers
2024/11/10 04:39:14 DEBUG : file1: reading active writers
2024/11/10 04:39:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/11/10 04:39:14 DEBUG : file1: md5 = 5d41402abc4b2a76b9719d911017c592 OK
2024/11/10 04:39:14 INFO  : file1: Copied (new)
2024/11/10 04:39:14 DEBUG : file1: vfs cache: fingerprint now "5,2024-11-10 04:39:13 +0000 UTC,5d41402abc4b2a76b9719d911017c592"
2024/11/10 04:39:14 DEBUG : file1: vfs cache: writeback object to VFS layer
2024/11/10 04:39:14 DEBUG : : Added virtual directory entry vAddFile: "file1"
2024/11/10 04:39:14 INFO  : file1: vfs cache: upload succeeded try #1
2024/11/10 04:39:14 DEBUG : : Looking for writers
2024/11/10 04:39:14 DEBUG : file1: reading active writers
2024/11/10 04:39:14 DEBUG : >WaitForWriters: 
2024/11/10 04:39:14 DEBUG : vfs cache: cleaner exiting
--- PASS: TestRWFileHandleSizeCreateNew (1.37s)
PASS
2024/11/10 04:39:15 DEBUG : gofile root 'rclone-test-ruvuqid9kagu': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^(TestDirHandleMethods|TestRWFileHandleSizeCreateNew)$'" - Finished OK in 6.234087011s (try 2/5)