"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestDirFileOpen|TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileRemove|TestFileRemoveAll|TestRWFileHandleFlushRead|TestRWFileHandleMethodsRead|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek)$|^TestFileRename$/^(full,forceCache=false|minimal,forceCache=false|minimal,forceCache=true|off,forceCache=false|writes,forceCache=false|writes,forceCache=true)$|^TestFileSetModTime$/^(cache=full,open=false,write=false|cache=full,open=true,write=false|cache=full,open=true,write=true|cache=off,open=false,write=false|cache=off,open=true,write=false|cache=off,open=true,write=true)$'" - Starting (try 2/5) 2025/01/30 01:50:22 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-gosipap1tupo" 2025/01/30 01:50:22 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/01/30 01:50:22 DEBUG : Creating backend with remote "/tmp/rclone643203880" === RUN TestDirFileOpen run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:50:22 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:50:22 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:50:30 DEBUG : dir: Added virtual directory entry vAddDir: "sub" 2025/01/30 01:50:30 DEBUG : dir/sub/file0: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw- 2025/01/30 01:50:30 DEBUG : dir/sub/file0: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2025/01/30 01:50:30 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0" 2025/01/30 01:50:30 DEBUG : dir/sub/file0: >Open: fd=dir/sub/file0 (w), err= 2025/01/30 01:50:30 DEBUG : dir/sub/file0: >OpenFile: fd=dir/sub/file0 (w), err= 2025/01/30 01:50:30 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0" 2025/01/30 01:50:30 DEBUG : dir/sub/file2: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw- 2025/01/30 01:50:30 DEBUG : dir/sub/file2: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2025/01/30 01:50:30 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2" 2025/01/30 01:50:30 DEBUG : dir/sub/file2: >Open: fd=dir/sub/file2 (w), err= 2025/01/30 01:50:30 DEBUG : dir/sub/file2: >OpenFile: fd=dir/sub/file2 (w), err= 2025/01/30 01:50:30 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2" 2025/01/30 01:50:30 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': File to upload is small (12 bytes), uploading instead of streaming 2025/01/30 01:50:31 ERROR : dir/sub/file2: 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.00000194B4E717A0B0DA4A3DE8CAF516Z9v+cC1sRnaWw6x0vi8pxxYA0YVnKxbYHUPAFpnxkX8sLV44u5b02Z+ailn2wCnRZAUGMKBTPLNX0FBOCABGg3EW5NXhUJ/b4bVuB+YqxpaoyV0=PUT\n\n\n1738209030\nx-amz-cf-id:NNTzyT0UHxz5DL1sw1CxqMfaXijFkfhAzEh9kR4qzlsJFQb-SFoMhg==\n/ozadj95fviptne/tmp/recycle/1d/user/922460207/fc3ff98e8c6a0d3087d515c0473f8677_1250 55 54 0a 0a 0a 31 37 33 38 32 30 39 30 33 30 0a 78 2d 61 6d 7a 2d 63 66 2d 69 64 3a 4e 4e 54 7a 79 54 30 55 48 78 7a 35 44 4c 31 73 77 31 43 78 71 4d 66 61 58 69 6a 46 6b 66 68 41 7a 45 68 39 6b 52 34 71 7a 6c 73 4a 46 51 62 2d 53 46 6f 4d 68 67 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 66 63 33 66 66 39 38 65 38 63 36 61 30 64 33 30 38 37 64 35 31 35 63 30 34 37 33 66 38 36 37 37 5f 31 32" 2025/01/30 01:50:31 DEBUG : dir/sub/file2: Remove: 2025/01/30 01:50:31 DEBUG : dir/sub: Added virtual directory entry vDel: "file2" 2025/01/30 01:50:31 DEBUG : dir/sub/file2: >Remove: err= dir_test.go:636: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:636 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.00000194B4E717A0B0DA4A3DE8CAF516Z9v+cC1sRnaWw6x0vi8pxxYA0YVnKxbYHUPAFpnxkX8sLV44u5b02Z+ailn2wCnRZAUGMKBTPLNX0FBOCABGg3EW5NXhUJ/b4bVuB+YqxpaoyV0=PUT\n\n\n1738209030\nx-amz-cf-id:NNTzyT0UHxz5DL1sw1CxqMfaXijFkfhAzEh9kR4qzlsJFQb-SFoMhg==\n/ozadj95fviptne/tmp/recycle/1d/user/922460207/fc3ff98e8c6a0d3087d515c0473f8677_1250 55 54 0a 0a 0a 31 37 33 38 32 30 39 30 33 30 0a 78 2d 61 6d 7a 2d 63 66 2d 69 64 3a 4e 4e 54 7a 79 54 30 55 48 78 7a 35 44 4c 31 73 77 31 43 78 71 4d 66 61 58 69 6a 46 6b 66 68 41 7a 45 68 39 6b 52 34 71 7a 6c 73 4a 46 51 62 2d 53 46 6f 4d 68 67 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 66 63 33 66 66 39 38 65 38 63 36 61 30 64 33 30 38 37 64 35 31 35 63 30 34 37 33 66 38 36 37 37 5f 31 32" Test: TestDirFileOpen 2025/01/30 01:50:31 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': File to upload is small (5 bytes), uploading instead of streaming 2025/01/30 01:50:33 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2025/01/30 01:50:33 DEBUG : dir/sub/file0: Size of src and dst objects identical 2025/01/30 01:50:33 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0" 2025/01/30 01:50:33 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:50:33 DEBUG : dir/sub: Looking for writers 2025/01/30 01:50:33 DEBUG : file0: reading active writers 2025/01/30 01:50:33 DEBUG : dir: Looking for writers 2025/01/30 01:50:33 DEBUG : file1: reading active writers 2025/01/30 01:50:33 DEBUG : sub: reading active writers 2025/01/30 01:50:33 DEBUG : : Looking for writers 2025/01/30 01:50:33 DEBUG : dir: reading active writers 2025/01/30 01:50:33 DEBUG : >WaitForWriters: --- FAIL: TestDirFileOpen (17.41s) === RUN TestFileMethods run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:50:40 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:50:40 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:50:44 DEBUG : dir/file1: Set virtual modtime to 2025-01-30 01:50:42 +0000 UTC 2025/01/30 01:50:44 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:50:44 DEBUG : dir: Looking for writers 2025/01/30 01:50:44 DEBUG : file1: reading active writers 2025/01/30 01:50:44 DEBUG : : Looking for writers 2025/01/30 01:50:44 DEBUG : dir: reading active writers 2025/01/30 01:50:44 DEBUG : >WaitForWriters: --- PASS: TestFileMethods (7.89s) === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=false,write=false run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:50:47 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:50:47 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:50:51 DEBUG : dir/file1: Trying to read object after upload: try again in 100ms (1/10) 2025/01/30 01:50:56 DEBUG : Can set mod time: false file_test.go:97: can't set mod time 2025/01/30 01:50:56 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:50:56 DEBUG : dir: Looking for writers 2025/01/30 01:50:56 DEBUG : file1: reading active writers 2025/01/30 01:50:56 DEBUG : : Looking for writers 2025/01/30 01:50:56 DEBUG : dir: reading active writers 2025/01/30 01:50:56 DEBUG : >WaitForWriters: === RUN TestFileSetModTime/cache=off,open=true,write=false file_test.go:93: can't set mod time === RUN TestFileSetModTime/cache=off,open=true,write=true file_test.go:93: can't set mod time === RUN TestFileSetModTime/cache=full,open=false,write=false file_test.go:93: can't set mod time === RUN TestFileSetModTime/cache=full,open=true,write=false file_test.go:93: can't set mod time === RUN TestFileSetModTime/cache=full,open=true,write=true file_test.go:93: can't set mod time --- PASS: TestFileSetModTime (11.71s) --- SKIP: TestFileSetModTime/cache=off,open=false,write=false (11.70s) --- SKIP: TestFileSetModTime/cache=off,open=true,write=false (0.00s) --- SKIP: TestFileSetModTime/cache=off,open=true,write=true (0.00s) --- SKIP: TestFileSetModTime/cache=full,open=false,write=false (0.00s) --- SKIP: TestFileSetModTime/cache=full,open=true,write=false (0.00s) --- SKIP: TestFileSetModTime/cache=full,open=true,write=true (0.00s) === RUN TestFileOpenRead run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:50:59 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:50:59 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:04 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:51:04 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:51:04 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:51:04 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728 2025/01/30 01:51:04 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:04 DEBUG : dir: Looking for writers 2025/01/30 01:51:04 DEBUG : file1: reading active writers 2025/01/30 01:51:04 DEBUG : : Looking for writers 2025/01/30 01:51:04 DEBUG : dir: reading active writers 2025/01/30 01:51:04 DEBUG : >WaitForWriters: --- PASS: TestFileOpenRead (8.09s) === RUN TestFileOpenWrite run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:07 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:07 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:12 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:51:12 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': File to upload is small (25 bytes), uploading instead of streaming 2025/01/30 01:51:12 DEBUG : dir/file1: Update: removing old file 2025/01/30 01:51:15 DEBUG : dir/file1: Size of src and dst objects identical 2025/01/30 01:51:15 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:51:15 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:15 DEBUG : dir: Looking for writers 2025/01/30 01:51:15 DEBUG : file1: reading active writers 2025/01/30 01:51:15 DEBUG : : Looking for writers 2025/01/30 01:51:15 DEBUG : dir: reading active writers 2025/01/30 01:51:15 DEBUG : >WaitForWriters: --- PASS: TestFileOpenWrite (11.25s) === RUN TestFileRemove run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:19 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:19 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:23 DEBUG : dir/file1: Remove: 2025/01/30 01:51:24 DEBUG : dir: Added virtual directory entry vDel: "file1" 2025/01/30 01:51:24 DEBUG : dir/file1: >Remove: err= 2025/01/30 01:51:25 DEBUG : dir/file1: Remove: 2025/01/30 01:51:25 DEBUG : dir/file1: >Remove: err=Read only file system 2025/01/30 01:51:25 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:25 DEBUG : dir: Looking for writers 2025/01/30 01:51:25 DEBUG : : Looking for writers 2025/01/30 01:51:25 DEBUG : dir: reading active writers 2025/01/30 01:51:25 DEBUG : >WaitForWriters: --- PASS: TestFileRemove (8.32s) === RUN TestFileRemoveAll run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:27 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:27 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:31 DEBUG : dir/file1: Remove: 2025/01/30 01:51:33 DEBUG : dir: Added virtual directory entry vDel: "file1" 2025/01/30 01:51:33 DEBUG : dir/file1: >Remove: err= 2025/01/30 01:51:33 DEBUG : dir/file1: Remove: 2025/01/30 01:51:33 DEBUG : dir/file1: >Remove: err=Read only file system 2025/01/30 01:51:33 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:33 DEBUG : dir: Looking for writers 2025/01/30 01:51:33 DEBUG : : Looking for writers 2025/01/30 01:51:33 DEBUG : dir: reading active writers 2025/01/30 01:51:33 DEBUG : >WaitForWriters: --- PASS: TestFileRemoveAll (8.28s) === RUN TestFileOpen run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:35 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:35 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:40 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:51:40 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:51:40 DEBUG : dir/file1: Open: flags=O_WRONLY 2025/01/30 01:51:40 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2025/01/30 01:51:40 DEBUG : dir/file1: Open: flags=O_RDWR 2025/01/30 01:51:40 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2025/01/30 01:51:40 DEBUG : dir/file1: Open: flags=0x3 2025/01/30 01:51:40 DEBUG : dir/file1: Can't figure out how to open with flags: 0x3 2025/01/30 01:51:40 DEBUG : dir/file1: >Open: fd=, err=permission denied 2025/01/30 01:51:40 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:40 DEBUG : dir: Looking for writers 2025/01/30 01:51:40 DEBUG : file1: reading active writers 2025/01/30 01:51:40 DEBUG : : Looking for writers 2025/01/30 01:51:40 DEBUG : dir: reading active writers 2025/01/30 01:51:40 DEBUG : >WaitForWriters: --- PASS: TestFileOpen (7.83s) === RUN TestFileRename === RUN TestFileRename/off,forceCache=false run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:43 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:43 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream file_test.go:305: skip as can't rename files 2025/01/30 01:51:47 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:47 DEBUG : dir: Looking for writers 2025/01/30 01:51:47 DEBUG : file1: reading active writers 2025/01/30 01:51:47 DEBUG : : Looking for writers 2025/01/30 01:51:47 DEBUG : dir: reading active writers 2025/01/30 01:51:47 DEBUG : >WaitForWriters: === RUN TestFileRename/minimal,forceCache=false run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:51 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:51 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:51 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:51:51 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:51 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:51 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:51 DEBUG : Config file has changed externally - reloading 2025/01/30 01:51:51 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:51:51 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:51 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:51 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:51:51 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:51 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) file_test.go:305: skip as can't rename files 2025/01/30 01:51:55 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:51:55 DEBUG : dir: Looking for writers 2025/01/30 01:51:55 DEBUG : file1: reading active writers 2025/01/30 01:51:55 DEBUG : : Looking for writers 2025/01/30 01:51:55 DEBUG : dir: reading active writers 2025/01/30 01:51:55 DEBUG : >WaitForWriters: 2025/01/30 01:51:55 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting === RUN TestFileRename/minimal,forceCache=true run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:51:59 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:51:59 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:51:59 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:51:59 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:59 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:59 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:59 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:51:59 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:59 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:59 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:51:59 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:51:59 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) file_test.go:305: skip as can't rename files 2025/01/30 01:52:03 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:03 DEBUG : dir: Looking for writers 2025/01/30 01:52:03 DEBUG : file1: reading active writers 2025/01/30 01:52:03 DEBUG : : Looking for writers 2025/01/30 01:52:03 DEBUG : dir: reading active writers 2025/01/30 01:52:03 DEBUG : >WaitForWriters: 2025/01/30 01:52:03 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=false run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:07 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:07 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:52:07 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:07 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:07 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:07 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:52:07 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:07 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:07 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:52:07 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:07 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) file_test.go:305: skip as can't rename files 2025/01/30 01:52:11 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:11 DEBUG : dir: Looking for writers 2025/01/30 01:52:11 DEBUG : file1: reading active writers 2025/01/30 01:52:11 DEBUG : : Looking for writers 2025/01/30 01:52:11 DEBUG : dir: reading active writers 2025/01/30 01:52:11 DEBUG : >WaitForWriters: 2025/01/30 01:52:11 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=true run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:14 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:14 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:52:14 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:14 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:14 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:14 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:52:14 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:14 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:14 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:52:14 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:14 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) file_test.go:305: skip as can't rename files 2025/01/30 01:52:19 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:19 DEBUG : dir: Looking for writers 2025/01/30 01:52:19 DEBUG : file1: reading active writers 2025/01/30 01:52:19 DEBUG : : Looking for writers 2025/01/30 01:52:19 DEBUG : dir: reading active writers 2025/01/30 01:52:19 DEBUG : >WaitForWriters: 2025/01/30 01:52:19 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting === RUN TestFileRename/full,forceCache=false run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:22 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:22 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:52:22 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:22 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:22 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:22 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:52:22 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:22 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:22 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:52:22 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:52:22 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) file_test.go:305: skip as can't rename files 2025/01/30 01:52:27 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:27 DEBUG : dir: Looking for writers 2025/01/30 01:52:27 DEBUG : file1: reading active writers 2025/01/30 01:52:27 DEBUG : : Looking for writers 2025/01/30 01:52:27 DEBUG : dir: reading active writers 2025/01/30 01:52:27 DEBUG : >WaitForWriters: 2025/01/30 01:52:27 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting --- PASS: TestFileRename (47.21s) --- SKIP: TestFileRename/off,forceCache=false (7.83s) --- SKIP: TestFileRename/minimal,forceCache=false (7.86s) --- SKIP: TestFileRename/minimal,forceCache=true (7.94s) --- SKIP: TestFileRename/writes,forceCache=false (7.85s) --- SKIP: TestFileRename/writes,forceCache=true (7.85s) --- SKIP: TestFileRename/full,forceCache=false (7.86s) === RUN TestReadFileHandleMethods run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:30 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:30 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:52:34 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:52:35 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:52:35 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:52:35 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2025/01/30 01:52:35 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:52:35 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2025/01/30 01:52:35 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 2025/01/30 01:52:35 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:35 DEBUG : dir: Looking for writers 2025/01/30 01:52:35 DEBUG : file1: reading active writers 2025/01/30 01:52:35 DEBUG : : Looking for writers 2025/01/30 01:52:35 DEBUG : dir: reading active writers 2025/01/30 01:52:35 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleMethods (8.04s) === RUN TestReadFileHandleSeek run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:38 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:38 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:52:42 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:52:43 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:52:43 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:52:43 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2025/01/30 01:52:43 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2025/01/30 01:52:43 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2025/01/30 01:52:43 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker) 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker) 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728 2025/01/30 01:52:43 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728 2025/01/30 01:52:43 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:43 DEBUG : dir: Looking for writers 2025/01/30 01:52:43 DEBUG : file1: reading active writers 2025/01/30 01:52:43 DEBUG : : Looking for writers 2025/01/30 01:52:43 DEBUG : dir: reading active writers 2025/01/30 01:52:43 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleSeek (8.70s) === RUN TestReadFileHandleReadAt run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:47 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:47 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:52:51 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:52:51 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:52:51 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:52:51 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2025/01/30 01:52:51 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:52:51 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2025/01/30 01:52:51 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2025/01/30 01:52:51 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2025/01/30 01:52:51 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2025/01/30 01:52:51 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2025/01/30 01:52:51 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2025/01/30 01:52:51 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2025/01/30 01:52:51 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2025/01/30 01:52:52 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2025/01/30 01:52:52 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2025/01/30 01:52:52 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2025/01/30 01:52:52 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2025/01/30 01:52:52 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2025/01/30 01:52:52 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2025/01/30 01:52:52 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2025/01/30 01:52:52 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2025/01/30 01:52:52 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2025/01/30 01:52:52 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2025/01/30 01:52:52 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2025/01/30 01:52:52 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:52:52 DEBUG : dir: Looking for writers 2025/01/30 01:52:52 DEBUG : file1: reading active writers 2025/01/30 01:52:52 DEBUG : : Looking for writers 2025/01/30 01:52:52 DEBUG : dir: reading active writers 2025/01/30 01:52:52 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleReadAt (8.94s) === RUN TestReadFileHandleFlush run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:52:56 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:52:56 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:53:00 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:00 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:00 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:53:00 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2025/01/30 01:53:00 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:00 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:00 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:00 DEBUG : dir: Looking for writers 2025/01/30 01:53:00 DEBUG : file1: reading active writers 2025/01/30 01:53:00 DEBUG : : Looking for writers 2025/01/30 01:53:00 DEBUG : dir: reading active writers 2025/01/30 01:53:00 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleFlush (8.05s) === RUN TestReadFileHandleRelease run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:04 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:04 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:53:08 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:08 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:08 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2025/01/30 01:53:08 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2025/01/30 01:53:08 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:08 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:08 DEBUG : dir/file1: ReadFileHandle.Release closing 2025/01/30 01:53:08 DEBUG : dir/file1: ReadFileHandle.Release nothing to do 2025/01/30 01:53:08 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:08 DEBUG : dir: Looking for writers 2025/01/30 01:53:08 DEBUG : file1: reading active writers 2025/01/30 01:53:08 DEBUG : : Looking for writers 2025/01/30 01:53:08 DEBUG : dir: reading active writers 2025/01/30 01:53:08 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleRelease (8.06s) === RUN TestRWFileHandleMethodsRead run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:12 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:12 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:53:12 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:12 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:12 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:12 DEBUG : Config file has changed externally - reloading 2025/01/30 01:53:12 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:12 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:12 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:12 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:12 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:12 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/01/30 01:53:16 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:16 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:16 DEBUG : dir/file1: newRWFileHandle: 2025/01/30 01:53:16 DEBUG : dir/file1: >newRWFileHandle: err= 2025/01/30 01:53:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2025/01/30 01:53:16 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): _readAt: size=1, off=0 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): openPending: 2025/01/30 01:53:16 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16" against cached fingerprint "" 2025/01/30 01:53:16 DEBUG : dir/file1: vfs cache: truncate to size=16 2025/01/30 01:53:16 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): >openPending: err= 2025/01/30 01:53:16 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2025/01/30 01:53:16 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/01/30 01:53:16 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:16 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): >_readAt: n=1, err= 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): _readAt: size=256, off=1 2025/01/30 01:53:16 DEBUG : vfs cache: looking for range={Pos:1 Size:15} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): >_readAt: n=15, err=EOF 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): _readAt: size=16, off=16 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): >_readAt: n=0, err=EOF 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): close: 2025/01/30 01:53:16 DEBUG : dir/file1: vfs cache: setting modification time to 2025-01-30 01:53:14 +0000 UTC 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): >close: err= 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): close: 2025/01/30 01:53:16 DEBUG : dir/file1(0xc00080ab40): >close: err=file already closed 2025/01/30 01:53:16 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:16 DEBUG : dir: Looking for writers 2025/01/30 01:53:16 DEBUG : file1: reading active writers 2025/01/30 01:53:16 DEBUG : : Looking for writers 2025/01/30 01:53:16 DEBUG : dir: reading active writers 2025/01/30 01:53:16 DEBUG : >WaitForWriters: 2025/01/30 01:53:16 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting --- PASS: TestRWFileHandleMethodsRead (8.10s) === RUN TestRWFileHandleSeek run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:20 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:20 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:53:20 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:20 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:20 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:20 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:20 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:20 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:20 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:20 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:20 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/01/30 01:53:24 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:24 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:24 DEBUG : dir/file1: newRWFileHandle: 2025/01/30 01:53:24 DEBUG : dir/file1: >newRWFileHandle: err= 2025/01/30 01:53:24 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2025/01/30 01:53:24 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): _readAt: size=1, off=0 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): openPending: 2025/01/30 01:53:24 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16" against cached fingerprint "" 2025/01/30 01:53:24 DEBUG : dir/file1: vfs cache: truncate to size=16 2025/01/30 01:53:24 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >openPending: err= 2025/01/30 01:53:24 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2025/01/30 01:53:24 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/01/30 01:53:24 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:24 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >_readAt: n=1, err= 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): _readAt: size=1, off=5 2025/01/30 01:53:24 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >_readAt: n=1, err= 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): _readAt: size=1, off=3 2025/01/30 01:53:24 DEBUG : vfs cache: looking for range={Pos:3 Size:1} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >_readAt: n=1, err= 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): _readAt: size=1, off=13 2025/01/30 01:53:24 DEBUG : vfs cache: looking for range={Pos:13 Size:1} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >_readAt: n=1, err= 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): _readAt: size=16, off=100 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >_readAt: n=0, err=EOF 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): close: 2025/01/30 01:53:24 DEBUG : dir/file1: vfs cache: setting modification time to 2025-01-30 01:53:22 +0000 UTC 2025/01/30 01:53:24 DEBUG : dir/file1(0xc0007f7180): >close: err= 2025/01/30 01:53:24 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:24 DEBUG : dir: Looking for writers 2025/01/30 01:53:24 DEBUG : file1: reading active writers 2025/01/30 01:53:24 DEBUG : : Looking for writers 2025/01/30 01:53:24 DEBUG : dir: reading active writers 2025/01/30 01:53:24 DEBUG : >WaitForWriters: 2025/01/30 01:53:24 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting --- PASS: TestRWFileHandleSeek (8.04s) === RUN TestRWFileHandleReadAt run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:28 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:28 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:53:28 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:28 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:28 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:28 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:28 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:28 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:28 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:28 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:28 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/01/30 01:53:32 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:32 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:32 DEBUG : dir/file1: newRWFileHandle: 2025/01/30 01:53:32 DEBUG : dir/file1: >newRWFileHandle: err= 2025/01/30 01:53:32 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2025/01/30 01:53:32 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2025/01/30 01:53:32 DEBUG : dir/file1(0xc000802080): _readAt: size=1, off=0 2025/01/30 01:53:32 DEBUG : dir/file1(0xc000802080): openPending: 2025/01/30 01:53:32 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16" against cached fingerprint "" 2025/01/30 01:53:32 DEBUG : dir/file1: vfs cache: truncate to size=16 2025/01/30 01:53:32 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:32 DEBUG : dir/file1(0xc000802080): >openPending: err= 2025/01/30 01:53:32 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2025/01/30 01:53:32 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/01/30 01:53:32 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:32 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=1, err= 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): _readAt: size=1, off=5 2025/01/30 01:53:33 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=1, err= 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): _readAt: size=1, off=1 2025/01/30 01:53:33 DEBUG : vfs cache: looking for range={Pos:1 Size:1} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=1, err= 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): _readAt: size=6, off=10 2025/01/30 01:53:33 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=6, err= 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): _readAt: size=256, off=10 2025/01/30 01:53:33 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=6, err=EOF 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): _readAt: size=256, off=100 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=0, err=EOF 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): close: 2025/01/30 01:53:33 DEBUG : dir/file1: vfs cache: setting modification time to 2025-01-30 01:53:30 +0000 UTC 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >close: err= 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): _readAt: size=256, off=100 2025/01/30 01:53:33 DEBUG : dir/file1(0xc000802080): >_readAt: n=0, err=file already closed 2025/01/30 01:53:33 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:33 DEBUG : dir: Looking for writers 2025/01/30 01:53:33 DEBUG : file1: reading active writers 2025/01/30 01:53:33 DEBUG : : Looking for writers 2025/01/30 01:53:33 DEBUG : dir: reading active writers 2025/01/30 01:53:33 DEBUG : >WaitForWriters: 2025/01/30 01:53:33 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting --- PASS: TestRWFileHandleReadAt (8.05s) === RUN TestRWFileHandleFlushRead run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:36 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:36 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:53:36 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:36 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:36 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:36 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:36 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:36 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:36 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:36 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:36 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/01/30 01:53:40 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:41 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:41 DEBUG : dir/file1: newRWFileHandle: 2025/01/30 01:53:41 DEBUG : dir/file1: >newRWFileHandle: err= 2025/01/30 01:53:41 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2025/01/30 01:53:41 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): RWFileHandle.Flush 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): _readAt: size=256, off=0 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): openPending: 2025/01/30 01:53:41 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16" against cached fingerprint "" 2025/01/30 01:53:41 DEBUG : dir/file1: vfs cache: truncate to size=16 2025/01/30 01:53:41 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): >openPending: err= 2025/01/30 01:53:41 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2025/01/30 01:53:41 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/01/30 01:53:41 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:41 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): >_readAt: n=16, err=EOF 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): RWFileHandle.Flush 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): RWFileHandle.Flush 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): close: 2025/01/30 01:53:41 DEBUG : dir/file1: vfs cache: setting modification time to 2025-01-30 01:53:38 +0000 UTC 2025/01/30 01:53:41 DEBUG : dir/file1(0xc00080b340): >close: err= 2025/01/30 01:53:41 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:41 DEBUG : dir: Looking for writers 2025/01/30 01:53:41 DEBUG : file1: reading active writers 2025/01/30 01:53:41 DEBUG : : Looking for writers 2025/01/30 01:53:41 DEBUG : dir: reading active writers 2025/01/30 01:53:41 DEBUG : >WaitForWriters: 2025/01/30 01:53:41 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting --- PASS: TestRWFileHandleFlushRead (8.05s) === RUN TestRWFileHandleReleaseRead run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:44 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:44 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: root is "/home/rclone/.cache/rclone" 2025/01/30 01:53:44 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:44 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:44 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:44 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2025/01/30 01:53:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-gosipap1tupo" 2025/01/30 01:53:44 INFO : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/01/30 01:53:48 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2025/01/30 01:53:49 DEBUG : dir/file1: Open: flags=O_RDONLY 2025/01/30 01:53:49 DEBUG : dir/file1: newRWFileHandle: 2025/01/30 01:53:49 DEBUG : dir/file1: >newRWFileHandle: err= 2025/01/30 01:53:49 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2025/01/30 01:53:49 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): _readAt: size=256, off=0 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): openPending: 2025/01/30 01:53:49 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16" against cached fingerprint "" 2025/01/30 01:53:49 DEBUG : dir/file1: vfs cache: truncate to size=16 2025/01/30 01:53:49 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): >openPending: err= 2025/01/30 01:53:49 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2025/01/30 01:53:49 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/01/30 01:53:49 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/01/30 01:53:49 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): >_readAt: n=16, err=EOF 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): RWFileHandle.Release 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): close: 2025/01/30 01:53:49 DEBUG : dir/file1: vfs cache: setting modification time to 2025-01-30 01:53:46 +0000 UTC 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): >close: err= 2025/01/30 01:53:49 DEBUG : dir/file1(0xc00080a240): RWFileHandle.Release 2025/01/30 01:53:49 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:49 DEBUG : dir: Looking for writers 2025/01/30 01:53:49 DEBUG : file1: reading active writers 2025/01/30 01:53:49 DEBUG : : Looking for writers 2025/01/30 01:53:49 DEBUG : dir: reading active writers 2025/01/30 01:53:49 DEBUG : >WaitForWriters: 2025/01/30 01:53:49 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': vfs cache: cleaner exiting --- PASS: TestRWFileHandleReleaseRead (8.07s) === RUN TestFileReadAtNonZeroLength run.go:180: Remote "Linkbox root 'rclone-test-gosipap1tupo'", Local "Local file system at /tmp/rclone643203880", Modify Window "876000h0m0s" 2025/01/30 01:53:52 INFO : Linkbox root 'rclone-test-gosipap1tupo': poll-interval is not supported by this remote 2025/01/30 01:53:52 NOTICE: Linkbox root 'rclone-test-gosipap1tupo': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/01/30 01:53:52 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/01/30 01:53:52 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/01/30 01:53:52 DEBUG : : Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:52 DEBUG : file1: >Open: fd=file1 (w), err= 2025/01/30 01:53:52 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/01/30 01:53:52 DEBUG : : Added virtual directory entry vAddFile: "file1" 2025/01/30 01:53:52 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': File to upload is small (100 bytes), uploading instead of streaming 2025/01/30 01:53:54 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.00000194B4EA2F68B157A2F01E31BD87Z9v+cC1sRnaWw6x0vi8pxxYA0YVnKxbYHUPAFpnxkX8sLV44u5b02Z+ailn2wCnRZAUGMKBTPLNX0FBOCABGATsYHumTpT1qjjYw0rbmdsxCJs0=PUT\n\n\n1738209233\nx-amz-cf-id:VQu9aCGfPYav2PYZ4k72C70zaaitX_rAuOn7KUGWEqtNlcPY-W48MQ==\n/ozadj95fviptne/tmp/recycle/1d/user/922460207/884e41b370d32097e6de9b8fb314a593_10050 55 54 0a 0a 0a 31 37 33 38 32 30 39 32 33 33 0a 78 2d 61 6d 7a 2d 63 66 2d 69 64 3a 56 51 75 39 61 43 47 66 50 59 61 76 32 50 59 5a 34 6b 37 32 43 37 30 7a 61 61 69 74 58 5f 72 41 75 4f 6e 37 4b 55 47 57 45 71 74 4e 6c 63 50 59 2d 57 34 38 4d 51 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 38 38 34 65 34 31 62 33 37 30 64 33 32 30 39 37 65 36 64 65 39 62 38 66 62 33 31 34 61 35 39 33 5f 31 30 30" 2025/01/30 01:53:54 DEBUG : file1: Remove: 2025/01/30 01:53:54 DEBUG : : Added virtual directory entry vDel: "file1" 2025/01/30 01:53:54 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.00000194B4EA2F68B157A2F01E31BD87Z9v+cC1sRnaWw6x0vi8pxxYA0YVnKxbYHUPAFpnxkX8sLV44u5b02Z+ailn2wCnRZAUGMKBTPLNX0FBOCABGATsYHumTpT1qjjYw0rbmdsxCJs0=PUT\n\n\n1738209233\nx-amz-cf-id:VQu9aCGfPYav2PYZ4k72C70zaaitX_rAuOn7KUGWEqtNlcPY-W48MQ==\n/ozadj95fviptne/tmp/recycle/1d/user/922460207/884e41b370d32097e6de9b8fb314a593_10050 55 54 0a 0a 0a 31 37 33 38 32 30 39 32 33 33 0a 78 2d 61 6d 7a 2d 63 66 2d 69 64 3a 56 51 75 39 61 43 47 66 50 59 61 76 32 50 59 5a 34 6b 37 32 43 37 30 7a 61 61 69 74 58 5f 72 41 75 4f 6e 37 4b 55 47 57 45 71 74 4e 6c 63 50 59 2d 57 34 38 4d 51 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 38 38 34 65 34 31 62 33 37 30 64 33 32 30 39 37 65 36 64 65 39 62 38 66 62 33 31 34 61 35 39 33 5f 31 30 30" Test: TestFileReadAtNonZeroLength 2025/01/30 01:53:54 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2025/01/30 01:53:54 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 2025/01/30 01:53:54 DEBUG : WaitForWriters: timeout=30s 2025/01/30 01:53:54 DEBUG : : Looking for writers 2025/01/30 01:53:54 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (1.84s) FAIL 2025/01/30 01:53:54 DEBUG : Linkbox root 'rclone-test-gosipap1tupo': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestDirFileOpen|TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileRemove|TestFileRemoveAll|TestRWFileHandleFlushRead|TestRWFileHandleMethodsRead|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek)$|^TestFileRename$/^(full,forceCache=false|minimal,forceCache=false|minimal,forceCache=true|off,forceCache=false|writes,forceCache=false|writes,forceCache=true)$|^TestFileSetModTime$/^(cache=full,open=false,write=false|cache=full,open=true,write=false|cache=full,open=true,write=true|cache=off,open=false,write=false|cache=off,open=true,write=false|cache=off,open=true,write=true)$'" - Finished ERROR in 3m33.749548383s (try 2/5): exit status 1: Failed [TestDirFileOpen TestFileReadAtNonZeroLength]