"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestVFSMkdir|TestVFSMkdirAll|TestVFSOpenFile|TestVFSRename|TestVFSStatParent|TestVFSStatfs|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$'" - Starting (try 2/5) 2024/12/21 02:34:14 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-cabewag0keyo" 2024/12/21 02:34:14 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/12/21 02:34:14 DEBUG : Creating backend with remote "/tmp/rclone2564268286" === RUN TestVFSStatParent run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:34:14 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:34:14 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:34:22 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:34:22 DEBUG : dir: Looking for writers 2024/12/21 02:34:22 DEBUG : : Looking for writers 2024/12/21 02:34:22 DEBUG : dir: reading active writers 2024/12/21 02:34:22 DEBUG : file1: reading active writers 2024/12/21 02:34:22 DEBUG : >WaitForWriters: --- PASS: TestVFSStatParent (12.67s) === RUN TestVFSOpenFile run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:34:27 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:34:27 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:34:33 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2024/12/21 02:34:33 DEBUG : file1: Open: flags=O_RDONLY 2024/12/21 02:34:33 DEBUG : file1: >Open: fd=file1 (r), err= 2024/12/21 02:34:33 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2024/12/21 02:34:33 DEBUG : dir: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2024/12/21 02:34:33 DEBUG : dir: >OpenFile: fd=dir/ (r), err= 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: >OpenFile: fd=, err=file does not exist 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:34:33 DEBUG : dir: Added virtual directory entry vAddFile: "new_file.txt" 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: >Open: fd=dir/new_file.txt (w), err= 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: >OpenFile: fd=dir/new_file.txt (w), err= 2024/12/21 02:34:33 DEBUG : dir: Added virtual directory entry vAddFile: "new_file.txt" 2024/12/21 02:34:33 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (0 bytes), uploading instead of streaming 2024/12/21 02:34:33 ERROR : dir/new_file.txt: WriteFileHandle.New Rcat failed: can't upload empty files to this remote 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: Remove: 2024/12/21 02:34:33 DEBUG : dir: Added virtual directory entry vDel: "new_file.txt" 2024/12/21 02:34:33 DEBUG : dir/new_file.txt: >Remove: err= 2024/12/21 02:34:33 DEBUG : not found/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:34:33 DEBUG : not found/new_file.txt: >OpenFile: fd=, err=file does not exist 2024/12/21 02:34:33 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:34:33 DEBUG : dir: Looking for writers 2024/12/21 02:34:33 DEBUG : file2: reading active writers 2024/12/21 02:34:33 DEBUG : : Looking for writers 2024/12/21 02:34:33 DEBUG : dir: reading active writers 2024/12/21 02:34:33 DEBUG : file1: reading active writers 2024/12/21 02:34:33 DEBUG : >WaitForWriters: --- PASS: TestVFSOpenFile (11.35s) === RUN TestVFSRename run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:34:38 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:34:38 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream vfs_test.go:292: skip as can't rename files 2024/12/21 02:34:38 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:34:38 DEBUG : : Looking for writers 2024/12/21 02:34:38 DEBUG : >WaitForWriters: --- SKIP: TestVFSRename (0.42s) === RUN TestVFSStatfs run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:34:39 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:34:39 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:34:39 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:34:39 DEBUG : : Looking for writers 2024/12/21 02:34:39 DEBUG : >WaitForWriters: --- PASS: TestVFSStatfs (0.44s) === RUN TestVFSMkdir run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:34:39 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:34:39 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:34:40 DEBUG : : Added virtual directory entry vAddDir: "/" 2024/12/21 02:34:41 DEBUG : : Added virtual directory entry vAddDir: "a" 2024/12/21 02:34:44 DEBUG : : Added virtual directory entry vAddDir: "b" 2024/12/21 02:34:46 DEBUG : : Added virtual directory entry vAddDir: "c" 2024/12/21 02:34:48 DEBUG : : Added virtual directory entry vAddDir: "d" 2024/12/21 02:34:49 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:34:49 DEBUG : : Looking for writers 2024/12/21 02:34:49 DEBUG : a: Looking for writers 2024/12/21 02:34:49 DEBUG : b: Looking for writers 2024/12/21 02:34:49 DEBUG : c: Looking for writers 2024/12/21 02:34:49 DEBUG : d: Looking for writers 2024/12/21 02:34:49 DEBUG : : Looking for writers 2024/12/21 02:34:49 DEBUG : b: reading active writers 2024/12/21 02:34:49 DEBUG : c: reading active writers 2024/12/21 02:34:49 DEBUG : d: reading active writers 2024/12/21 02:34:49 DEBUG : /: reading active writers 2024/12/21 02:34:49 DEBUG : a: reading active writers 2024/12/21 02:34:49 DEBUG : >WaitForWriters: --- PASS: TestVFSMkdir (17.46s) === RUN TestVFSMkdirAll run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:34:57 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:34:57 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:34:59 DEBUG : : Added virtual directory entry vAddDir: "a" 2024/12/21 02:35:01 DEBUG : a: Added virtual directory entry vAddDir: "b" 2024/12/21 02:35:02 DEBUG : a/b: Added virtual directory entry vAddDir: "c" 2024/12/21 02:35:04 DEBUG : a/b/c: Added virtual directory entry vAddDir: "d" 2024/12/21 02:35:07 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:35:07 DEBUG : a/b/c/d: Looking for writers 2024/12/21 02:35:07 DEBUG : a/b/c: Looking for writers 2024/12/21 02:35:07 DEBUG : d: reading active writers 2024/12/21 02:35:07 DEBUG : a/b: Looking for writers 2024/12/21 02:35:07 DEBUG : c: reading active writers 2024/12/21 02:35:07 DEBUG : a: Looking for writers 2024/12/21 02:35:07 DEBUG : b: reading active writers 2024/12/21 02:35:07 DEBUG : : Looking for writers 2024/12/21 02:35:07 DEBUG : a: reading active writers 2024/12/21 02:35:07 DEBUG : >WaitForWriters: --- PASS: TestVFSMkdirAll (18.24s) === RUN TestWriteFileHandleMethods run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:35:15 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:35:15 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:35:15 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:15 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:15 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:15 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:15 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:15 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:15 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2024/12/21 02:35:15 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2024/12/21 02:35:15 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2024/12/21 02:35:15 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (5 bytes), uploading instead of streaming 2024/12/21 02:35:18 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2024/12/21 02:35:18 DEBUG : file1: Size of src and dst objects identical 2024/12/21 02:35:18 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:19 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:19 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:19 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2024/12/21 02:35:19 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2024/12/21 02:35:19 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2024/12/21 02:35:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (0 bytes), uploading instead of streaming 2024/12/21 02:35:19 ERROR : file1: WriteFileHandle.New Rcat failed: can't upload empty files to this remote 2024/12/21 02:35:19 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2024/12/21 02:35:19 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2024/12/21 02:35:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:19 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (7 bytes), uploading instead of streaming 2024/12/21 02:35:19 DEBUG : file1: Update: removing old file 2024/12/21 02:35:22 DEBUG : file1: Size of src and dst objects identical 2024/12/21 02:35:22 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:22 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:35:22 DEBUG : : Looking for writers 2024/12/21 02:35:22 DEBUG : file1: reading active writers 2024/12/21 02:35:22 DEBUG : >WaitForWriters: --- PASS: TestWriteFileHandleMethods (8.76s) === RUN TestWriteFileHandleWriteAt run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:35:24 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:35:24 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:35:24 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:24 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:24 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:24 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:24 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:24 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:24 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2024/12/21 02:35:25 DEBUG : file1: aborting in-sequence write wait, off=100 2024/12/21 02:35:25 DEBUG : file1: failed to wait for in-sequence write to 100 2024/12/21 02:35:25 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2024/12/21 02:35:25 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (11 bytes), uploading instead of streaming 2024/12/21 02:35:27 DEBUG : file1: Size of src and dst objects identical 2024/12/21 02:35:27 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:27 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor 2024/12/21 02:35:27 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:35:27 DEBUG : : Looking for writers 2024/12/21 02:35:27 DEBUG : file1: reading active writers 2024/12/21 02:35:27 DEBUG : >WaitForWriters: --- PASS: TestWriteFileHandleWriteAt (5.28s) === RUN TestWriteFileHandleFlush run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:35:29 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:35:29 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:35:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:29 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:29 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:29 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:29 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2024/12/21 02:35:29 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:29 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (5 bytes), uploading instead of streaming 2024/12/21 02:35:31 DEBUG : file1: Size of src and dst objects identical 2024/12/21 02:35:31 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:31 DEBUG : file1: WriteFileHandle.Flush nothing to do 2024/12/21 02:35:31 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:35:31 DEBUG : : Looking for writers 2024/12/21 02:35:31 DEBUG : file1: reading active writers 2024/12/21 02:35:31 DEBUG : >WaitForWriters: --- PASS: TestWriteFileHandleFlush (4.07s) === RUN TestWriteFileHandleRelease run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:35:33 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:35:33 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:35:33 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:33 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:33 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:33 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:33 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:33 DEBUG : file1: WriteFileHandle.Release closing 2024/12/21 02:35:33 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:33 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (0 bytes), uploading instead of streaming 2024/12/21 02:35:33 ERROR : file1: WriteFileHandle.New Rcat failed: can't upload empty files to this remote 2024/12/21 02:35:33 DEBUG : file1: Remove: 2024/12/21 02:35:33 DEBUG : : Added virtual directory entry vDel: "file1" 2024/12/21 02:35:33 DEBUG : file1: >Remove: err= 2024/12/21 02:35:33 ERROR : file1: WriteFileHandle.Release error: can't upload empty files to this remote write_test.go:276: skipping test: can't upload empty files to this remote 2024/12/21 02:35:33 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:35:33 DEBUG : : Looking for writers 2024/12/21 02:35:33 DEBUG : >WaitForWriters: --- PASS: TestWriteFileHandleRelease (0.65s) === RUN TestWriteFileModTimeWithOpenWriters run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:35:34 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:35:34 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:35:34 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:35:34 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:35:34 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:35:34 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:35:34 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:35:37 DEBUG : Can set mod time: false write_test.go:321: can't set mod time 2024/12/21 02:35:37 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:35:37 DEBUG : : Looking for writers 2024/12/21 02:35:37 DEBUG : file1: reading active writers 2024/12/21 02:35:37 DEBUG : file1: active writers 1 2024/12/21 02:35:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2024/12/21 02:35:37 DEBUG : : Looking for writers 2024/12/21 02:35:37 DEBUG : file1: reading active writers 2024/12/21 02:35:37 DEBUG : file1: active writers 1 2024/12/21 02:35:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2024/12/21 02:35:37 DEBUG : : Looking for writers 2024/12/21 02:35:37 DEBUG : file1: reading active writers 2024/12/21 02:35:37 DEBUG : file1: active writers 1 2024/12/21 02:35:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2024/12/21 02:35:38 DEBUG : : Looking for writers 2024/12/21 02:35:38 DEBUG : file1: reading active writers 2024/12/21 02:35:38 DEBUG : file1: active writers 1 2024/12/21 02:35:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2024/12/21 02:35:38 DEBUG : : Looking for writers 2024/12/21 02:35:38 DEBUG : file1: reading active writers 2024/12/21 02:35:38 DEBUG : file1: active writers 1 2024/12/21 02:35:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2024/12/21 02:35:38 DEBUG : : Looking for writers 2024/12/21 02:35:38 DEBUG : file1: reading active writers 2024/12/21 02:35:38 DEBUG : file1: active writers 1 2024/12/21 02:35:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2024/12/21 02:35:38 DEBUG : : Looking for writers 2024/12/21 02:35:38 DEBUG : file1: reading active writers 2024/12/21 02:35:38 DEBUG : file1: active writers 1 2024/12/21 02:35:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2024/12/21 02:35:39 DEBUG : : Looking for writers 2024/12/21 02:35:39 DEBUG : file1: reading active writers 2024/12/21 02:35:39 DEBUG : file1: active writers 1 2024/12/21 02:35:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:40 DEBUG : : Looking for writers 2024/12/21 02:35:40 DEBUG : file1: reading active writers 2024/12/21 02:35:40 DEBUG : file1: active writers 1 2024/12/21 02:35:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:41 DEBUG : : Looking for writers 2024/12/21 02:35:41 DEBUG : file1: reading active writers 2024/12/21 02:35:41 DEBUG : file1: active writers 1 2024/12/21 02:35:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:42 DEBUG : : Looking for writers 2024/12/21 02:35:42 DEBUG : file1: reading active writers 2024/12/21 02:35:42 DEBUG : file1: active writers 1 2024/12/21 02:35:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:43 DEBUG : : Looking for writers 2024/12/21 02:35:43 DEBUG : file1: reading active writers 2024/12/21 02:35:43 DEBUG : file1: active writers 1 2024/12/21 02:35:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:44 DEBUG : : Looking for writers 2024/12/21 02:35:44 DEBUG : file1: reading active writers 2024/12/21 02:35:44 DEBUG : file1: active writers 1 2024/12/21 02:35:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:45 DEBUG : : Looking for writers 2024/12/21 02:35:45 DEBUG : file1: reading active writers 2024/12/21 02:35:45 DEBUG : file1: active writers 1 2024/12/21 02:35:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:46 DEBUG : : Looking for writers 2024/12/21 02:35:46 DEBUG : file1: reading active writers 2024/12/21 02:35:46 DEBUG : file1: active writers 1 2024/12/21 02:35:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:47 DEBUG : : Looking for writers 2024/12/21 02:35:47 DEBUG : file1: reading active writers 2024/12/21 02:35:47 DEBUG : file1: active writers 1 2024/12/21 02:35:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:48 DEBUG : : Looking for writers 2024/12/21 02:35:48 DEBUG : file1: reading active writers 2024/12/21 02:35:48 DEBUG : file1: active writers 1 2024/12/21 02:35:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:49 DEBUG : : Looking for writers 2024/12/21 02:35:49 DEBUG : file1: reading active writers 2024/12/21 02:35:49 DEBUG : file1: active writers 1 2024/12/21 02:35:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:50 DEBUG : : Looking for writers 2024/12/21 02:35:50 DEBUG : file1: reading active writers 2024/12/21 02:35:50 DEBUG : file1: active writers 1 2024/12/21 02:35:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:51 DEBUG : : Looking for writers 2024/12/21 02:35:51 DEBUG : file1: reading active writers 2024/12/21 02:35:51 DEBUG : file1: active writers 1 2024/12/21 02:35:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:52 DEBUG : : Looking for writers 2024/12/21 02:35:52 DEBUG : file1: reading active writers 2024/12/21 02:35:52 DEBUG : file1: active writers 1 2024/12/21 02:35:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:53 DEBUG : : Looking for writers 2024/12/21 02:35:53 DEBUG : file1: reading active writers 2024/12/21 02:35:53 DEBUG : file1: active writers 1 2024/12/21 02:35:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:54 DEBUG : : Looking for writers 2024/12/21 02:35:54 DEBUG : file1: reading active writers 2024/12/21 02:35:54 DEBUG : file1: active writers 1 2024/12/21 02:35:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:55 DEBUG : : Looking for writers 2024/12/21 02:35:55 DEBUG : file1: reading active writers 2024/12/21 02:35:55 DEBUG : file1: active writers 1 2024/12/21 02:35:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:56 DEBUG : : Looking for writers 2024/12/21 02:35:56 DEBUG : file1: reading active writers 2024/12/21 02:35:56 DEBUG : file1: active writers 1 2024/12/21 02:35:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:57 DEBUG : : Looking for writers 2024/12/21 02:35:57 DEBUG : file1: reading active writers 2024/12/21 02:35:57 DEBUG : file1: active writers 1 2024/12/21 02:35:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:58 DEBUG : : Looking for writers 2024/12/21 02:35:58 DEBUG : file1: reading active writers 2024/12/21 02:35:58 DEBUG : file1: active writers 1 2024/12/21 02:35:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:35:59 DEBUG : : Looking for writers 2024/12/21 02:35:59 DEBUG : file1: reading active writers 2024/12/21 02:35:59 DEBUG : file1: active writers 1 2024/12/21 02:35:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:00 DEBUG : : Looking for writers 2024/12/21 02:36:00 DEBUG : file1: reading active writers 2024/12/21 02:36:00 DEBUG : file1: active writers 1 2024/12/21 02:36:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:01 DEBUG : : Looking for writers 2024/12/21 02:36:01 DEBUG : file1: reading active writers 2024/12/21 02:36:01 DEBUG : file1: active writers 1 2024/12/21 02:36:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:02 DEBUG : : Looking for writers 2024/12/21 02:36:02 DEBUG : file1: reading active writers 2024/12/21 02:36:02 DEBUG : file1: active writers 1 2024/12/21 02:36:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:03 DEBUG : : Looking for writers 2024/12/21 02:36:03 DEBUG : file1: reading active writers 2024/12/21 02:36:03 DEBUG : file1: active writers 1 2024/12/21 02:36:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:04 DEBUG : : Looking for writers 2024/12/21 02:36:04 DEBUG : file1: reading active writers 2024/12/21 02:36:04 DEBUG : file1: active writers 1 2024/12/21 02:36:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:05 DEBUG : : Looking for writers 2024/12/21 02:36:05 DEBUG : file1: reading active writers 2024/12/21 02:36:05 DEBUG : file1: active writers 1 2024/12/21 02:36:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:06 DEBUG : : Looking for writers 2024/12/21 02:36:06 DEBUG : file1: reading active writers 2024/12/21 02:36:06 DEBUG : file1: active writers 1 2024/12/21 02:36:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:07 DEBUG : : Looking for writers 2024/12/21 02:36:07 DEBUG : file1: reading active writers 2024/12/21 02:36:07 DEBUG : file1: active writers 1 2024/12/21 02:36:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2024/12/21 02:36:07 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2024/12/21 02:36:07 DEBUG : >WaitForWriters: --- SKIP: TestWriteFileModTimeWithOpenWriters (34.26s) === RUN TestFileReadAtZeroLength run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:36:08 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:36:08 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:36:08 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:36:08 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:36:08 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:36:08 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:36:08 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:36:08 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:36:08 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (0 bytes), uploading instead of streaming 2024/12/21 02:36:08 ERROR : file1: WriteFileHandle.New Rcat failed: can't upload empty files to this remote 2024/12/21 02:36:08 DEBUG : file1: Remove: 2024/12/21 02:36:08 DEBUG : : Added virtual directory entry vDel: "file1" 2024/12/21 02:36:08 DEBUG : file1: >Remove: err= write_test.go:357: skipping test: can't upload empty files to this remote 2024/12/21 02:36:08 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:36:08 DEBUG : : Looking for writers 2024/12/21 02:36:08 DEBUG : >WaitForWriters: --- PASS: TestFileReadAtZeroLength (0.65s) === RUN TestFileReadAtNonZeroLength run.go:180: Remote "Linkbox root 'rclone-test-cabewag0keyo'", Local "Local file system at /tmp/rclone2564268286", Modify Window "876000h0m0s" 2024/12/21 02:36:09 INFO : Linkbox root 'rclone-test-cabewag0keyo': poll-interval is not supported by this remote 2024/12/21 02:36:09 NOTICE: Linkbox root 'rclone-test-cabewag0keyo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2024/12/21 02:36:09 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 02:36:09 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2024/12/21 02:36:09 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:36:09 DEBUG : file1: >Open: fd=file1 (w), err= 2024/12/21 02:36:09 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2024/12/21 02:36:09 DEBUG : : Added virtual directory entry vAddFile: "file1" 2024/12/21 02:36:09 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': File to upload is small (100 bytes), uploading instead of streaming 2024/12/21 02:36:10 ERROR : file1: WriteFileHandle.New Rcat failed: update err in uploading file: HTTP error 403 (403 Forbidden) returned body: "SignatureDoesNotMatchThe request signature we calculated does not match the signature you provided. Check your key and signing method.00000193E71282D0B11933DB6A81AAA0Z9v+cC1sRnaWw6x0vi8pxxYA0YVnKxbYHUPAFpnxkX8sLV44u5b02Z+ailn2wCnRZAUGMKBTPLNX0FBOCABGOXCaXu9X0m4NIAENs3u+dFAgMk8=PUT\n\n\n1734755769\nx-amz-cf-id:fHXMRdryMNjhgSTkigBY41QVR7c6rtD6rtkCf5jiNTEASBw7JctwDw==\n/ozadj95fviptne/tmp/recycle/1d/user/922460207/19e0e5348ffa41fa645b254e5a0aa1c0_10050 55 54 0a 0a 0a 31 37 33 34 37 35 35 37 36 39 0a 78 2d 61 6d 7a 2d 63 66 2d 69 64 3a 66 48 58 4d 52 64 72 79 4d 4e 6a 68 67 53 54 6b 69 67 42 59 34 31 51 56 52 37 63 36 72 74 44 36 72 74 6b 43 66 35 6a 69 4e 54 45 41 53 42 77 37 4a 63 74 77 44 77 3d 3d 0a 2f 6f 7a 61 64 6a 39 35 66 76 69 70 74 6e 65 2f 74 6d 70 2f 72 65 63 79 63 6c 65 2f 31 64 2f 75 73 65 72 2f 39 32 32 34 36 30 32 30 37 2f 31 39 65 30 65 35 33 34 38 66 66 61 34 31 66 61 36 34 35 62 32 35 34 65 35 61 30 61 61 31 63 30 5f 31 30 30" 2024/12/21 02:36:10 DEBUG : file1: Remove: 2024/12/21 02:36:10 DEBUG : : Added virtual directory entry vDel: "file1" 2024/12/21 02:36:10 DEBUG : file1: >Remove: err= write_test.go:360: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:360 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:384 Error: Received unexpected error: update err in uploading file: HTTP error 403 (403 Forbidden) returned body: "SignatureDoesNotMatchThe request signature we calculated does not match the signature you provided. Check your key and signing method.00000193E71282D0B11933DB6A81AAA0Z9v+cC1sRnaWw6x0vi8pxxYA0YVnKxbYHUPAFpnxkX8sLV44u5b02Z+ailn2wCnRZAUGMKBTPLNX0FBOCABGOXCaXu9X0m4NIAENs3u+dFAgMk8=PUT\n\n\n1734755769\nx-amz-cf-id:fHXMRdryMNjhgSTkigBY41QVR7c6rtD6rtkCf5jiNTEASBw7JctwDw==\n/ozadj95fviptne/tmp/recycle/1d/user/922460207/19e0e5348ffa41fa645b254e5a0aa1c0_10050 55 54 0a 0a 0a 31 37 33 34 37 35 35 37 36 39 0a 78 2d 61 6d 7a 2d 63 66 2d 69 64 3a 66 48 58 4d 52 64 72 79 4d 4e 6a 68 67 53 54 6b 69 67 42 59 34 31 51 56 52 37 63 36 72 74 44 36 72 74 6b 43 66 35 6a 69 4e 54 45 41 53 42 77 37 4a 63 74 77 44 77 3d 3d 0a 2f 6f 7a 61 64 6a 39 35 66 76 69 70 74 6e 65 2f 74 6d 70 2f 72 65 63 79 63 6c 65 2f 31 64 2f 75 73 65 72 2f 39 32 32 34 36 30 32 30 37 2f 31 39 65 30 65 35 33 34 38 66 66 61 34 31 66 61 36 34 35 62 32 35 34 65 35 61 30 61 61 31 63 30 5f 31 30 30" Test: TestFileReadAtNonZeroLength 2024/12/21 02:36:10 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2024/12/21 02:36:10 DEBUG : file1: >OpenFile: fd=, err=file does not exist write_test.go:365: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:365 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:384 Error: Received unexpected error: file does not exist Test: TestFileReadAtNonZeroLength 2024/12/21 02:36:10 DEBUG : WaitForWriters: timeout=30s 2024/12/21 02:36:10 DEBUG : : Looking for writers 2024/12/21 02:36:10 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (1.83s) FAIL 2024/12/21 02:36:10 DEBUG : Linkbox root 'rclone-test-cabewag0keyo': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestVFSMkdir|TestVFSMkdirAll|TestVFSOpenFile|TestVFSRename|TestVFSStatParent|TestVFSStatfs|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$'" - Finished ERROR in 1m57.91953067s (try 2/5): exit status 1: Failed [TestFileReadAtNonZeroLength]