"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestDirMkdir|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestRWCacheUpdate)$'" - Starting (try 2/5) 2025/04/05 05:36:48 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-bumipol9xavi" 2025/04/05 05:36:48 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/04/05 05:36:49 DEBUG : Starting OpenDrive session with ID: 99056a40d886927d4f62000cfd7c2343cc80ec77daffb7de8e2c4c9648700c6b 2025/04/05 05:36:49 DEBUG : Creating backend with remote "/tmp/rclone859694501" === RUN TestDirMkdir run.go:180: Remote "OpenDrive root 'rclone-test-bumipol9xavi'", Local "Local file system at /tmp/rclone859694501", Modify Window "1s" 2025/04/05 05:36:49 INFO : OpenDrive root 'rclone-test-bumipol9xavi': poll-interval is not supported by this remote 2025/04/05 05:36:49 NOTICE: OpenDrive root 'rclone-test-bumipol9xavi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream run.go:285: Failed to put "dir/file1" to "OpenDrive root 'rclone-test-bumipol9xavi'": failed to get folder list: Directory doesn't exist (Error 404) 2025/04/05 05:36:49 DEBUG : WaitForWriters: timeout=30s 2025/04/05 05:36:49 DEBUG : : Looking for writers 2025/04/05 05:36:49 DEBUG : >WaitForWriters: --- FAIL: TestDirMkdir (0.85s) === RUN TestDirRemoveAll run.go:180: Remote "OpenDrive root 'rclone-test-bumipol9xavi'", Local "Local file system at /tmp/rclone859694501", Modify Window "1s" 2025/04/05 05:36:50 INFO : OpenDrive root 'rclone-test-bumipol9xavi': poll-interval is not supported by this remote 2025/04/05 05:36:50 NOTICE: OpenDrive root 'rclone-test-bumipol9xavi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/04/05 05:36:51 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0 2025/04/05 05:36:52 DEBUG : dir/file1: Remove: 2025/04/05 05:36:53 DEBUG : dir: Added virtual directory entry vDel: "file1" 2025/04/05 05:36:53 DEBUG : dir/file1: >Remove: err= 2025/04/05 05:36:53 DEBUG : : Added virtual directory entry vDel: "dir" 2025/04/05 05:36:53 DEBUG : WaitForWriters: timeout=30s 2025/04/05 05:36:53 DEBUG : : Looking for writers 2025/04/05 05:36:53 DEBUG : >WaitForWriters: --- PASS: TestDirRemoveAll (3.74s) === RUN TestDirRemoveName run.go:180: Remote "OpenDrive root 'rclone-test-bumipol9xavi'", Local "Local file system at /tmp/rclone859694501", Modify Window "1s" 2025/04/05 05:36:53 INFO : OpenDrive root 'rclone-test-bumipol9xavi': poll-interval is not supported by this remote 2025/04/05 05:36:53 NOTICE: OpenDrive root 'rclone-test-bumipol9xavi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/04/05 05:36:55 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0 2025/04/05 05:36:56 DEBUG : dir/file1: Remove: 2025/04/05 05:36:57 DEBUG : dir: Added virtual directory entry vDel: "file1" 2025/04/05 05:36:57 DEBUG : dir/file1: >Remove: err= dir_test.go:503: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:503 Error: Should be true Test: TestDirRemoveName 2025/04/05 05:36:57 DEBUG : WaitForWriters: timeout=30s 2025/04/05 05:36:57 DEBUG : dir: Looking for writers 2025/04/05 05:36:57 DEBUG : : Looking for writers 2025/04/05 05:36:57 DEBUG : dir: reading active writers 2025/04/05 05:36:57 DEBUG : >WaitForWriters: --- FAIL: TestDirRemoveName (4.30s) === RUN TestDirRename run.go:180: Remote "OpenDrive root 'rclone-test-bumipol9xavi'", Local "Local file system at /tmp/rclone859694501", Modify Window "1s" 2025/04/05 05:36:58 INFO : OpenDrive root 'rclone-test-bumipol9xavi': poll-interval is not supported by this remote 2025/04/05 05:36:58 NOTICE: OpenDrive root 'rclone-test-bumipol9xavi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2025/04/05 05:36:59 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0 2025/04/05 05:37:01 DEBUG : dir/file3: Uploading chunk 0, size=15, remain=0 2025/04/05 05:37:03 ERROR : dir/not found: Dir.Rename error: file does not exist 2025/04/05 05:37:03 DEBUG : dir2: same parent dir (ODFfODIwNDQxN19UR241NA) - using folder/rename instead of move_copy 2025/04/05 05:37:03 DEBUG : dir: Updating dir with dir2 0xc000b0e750 2025/04/05 05:37:03 DEBUG : dir: forgetting directory cache 2025/04/05 05:37:03 DEBUG : : Added virtual directory entry vDel: "dir" 2025/04/05 05:37:03 DEBUG : : Added virtual directory entry vAddDir: "dir2" 2025/04/05 05:37:04 INFO : dir2/file1: Moved (server-side) to: file2 2025/04/05 05:37:04 DEBUG : file2: Updating file with file2 0xc00081e6c0 2025/04/05 05:37:04 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2025/04/05 05:37:04 DEBUG : : Added virtual directory entry vAddFile: "file2" 2025/04/05 05:37:05 INFO : dir2/file3: Deleted 2025/04/05 05:37:06 INFO : file2: Moved (server-side) to: dir2/file3 2025/04/05 05:37:06 DEBUG : dir2/file3: Updating file with dir2/file3 0xc00081e6c0 2025/04/05 05:37:06 DEBUG : : Added virtual directory entry vDel: "file2" 2025/04/05 05:37:06 DEBUG : dir2: Added virtual directory entry vAddFile: "file3" 2025/04/05 05:37:06 DEBUG : : Added virtual directory entry vAddDir: "empty directory" 2025/04/05 05:37:06 DEBUG : renamed empty directory: same parent dir (ODFfODIwNDQxN19UR241NA) - using folder/rename instead of move_copy 2025/04/05 05:37:07 DEBUG : empty directory: Updating dir with renamed empty directory 0xc0009220d0 2025/04/05 05:37:07 DEBUG : empty directory: forgetting directory cache 2025/04/05 05:37:07 DEBUG : : Added virtual directory entry vDel: "empty directory" 2025/04/05 05:37:07 DEBUG : : Added virtual directory entry vAddDir: "renamed empty directory" 2025/04/05 05:37:07 DEBUG : dir2: Renaming to "dir3" 2025/04/05 05:37:07 DEBUG : WaitForWriters: timeout=30s 2025/04/05 05:37:07 DEBUG : dir3: Looking for writers 2025/04/05 05:37:07 DEBUG : file3: reading active writers 2025/04/05 05:37:07 DEBUG : renamed empty directory: Looking for writers 2025/04/05 05:37:07 DEBUG : : Looking for writers 2025/04/05 05:37:07 DEBUG : dir3: reading active writers 2025/04/05 05:37:07 DEBUG : renamed empty directory: reading active writers 2025/04/05 05:37:07 DEBUG : >WaitForWriters: --- PASS: TestDirRename (10.39s) === RUN TestRWCacheUpdate run.go:180: Remote "OpenDrive root 'rclone-test-bumipol9xavi'", Local "Local file system at /tmp/rclone859694501", Modify Window "1s" 2025/04/05 05:37:08 INFO : OpenDrive root 'rclone-test-bumipol9xavi': poll-interval is not supported by this remote 2025/04/05 05:37:08 DEBUG : OpenDrive root 'rclone-test-bumipol9xavi': vfs cache: root is "/home/rclone/.cache/rclone" 2025/04/05 05:37:08 DEBUG : OpenDrive root 'rclone-test-bumipol9xavi': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-bumipol9xavi" 2025/04/05 05:37:08 DEBUG : OpenDrive root 'rclone-test-bumipol9xavi': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestOpenDrive/rclone-test-bumipol9xavi" 2025/04/05 05:37:08 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-bumipol9xavi" 2025/04/05 05:37:08 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/04/05 05:37:08 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-bumipol9xavi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-bumipol9xavi" 2025/04/05 05:37:08 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestOpenDrive/rclone-test-bumipol9xavi" 2025/04/05 05:37:08 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/04/05 05:37:08 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestOpenDrive/rclone-test-bumipol9xavi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestOpenDrive/rclone-test-bumipol9xavi" 2025/04/05 05:37:08 INFO : OpenDrive root 'rclone-test-bumipol9xavi': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/04/05 05:37:08 DEBUG : : forgetting directory cache 2025/04/05 05:37:09 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=20, remain=0 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate(0xc00048a5c0): _readAt: size=512, off=0 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate(0xc00048a5c0): openPending: 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-04-05 04:38:08 +0000 UTC,8558f20bbf1a5777c862752b37ad49be" against cached fingerprint "" 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2025/04/05 05:37:10 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate(0xc00048a5c0): >openPending: err= 2025/04/05 05:37:10 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate(0xc00048a5c0): >_readAt: n=20, err=EOF 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate(0xc00048a5c0): close: 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:38:08 +0000 UTC 2025/04/05 05:37:10 DEBUG : TestRWCacheUpdate(0xc00048a5c0): >close: err= 2025/04/05 05:37:10 DEBUG : : Re-reading directory (336.12298ms old) 2025/04/05 05:37:11 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:11 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:11 DEBUG : : forgetting directory cache 2025/04/05 05:37:11 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=20, remain=0 2025/04/05 05:37:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate(0xc0008d0000): _readAt: size=512, off=0 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate(0xc0008d0000): openPending: 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-04-05 04:39:08 +0000 UTC,944a242d910e2bbacae0d0db8c64490a" against cached fingerprint "20,2025-04-05 04:38:08 +0000 UTC,8558f20bbf1a5777c862752b37ad49be" 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-04-05 04:39:08 +0000 UTC,944a242d910e2bbacae0d0db8c64490a" != cached fingerprint "20,2025-04-05 04:38:08 +0000 UTC,8558f20bbf1a5777c862752b37ad49be") 2025/04/05 05:37:13 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2025/04/05 05:37:13 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate(0xc0008d0000): >openPending: err= 2025/04/05 05:37:13 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate(0xc0008d0000): >_readAt: n=20, err=EOF 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate(0xc0008d0000): close: 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:39:08 +0000 UTC 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate(0xc0008d0000): >close: err= 2025/04/05 05:37:13 DEBUG : : Re-reading directory (346.201392ms old) 2025/04/05 05:37:13 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:13 DEBUG : : forgetting directory cache 2025/04/05 05:37:13 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=20, remain=0 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate(0xc00048ae40): _readAt: size=512, off=0 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate(0xc00048ae40): openPending: 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-04-05 04:40:08 +0000 UTC,4e063366550d230fc1fb85c19dbb494d" against cached fingerprint "20,2025-04-05 04:39:08 +0000 UTC,944a242d910e2bbacae0d0db8c64490a" 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-04-05 04:40:08 +0000 UTC,4e063366550d230fc1fb85c19dbb494d" != cached fingerprint "20,2025-04-05 04:39:08 +0000 UTC,944a242d910e2bbacae0d0db8c64490a") 2025/04/05 05:37:15 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2025/04/05 05:37:15 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate(0xc00048ae40): >openPending: err= 2025/04/05 05:37:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate(0xc00048ae40): >_readAt: n=20, err=EOF 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate(0xc00048ae40): close: 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:40:08 +0000 UTC 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate(0xc00048ae40): >close: err= 2025/04/05 05:37:15 DEBUG : : Re-reading directory (334.24563ms old) 2025/04/05 05:37:15 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:15 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:16 DEBUG : : forgetting directory cache 2025/04/05 05:37:16 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=20, remain=0 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate(0xc000434740): _readAt: size=512, off=0 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate(0xc000434740): openPending: 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-04-05 04:41:08 +0000 UTC,a8c7956852282e88c22a986150cb5a68" against cached fingerprint "20,2025-04-05 04:40:08 +0000 UTC,4e063366550d230fc1fb85c19dbb494d" 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-04-05 04:41:08 +0000 UTC,a8c7956852282e88c22a986150cb5a68" != cached fingerprint "20,2025-04-05 04:40:08 +0000 UTC,4e063366550d230fc1fb85c19dbb494d") 2025/04/05 05:37:17 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2025/04/05 05:37:17 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate(0xc000434740): >openPending: err= 2025/04/05 05:37:17 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate(0xc000434740): >_readAt: n=20, err=EOF 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate(0xc000434740): close: 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:41:08 +0000 UTC 2025/04/05 05:37:17 DEBUG : TestRWCacheUpdate(0xc000434740): >close: err= 2025/04/05 05:37:17 DEBUG : : Re-reading directory (334.753615ms old) 2025/04/05 05:37:18 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:18 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:18 DEBUG : : forgetting directory cache 2025/04/05 05:37:18 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=20, remain=0 2025/04/05 05:37:19 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate(0xc0001564c0): _readAt: size=512, off=0 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate(0xc0001564c0): openPending: 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-04-05 04:42:08 +0000 UTC,25074c7237d5f7774d304950950b2d66" against cached fingerprint "20,2025-04-05 04:41:08 +0000 UTC,a8c7956852282e88c22a986150cb5a68" 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-04-05 04:42:08 +0000 UTC,25074c7237d5f7774d304950950b2d66" != cached fingerprint "20,2025-04-05 04:41:08 +0000 UTC,a8c7956852282e88c22a986150cb5a68") 2025/04/05 05:37:20 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2025/04/05 05:37:20 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate(0xc0001564c0): >openPending: err= 2025/04/05 05:37:20 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate(0xc0001564c0): >_readAt: n=20, err=EOF 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate(0xc0001564c0): close: 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:42:08 +0000 UTC 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate(0xc0001564c0): >close: err= 2025/04/05 05:37:20 DEBUG : : Re-reading directory (332.270274ms old) 2025/04/05 05:37:20 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:20 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:20 DEBUG : : forgetting directory cache 2025/04/05 05:37:21 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=20, remain=0 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate(0xc0008d05c0): _readAt: size=512, off=0 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate(0xc0008d05c0): openPending: 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-04-05 04:43:08 +0000 UTC,58e51f3b328781d7a035e462b2e9bd00" against cached fingerprint "20,2025-04-05 04:42:08 +0000 UTC,25074c7237d5f7774d304950950b2d66" 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-04-05 04:43:08 +0000 UTC,58e51f3b328781d7a035e462b2e9bd00" != cached fingerprint "20,2025-04-05 04:42:08 +0000 UTC,25074c7237d5f7774d304950950b2d66") 2025/04/05 05:37:22 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2025/04/05 05:37:22 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate(0xc0008d05c0): >openPending: err= 2025/04/05 05:37:22 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate(0xc0008d05c0): >_readAt: n=20, err=EOF 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate(0xc0008d05c0): close: 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:43:08 +0000 UTC 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate(0xc0008d05c0): >close: err= 2025/04/05 05:37:22 DEBUG : : Re-reading directory (333.293696ms old) 2025/04/05 05:37:22 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:22 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:23 DEBUG : : forgetting directory cache 2025/04/05 05:37:23 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=21, remain=0 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate(0xc000156640): _readAt: size=512, off=0 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate(0xc000156640): openPending: 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2025-04-05 04:44:08 +0000 UTC,8dbc613757cc0c1614e9b1aafd9156a7" against cached fingerprint "20,2025-04-05 04:43:08 +0000 UTC,58e51f3b328781d7a035e462b2e9bd00" 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2025-04-05 04:44:08 +0000 UTC,8dbc613757cc0c1614e9b1aafd9156a7" != cached fingerprint "20,2025-04-05 04:43:08 +0000 UTC,58e51f3b328781d7a035e462b2e9bd00") 2025/04/05 05:37:24 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2025/04/05 05:37:24 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate(0xc000156640): >openPending: err= 2025/04/05 05:37:24 DEBUG : vfs cache: looking for range={Pos:0 Size:21} in [] - present false 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate(0xc000156640): >_readAt: n=21, err=EOF 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate(0xc000156640): close: 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:44:08 +0000 UTC 2025/04/05 05:37:24 DEBUG : TestRWCacheUpdate(0xc000156640): >close: err= 2025/04/05 05:37:24 DEBUG : : Re-reading directory (332.169166ms old) 2025/04/05 05:37:25 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:25 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:25 DEBUG : : forgetting directory cache 2025/04/05 05:37:25 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=22, remain=0 2025/04/05 05:37:26 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate(0xc0008d0500): _readAt: size=512, off=0 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate(0xc0008d0500): openPending: 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "22,2025-04-05 04:45:08 +0000 UTC,d6db0c1b4814e22b98d1f690596f68ca" against cached fingerprint "21,2025-04-05 04:44:08 +0000 UTC,8dbc613757cc0c1614e9b1aafd9156a7" 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "22,2025-04-05 04:45:08 +0000 UTC,d6db0c1b4814e22b98d1f690596f68ca" != cached fingerprint "21,2025-04-05 04:44:08 +0000 UTC,8dbc613757cc0c1614e9b1aafd9156a7") 2025/04/05 05:37:27 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=22 2025/04/05 05:37:27 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate(0xc0008d0500): >openPending: err= 2025/04/05 05:37:27 DEBUG : vfs cache: looking for range={Pos:0 Size:22} in [] - present false 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate(0xc0008d0500): >_readAt: n=22, err=EOF 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate(0xc0008d0500): close: 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:45:08 +0000 UTC 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate(0xc0008d0500): >close: err= 2025/04/05 05:37:27 DEBUG : : Re-reading directory (332.914415ms old) 2025/04/05 05:37:27 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:27 DEBUG : : forgetting directory cache 2025/04/05 05:37:27 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=23, remain=0 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate(0xc000434980): _readAt: size=512, off=0 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate(0xc000434980): openPending: 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "23,2025-04-05 04:46:08 +0000 UTC,a04b60cad5c51870e80f668df3d720c0" against cached fingerprint "22,2025-04-05 04:45:08 +0000 UTC,d6db0c1b4814e22b98d1f690596f68ca" 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "23,2025-04-05 04:46:08 +0000 UTC,a04b60cad5c51870e80f668df3d720c0" != cached fingerprint "22,2025-04-05 04:45:08 +0000 UTC,d6db0c1b4814e22b98d1f690596f68ca") 2025/04/05 05:37:29 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=23 2025/04/05 05:37:29 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate(0xc000434980): >openPending: err= 2025/04/05 05:37:29 DEBUG : vfs cache: looking for range={Pos:0 Size:23} in [] - present false 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate(0xc000434980): >_readAt: n=23, err=EOF 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate(0xc000434980): close: 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:46:08 +0000 UTC 2025/04/05 05:37:29 DEBUG : TestRWCacheUpdate(0xc000434980): >close: err= 2025/04/05 05:37:29 DEBUG : : Re-reading directory (334.379796ms old) 2025/04/05 05:37:30 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:30 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:30 DEBUG : : forgetting directory cache 2025/04/05 05:37:30 DEBUG : TestRWCacheUpdate: Uploading chunk 0, size=24, remain=0 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate(0xc0008d0900): _readAt: size=512, off=0 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate(0xc0008d0900): openPending: 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "24,2025-04-05 04:47:08 +0000 UTC,074978d6705e58530a3c8d378a08fa37" against cached fingerprint "23,2025-04-05 04:46:08 +0000 UTC,a04b60cad5c51870e80f668df3d720c0" 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "24,2025-04-05 04:47:08 +0000 UTC,074978d6705e58530a3c8d378a08fa37" != cached fingerprint "23,2025-04-05 04:46:08 +0000 UTC,a04b60cad5c51870e80f668df3d720c0") 2025/04/05 05:37:31 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=24 2025/04/05 05:37:31 DEBUG : : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate(0xc0008d0900): >openPending: err= 2025/04/05 05:37:31 DEBUG : vfs cache: looking for range={Pos:0 Size:24} in [] - present false 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2025/04/05 05:37:31 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2025/04/05 05:37:32 DEBUG : : forgetting directory cache 2025/04/05 05:37:32 DEBUG : TestRWCacheUpdate(0xc0008d0900): >_readAt: n=24, err=EOF 2025/04/05 05:37:32 DEBUG : TestRWCacheUpdate(0xc0008d0900): close: 2025/04/05 05:37:32 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-04-05 04:47:08 +0000 UTC 2025/04/05 05:37:32 DEBUG : TestRWCacheUpdate(0xc0008d0900): >close: err= 2025/04/05 05:37:32 DEBUG : : Re-reading directory (378.444064ms old) 2025/04/05 05:37:32 DEBUG : : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2025/04/05 05:37:32 DEBUG : TestRWCacheUpdate: Reset virtual modtime 2025/04/05 05:37:32 DEBUG : WaitForWriters: timeout=30s 2025/04/05 05:37:32 DEBUG : : Looking for writers 2025/04/05 05:37:32 DEBUG : TestRWCacheUpdate: reading active writers 2025/04/05 05:37:32 DEBUG : >WaitForWriters: 2025/04/05 05:37:32 DEBUG : : forgetting directory cache 2025/04/05 05:37:32 DEBUG : OpenDrive root 'rclone-test-bumipol9xavi': vfs cache: cleaner exiting --- PASS: TestRWCacheUpdate (24.46s) FAIL 2025/04/05 05:37:33 DEBUG : OpenDrive root 'rclone-test-bumipol9xavi': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestDirMkdir|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestRWCacheUpdate)$'" - Finished ERROR in 45.143099217s (try 2/5): exit status 1: Failed [TestDirMkdir TestDirRemoveName]