"./vfs.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose -test.run '^(TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileRemove|TestFileRemoveAll)$|^TestFileRename$/^(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)
2024/12/10 01:12:13 DEBUG : Creating backend with remote "TestBox:rclone-test-zunagey2hato"
2024/12/10 01:12:13 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/12/10 01:12:14 DEBUG : box root 'rclone-test-zunagey2hato': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2024/12/10 01:12:14 DEBUG : Creating backend with remote "/tmp/rclone3155000713"
=== RUN   TestFileMethods
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:12:16 DEBUG : box root 'rclone-test-zunagey2hato': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2024/12/10 01:12:21 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:12:21 DEBUG : dir: Looking for writers
2024/12/10 01:12:21 DEBUG : file1: reading active writers
2024/12/10 01:12:21 DEBUG : : Looking for writers
2024/12/10 01:12:21 DEBUG : dir: reading active writers
2024/12/10 01:12:21 DEBUG : >WaitForWriters: 
--- PASS: TestFileMethods (10.33s)
=== RUN   TestFileSetModTime
=== RUN   TestFileSetModTime/cache=off,open=false,write=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:12:34 DEBUG : Can set mod time: true
2024/12/10 01:12:34 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2024/12/10 01:12:35 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:12:35 DEBUG : dir: Looking for writers
2024/12/10 01:12:35 DEBUG : file1: reading active writers
2024/12/10 01:12:35 DEBUG : : Looking for writers
2024/12/10 01:12:35 DEBUG : dir: reading active writers
2024/12/10 01:12:35 DEBUG : >WaitForWriters: 
=== RUN   TestFileSetModTime/cache=off,open=true,write=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:12:43 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:12:43 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2024/12/10 01:12:43 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:12:43 DEBUG : box root 'rclone-test-zunagey2hato': File to upload is small (0 bytes), uploading instead of streaming
2024/12/10 01:12:45 DEBUG : dir/file1: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK
2024/12/10 01:12:45 DEBUG : dir/file1: Size and sha1 of src and dst objects identical
2024/12/10 01:12:46 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2024/12/10 01:12:46 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:12:46 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:12:46 DEBUG : dir: Looking for writers
2024/12/10 01:12:46 DEBUG : file1: reading active writers
2024/12/10 01:12:46 DEBUG : : Looking for writers
2024/12/10 01:12:46 DEBUG : dir: reading active writers
2024/12/10 01:12:46 DEBUG : >WaitForWriters: 
2024/12/10 01:12:46 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:12:46 DEBUG : dir: Looking for writers
2024/12/10 01:12:46 DEBUG : file1: reading active writers
2024/12/10 01:12:46 DEBUG : : Looking for writers
2024/12/10 01:12:46 DEBUG : dir: reading active writers
2024/12/10 01:12:46 DEBUG : >WaitForWriters: 
=== RUN   TestFileSetModTime/cache=off,open=true,write=true
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:12:55 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:12:55 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2024/12/10 01:12:55 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:12:55 DEBUG : box root 'rclone-test-zunagey2hato': File to upload is small (5 bytes), uploading instead of streaming
2024/12/10 01:12:56 DEBUG : dir/file1: sha1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK
2024/12/10 01:12:56 DEBUG : dir/file1: Size and sha1 of src and dst objects identical
2024/12/10 01:12:57 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2024/12/10 01:12:57 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:12:57 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:12:57 DEBUG : dir: Looking for writers
2024/12/10 01:12:57 DEBUG : file1: reading active writers
2024/12/10 01:12:57 DEBUG : : Looking for writers
2024/12/10 01:12:57 DEBUG : dir: reading active writers
2024/12/10 01:12:57 DEBUG : >WaitForWriters: 
2024/12/10 01:12:58 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:12:58 DEBUG : dir: Looking for writers
2024/12/10 01:12:58 DEBUG : file1: reading active writers
2024/12/10 01:12:58 DEBUG : : Looking for writers
2024/12/10 01:12:58 DEBUG : dir: reading active writers
2024/12/10 01:12:58 DEBUG : >WaitForWriters: 
=== RUN   TestFileSetModTime/cache=full,open=false,write=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:13:02 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:13:02 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:02 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:02 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:02 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:13:02 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:02 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:02 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:13:02 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:02 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:13:07 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2024/12/10 01:13:08 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:13:08 DEBUG : dir: Looking for writers
2024/12/10 01:13:08 DEBUG : file1: reading active writers
2024/12/10 01:13:08 DEBUG : : Looking for writers
2024/12/10 01:13:08 DEBUG : dir: reading active writers
2024/12/10 01:13:08 DEBUG : >WaitForWriters: 
2024/12/10 01:13:08 DEBUG : vfs cache: cleaner exiting
=== RUN   TestFileSetModTime/cache=full,open=true,write=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:13:11 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:13:11 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:11 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:11 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:11 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:13:11 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:11 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:11 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:13:11 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:11 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:13:14 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277881629")
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720993470995|03a13053c65d0e2e3c3c1c847c39564b165d6606] new parent not found
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633707550|364004daa526b5c8fe83f837fa57aea96057620d] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720988583966|76349f6d0bae9602ad9edf70ee287e6347d605c2] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["rclone-test-zunagey2hato"(0)|folder|ITEM_CREATE|297631307118|50d9d6515f9ba1fab304106db6ff1739686bec7a] new parent not found
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297633707550|b54822f38859cbc64fcf1644f57a577090d4e1f8] added old path ("dir") for notify
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720988583966|de18b2330417679704a62c8911b145bb941f1f52] old parent not cached
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_RENAME|1720979115978|cf08fafc1e132ca0053a9b26e6fb36716235c348] added new path ("time_test") for notify
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992246611|b48fed53aebabbf920be305ea6cbe34a0355262c] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_UPLOAD|1720979115978|4f31e90a25da2128601692b3dc697d1750d42da1] added new path ("time_test") for notify
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984686545|4b06bfd24b2e6221c4a3a99596ecb8f84a551e45] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992246611|81e4102f71e3fd23204d74a76bc815fdd169c9d6] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720992246611|1dae04b11ae35acb3e65701f0d359ff83f365233] old parent not cached
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720984686545|97bdc17fa656b56c726d0646810fe579639d2fa5] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630368757|5c2d0a5aed5efa571ddd115745d8b43f08e8e1da] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630825454|6827bc0337511f97013b3352dde0397f9ff09222] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720993472414|f183415b1bccba13abdd24e5546b51ac5ebc122d] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720984686545|598dd2fceb30d4a2dfcf2d7a3c48fdcedf0e84d0] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630825454|4705126be58cf2f6c60f72715ede0c91fd6f4032] added old path ("dir") for notify
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630368757|7b267321ccb3a877dd439bb1b46a18fb761dee22] added old path ("dir") for notify
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633474778|43141f5d607343865ac814bfecf61e15954e8318] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:15 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:13:15 DEBUG : : invalidating directory cache
2024/12/10 01:13:15 DEBUG : dir: invalidating directory cache
2024/12/10 01:13:15 DEBUG : : >changeNotify: 
2024/12/10 01:13:15 DEBUG : : changeNotify: relativePath="time_test", type=1
2024/12/10 01:13:15 DEBUG : : >changeNotify: 
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': Received 25 events, resulting in 5 paths and 2 notifications
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277941914")
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] ignored due to duplicate EventID
2024/12/10 01:13:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] ignored due to duplicate EventID
2024/12/10 01:13:16 DEBUG : dir/file1: Open: flags=O_WRONLY
2024/12/10 01:13:16 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:13:16 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:13:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:13:16 DEBUG : dir/file1(0xc0005e6e40): close: 
2024/12/10 01:13:17 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2024/12/10 01:13:17 DEBUG : dir/file1(0xc0005e6e40): >close: err=<nil>
2024/12/10 01:13:17 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:13:17 DEBUG : dir: Looking for writers
2024/12/10 01:13:17 DEBUG : file1: reading active writers
2024/12/10 01:13:17 DEBUG : : Looking for writers
2024/12/10 01:13:17 DEBUG : dir: reading active writers
2024/12/10 01:13:17 DEBUG : >WaitForWriters: 
2024/12/10 01:13:18 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:13:18 DEBUG : dir: Looking for writers
2024/12/10 01:13:18 DEBUG : file1: reading active writers
2024/12/10 01:13:18 DEBUG : : Looking for writers
2024/12/10 01:13:18 DEBUG : dir: reading active writers
2024/12/10 01:13:18 DEBUG : >WaitForWriters: 
2024/12/10 01:13:18 DEBUG : vfs cache: cleaner exiting
=== RUN   TestFileSetModTime/cache=full,open=true,write=true
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:13:21 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:13:21 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:21 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:21 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:21 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:13:21 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:21 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:21 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:13:21 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:13:21 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277891952")
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633707550|364004daa526b5c8fe83f837fa57aea96057620d] added new path ("dir") for notify
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720988583966|76349f6d0bae9602ad9edf70ee287e6347d605c2] new parent not found
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["rclone-test-zunagey2hato"(0)|folder|ITEM_CREATE|297631307118|50d9d6515f9ba1fab304106db6ff1739686bec7a] new parent not found
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_RENAME|1720979115978|cf08fafc1e132ca0053a9b26e6fb36716235c348] added new path ("time_test") for notify
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992246611|b48fed53aebabbf920be305ea6cbe34a0355262c] new parent not found
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_UPLOAD|1720979115978|4f31e90a25da2128601692b3dc697d1750d42da1] added new path ("time_test") for notify
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984686545|4b06bfd24b2e6221c4a3a99596ecb8f84a551e45] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992246611|81e4102f71e3fd23204d74a76bc815fdd169c9d6] new parent not found
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720984686545|97bdc17fa656b56c726d0646810fe579639d2fa5] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630368757|5c2d0a5aed5efa571ddd115745d8b43f08e8e1da] added new path ("dir") for notify
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630825454|6827bc0337511f97013b3352dde0397f9ff09222] added new path ("dir") for notify
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720993472414|f183415b1bccba13abdd24e5546b51ac5ebc122d] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720984686545|598dd2fceb30d4a2dfcf2d7a3c48fdcedf0e84d0] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633474778|43141f5d607343865ac814bfecf61e15954e8318] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297632809364|9ea38fe0cfffa53b4fe9a97bfd2414ef42d13cf8] added old path ("dir") for notify
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720993472414|c501505d726a4766203f279b2489df6fcdf58449] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720984686545|32cb54a12491e76112b841a33742fd35c13ba393] old parent not cached
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720993472414|e16baaeca4860aaaada22e8d91d7ac5f320dcbb7] old parent not cached
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720992194087|fc6f13647fcaa5e783dc2178de94651ee9798e35] old parent not cached
2024/12/10 01:13:25 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:13:25 DEBUG : : invalidating directory cache
2024/12/10 01:13:25 DEBUG : dir: invalidating directory cache
2024/12/10 01:13:25 DEBUG : : >changeNotify: 
2024/12/10 01:13:25 DEBUG : : changeNotify: relativePath="time_test", type=1
2024/12/10 01:13:25 DEBUG : : >changeNotify: 
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': Received 30 events, resulting in 6 paths and 2 notifications
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277952195")
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] ignored due to duplicate EventID
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720993472414|e16baaeca4860aaaada22e8d91d7ac5f320dcbb7] ignored due to duplicate EventID
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] ignored due to duplicate EventID
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720992194087|fc6f13647fcaa5e783dc2178de94651ee9798e35] ignored due to duplicate EventID
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297633474778|7f2c05fa9605a10ff881122ff701a5151f93d6bb] added old path ("dir") for notify
2024/12/10 01:13:25 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:13:25 DEBUG : : >changeNotify: 
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': Received 5 events, resulting in 1 paths and 1 notifications
2024/12/10 01:13:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277952529")
2024/12/10 01:13:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720993472414|e16baaeca4860aaaada22e8d91d7ac5f320dcbb7] ignored due to duplicate EventID
2024/12/10 01:13:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] ignored due to duplicate EventID
2024/12/10 01:13:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720992194087|fc6f13647fcaa5e783dc2178de94651ee9798e35] ignored due to duplicate EventID
2024/12/10 01:13:26 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297633474778|7f2c05fa9605a10ff881122ff701a5151f93d6bb] ignored due to duplicate EventID
2024/12/10 01:13:37 DEBUG : dir/file1: Open: flags=O_WRONLY
2024/12/10 01:13:37 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:13:37 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:13:37 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:13:37 DEBUG : dir/file1(0xc000542e80): _writeAt: size=5, off=0
2024/12/10 01:13:37 DEBUG : dir/file1(0xc000542e80): openPending: 
2024/12/10 01:13:37 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint ""
2024/12/10 01:13:37 DEBUG : dir/file1: vfs cache: truncate to size=14
2024/12/10 01:13:37 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:13:37 DEBUG : dir/file1(0xc000542e80): >openPending: err=<nil>
2024/12/10 01:13:37 DEBUG : dir/file1(0xc000542e80): >_writeAt: n=5, err=<nil>
2024/12/10 01:13:37 DEBUG : dir/file1: vfs cache: setting modification time to 2011-12-25 12:59:59.123456789 +0000 UTC
2024/12/10 01:13:37 DEBUG : dir/file1(0xc000542e80): close: 
2024/12/10 01:13:37 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:5}] - present false
2024/12/10 01:13:37 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 5 length -1
2024/12/10 01:13:37 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728
2024/12/10 01:13:37 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2024/12/10 01:13:37 DEBUG : dir/file1: vfs cache: setting modification time to 2011-12-25 12:59:59.123456789 +0000 UTC
2024/12/10 01:13:37 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2024/12/10 01:13:37 DEBUG : dir/file1(0xc000542e80): >close: err=<nil>
2024/12/10 01:13:37 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:13:37 DEBUG : dir: Looking for writers
2024/12/10 01:13:37 DEBUG : file1: reading active writers
2024/12/10 01:13:37 DEBUG : : Looking for writers
2024/12/10 01:13:37 DEBUG : dir: reading active writers
2024/12/10 01:13:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/12/10 01:13:37 DEBUG : dir: Looking for writers
2024/12/10 01:13:37 DEBUG : file1: reading active writers
2024/12/10 01:13:37 DEBUG : : Looking for writers
2024/12/10 01:13:37 DEBUG : dir: reading active writers
2024/12/10 01:13:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/12/10 01:13:37 DEBUG : dir: Looking for writers
2024/12/10 01:13:37 DEBUG : file1: reading active writers
2024/12/10 01:13:37 DEBUG : : Looking for writers
2024/12/10 01:13:37 DEBUG : dir: reading active writers
2024/12/10 01:13:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/12/10 01:13:37 DEBUG : dir: Looking for writers
2024/12/10 01:13:37 DEBUG : file1: reading active writers
2024/12/10 01:13:37 DEBUG : : Looking for writers
2024/12/10 01:13:37 DEBUG : dir: reading active writers
2024/12/10 01:13:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/12/10 01:13:37 DEBUG : dir/file1: vfs cache: starting upload
2024/12/10 01:13:38 DEBUG : dir: Looking for writers
2024/12/10 01:13:38 DEBUG : file1: reading active writers
2024/12/10 01:13:38 DEBUG : : Looking for writers
2024/12/10 01:13:38 DEBUG : dir: reading active writers
2024/12/10 01:13:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/12/10 01:13:38 DEBUG : dir: Looking for writers
2024/12/10 01:13:38 DEBUG : file1: reading active writers
2024/12/10 01:13:38 DEBUG : : Looking for writers
2024/12/10 01:13:38 DEBUG : dir: reading active writers
2024/12/10 01:13:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/12/10 01:13:38 DEBUG : dir: Looking for writers
2024/12/10 01:13:38 DEBUG : file1: reading active writers
2024/12/10 01:13:38 DEBUG : : Looking for writers
2024/12/10 01:13:38 DEBUG : dir: reading active writers
2024/12/10 01:13:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2024/12/10 01:13:38 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277905623")
2024/12/10 01:13:39 DEBUG : dir: Looking for writers
2024/12/10 01:13:39 DEBUG : file1: reading active writers
2024/12/10 01:13:39 DEBUG : : Looking for writers
2024/12/10 01:13:39 DEBUG : dir: reading active writers
2024/12/10 01:13:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_RENAME|1720979115978|cf08fafc1e132ca0053a9b26e6fb36716235c348] added new path ("time_test") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992246611|b48fed53aebabbf920be305ea6cbe34a0355262c] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_UPLOAD|1720979115978|4f31e90a25da2128601692b3dc697d1750d42da1] added new path ("time_test") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984686545|4b06bfd24b2e6221c4a3a99596ecb8f84a551e45] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992246611|81e4102f71e3fd23204d74a76bc815fdd169c9d6] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720984686545|97bdc17fa656b56c726d0646810fe579639d2fa5] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630368757|5c2d0a5aed5efa571ddd115745d8b43f08e8e1da] added new path ("dir") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630825454|6827bc0337511f97013b3352dde0397f9ff09222] added new path ("dir") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720993472414|f183415b1bccba13abdd24e5546b51ac5ebc122d] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720984686545|598dd2fceb30d4a2dfcf2d7a3c48fdcedf0e84d0] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633474778|43141f5d607343865ac814bfecf61e15954e8318] added new path ("dir") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] added new path ("dir") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720993472414|c501505d726a4766203f279b2489df6fcdf58449] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] new parent not found
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630911858|1cbdd8a968baa8e3b6c0fb0c9408ef24d55b1428] added old path ("dir") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720990868743|b424f6f1f0b2891956c4fb9d7aaf329995b3a7f5] old parent not cached
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:13:39 DEBUG : : changeNotify: relativePath="time_test", type=1
2024/12/10 01:13:39 DEBUG : : invalidating directory cache
2024/12/10 01:13:39 DEBUG : : >changeNotify: 
2024/12/10 01:13:39 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:13:39 DEBUG : dir: invalidating directory cache
2024/12/10 01:13:39 DEBUG : : >changeNotify: 
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': Received 33 events, resulting in 8 paths and 2 notifications
2024/12/10 01:13:39 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277965864")
2024/12/10 01:13:39 DEBUG : dir/file1: sha1 = 5ec62fa7440335ab2e3e5529744fa9627e9c4174 OK
2024/12/10 01:13:39 INFO  : dir/file1: Copied (replaced existing)
2024/12/10 01:13:39 DEBUG : dir/file1: vfs cache: fingerprint now "14,2011-12-25 12:59:59 +0000 UTC,5ec62fa7440335ab2e3e5529744fa9627e9c4174"
2024/12/10 01:13:39 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2024/12/10 01:13:39 DEBUG : dir/file1: Not setting pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC as it is already set
2024/12/10 01:13:39 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:13:39 INFO  : dir/file1: vfs cache: upload succeeded try #1
2024/12/10 01:13:40 DEBUG : dir: Looking for writers
2024/12/10 01:13:40 DEBUG : file1: reading active writers
2024/12/10 01:13:40 DEBUG : : Looking for writers
2024/12/10 01:13:40 DEBUG : dir: reading active writers
2024/12/10 01:13:40 DEBUG : >WaitForWriters: 
2024/12/10 01:13:40 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:13:40 DEBUG : dir: Looking for writers
2024/12/10 01:13:40 DEBUG : file1: reading active writers
2024/12/10 01:13:40 DEBUG : : Looking for writers
2024/12/10 01:13:40 DEBUG : dir: reading active writers
2024/12/10 01:13:40 DEBUG : >WaitForWriters: 
2024/12/10 01:13:40 DEBUG : vfs cache: cleaner exiting
2024/12/10 01:13:42 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2024/12/10 01:13:42 DEBUG : pacer: low level retry 1/10 (error Error "502 Bad Gateway" (502))
2024/12/10 01:13:42 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2024/12/10 01:13:43 DEBUG : pacer: Reducing sleep to 15ms
2024/12/10 01:13:45 DEBUG : pacer: Reducing sleep to 11.25ms
2024/12/10 01:13:45 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestFileSetModTime (80.47s)
    --- PASS: TestFileSetModTime/cache=off,open=false,write=false (13.64s)
    --- PASS: TestFileSetModTime/cache=off,open=true,write=false (11.58s)
    --- PASS: TestFileSetModTime/cache=off,open=true,write=true (11.63s)
    --- PASS: TestFileSetModTime/cache=full,open=false,write=false (9.90s)
    --- PASS: TestFileSetModTime/cache=full,open=true,write=false (9.84s)
    --- PASS: TestFileSetModTime/cache=full,open=true,write=true (23.87s)
=== RUN   TestFileOpenRead
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:13:46 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2024/12/10 01:13:46 DEBUG : pacer: low level retry 1/10 (error Error "502 Bad Gateway" (502))
2024/12/10 01:13:46 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2024/12/10 01:13:46 DEBUG : pacer: Reducing sleep to 15ms
2024/12/10 01:13:47 DEBUG : pacer: Reducing sleep to 11.25ms
2024/12/10 01:13:49 DEBUG : pacer: Reducing sleep to 10ms
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277917161")
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["time_test"(0)|file|ITEM_UPLOAD|1720979115978|4f31e90a25da2128601692b3dc697d1750d42da1] added new path ("time_test") for notify
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984686545|4b06bfd24b2e6221c4a3a99596ecb8f84a551e45] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992246611|81e4102f71e3fd23204d74a76bc815fdd169c9d6] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720984686545|97bdc17fa656b56c726d0646810fe579639d2fa5] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630368757|5c2d0a5aed5efa571ddd115745d8b43f08e8e1da] added new path ("dir") for notify
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630825454|6827bc0337511f97013b3352dde0397f9ff09222] added new path ("dir") for notify
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720993472414|f183415b1bccba13abdd24e5546b51ac5ebc122d] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720984686545|598dd2fceb30d4a2dfcf2d7a3c48fdcedf0e84d0] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633474778|43141f5d607343865ac814bfecf61e15954e8318] added new path ("dir") for notify
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] added new path ("dir") for notify
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720993472414|c501505d726a4766203f279b2489df6fcdf58449] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] ignored due to old SequenceID ('\x00')
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] ignored due to old SequenceID ('\x01')
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297635709593|fcb777532159f4598ad369166de5804ab474dbab] added old path ("dir") for notify
2024/12/10 01:13:50 DEBUG : : changeNotify: relativePath="time_test", type=1
2024/12/10 01:13:50 DEBUG : : invalidating directory cache
2024/12/10 01:13:50 DEBUG : : >changeNotify: 
2024/12/10 01:13:50 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:13:50 DEBUG : dir: invalidating directory cache
2024/12/10 01:13:50 DEBUG : : >changeNotify: 
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': Received 32 events, resulting in 7 paths and 2 notifications
2024/12/10 01:13:50 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277977436")
2024/12/10 01:13:51 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] ignored due to duplicate EventID
2024/12/10 01:13:51 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297635709593|fcb777532159f4598ad369166de5804ab474dbab] ignored due to duplicate EventID
2024/12/10 01:13:54 DEBUG : dir/file1: Open: flags=O_RDONLY
2024/12/10 01:13:54 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2024/12/10 01:13:54 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2024/12/10 01:13:55 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2024/12/10 01:13:55 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:13:55 DEBUG : dir: Looking for writers
2024/12/10 01:13:55 DEBUG : file1: reading active writers
2024/12/10 01:13:55 DEBUG : : Looking for writers
2024/12/10 01:13:55 DEBUG : dir: reading active writers
2024/12/10 01:13:55 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenRead (12.79s)
=== RUN   TestFileOpenWrite
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277928823")
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630368757|5c2d0a5aed5efa571ddd115745d8b43f08e8e1da] added new path ("dir") for notify
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630825454|6827bc0337511f97013b3352dde0397f9ff09222] added new path ("dir") for notify
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720993472414|f183415b1bccba13abdd24e5546b51ac5ebc122d] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720984686545|598dd2fceb30d4a2dfcf2d7a3c48fdcedf0e84d0] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633474778|43141f5d607343865ac814bfecf61e15954e8318] added new path ("dir") for notify
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] added new path ("dir") for notify
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720993472414|c501505d726a4766203f279b2489df6fcdf58449] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] ignored due to old SequenceID ('\x01')
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] ignored due to old SequenceID ('\x01')
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720992199019|90d365b0b59c23e38f87eeb55afe9b13bc147248] old parent not cached
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720983255668|73e8da743d36fb00ba71d1d73c78005723c52999] old parent not cached
2024/12/10 01:14:02 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:02 DEBUG : : invalidating directory cache
2024/12/10 01:14:02 DEBUG : dir: invalidating directory cache
2024/12/10 01:14:02 DEBUG : : >changeNotify: 
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': Received 30 events, resulting in 6 paths and 1 notifications
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277989126")
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] ignored due to duplicate EventID
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720983255668|73e8da743d36fb00ba71d1d73c78005723c52999] ignored due to duplicate EventID
2024/12/10 01:14:02 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:14:02 DEBUG : box root 'rclone-test-zunagey2hato': File to upload is small (25 bytes), uploading instead of streaming
2024/12/10 01:14:04 DEBUG : dir/file1: sha1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK
2024/12/10 01:14:04 DEBUG : dir/file1: Size and sha1 of src and dst objects identical
2024/12/10 01:14:04 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:14:04 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:04 DEBUG : dir: Looking for writers
2024/12/10 01:14:04 DEBUG : file1: reading active writers
2024/12/10 01:14:04 DEBUG : : Looking for writers
2024/12/10 01:14:04 DEBUG : dir: reading active writers
2024/12/10 01:14:04 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenWrite (9.68s)
=== RUN   TestFileRemove
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:14:11 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277938696")
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720984686545|598dd2fceb30d4a2dfcf2d7a3c48fdcedf0e84d0] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297633474778|43141f5d607343865ac814bfecf61e15954e8318] added new path ("dir") for notify
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] added new path ("dir") for notify
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720993472414|c501505d726a4766203f279b2489df6fcdf58449] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297634854183|655f13ec33ed0d79a95fe5115b9b090d3156eeb5] added old path ("dir") for notify
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] ignored due to old SequenceID ('\x01')
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630955163|eea60b55a63a5afe23a53a00c3cac9129508d17d] added old path ("dir") for notify
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] ignored due to old SequenceID ('\x01')
2024/12/10 01:14:12 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:12 DEBUG : : invalidating directory cache
2024/12/10 01:14:12 DEBUG : dir: invalidating directory cache
2024/12/10 01:14:12 DEBUG : : >changeNotify: 
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': Received 32 events, resulting in 6 paths and 1 notifications
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277998938")
2024/12/10 01:14:12 DEBUG : dir/file1: Remove: 
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] ignored due to duplicate EventID
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] ignored due to duplicate EventID
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630955163|eea60b55a63a5afe23a53a00c3cac9129508d17d] ignored due to duplicate EventID
2024/12/10 01:14:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] ignored due to duplicate EventID
2024/12/10 01:14:13 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:14:13 DEBUG : dir/file1: >Remove: err=<nil>
2024/12/10 01:14:14 DEBUG : dir/file1: Remove: 
2024/12/10 01:14:14 DEBUG : dir/file1: >Remove: err=Read only file system
2024/12/10 01:14:14 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:14 DEBUG : dir: Looking for writers
2024/12/10 01:14:14 DEBUG : : Looking for writers
2024/12/10 01:14:14 DEBUG : dir: reading active writers
2024/12/10 01:14:14 DEBUG : >WaitForWriters: 
2024/12/10 01:14:14 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277942381")
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990868743|ddc8ed4e553e633d9a71c4d3bc3a69bbc6a47802] ignored due to duplicate EventID
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297632809364|1dc0164a5b5bf5dbcddd2ae32d1d26641cf6d08c] ignored due to duplicate EventID
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_RENAME|1720993472414|c501505d726a4766203f279b2489df6fcdf58449] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] ignored due to old SequenceID ('\x01')
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] ignored due to old SequenceID ('\x01')
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720994492660|c9a6ede6cf17b9463009313a2f5613bce22eff01] old parent not cached
2024/12/10 01:14:15 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:15 DEBUG : : >changeNotify: 
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 4 paths and 1 notifications
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278001911")
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630955163|eea60b55a63a5afe23a53a00c3cac9129508d17d] ignored due to duplicate EventID
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] ignored due to duplicate EventID
2024/12/10 01:14:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720994492660|c9a6ede6cf17b9463009313a2f5613bce22eff01] ignored due to duplicate EventID
--- PASS: TestFileRemove (8.71s)
=== RUN   TestFileRemoveAll
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:14:21 DEBUG : dir/file1: Remove: 
2024/12/10 01:14:21 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277948546")
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720993472414|f818791bd6665bc1cb6cb4667d76ee7709ba8c4b] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992194087|6b93b5f7ae240d1b6d9416a85201485b74a7e6af] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720982404683|1a3513f68d5074d8259f6d464b96eed6a930fe89] old parent not cached
2024/12/10 01:14:22 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:22 DEBUG : : invalidating directory cache
2024/12/10 01:14:22 DEBUG : dir: invalidating directory cache
2024/12/10 01:14:22 DEBUG : : >changeNotify: 
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': Received 25 events, resulting in 4 paths and 1 notifications
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278008792")
2024/12/10 01:14:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720982404683|1a3513f68d5074d8259f6d464b96eed6a930fe89] ignored due to duplicate EventID
2024/12/10 01:14:22 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:14:22 DEBUG : dir/file1: >Remove: err=<nil>
2024/12/10 01:14:23 DEBUG : dir/file1: Remove: 
2024/12/10 01:14:23 DEBUG : dir/file1: >Remove: err=Read only file system
2024/12/10 01:14:23 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:23 DEBUG : dir: Looking for writers
2024/12/10 01:14:23 DEBUG : : Looking for writers
2024/12/10 01:14:23 DEBUG : dir: reading active writers
2024/12/10 01:14:23 DEBUG : >WaitForWriters: 
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277952781")
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720993472414|e16baaeca4860aaaada22e8d91d7ac5f320dcbb7] ignored due to duplicate EventID
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720990868743|3afdbc680b51eeedc1093ab1ed7e547b09414d91] ignored due to duplicate EventID
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720992194087|fc6f13647fcaa5e783dc2178de94651ee9798e35] ignored due to duplicate EventID
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297633474778|7f2c05fa9605a10ff881122ff701a5151f93d6bb] ignored due to duplicate EventID
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720992199019|1f0b5dda02e2f3d5187f623d902c7297fabcb7c8] new parent not found
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630911858|329f198de58ca02ebcd5236891ea84767d1d5030] added new path ("dir") for notify
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_RENAME|1720992194087|e2f24f889912ff64839b25b4dd147c28ddd48b38] new parent not found
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] new parent not found
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:25 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:25 DEBUG : : >changeNotify: 
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': Received 25 events, resulting in 4 paths and 1 notifications
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278012185")
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] ignored due to duplicate EventID
2024/12/10 01:14:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] ignored due to duplicate EventID
--- PASS: TestFileRemoveAll (9.31s)
=== RUN   TestFileOpen
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:14:31 DEBUG : dir/file1: Open: flags=O_RDONLY
2024/12/10 01:14:31 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2024/12/10 01:14:31 DEBUG : dir/file1: Open: flags=O_WRONLY
2024/12/10 01:14:31 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2024/12/10 01:14:31 DEBUG : dir/file1: Open: flags=O_RDWR
2024/12/10 01:14:31 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2024/12/10 01:14:31 DEBUG : dir/file1: Open: flags=0x3
2024/12/10 01:14:31 DEBUG : dir/file1: Can't figure out how to open with flags: 0x3
2024/12/10 01:14:31 DEBUG : dir/file1: >Open: fd=<nil>, err=permission denied
2024/12/10 01:14:31 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:31 DEBUG : dir: Looking for writers
2024/12/10 01:14:31 DEBUG : file1: reading active writers
2024/12/10 01:14:31 DEBUG : : Looking for writers
2024/12/10 01:14:31 DEBUG : dir: reading active writers
2024/12/10 01:14:31 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpen (8.34s)
=== RUN   TestFileRename
=== RUN   TestFileRename/off,forceCache=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:14:38 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277966307")
2024/12/10 01:14:38 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:38 DEBUG : dir: Looking for writers
2024/12/10 01:14:38 DEBUG : file1: reading active writers
2024/12/10 01:14:38 DEBUG : : Looking for writers
2024/12/10 01:14:38 DEBUG : dir: reading active writers
2024/12/10 01:14:38 DEBUG : >WaitForWriters: 
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] new parent not found
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720984173482|6aff00585d7f156eedc10f6896fc463395a67d5d] old parent not cached
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297635985241|fc5f2484d20db65194fc534eaeea8ff2aaebdb18] added old path ("dir") for notify
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631398626|3232f0c2fab4814f32c7183f8db75194ecf57be2] added old path ("dir") for notify
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:14:39 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:39 DEBUG : : >changeNotify: 
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': Received 23 events, resulting in 5 paths and 1 notifications
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278025873")
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] ignored due to duplicate EventID
2024/12/10 01:14:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] ignored due to duplicate EventID
2024/12/10 01:14:41 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:14:41 DEBUG : newLeaf: Updating file with newLeaf 0xc0007dc3c0
2024/12/10 01:14:41 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:14:41 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:14:43 INFO  : newLeaf: Moved (server-side) to: dir/file1
2024/12/10 01:14:43 DEBUG : dir/file1: Updating file with dir/file1 0xc0007dc3c0
2024/12/10 01:14:43 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2024/12/10 01:14:43 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:14:44 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:14:44 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2024/12/10 01:14:44 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:14:44 DEBUG : dir/file1: File is currently open, delaying rename 0xc0007dc3c0
2024/12/10 01:14:44 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:14:44 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:14:44 DEBUG : box root 'rclone-test-zunagey2hato': File to upload is small (25 bytes), uploading instead of streaming
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277972402")
2024/12/10 01:14:45 DEBUG : dir/file1: sha1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK
2024/12/10 01:14:45 DEBUG : dir/file1: Size and sha1 of src and dst objects identical
2024/12/10 01:14:45 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:14:45 DEBUG : newLeaf: Running delayed rename now
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635709593|fb724ffc37a5ea459e5ce3167b31c5832cc3fadb] added new path ("dir") for notify
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720992199019|ca916cba3f0e8ba2a16eca27a6b81abc9b5a3fa2] new parent not found
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630944705|c09891b4228c9a2a84bb1b7388689d967c0ebdad] added old path ("dir") for notify
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:45 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:45 DEBUG : : invalidating directory cache
2024/12/10 01:14:45 DEBUG : dir: invalidating directory cache
2024/12/10 01:14:45 DEBUG : : >changeNotify: 
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': Received 25 events, resulting in 6 paths and 1 notifications
2024/12/10 01:14:45 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278032649")
2024/12/10 01:14:46 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630944705|c09891b4228c9a2a84bb1b7388689d967c0ebdad] ignored due to duplicate EventID
2024/12/10 01:14:46 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] ignored due to duplicate EventID
2024/12/10 01:14:47 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:14:47 DEBUG : newLeaf: Updating file with newLeaf 0xc0007dc3c0
2024/12/10 01:14:47 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:47 DEBUG : dir: Looking for writers
2024/12/10 01:14:47 DEBUG : : Looking for writers
2024/12/10 01:14:47 DEBUG : dir: reading active writers
2024/12/10 01:14:47 DEBUG : newLeaf: reading active writers
2024/12/10 01:14:47 DEBUG : >WaitForWriters: 
2024/12/10 01:14:48 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:48 DEBUG : dir: Looking for writers
2024/12/10 01:14:48 DEBUG : : Looking for writers
2024/12/10 01:14:48 DEBUG : dir: reading active writers
2024/12/10 01:14:48 DEBUG : newLeaf: reading active writers
2024/12/10 01:14:48 DEBUG : >WaitForWriters: 
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277977958")
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297635709593|fcb777532159f4598ad369166de5804ab474dbab] ignored due to duplicate EventID
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:50 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:50 DEBUG : : >changeNotify: 
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': Received 23 events, resulting in 5 paths and 1 notifications
2024/12/10 01:14:50 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278037422")
=== RUN   TestFileRename/minimal,forceCache=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:14:51 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:14:51 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:14:51 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:14:51 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:14:51 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:14:51 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:14:51 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:14:51 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:14:51 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:14:51 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:14:56 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:14:56 DEBUG : dir: Looking for writers
2024/12/10 01:14:56 DEBUG : file1: reading active writers
2024/12/10 01:14:56 DEBUG : : Looking for writers
2024/12/10 01:14:56 DEBUG : dir: reading active writers
2024/12/10 01:14:56 DEBUG : >WaitForWriters: 
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277985200")
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983255668|3b19bc4c0397b41391972fa15d5564db6a94c41f] new parent not found
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] added new path ("dir") for notify
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] ignored due to old SequenceID ('\x00')
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720982003238|d1a441990a5cede654d202efc938f5c4f14032f3] old parent not cached
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to old SequenceID ('\x04')
2024/12/10 01:14:58 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:14:58 DEBUG : : invalidating directory cache
2024/12/10 01:14:58 DEBUG : dir: invalidating directory cache
2024/12/10 01:14:58 DEBUG : : >changeNotify: 
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': Received 24 events, resulting in 5 paths and 1 notifications
2024/12/10 01:14:58 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278045463")
2024/12/10 01:14:59 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:14:59 DEBUG : newLeaf: Updating file with newLeaf 0xc000192e40
2024/12/10 01:14:59 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:14:59 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:14:59 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to duplicate EventID
2024/12/10 01:15:01 INFO  : newLeaf: Moved (server-side) to: dir/file1
2024/12/10 01:15:01 DEBUG : dir/file1: Updating file with dir/file1 0xc000192e40
2024/12/10 01:15:01 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2024/12/10 01:15:01 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:02 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:15:02 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2024/12/10 01:15:02 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:02 DEBUG : dir/file1: File is currently open, delaying rename 0xc000192e40
2024/12/10 01:15:02 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:15:02 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': File to upload is small (25 bytes), uploading instead of streaming
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277989539")
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297634854183|501cddeaf179d8291fe98d63a18699d2dad64b93] ignored due to duplicate EventID
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720983255668|73e8da743d36fb00ba71d1d73c78005723c52999] ignored due to duplicate EventID
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631249973|d1ccae836e9a56098978f30aaa1ab0241aa1780d] added old path ("dir") for notify
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:02 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:02 DEBUG : : >changeNotify: 
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': Received 25 events, resulting in 5 paths and 1 notifications
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278049089")
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631249973|d1ccae836e9a56098978f30aaa1ab0241aa1780d] ignored due to duplicate EventID
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to duplicate EventID
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to duplicate EventID
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': Received 5 events, resulting in 0 paths and 0 notifications
2024/12/10 01:15:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278049497")
2024/12/10 01:15:03 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631249973|d1ccae836e9a56098978f30aaa1ab0241aa1780d] ignored due to duplicate EventID
2024/12/10 01:15:03 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to duplicate EventID
2024/12/10 01:15:03 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to duplicate EventID
2024/12/10 01:15:03 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] ignored due to duplicate EventID
2024/12/10 01:15:03 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to duplicate EventID
2024/12/10 01:15:04 DEBUG : dir/file1: sha1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK
2024/12/10 01:15:04 DEBUG : dir/file1: Size and sha1 of src and dst objects identical
2024/12/10 01:15:04 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:04 DEBUG : newLeaf: Running delayed rename now
2024/12/10 01:15:06 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:15:06 DEBUG : newLeaf: Updating file with newLeaf 0xc000192e40
2024/12/10 01:15:06 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:06 DEBUG : dir: Looking for writers
2024/12/10 01:15:06 DEBUG : : Looking for writers
2024/12/10 01:15:06 DEBUG : dir: reading active writers
2024/12/10 01:15:06 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:06 DEBUG : >WaitForWriters: 
2024/12/10 01:15:07 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:07 DEBUG : dir: Looking for writers
2024/12/10 01:15:07 DEBUG : : Looking for writers
2024/12/10 01:15:07 DEBUG : dir: reading active writers
2024/12/10 01:15:07 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:07 DEBUG : >WaitForWriters: 
2024/12/10 01:15:07 DEBUG : vfs cache: cleaner exiting
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277994874")
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] added new path ("dir") for notify
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] new parent not found
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] new parent not found
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:08 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:08 DEBUG : : invalidating directory cache
2024/12/10 01:15:08 DEBUG : dir: invalidating directory cache
2024/12/10 01:15:08 DEBUG : : >changeNotify: 
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 5 paths and 1 notifications
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278055236")
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to duplicate EventID
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to duplicate EventID
2024/12/10 01:15:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to duplicate EventID
=== RUN   TestFileRename/minimal,forceCache=true
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:15:10 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:15:10 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:10 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:10 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:10 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:15:10 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:10 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:10 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:15:10 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:10 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:15:11 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031277999458")
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630955163|56287deb7ce1e97254e883a48d0e61999e78348c] ignored due to duplicate EventID
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720994492660|57e08cb5fc5e3fe31577f3f2b44616f9c0bf4825] ignored due to duplicate EventID
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630955163|eea60b55a63a5afe23a53a00c3cac9129508d17d] ignored due to duplicate EventID
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] ignored due to duplicate EventID
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:12 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:12 DEBUG : : >changeNotify: 
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 4 paths and 1 notifications
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278058955")
2024/12/10 01:15:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] ignored due to duplicate EventID
2024/12/10 01:15:14 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278002280")
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630955163|eea60b55a63a5afe23a53a00c3cac9129508d17d] ignored due to duplicate EventID
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994492660|5aca95a0f267e2ca9ad7d79e71973e20855cc60f] ignored due to duplicate EventID
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_TRASH|1720994492660|c9a6ede6cf17b9463009313a2f5613bce22eff01] ignored due to duplicate EventID
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720994984953|e66c2aeb4fa8cc437bd8b09ea85890b20dd51b87] added old path ("newLeaf") for notify
2024/12/10 01:15:15 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:15 DEBUG : : >changeNotify: 
2024/12/10 01:15:15 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:15 DEBUG : : >changeNotify: 
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': Received 28 events, resulting in 5 paths and 2 notifications
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278061935")
2024/12/10 01:15:15 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720994984953|e66c2aeb4fa8cc437bd8b09ea85890b20dd51b87] ignored due to duplicate EventID
2024/12/10 01:15:15 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2024/12/10 01:15:15 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:15:15 DEBUG : dir/file1(0xc000542280): openPending: 
2024/12/10 01:15:15 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint ""
2024/12/10 01:15:15 DEBUG : dir/file1: vfs cache: truncate to size=14
2024/12/10 01:15:15 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:15 DEBUG : dir/file1(0xc000542280): >openPending: err=<nil>
2024/12/10 01:15:15 DEBUG : dir/file1: vfs cache: truncate to size=0
2024/12/10 01:15:15 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:15:15 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:15 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:15:15 DEBUG : dir/file1(0xc000542280): _writeAt: size=14, off=0
2024/12/10 01:15:15 DEBUG : dir/file1(0xc000542280): >_writeAt: n=14, err=<nil>
2024/12/10 01:15:15 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2024/12/10 01:15:15 DEBUG : dir/file1(0xc000542280): close: 
2024/12/10 01:15:15 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2024/12/10 01:15:15 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2024/12/10 01:15:15 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2024/12/10 01:15:15 DEBUG : dir/file1(0xc000542280): >close: err=<nil>
2024/12/10 01:15:15 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:15 DEBUG : dir: Looking for writers
2024/12/10 01:15:15 DEBUG : file1: reading active writers
2024/12/10 01:15:15 DEBUG : : Looking for writers
2024/12/10 01:15:15 DEBUG : dir: reading active writers
2024/12/10 01:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/12/10 01:15:15 DEBUG : dir: Looking for writers
2024/12/10 01:15:15 DEBUG : file1: reading active writers
2024/12/10 01:15:15 DEBUG : : Looking for writers
2024/12/10 01:15:15 DEBUG : dir: reading active writers
2024/12/10 01:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/12/10 01:15:15 DEBUG : dir: Looking for writers
2024/12/10 01:15:15 DEBUG : file1: reading active writers
2024/12/10 01:15:15 DEBUG : : Looking for writers
2024/12/10 01:15:15 DEBUG : dir: reading active writers
2024/12/10 01:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/12/10 01:15:15 DEBUG : dir: Looking for writers
2024/12/10 01:15:15 DEBUG : file1: reading active writers
2024/12/10 01:15:15 DEBUG : : Looking for writers
2024/12/10 01:15:15 DEBUG : dir: reading active writers
2024/12/10 01:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/12/10 01:15:15 DEBUG : dir/file1: vfs cache: starting upload
2024/12/10 01:15:15 DEBUG : dir: Looking for writers
2024/12/10 01:15:15 DEBUG : file1: reading active writers
2024/12/10 01:15:15 DEBUG : : Looking for writers
2024/12/10 01:15:15 DEBUG : dir: reading active writers
2024/12/10 01:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/12/10 01:15:15 DEBUG : dir: Looking for writers
2024/12/10 01:15:15 DEBUG : file1: reading active writers
2024/12/10 01:15:15 DEBUG : : Looking for writers
2024/12/10 01:15:15 DEBUG : dir: reading active writers
2024/12/10 01:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/12/10 01:15:16 DEBUG : dir: Looking for writers
2024/12/10 01:15:16 DEBUG : file1: reading active writers
2024/12/10 01:15:16 DEBUG : : Looking for writers
2024/12/10 01:15:16 DEBUG : dir: reading active writers
2024/12/10 01:15:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2024/12/10 01:15:16 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278003593")
2024/12/10 01:15:16 DEBUG : dir: Looking for writers
2024/12/10 01:15:16 DEBUG : file1: reading active writers
2024/12/10 01:15:16 DEBUG : : Looking for writers
2024/12/10 01:15:16 DEBUG : dir: reading active writers
2024/12/10 01:15:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297635971084|5c63c0355a14ac6ac5492ed4e4fbf403c5dd203f] added old path ("dir") for notify
2024/12/10 01:15:17 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:17 DEBUG : : invalidating directory cache
2024/12/10 01:15:17 DEBUG : dir: invalidating directory cache
2024/12/10 01:15:17 DEBUG : : >changeNotify: 
2024/12/10 01:15:17 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:17 DEBUG : : >changeNotify: 
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': Received 27 events, resulting in 7 paths and 2 notifications
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278063823")
2024/12/10 01:15:17 DEBUG : dir/file1: sha1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK
2024/12/10 01:15:17 INFO  : dir/file1: Copied (replaced existing)
2024/12/10 01:15:17 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2024/12/10 01:15:17 DEBUG : dir/file1: Not setting pending mod time 2001-02-03 04:05:06.499999999 +0000 UTC as it is already set
2024/12/10 01:15:17 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:17 INFO  : dir/file1: vfs cache: upload succeeded try #1
2024/12/10 01:15:17 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297635971084|5c63c0355a14ac6ac5492ed4e4fbf403c5dd203f] ignored due to duplicate EventID
2024/12/10 01:15:17 DEBUG : dir: Looking for writers
2024/12/10 01:15:17 DEBUG : file1: reading active writers
2024/12/10 01:15:17 DEBUG : : Looking for writers
2024/12/10 01:15:17 DEBUG : dir: reading active writers
2024/12/10 01:15:17 DEBUG : >WaitForWriters: 
2024/12/10 01:15:17 DEBUG : dir/file1: Open: flags=O_RDONLY
2024/12/10 01:15:17 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:15:17 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:15:17 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:15:17 DEBUG : dir/file1(0xc000a04900): _readAt: size=512, off=0
2024/12/10 01:15:17 DEBUG : dir/file1(0xc000a04900): openPending: 
2024/12/10 01:15:17 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6"
2024/12/10 01:15:17 DEBUG : dir/file1: vfs cache: truncate to size=14 (not needed as size correct)
2024/12/10 01:15:17 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:17 DEBUG : dir/file1(0xc000a04900): >openPending: err=<nil>
2024/12/10 01:15:17 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2024/12/10 01:15:17 DEBUG : dir/file1(0xc000a04900): >_readAt: n=14, err=EOF
2024/12/10 01:15:17 DEBUG : dir/file1(0xc000a04900): close: 
2024/12/10 01:15:17 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800
2024/12/10 01:15:17 DEBUG : dir/file1(0xc000a04900): >close: err=<nil>
2024/12/10 01:15:20 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:15:20 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2024/12/10 01:15:20 DEBUG : newLeaf: Updating file with newLeaf 0xc000590000
2024/12/10 01:15:20 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:15:20 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:21 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278009107")
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_TRASH|1720982404683|1a3513f68d5074d8259f6d464b96eed6a930fe89] ignored due to duplicate EventID
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720983477470|d0ada62d799f69ba1e0ae372f2f0e0aa8df2adc7] added old path ("newLeaf") for notify
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] ignored due to old SequenceID ('\x02')
2024/12/10 01:15:22 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:22 DEBUG : : >changeNotify: 
2024/12/10 01:15:22 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:22 DEBUG : : >changeNotify: 
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 8 paths and 2 notifications
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278068795")
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720983477470|d0ada62d799f69ba1e0ae372f2f0e0aa8df2adc7] ignored due to duplicate EventID
2024/12/10 01:15:22 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] ignored due to duplicate EventID
2024/12/10 01:15:23 INFO  : newLeaf: Moved (server-side) to: dir/file1
2024/12/10 01:15:23 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2024/12/10 01:15:23 DEBUG : dir/file1: Updating file with dir/file1 0xc000590000
2024/12/10 01:15:23 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2024/12/10 01:15:23 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:24 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:15:24 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:15:24 DEBUG : dir/file1(0xc000a04e00): openPending: 
2024/12/10 01:15:24 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6"
2024/12/10 01:15:24 DEBUG : dir/file1: vfs cache: truncate to size=14 (not needed as size correct)
2024/12/10 01:15:24 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:24 DEBUG : dir/file1(0xc000a04e00): >openPending: err=<nil>
2024/12/10 01:15:24 DEBUG : dir/file1: vfs cache: truncate to size=0
2024/12/10 01:15:24 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:15:24 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:15:24 DEBUG : dir/file1(0xc000a04e00): _writeAt: size=25, off=0
2024/12/10 01:15:24 DEBUG : dir/file1(0xc000a04e00): >_writeAt: n=25, err=<nil>
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278012609")
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] ignored due to duplicate EventID
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] ignored due to duplicate EventID
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] ignored due to old SequenceID ('\x03')
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] ignored due to old SequenceID ('\x03')
2024/12/10 01:15:25 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:25 DEBUG : : >changeNotify: 
2024/12/10 01:15:25 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:25 DEBUG : : >changeNotify: 
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 8 paths and 2 notifications
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278072190")
2024/12/10 01:15:25 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:15:25 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2024/12/10 01:15:25 DEBUG : newLeaf: Updating file with newLeaf 0xc000590000
2024/12/10 01:15:25 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:15:25 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:25 DEBUG : newLeaf(0xc000a04e00): close: 
2024/12/10 01:15:25 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2024/12/10 01:15:25 DEBUG : newLeaf: vfs cache: setting modification time to 2024-12-10 01:15:24.150121458 +0000 UTC m=+190.674075089
2024/12/10 01:15:25 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2024/12/10 01:15:25 DEBUG : newLeaf(0xc000a04e00): >close: err=<nil>
2024/12/10 01:15:25 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:25 DEBUG : dir: Looking for writers
2024/12/10 01:15:25 DEBUG : : Looking for writers
2024/12/10 01:15:25 DEBUG : dir: reading active writers
2024/12/10 01:15:25 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/12/10 01:15:25 DEBUG : dir: Looking for writers
2024/12/10 01:15:25 DEBUG : : Looking for writers
2024/12/10 01:15:25 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:25 DEBUG : dir: reading active writers
2024/12/10 01:15:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/12/10 01:15:25 DEBUG : dir: Looking for writers
2024/12/10 01:15:25 DEBUG : : Looking for writers
2024/12/10 01:15:25 DEBUG : dir: reading active writers
2024/12/10 01:15:25 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/12/10 01:15:25 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] ignored due to duplicate EventID
2024/12/10 01:15:25 DEBUG : dir: Looking for writers
2024/12/10 01:15:25 DEBUG : : Looking for writers
2024/12/10 01:15:25 DEBUG : dir: reading active writers
2024/12/10 01:15:25 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/12/10 01:15:25 DEBUG : newLeaf: vfs cache: starting upload
2024/12/10 01:15:25 DEBUG : dir: Looking for writers
2024/12/10 01:15:25 DEBUG : : Looking for writers
2024/12/10 01:15:25 DEBUG : dir: reading active writers
2024/12/10 01:15:25 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/12/10 01:15:26 DEBUG : dir: Looking for writers
2024/12/10 01:15:26 DEBUG : : Looking for writers
2024/12/10 01:15:26 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:26 DEBUG : dir: reading active writers
2024/12/10 01:15:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278012924")
2024/12/10 01:15:26 DEBUG : dir: Looking for writers
2024/12/10 01:15:26 DEBUG : : Looking for writers
2024/12/10 01:15:26 DEBUG : dir: reading active writers
2024/12/10 01:15:26 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635985241|b778d9a3fa5a2698e1829e07c23a922b9de8bdb0] added new path ("dir") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720984173482|c728df59d21dcd00d1f59fcbe7e8b5e536d2a364] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] ignored due to old SequenceID ('\x03')
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] ignored due to old SequenceID ('\x03')
2024/12/10 01:15:26 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:26 DEBUG : : invalidating directory cache
2024/12/10 01:15:26 DEBUG : dir: invalidating directory cache
2024/12/10 01:15:26 DEBUG : : >changeNotify: 
2024/12/10 01:15:26 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:26 DEBUG : : >changeNotify: 
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 9 paths and 2 notifications
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278073175")
2024/12/10 01:15:26 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] ignored due to duplicate EventID
2024/12/10 01:15:27 DEBUG : dir: Looking for writers
2024/12/10 01:15:27 DEBUG : : Looking for writers
2024/12/10 01:15:27 DEBUG : dir: reading active writers
2024/12/10 01:15:27 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2024/12/10 01:15:27 DEBUG : newLeaf: sha1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK
2024/12/10 01:15:27 INFO  : newLeaf: Copied (replaced existing)
2024/12/10 01:15:27 DEBUG : newLeaf: vfs cache: fingerprint now "25,2024-12-10 01:15:24 +0000 UTC,f1f3d7db56f36d9a5a912b01803c2176a972b9b0"
2024/12/10 01:15:27 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2024/12/10 01:15:27 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:27 INFO  : newLeaf: vfs cache: upload succeeded try #1
2024/12/10 01:15:28 DEBUG : dir: Looking for writers
2024/12/10 01:15:28 DEBUG : : Looking for writers
2024/12/10 01:15:28 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:28 DEBUG : dir: reading active writers
2024/12/10 01:15:28 DEBUG : >WaitForWriters: 
2024/12/10 01:15:28 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:28 DEBUG : dir: Looking for writers
2024/12/10 01:15:28 DEBUG : : Looking for writers
2024/12/10 01:15:28 DEBUG : dir: reading active writers
2024/12/10 01:15:28 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:28 DEBUG : >WaitForWriters: 
2024/12/10 01:15:28 DEBUG : vfs cache: cleaner exiting
=== RUN   TestFileRename/writes,forceCache=false
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:15:32 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:15:32 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:32 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:32 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:32 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:15:32 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:32 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:32 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:15:32 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:32 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278021244")
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630944705|4e4af3bd3cbe299aca18171521b5002f73cbcf88] added new path ("dir") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631398626|81c73fa66cab733bdd22be0875ca1f73087699f7] added new path ("dir") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] ignored due to old SequenceID ('\x05')
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] ignored due to old SequenceID ('\x05')
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] ignored due to old SequenceID ('\x05')
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] ignored due to old SequenceID ('\x05')
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(6)|file|ITEM_TRASH|1720990348337|a598ec280328d08c0fb0fe6cf829a0833e558329] added old path ("newLeaf") for notify
2024/12/10 01:15:34 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:34 DEBUG : : invalidating directory cache
2024/12/10 01:15:34 DEBUG : dir: invalidating directory cache
2024/12/10 01:15:34 DEBUG : : >changeNotify: 
2024/12/10 01:15:34 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:34 DEBUG : : >changeNotify: 
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': Received 30 events, resulting in 9 paths and 2 notifications
2024/12/10 01:15:34 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278081489")
2024/12/10 01:15:35 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] ignored due to duplicate EventID
2024/12/10 01:15:35 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] ignored due to duplicate EventID
2024/12/10 01:15:35 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(6)|file|ITEM_TRASH|1720990348337|a598ec280328d08c0fb0fe6cf829a0833e558329] ignored due to duplicate EventID
2024/12/10 01:15:37 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:37 DEBUG : dir: Looking for writers
2024/12/10 01:15:37 DEBUG : file1: reading active writers
2024/12/10 01:15:37 DEBUG : : Looking for writers
2024/12/10 01:15:37 DEBUG : dir: reading active writers
2024/12/10 01:15:37 DEBUG : >WaitForWriters: 
2024/12/10 01:15:38 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278026182")
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982003238|642a404e8b94c9b5ead7c5262aa8211b002cc6c0] ignored due to duplicate EventID
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720982404683|0f2e85322caf407b7ee1644cc1670bcee6c3e77e] ignored due to duplicate EventID
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] added new path ("dir") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:39 DEBUG : : >changeNotify: 
2024/12/10 01:15:39 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:39 DEBUG : : >changeNotify: 
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': Received 27 events, resulting in 8 paths and 2 notifications
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278085867")
2024/12/10 01:15:39 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:15:39 DEBUG : newLeaf: Updating file with newLeaf 0xc0007dcb40
2024/12/10 01:15:39 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:15:39 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] ignored due to duplicate EventID
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:15:39 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:39 DEBUG : : >changeNotify: 
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': Received 2 events, resulting in 1 paths and 1 notifications
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278086225")
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] ignored due to duplicate EventID
2024/12/10 01:15:39 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] ignored due to duplicate EventID
2024/12/10 01:15:41 INFO  : newLeaf: Moved (server-side) to: dir/file1
2024/12/10 01:15:41 DEBUG : dir/file1: Updating file with dir/file1 0xc0007dcb40
2024/12/10 01:15:41 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2024/12/10 01:15:41 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:42 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:15:42 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:15:42 DEBUG : dir/file1(0xc000a05380): openPending: 
2024/12/10 01:15:42 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint ""
2024/12/10 01:15:42 DEBUG : dir/file1: vfs cache: truncate to size=14
2024/12/10 01:15:42 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:42 DEBUG : dir/file1(0xc000a05380): >openPending: err=<nil>
2024/12/10 01:15:42 DEBUG : dir/file1: vfs cache: truncate to size=0
2024/12/10 01:15:42 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:15:42 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:15:42 DEBUG : dir/file1(0xc000a05380): _writeAt: size=25, off=0
2024/12/10 01:15:42 DEBUG : dir/file1(0xc000a05380): >_writeAt: n=25, err=<nil>
2024/12/10 01:15:44 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:15:44 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2024/12/10 01:15:44 DEBUG : newLeaf: Updating file with newLeaf 0xc0007dcb40
2024/12/10 01:15:44 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:15:44 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:44 DEBUG : newLeaf(0xc000a05380): close: 
2024/12/10 01:15:44 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2024/12/10 01:15:44 DEBUG : newLeaf: vfs cache: setting modification time to 2024-12-10 01:15:42.629425014 +0000 UTC m=+209.153378646
2024/12/10 01:15:44 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2024/12/10 01:15:44 DEBUG : newLeaf(0xc000a05380): >close: err=<nil>
2024/12/10 01:15:44 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/12/10 01:15:44 DEBUG : newLeaf: vfs cache: starting upload
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/12/10 01:15:44 DEBUG : dir: Looking for writers
2024/12/10 01:15:44 DEBUG : : Looking for writers
2024/12/10 01:15:44 DEBUG : dir: reading active writers
2024/12/10 01:15:44 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2024/12/10 01:15:45 DEBUG : dir: Looking for writers
2024/12/10 01:15:45 DEBUG : : Looking for writers
2024/12/10 01:15:45 DEBUG : dir: reading active writers
2024/12/10 01:15:45 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2024/12/10 01:15:45 DEBUG : newLeaf: sha1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK
2024/12/10 01:15:45 INFO  : newLeaf: Copied (replaced existing)
2024/12/10 01:15:45 DEBUG : newLeaf: vfs cache: fingerprint now "25,2024-12-10 01:15:42 +0000 UTC,f1f3d7db56f36d9a5a912b01803c2176a972b9b0"
2024/12/10 01:15:45 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2024/12/10 01:15:45 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:15:45 INFO  : newLeaf: vfs cache: upload succeeded try #1
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278032953")
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297630944705|c09891b4228c9a2a84bb1b7388689d967c0ebdad] ignored due to duplicate EventID
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631249973|ca7feaf2dc38a1db4243bbf26e4303fe0ace82d2] ignored due to duplicate EventID
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631768678|c6eeef1deb18ea246741f1cb13be4e47a7b27d17] added old path ("dir") for notify
2024/12/10 01:15:45 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:45 DEBUG : : >changeNotify: 
2024/12/10 01:15:45 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:45 DEBUG : : >changeNotify: 
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': Received 27 events, resulting in 9 paths and 2 notifications
2024/12/10 01:15:45 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278092653")
2024/12/10 01:15:46 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631768678|c6eeef1deb18ea246741f1cb13be4e47a7b27d17] ignored due to duplicate EventID
2024/12/10 01:15:46 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x02')
2024/12/10 01:15:46 DEBUG : box root 'rclone-test-zunagey2hato': Received 2 events, resulting in 0 paths and 0 notifications
2024/12/10 01:15:46 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278092988")
2024/12/10 01:15:46 DEBUG : dir: Looking for writers
2024/12/10 01:15:46 DEBUG : : Looking for writers
2024/12/10 01:15:46 DEBUG : dir: reading active writers
2024/12/10 01:15:46 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:46 DEBUG : >WaitForWriters: 
2024/12/10 01:15:46 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631768678|c6eeef1deb18ea246741f1cb13be4e47a7b27d17] ignored due to duplicate EventID
2024/12/10 01:15:46 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to duplicate EventID
2024/12/10 01:15:47 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:47 DEBUG : dir: Looking for writers
2024/12/10 01:15:47 DEBUG : : Looking for writers
2024/12/10 01:15:47 DEBUG : newLeaf: reading active writers
2024/12/10 01:15:47 DEBUG : dir: reading active writers
2024/12/10 01:15:47 DEBUG : >WaitForWriters: 
2024/12/10 01:15:47 DEBUG : vfs cache: cleaner exiting
=== RUN   TestFileRename/writes,forceCache=true
    run.go:180: Remote "box root 'rclone-test-zunagey2hato'", Local "Local file system at /tmp/rclone3155000713", Modify Window "1s"
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278037727")
2024/12/10 01:15:50 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone"
2024/12/10 01:15:50 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:50 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:50 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:50 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:15:50 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfs/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:50 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:50 DEBUG : :local: detected overridden config - adding "{bxYPm}" suffix to name
2024/12/10 01:15:50 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot':/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato" to be canonical ":local{bxYPm}:/home/rclone/.cache/rclone/vfsMeta/TestBox/rclone-test-zunagey2hato"
2024/12/10 01:15:50 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:50 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:50 DEBUG : : >changeNotify: 
2024/12/10 01:15:50 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:50 DEBUG : : >changeNotify: 
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': Received 26 events, resulting in 9 paths and 2 notifications
2024/12/10 01:15:50 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278097396")
2024/12/10 01:15:51 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278038658")
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:52 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:52 DEBUG : : invalidating directory cache
2024/12/10 01:15:52 DEBUG : : >changeNotify: 
2024/12/10 01:15:52 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:52 DEBUG : dir: invalidating directory cache
2024/12/10 01:15:52 DEBUG : : >changeNotify: 
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': Received 26 events, resulting in 9 paths and 2 notifications
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278098891")
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': Received 1 events, resulting in 0 paths and 0 notifications
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278099319")
2024/12/10 01:15:52 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] ignored due to duplicate EventID
2024/12/10 01:15:55 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2024/12/10 01:15:55 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:15:55 DEBUG : dir/file1(0xc000a04980): openPending: 
2024/12/10 01:15:55 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint ""
2024/12/10 01:15:55 DEBUG : dir/file1: vfs cache: truncate to size=14
2024/12/10 01:15:55 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:55 DEBUG : dir/file1(0xc000a04980): >openPending: err=<nil>
2024/12/10 01:15:55 DEBUG : dir/file1: vfs cache: truncate to size=0
2024/12/10 01:15:55 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:15:55 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:55 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:15:55 DEBUG : dir/file1(0xc000a04980): _writeAt: size=14, off=0
2024/12/10 01:15:55 DEBUG : dir/file1(0xc000a04980): >_writeAt: n=14, err=<nil>
2024/12/10 01:15:55 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2024/12/10 01:15:55 DEBUG : dir/file1(0xc000a04980): close: 
2024/12/10 01:15:55 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2024/12/10 01:15:55 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2024/12/10 01:15:55 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2024/12/10 01:15:55 DEBUG : dir/file1(0xc000a04980): >close: err=<nil>
2024/12/10 01:15:55 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:15:55 DEBUG : dir: Looking for writers
2024/12/10 01:15:55 DEBUG : file1: reading active writers
2024/12/10 01:15:55 DEBUG : : Looking for writers
2024/12/10 01:15:55 DEBUG : dir: reading active writers
2024/12/10 01:15:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/12/10 01:15:55 DEBUG : dir: Looking for writers
2024/12/10 01:15:55 DEBUG : file1: reading active writers
2024/12/10 01:15:55 DEBUG : : Looking for writers
2024/12/10 01:15:55 DEBUG : dir: reading active writers
2024/12/10 01:15:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/12/10 01:15:55 DEBUG : dir: Looking for writers
2024/12/10 01:15:55 DEBUG : file1: reading active writers
2024/12/10 01:15:55 DEBUG : : Looking for writers
2024/12/10 01:15:55 DEBUG : dir: reading active writers
2024/12/10 01:15:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/12/10 01:15:55 DEBUG : dir: Looking for writers
2024/12/10 01:15:55 DEBUG : file1: reading active writers
2024/12/10 01:15:55 DEBUG : : Looking for writers
2024/12/10 01:15:55 DEBUG : dir: reading active writers
2024/12/10 01:15:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/12/10 01:15:55 DEBUG : dir/file1: vfs cache: starting upload
2024/12/10 01:15:55 DEBUG : dir: Looking for writers
2024/12/10 01:15:55 DEBUG : file1: reading active writers
2024/12/10 01:15:55 DEBUG : : Looking for writers
2024/12/10 01:15:55 DEBUG : dir: reading active writers
2024/12/10 01:15:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/12/10 01:15:55 DEBUG : dir: Looking for writers
2024/12/10 01:15:55 DEBUG : file1: reading active writers
2024/12/10 01:15:55 DEBUG : : Looking for writers
2024/12/10 01:15:55 DEBUG : dir: reading active writers
2024/12/10 01:15:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/12/10 01:15:56 DEBUG : dir: Looking for writers
2024/12/10 01:15:56 DEBUG : file1: reading active writers
2024/12/10 01:15:56 DEBUG : : Looking for writers
2024/12/10 01:15:56 DEBUG : dir: reading active writers
2024/12/10 01:15:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2024/12/10 01:15:56 DEBUG : dir: Looking for writers
2024/12/10 01:15:56 DEBUG : file1: reading active writers
2024/12/10 01:15:56 DEBUG : : Looking for writers
2024/12/10 01:15:56 DEBUG : dir: reading active writers
2024/12/10 01:15:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2024/12/10 01:15:56 DEBUG : dir/file1: sha1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK
2024/12/10 01:15:56 INFO  : dir/file1: Copied (replaced existing)
2024/12/10 01:15:56 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2024/12/10 01:15:56 DEBUG : dir/file1: Not setting pending mod time 2001-02-03 04:05:06.499999999 +0000 UTC as it is already set
2024/12/10 01:15:56 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:56 INFO  : dir/file1: vfs cache: upload succeeded try #1
2024/12/10 01:15:57 DEBUG : dir: Looking for writers
2024/12/10 01:15:57 DEBUG : file1: reading active writers
2024/12/10 01:15:57 DEBUG : : Looking for writers
2024/12/10 01:15:57 DEBUG : dir: reading active writers
2024/12/10 01:15:57 DEBUG : >WaitForWriters: 
2024/12/10 01:15:57 DEBUG : dir/file1: Open: flags=O_RDONLY
2024/12/10 01:15:57 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:15:57 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:15:57 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:15:57 DEBUG : dir/file1(0xc000984dc0): _readAt: size=512, off=0
2024/12/10 01:15:57 DEBUG : dir/file1(0xc000984dc0): openPending: 
2024/12/10 01:15:57 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6"
2024/12/10 01:15:57 DEBUG : dir/file1: vfs cache: truncate to size=14 (not needed as size correct)
2024/12/10 01:15:57 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:15:57 DEBUG : dir/file1(0xc000984dc0): >openPending: err=<nil>
2024/12/10 01:15:57 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2024/12/10 01:15:57 DEBUG : dir/file1(0xc000984dc0): >_readAt: n=14, err=EOF
2024/12/10 01:15:57 DEBUG : dir/file1(0xc000984dc0): close: 
2024/12/10 01:15:57 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800
2024/12/10 01:15:57 DEBUG : dir/file1(0xc000984dc0): >close: err=<nil>
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278045835")
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720994984953|2cbb61a9067ea3749cbd00f3e4ff565ef25db98b] ignored due to duplicate EventID
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] added new path ("dir") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631101081|500399d456f5f35999dddea37ba2bf5439b91dd0] ignored due to old SequenceID ('\x00')
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_UPLOAD|1720985759439|326b3f19b2bd7406029b4cccbc6bfe6e10184d24] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720985759439|6cd98c1d326fd71e76fb07701359400135e4ddfc] ignored due to old SequenceID ('\x04')
2024/12/10 01:15:58 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:15:58 DEBUG : : >changeNotify: 
2024/12/10 01:15:58 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:15:58 DEBUG : : >changeNotify: 
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': Received 29 events, resulting in 9 paths and 2 notifications
2024/12/10 01:15:58 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278105439")
2024/12/10 01:15:59 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_UPLOAD|1720985759439|326b3f19b2bd7406029b4cccbc6bfe6e10184d24] ignored due to duplicate EventID
2024/12/10 01:15:59 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720985759439|6cd98c1d326fd71e76fb07701359400135e4ddfc] ignored due to duplicate EventID
2024/12/10 01:16:00 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:16:00 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2024/12/10 01:16:00 DEBUG : newLeaf: Updating file with newLeaf 0xc0005903c0
2024/12/10 01:16:00 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:16:00 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278049897")
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631249973|d1ccae836e9a56098978f30aaa1ab0241aa1780d] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720994984953|25018175da914d3b0232c33c7b1336fd5299783b] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720994984953|efbe5c63f3453bb003f98d0518c1cb6ddcd7a8f3] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720994984953|3aa6325936a7d7a5a7f36493f9dab7ae4826e865] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297635971084|6fd6318dfb1e8ebd92fe2a4dabe902e452ec001e] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720994984953|190348441a2d39a52ff2be30c7b3852413740d93] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] added new path ("newLeaf") for notify
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631101081|500399d456f5f35999dddea37ba2bf5439b91dd0] ignored due to old SequenceID ('\x00')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_UPLOAD|1720985759439|326b3f19b2bd7406029b4cccbc6bfe6e10184d24] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720985759439|6cd98c1d326fd71e76fb07701359400135e4ddfc] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720986875263|386f4c11574f55a4c76bff300f7b466763712f26] ignored due to old SequenceID ('\x02')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631101081|4dc07b2fcd3f81ca84a6fa40998f4b557182f8fd] added old path ("dir") for notify
2024/12/10 01:16:02 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:16:02 DEBUG : : >changeNotify: 
2024/12/10 01:16:02 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:16:02 DEBUG : : >changeNotify: 
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': Received 30 events, resulting in 7 paths and 2 notifications
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278109178")
2024/12/10 01:16:02 INFO  : newLeaf: Moved (server-side) to: dir/file1
2024/12/10 01:16:02 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2024/12/10 01:16:02 DEBUG : dir/file1: Updating file with dir/file1 0xc0005903c0
2024/12/10 01:16:02 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2024/12/10 01:16:02 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720986875263|386f4c11574f55a4c76bff300f7b466763712f26] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631101081|4dc07b2fcd3f81ca84a6fa40998f4b557182f8fd] ignored due to duplicate EventID
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720985759439|c15ebe8389b84eb1ffcfb1cf0fda266dbe43ba27] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': Received 3 events, resulting in 0 paths and 0 notifications
2024/12/10 01:16:02 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278109541")
2024/12/10 01:16:03 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720986875263|386f4c11574f55a4c76bff300f7b466763712f26] ignored due to duplicate EventID
2024/12/10 01:16:03 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(1)|folder|ITEM_TRASH|297631101081|4dc07b2fcd3f81ca84a6fa40998f4b557182f8fd] ignored due to duplicate EventID
2024/12/10 01:16:03 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720985759439|c15ebe8389b84eb1ffcfb1cf0fda266dbe43ba27] ignored due to duplicate EventID
2024/12/10 01:16:03 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2024/12/10 01:16:03 DEBUG : dir/file1: newRWFileHandle: 
2024/12/10 01:16:03 DEBUG : dir/file1(0xc0005e6c40): openPending: 
2024/12/10 01:16:03 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6"
2024/12/10 01:16:03 DEBUG : dir/file1: vfs cache: truncate to size=14 (not needed as size correct)
2024/12/10 01:16:03 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2024/12/10 01:16:03 DEBUG : dir/file1(0xc0005e6c40): >openPending: err=<nil>
2024/12/10 01:16:03 DEBUG : dir/file1: vfs cache: truncate to size=0
2024/12/10 01:16:03 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2024/12/10 01:16:03 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2024/12/10 01:16:03 DEBUG : dir/file1(0xc0005e6c40): _writeAt: size=25, off=0
2024/12/10 01:16:03 DEBUG : dir/file1(0xc0005e6c40): >_writeAt: n=25, err=<nil>
2024/12/10 01:16:05 INFO  : dir/file1: Moved (server-side) to: newLeaf
2024/12/10 01:16:05 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2024/12/10 01:16:05 DEBUG : newLeaf: Updating file with newLeaf 0xc0005903c0
2024/12/10 01:16:05 DEBUG : dir: Added virtual directory entry vDel: "file1"
2024/12/10 01:16:05 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:16:05 DEBUG : newLeaf(0xc0005e6c40): close: 
2024/12/10 01:16:05 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2024/12/10 01:16:05 DEBUG : newLeaf: vfs cache: setting modification time to 2024-12-10 01:16:03.545463122 +0000 UTC m=+230.069416794
2024/12/10 01:16:05 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2024/12/10 01:16:05 DEBUG : newLeaf(0xc0005e6c40): >close: err=<nil>
2024/12/10 01:16:05 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2024/12/10 01:16:05 DEBUG : newLeaf: vfs cache: starting upload
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2024/12/10 01:16:05 DEBUG : dir: Looking for writers
2024/12/10 01:16:05 DEBUG : : Looking for writers
2024/12/10 01:16:05 DEBUG : dir: reading active writers
2024/12/10 01:16:05 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2024/12/10 01:16:06 DEBUG : dir: Looking for writers
2024/12/10 01:16:06 DEBUG : : Looking for writers
2024/12/10 01:16:06 DEBUG : dir: reading active writers
2024/12/10 01:16:06 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2024/12/10 01:16:06 DEBUG : newLeaf: sha1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK
2024/12/10 01:16:06 INFO  : newLeaf: Copied (replaced existing)
2024/12/10 01:16:06 DEBUG : newLeaf: vfs cache: fingerprint now "25,2024-12-10 01:16:03 +0000 UTC,f1f3d7db56f36d9a5a912b01803c2176a972b9b0"
2024/12/10 01:16:06 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2024/12/10 01:16:06 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2024/12/10 01:16:06 INFO  : newLeaf: vfs cache: upload succeeded try #1
2024/12/10 01:16:07 DEBUG : dir: Looking for writers
2024/12/10 01:16:07 DEBUG : : Looking for writers
2024/12/10 01:16:07 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:07 DEBUG : dir: reading active writers
2024/12/10 01:16:07 DEBUG : >WaitForWriters: 
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278055603")
2024/12/10 01:16:08 DEBUG : WaitForWriters: timeout=30s
2024/12/10 01:16:08 DEBUG : dir: Looking for writers
2024/12/10 01:16:08 DEBUG : : Looking for writers
2024/12/10 01:16:08 DEBUG : dir: reading active writers
2024/12/10 01:16:08 DEBUG : newLeaf: reading active writers
2024/12/10 01:16:08 DEBUG : >WaitForWriters: 
2024/12/10 01:16:08 DEBUG : vfs cache: cleaner exiting
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720983477470|c3f3b8f6b91f7dbae156168e8b7e31d408c3a978] ignored due to duplicate EventID
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] ignored due to duplicate EventID
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] ignored due to duplicate EventID
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631101081|500399d456f5f35999dddea37ba2bf5439b91dd0] added new path ("dir") for notify
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_UPLOAD|1720985759439|326b3f19b2bd7406029b4cccbc6bfe6e10184d24] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720985759439|6cd98c1d326fd71e76fb07701359400135e4ddfc] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720986875263|386f4c11574f55a4c76bff300f7b466763712f26] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720985759439|c15ebe8389b84eb1ffcfb1cf0fda266dbe43ba27] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720986875263|c60bc177ac20b5de709af1be0199dcc0e52ed02a] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630645154|988679f9c7202850817c70316599381b94297743] ignored due to old SequenceID ('\x00')
2024/12/10 01:16:08 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:16:08 DEBUG : : >changeNotify: 
2024/12/10 01:16:08 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:16:08 DEBUG : : >changeNotify: 
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': Received 27 events, resulting in 6 paths and 2 notifications
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278115133")
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720986875263|c60bc177ac20b5de709af1be0199dcc0e52ed02a] ignored due to duplicate EventID
2024/12/10 01:16:08 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630645154|988679f9c7202850817c70316599381b94297743] ignored due to duplicate EventID
2024/12/10 01:16:10 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278057556")
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720983477470|3036959442f274255ce252fe82f3def97f11b5a7] new parent not found
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720983477470|ef88becb2a39c5fa66bbbac7b4e634717d78b04e] new parent not found
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] new parent not found
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631101081|500399d456f5f35999dddea37ba2bf5439b91dd0] added new path ("dir") for notify
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_UPLOAD|1720985759439|326b3f19b2bd7406029b4cccbc6bfe6e10184d24] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720985759439|6cd98c1d326fd71e76fb07701359400135e4ddfc] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720986875263|386f4c11574f55a4c76bff300f7b466763712f26] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720985759439|c15ebe8389b84eb1ffcfb1cf0fda266dbe43ba27] ignored due to old SequenceID ('\x04')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720986875263|c60bc177ac20b5de709af1be0199dcc0e52ed02a] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630645154|988679f9c7202850817c70316599381b94297743] ignored due to old SequenceID ('\x00')
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720985759439|abbc0edbcbb8ed14e7ce7e72da9aaa8f4ab80bcc] added old path ("newLeaf") for notify
2024/12/10 01:16:11 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:16:11 DEBUG : : invalidating directory cache
2024/12/10 01:16:11 DEBUG : : >changeNotify: 
2024/12/10 01:16:11 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:16:11 DEBUG : dir: invalidating directory cache
2024/12/10 01:16:11 DEBUG : : >changeNotify: 
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': Received 27 events, resulting in 7 paths and 2 notifications
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278117801")
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630645154|988679f9c7202850817c70316599381b94297743] ignored due to duplicate EventID
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720985759439|abbc0edbcbb8ed14e7ce7e72da9aaa8f4ab80bcc] ignored due to duplicate EventID
--- PASS: TestFileRename (97.36s)
    --- PASS: TestFileRename/off,forceCache=false (17.39s)
    --- PASS: TestFileRename/minimal,forceCache=false (18.92s)
    --- PASS: TestFileRename/minimal,forceCache=true (21.46s)
    --- PASS: TestFileRename/writes,forceCache=false (18.21s)
    --- PASS: TestFileRename/writes,forceCache=true (21.38s)
PASS
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': Purge remote
2024/12/10 01:16:11 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278059283")
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_UPLOAD|1720983477470|1b6823b4150109a6ffaf88c32296210769fce5e8] ignored due to duplicate EventID
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720983477470|2689b7c0990275558fb1a943e5869229cdd76caa] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720990348337|12b3fa38c8fe68f888bd5d5496b1d4bf6b2905fd] new parent not found
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720990348337|2f2f0f37bfd8959fda06b0c0d11075d554697d41] new parent not found
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(3)|file|ITEM_MOVE|1720990348337|9d6a35415098c952fc983b3d4fd73f29ad8f4e65] new parent not found
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631768678|f4ffddc5795c94b4723bc643b78a6b731d008fc3] added new path ("dir") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720990348337|ebc5aa721099b382f26e238043d70bcc5fc1f6cd] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_UPLOAD|1720990348337|c3cefec28a0274320573a45a659c285d1c1854b9] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_MOVE|1720990348337|f95d805ac4673aeb098bd71ff18960ed8f0a4dde] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720985759439|59025222ea95709310f403692f6ea172dbffc0ce] new parent not found
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(3)|file|ITEM_MOVE|1720985759439|fe147e000871e4dc25b6a26c62dfffe35cf1e60b] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297631101081|500399d456f5f35999dddea37ba2bf5439b91dd0] added new path ("dir") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(4)|file|ITEM_UPLOAD|1720985759439|326b3f19b2bd7406029b4cccbc6bfe6e10184d24] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(1)|file|ITEM_MOVE|1720985759439|6cd98c1d326fd71e76fb07701359400135e4ddfc] added new path ("newLeaf") for notify
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(1)|file|ITEM_UPLOAD|1720986875263|386f4c11574f55a4c76bff300f7b466763712f26] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(2)|file|ITEM_MOVE|1720985759439|c15ebe8389b84eb1ffcfb1cf0fda266dbe43ba27] new parent not found
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(2)|file|ITEM_MOVE|1720986875263|c60bc177ac20b5de709af1be0199dcc0e52ed02a] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["dir"(0)|folder|ITEM_CREATE|297630645154|988679f9c7202850817c70316599381b94297743] ignored due to old SequenceID ('\x00')
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720986875263|38ead18d6adacab54778445a6028d8543af49508] ignored due to old SequenceID ('\x05')
2024/12/10 01:16:12 DEBUG : : changeNotify: relativePath="newLeaf", type=1
2024/12/10 01:16:12 DEBUG : : >changeNotify: 
2024/12/10 01:16:12 DEBUG : : changeNotify: relativePath="dir", type=0
2024/12/10 01:16:12 DEBUG : : >changeNotify: 
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': Received 26 events, resulting in 9 paths and 2 notifications
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': Checking for changes on remote (next_stream_position: "30401031278118930")
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["newLeaf"(5)|file|ITEM_TRASH|1720985759439|abbc0edbcbb8ed14e7ce7e72da9aaa8f4ab80bcc] ignored due to duplicate EventID
2024/12/10 01:16:12 DEBUG : box root 'rclone-test-zunagey2hato': ["file1"(0)|file|ITEM_UPLOAD|1720986875263|38ead18d6adacab54778445a6028d8543af49508] ignored due to duplicate EventID
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose -test.run '^(TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileRemove|TestFileRemoveAll)$|^TestFileRename$/^(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 OK in 3m59.152928425s (try 2/5)