"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestFileReadAtNonZeroLength|TestUnicodeNormalization)$'" - Starting (try 2/5)
2026/01/22 01:36:07 DEBUG : Creating backend with remote "TestDropbox:rclone-test-wajicaf7buse"
2026/01/22 01:36:07 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/01/22 01:36:08 DEBUG : Creating backend with remote "/tmp/rclone939089693"
=== RUN   TestUnicodeNormalization
    run.go:185: Remote "Dropbox root 'rclone-test-wajicaf7buse'", Local "Local file system at /tmp/rclone939089693", Modify Window "1s"
2026/01/22 01:36:09 DEBUG : normal name with no special characters.txt: Uploading chunk 1/1
2026/01/22 01:36:09 DEBUG : normal name with no special characters.txt: Uploading chunk 2/1
2026/01/22 01:36:10 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Adding "normal name with no special characters.txt" to batch
2026/01/22 01:36:10 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Batch idle for 500ms so committing
2026/01/22 01:36:10 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Committing sync batch length 1 starting with: normal name with no special characters.txt
2026/01/22 01:36:11 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Committed sync batch length 1 starting with: normal name with no special characters.txt
2026/01/22 01:36:11 DEBUG : 測試_Русский___ě_áñ: Uploading chunk 1/1
2026/01/22 01:36:11 DEBUG : 測試_Русский___ě_áñ: Uploading chunk 2/1
2026/01/22 01:36:12 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Adding "測試_Русский___ě_áñ" to batch
2026/01/22 01:36:12 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Batch idle for 500ms so committing
2026/01/22 01:36:12 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Committing sync batch length 1 starting with: 測試_Русский___ě_áñ
2026/01/22 01:36:13 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Committed sync batch length 1 starting with: 測試_Русский___ě_áñ
2026/01/22 01:36:14 DEBUG : normal name with no special characters.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/01/22 01:36:14 DEBUG : normal name with no special characters.txt: Open: flags=O_RDONLY
2026/01/22 01:36:14 DEBUG : normal name with no special characters.txt: >Open: fd=normal name with no special characters.txt (r), err=<nil>
2026/01/22 01:36:14 DEBUG : normal name with no special characters.txt: >OpenFile: fd=normal name with no special characters.txt (r), err=<nil>
2026/01/22 01:36:14 DEBUG : normal name with no special characters.txt: ChunkedReader.openRange at 0 length 134217728
2026/01/22 01:36:14 DEBUG : normal name with no special characters.txt: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/01/22 01:36:14 DEBUG : 測試_Русский___ě_áñ: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/01/22 01:36:14 DEBUG : 測試_Русский___ě_áñ: Open: flags=O_RDONLY
2026/01/22 01:36:14 DEBUG : 測試_Русский___ě_áñ: >Open: fd=測試_Русский___ě_áñ (r), err=<nil>
2026/01/22 01:36:14 DEBUG : 測試_Русский___ě_áñ: >OpenFile: fd=測試_Русский___ě_áñ (r), err=<nil>
2026/01/22 01:36:14 DEBUG : 測試_Русский___ě_áñ: ChunkedReader.openRange at 0 length 134217728
2026/01/22 01:36:15 DEBUG : 測試_Русский___ě_áñ: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/01/22 01:36:15 DEBUG : normal name with no special characters.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/01/22 01:36:15 DEBUG : normal name with no special characters.txt: Open: flags=O_RDONLY
2026/01/22 01:36:15 DEBUG : normal name with no special characters.txt: >Open: fd=normal name with no special characters.txt (r), err=<nil>
2026/01/22 01:36:15 DEBUG : normal name with no special characters.txt: >OpenFile: fd=normal name with no special characters.txt (r), err=<nil>
2026/01/22 01:36:15 DEBUG : normal name with no special characters.txt: ChunkedReader.openRange at 0 length 134217728
2026/01/22 01:36:16 DEBUG : normal name with no special characters.txt: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/01/22 01:36:16 DEBUG : 測試_Русский___ě_áñ: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/01/22 01:36:16 DEBUG : 測試_Русский___ě_áñ: >OpenFile: fd=<nil>, err=file does not exist
2026/01/22 01:36:16 DEBUG : WaitForWriters: timeout=30s
2026/01/22 01:36:16 DEBUG : Looking for writers
2026/01/22 01:36:16 DEBUG : normal name with no special characters.txt: reading active writers
2026/01/22 01:36:16 DEBUG : 測試_Русский___ě_áñ: reading active writers
2026/01/22 01:36:16 DEBUG : >WaitForWriters: 
--- PASS: TestUnicodeNormalization (9.62s)
=== RUN   TestFileReadAtNonZeroLength
    run.go:185: Remote "Dropbox root 'rclone-test-wajicaf7buse'", Local "Local file system at /tmp/rclone939089693", Modify Window "1s"
2026/01/22 01:36:18 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/01/22 01:36:18 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/01/22 01:36:18 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/01/22 01:36:18 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/01/22 01:36:18 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/01/22 01:36:18 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/01/22 01:36:18 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': File to upload is small (100 bytes), uploading instead of streaming
2026/01/22 01:36:18 DEBUG : file1: Uploading chunk 1/1
2026/01/22 01:36:19 DEBUG : file1: Uploading chunk 2/1
2026/01/22 01:36:19 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Adding "file1" to batch
2026/01/22 01:36:19 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Batch idle for 500ms so committing
2026/01/22 01:36:19 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Committing sync batch length 1 starting with: file1
2026/01/22 01:36:20 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Committed sync batch length 1 starting with: file1
2026/01/22 01:36:20 DEBUG : file1: size = 100 OK
2026/01/22 01:36:20 DEBUG : file1: dropbox = 84363465fea02cefe90693199f6ae1f18743061f04538bcfc09ed6c5af4b112f OK
2026/01/22 01:36:20 DEBUG : file1: Size and dropbox of src and dst objects identical
2026/01/22 01:36:20 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/01/22 01:36:20 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=----------
2026/01/22 01:36:20 DEBUG : file1: Open: flags=O_RDONLY
2026/01/22 01:36:20 DEBUG : file1: >Open: fd=file1 (r), err=<nil>
2026/01/22 01:36:20 DEBUG : file1: >OpenFile: fd=file1 (r), err=<nil>
2026/01/22 01:36:20 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728
2026/01/22 01:36:21 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728
2026/01/22 01:36:21 DEBUG : WaitForWriters: timeout=30s
2026/01/22 01:36:21 DEBUG : Looking for writers
2026/01/22 01:36:21 DEBUG : file1: reading active writers
2026/01/22 01:36:21 DEBUG : >WaitForWriters: 
--- PASS: TestFileReadAtNonZeroLength (4.51s)
PASS
2026/01/22 01:36:22 DEBUG : Dropbox root 'rclone-test-wajicaf7buse': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestFileReadAtNonZeroLength|TestUnicodeNormalization)$'" - Finished OK in 15.104968934s (try 2/5)