"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPremiumizeMe: -verbose -test.run '^TestRWCacheRename$'" - Starting (try 2/5) 2024/12/21 04:50:07 DEBUG : Creating backend with remote "TestPremiumizeMe:rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/12/21 04:50:07 DEBUG : Creating backend with remote "/tmp/rclone3202318894" === RUN TestRWCacheRename run.go:180: Remote "premiumize.me root 'rclone-test-pegiyiy6garo'", Local "Local file system at /tmp/rclone3202318894", Modify Window "876000h0m0s" 2024/12/21 04:50:07 INFO : premiumize.me root 'rclone-test-pegiyiy6garo': poll-interval is not supported by this remote 2024/12/21 04:50:07 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2024/12/21 04:50:07 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestPremiumizeMe/rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestPremiumizeMe/rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestPremiumizeMe/rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2024/12/21 04:50:07 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestPremiumizeMe/rclone-test-pegiyiy6garo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestPremiumizeMe/rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestPremiumizeMe/rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name 2024/12/21 04:50:07 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestPremiumizeMe/rclone-test-pegiyiy6garo" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestPremiumizeMe/rclone-test-pegiyiy6garo" 2024/12/21 04:50:07 DEBUG : rename_me: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2024/12/21 04:50:07 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2024/12/21 04:50:07 DEBUG : rename_me: Open: flags=O_WRONLY|O_CREATE 2024/12/21 04:50:07 DEBUG : rename_me: newRWFileHandle: 2024/12/21 04:50:07 DEBUG : rename_me(0xc00041e940): openPending: 2024/12/21 04:50:07 DEBUG : rename_me: vfs cache: truncate to size=0 (not needed as size correct) 2024/12/21 04:50:07 DEBUG : : Added virtual directory entry vAddFile: "rename_me" 2024/12/21 04:50:07 DEBUG : rename_me(0xc00041e940): >openPending: err= 2024/12/21 04:50:07 DEBUG : rename_me: >newRWFileHandle: err= 2024/12/21 04:50:07 DEBUG : : Added virtual directory entry vAddFile: "rename_me" 2024/12/21 04:50:07 DEBUG : rename_me: >Open: fd=rename_me (rw), err= 2024/12/21 04:50:07 DEBUG : rename_me: >OpenFile: fd=rename_me (rw), err= 2024/12/21 04:50:07 DEBUG : rename_me(0xc00041e940): _writeAt: size=5, off=0 2024/12/21 04:50:07 DEBUG : rename_me(0xc00041e940): >_writeAt: n=5, err= 2024/12/21 04:50:07 DEBUG : rename_me(0xc00041e940): close: 2024/12/21 04:50:07 DEBUG : rename_me: vfs cache: setting modification time to 2024-12-21 04:50:07.609724209 +0000 UTC m=+0.277782872 2024/12/21 04:50:07 INFO : rename_me: vfs cache: queuing for upload in 100ms 2024/12/21 04:50:07 DEBUG : rename_me(0xc00041e940): >close: err= 2024/12/21 04:50:07 INFO : rename_me: vfs cache: renamed in cache to "i_was_renamed" 2024/12/21 04:50:07 DEBUG : i_was_renamed: Updating file with 0xc0008a2300 2024/12/21 04:50:07 DEBUG : : Added virtual directory entry vDel: "rename_me" 2024/12/21 04:50:07 DEBUG : : Added virtual directory entry vAddFile: "i_was_renamed" 2024/12/21 04:50:07 DEBUG : WaitForWriters: timeout=30s 2024/12/21 04:50:07 DEBUG : : Looking for writers 2024/12/21 04:50:07 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2024/12/21 04:50:07 DEBUG : : Looking for writers 2024/12/21 04:50:07 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2024/12/21 04:50:07 DEBUG : : Looking for writers 2024/12/21 04:50:07 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2024/12/21 04:50:07 DEBUG : : Looking for writers 2024/12/21 04:50:07 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2024/12/21 04:50:07 DEBUG : i_was_renamed: vfs cache: starting upload 2024/12/21 04:50:07 DEBUG : : Looking for writers 2024/12/21 04:50:07 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2024/12/21 04:50:07 DEBUG : : Looking for writers 2024/12/21 04:50:07 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2024/12/21 04:50:08 DEBUG : : Looking for writers 2024/12/21 04:50:08 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2024/12/21 04:50:08 DEBUG : : Looking for writers 2024/12/21 04:50:08 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2024/12/21 04:50:09 DEBUG : : Looking for writers 2024/12/21 04:50:09 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2024/12/21 04:50:10 DEBUG : : Looking for writers 2024/12/21 04:50:10 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2024/12/21 04:50:11 DEBUG : : Looking for writers 2024/12/21 04:50:11 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2024/12/21 04:50:12 DEBUG : : Looking for writers 2024/12/21 04:50:12 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2024/12/21 04:50:13 INFO : i_was_renamed: Copied (new) 2024/12/21 04:50:13 DEBUG : i_was_renamed: vfs cache: fingerprint now "5" 2024/12/21 04:50:13 DEBUG : i_was_renamed: vfs cache: writeback object to VFS layer 2024/12/21 04:50:13 DEBUG : : Added virtual directory entry vAddFile: "i_was_renamed" 2024/12/21 04:50:13 INFO : i_was_renamed: vfs cache: upload succeeded try #1 2024/12/21 04:50:13 DEBUG : : Looking for writers 2024/12/21 04:50:13 DEBUG : i_was_renamed: reading active writers 2024/12/21 04:50:13 DEBUG : >WaitForWriters: 2024/12/21 04:50:13 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWCacheRename (6.49s) PASS 2024/12/21 04:50:14 DEBUG : premiumize.me root 'rclone-test-pegiyiy6garo': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestPremiumizeMe: -verbose -test.run '^TestRWCacheRename$'" - Finished OK in 6.78155361s (try 2/5)