"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestDirMkdir|TestDirReadDirAll|TestDirSetModTime|TestDirWalk|TestRWFileHandleSizeCreateNew|TestRcGetVFS|TestVFSNew|TestVFSStat)$'" - Starting (try 2/5)
2021/07/25 06:29:55 DEBUG : Creating backend with remote "TestDropbox:rclone-test-qaburap2kecevav5jolirud2"
2021/07/25 06:29:55 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/07/25 06:29:55 DEBUG : Creating backend with remote "/tmp/rclone215041942"
=== RUN   TestDirWalk
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:29:55 INFO  : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Failed to get StartCursor: path/not_found/...
2021/07/25 06:29:56 DEBUG : dir/file1: Uploading chunk 1/1
2021/07/25 06:29:57 DEBUG : dir/file1: Uploading chunk 2/1
2021/07/25 06:29:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/file1" to batch
2021/07/25 06:29:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:29:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:29:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:29:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:29:59 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:29:59 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:00 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:01 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:30:02 DEBUG : fil/a/b/c: Uploading chunk 1/1
2021/07/25 06:30:03 DEBUG : fil/a/b/c: Uploading chunk 2/1
2021/07/25 06:30:03 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/fil/a/b/c" to batch
2021/07/25 06:30:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:30:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/fil/a/b/c
2021/07/25 06:30:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:30:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:30:05 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:30:05 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:06 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:07 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:30:08 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 06:30:10 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/fil/a/b/c
2021/07/25 06:30:11 DEBUG : : forgetting directory cache
2021/07/25 06:30:11 DEBUG : dir: forgetting directory cache
2021/07/25 06:30:11 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:30:11 DEBUG : fil/a/b: Looking for writers
2021/07/25 06:30:11 DEBUG : fil/a: Looking for writers
2021/07/25 06:30:11 DEBUG : b: reading active writers
2021/07/25 06:30:11 DEBUG : fil: Looking for writers
2021/07/25 06:30:11 DEBUG : a: reading active writers
2021/07/25 06:30:11 DEBUG : dir: Looking for writers
2021/07/25 06:30:11 DEBUG : : Looking for writers
2021/07/25 06:30:11 DEBUG : dir: reading active writers
2021/07/25 06:30:11 DEBUG : fil: reading active writers
2021/07/25 06:30:11 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (25.52s)
=== RUN   TestDirSetModTime
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:30:21 DEBUG : dir/file1: Uploading chunk 1/1
2021/07/25 06:30:22 DEBUG : dir/file1: Uploading chunk 2/1
2021/07/25 06:30:22 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/file1" to batch
2021/07/25 06:30:23 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:30:23 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:30:23 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:30:23 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:30:23 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:30:24 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:25 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:26 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:30:27 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:30:28 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:30:28 DEBUG : dir: Looking for writers
2021/07/25 06:30:28 DEBUG : : Looking for writers
2021/07/25 06:30:28 DEBUG : dir: reading active writers
2021/07/25 06:30:28 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (11.26s)
=== RUN   TestDirReadDirAll
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:30:33 DEBUG : dir/file1: Uploading chunk 1/1
2021/07/25 06:30:33 DEBUG : dir/file1: Uploading chunk 2/1
2021/07/25 06:30:33 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/file1" to batch
2021/07/25 06:30:34 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:30:34 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:30:34 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:30:34 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:30:35 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:30:35 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:36 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:37 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:30:39 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 06:30:40 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:30:40 DEBUG : dir/file2: Uploading chunk 1/1
2021/07/25 06:30:41 DEBUG : dir/file2: Uploading chunk 2/1
2021/07/25 06:30:41 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/file2" to batch
2021/07/25 06:30:41 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:30:41 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file2
2021/07/25 06:30:42 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:30:42 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:30:42 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:30:43 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:44 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:45 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file2
2021/07/25 06:30:45 DEBUG : dir/subdir/file3: Uploading chunk 1/1
2021/07/25 06:30:46 DEBUG : dir/subdir/file3: Uploading chunk 2/1
2021/07/25 06:30:46 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/subdir/file3" to batch
2021/07/25 06:30:47 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:30:47 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/subdir/file3
2021/07/25 06:30:47 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:30:47 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:30:48 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:30:48 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:49 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:50 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:30:51 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 06:30:53 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/subdir/file3
=== RUN   TestDirReadDirAll/Virtual
2021/07/25 06:30:54 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2021/07/25 06:30:54 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2021/07/25 06:30:54 DEBUG : dir: Added virtual directory entry vDel: "file2"
2021/07/25 06:30:54 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2021/07/25 06:30:54 DEBUG : dir/virtualFile: Uploading chunk 1/1
2021/07/25 06:30:55 DEBUG : dir/virtualFile: Uploading chunk 2/1
2021/07/25 06:30:55 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/virtualFile" to batch
2021/07/25 06:30:56 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Checking for changes on remote
2021/07/25 06:30:56 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:30:56 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/virtualFile
2021/07/25 06:30:56 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:30:56 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:30:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:30:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:30:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:30:59 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:31:00 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 06:31:01 DEBUG : : changeNotify: relativePath="dir/virtualFile", type=1
2021/07/25 06:31:01 DEBUG : : >changeNotify: 
2021/07/25 06:31:01 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/virtualFile
2021/07/25 06:31:02 DEBUG : dir/virtualDir/testFile: Uploading chunk 1/1
2021/07/25 06:31:02 DEBUG : dir/virtualDir/testFile: Uploading chunk 2/1
2021/07/25 06:31:03 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/virtualDir/testFile" to batch
2021/07/25 06:31:03 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:31:03 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/virtualDir/testFile
2021/07/25 06:31:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:31:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:31:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:31:05 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:31:06 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:31:07 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:31:08 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 06:31:09 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 06:31:10 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 06:31:11 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 10/120
2021/07/25 06:31:12 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 11/120
2021/07/25 06:31:14 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/virtualDir/testFile
2021/07/25 06:31:16 DEBUG : dir: invalidating directory cache
2021/07/25 06:31:16 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2021/07/25 06:31:16 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2021/07/25 06:31:16 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2021/07/25 06:31:16 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2021/07/25 06:31:16 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2021/07/25 06:31:16 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2021/07/25 06:31:16 DEBUG : dir: Added virtual directory entry vDel: "file1"
2021/07/25 06:31:16 DEBUG : dir: invalidating directory cache
2021/07/25 06:31:16 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2"
2021/07/25 06:31:16 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2021/07/25 06:31:16 DEBUG : : forgetting directory cache
2021/07/25 06:31:16 DEBUG : dir: forgetting directory cache
2021/07/25 06:31:16 DEBUG : dir/virtualDir: forgetting directory cache
2021/07/25 06:31:17 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:31:17 DEBUG : dir/virtualDir: Looking for writers
2021/07/25 06:31:17 DEBUG : dir: Looking for writers
2021/07/25 06:31:17 DEBUG : virtualFile: reading active writers
2021/07/25 06:31:17 DEBUG : virtualDir: reading active writers
2021/07/25 06:31:17 DEBUG : file1: reading active writers
2021/07/25 06:31:17 DEBUG : virtualFile2: reading active writers
2021/07/25 06:31:17 DEBUG : : Looking for writers
2021/07/25 06:31:17 DEBUG : dir: reading active writers
2021/07/25 06:31:17 DEBUG : >WaitForWriters: 
2021/07/25 06:31:21 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Checking for changes on remote
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir", type=0
2021/07/25 06:31:21 DEBUG : : invalidating directory cache
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/virtualDir", type=0
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/file2", type=1
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/subdir/file3", type=1
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/subdir", type=1
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/file1", type=1
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/virtualFile", type=1
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
2021/07/25 06:31:21 DEBUG : : changeNotify: relativePath="dir/virtualDir/testFile", type=1
2021/07/25 06:31:21 DEBUG : : >changeNotify: 
--- PASS: TestDirReadDirAll (53.11s)
    --- PASS: TestDirReadDirAll/Virtual (22.81s)
=== RUN   TestDirMkdir
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:31:26 DEBUG : dir/file1: Uploading chunk 1/1
2021/07/25 06:31:26 DEBUG : dir/file1: Uploading chunk 2/1
2021/07/25 06:31:26 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/file1" to batch
2021/07/25 06:31:27 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:31:27 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:31:27 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:31:27 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:31:28 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:31:28 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:31:29 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:31:30 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:31:31 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file1
2021/07/25 06:31:32 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Checking for changes on remote
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/file2", type=1
2021/07/25 06:31:32 DEBUG : dir: invalidating directory cache
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/subdir/file3", type=1
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/subdir", type=1
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/virtualFile", type=1
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/virtualDir/testFile", type=1
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/virtualDir", type=1
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir", type=0
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:32 DEBUG : : changeNotify: relativePath="dir/file1", type=1
2021/07/25 06:31:32 DEBUG : : >changeNotify: 
2021/07/25 06:31:33 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2021/07/25 06:31:34 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:31:34 DEBUG : dir/sub: Looking for writers
2021/07/25 06:31:34 DEBUG : dir: Looking for writers
2021/07/25 06:31:34 DEBUG : file1: reading active writers
2021/07/25 06:31:34 DEBUG : sub: reading active writers
2021/07/25 06:31:34 DEBUG : : Looking for writers
2021/07/25 06:31:34 DEBUG : dir: reading active writers
2021/07/25 06:31:34 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdir (13.21s)
=== RUN   TestRcGetVFS
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:31:39 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:31:39 DEBUG : : Looking for writers
2021/07/25 06:31:39 DEBUG : >WaitForWriters: 
--- PASS: TestRcGetVFS (0.74s)
=== RUN   TestRWFileHandleSizeCreateNew
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:31:39 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestDropbox/rclone-test-qaburap2kecevav5jolirud2"
2021/07/25 06:31:39 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestDropbox/rclone-test-qaburap2kecevav5jolirud2"
2021/07/25 06:31:39 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestDropbox/rclone-test-qaburap2kecevav5jolirud2"
2021/07/25 06:31:39 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2021/07/25 06:31:39 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/07/25 06:31:39 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2021/07/25 06:31:39 DEBUG : file1: newRWFileHandle: 
2021/07/25 06:31:39 DEBUG : file1(0xc00035b100): openPending: 
2021/07/25 06:31:39 DEBUG : file1: vfs cache: truncate to size=0
2021/07/25 06:31:39 DEBUG : : Added virtual directory entry vAddFile: "file1"
2021/07/25 06:31:39 DEBUG : file1(0xc00035b100): >openPending: err=<nil>
2021/07/25 06:31:39 DEBUG : file1: >newRWFileHandle: err=<nil>
2021/07/25 06:31:39 DEBUG : : Added virtual directory entry vAddFile: "file1"
2021/07/25 06:31:39 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2021/07/25 06:31:39 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2021/07/25 06:31:39 DEBUG : file1(0xc00035b100): _writeAt: size=5, off=0
2021/07/25 06:31:39 DEBUG : file1(0xc00035b100): >_writeAt: n=5, err=<nil>
2021/07/25 06:31:39 DEBUG : file1(0xc00035b100): close: 
2021/07/25 06:31:39 DEBUG : file1: vfs cache: setting modification time to 2021-07-25 06:31:39.942087051 +0000 UTC m=+104.641718533
2021/07/25 06:31:39 INFO  : file1: vfs cache: queuing for upload in 100ms
2021/07/25 06:31:39 DEBUG : file1(0xc00035b100): >close: err=<nil>
2021/07/25 06:31:39 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:31:39 DEBUG : : Looking for writers
2021/07/25 06:31:39 DEBUG : file1: reading active writers
2021/07/25 06:31:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2021/07/25 06:31:39 DEBUG : : Looking for writers
2021/07/25 06:31:39 DEBUG : file1: reading active writers
2021/07/25 06:31:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2021/07/25 06:31:39 DEBUG : : Looking for writers
2021/07/25 06:31:39 DEBUG : file1: reading active writers
2021/07/25 06:31:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2021/07/25 06:31:40 DEBUG : : Looking for writers
2021/07/25 06:31:40 DEBUG : file1: reading active writers
2021/07/25 06:31:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2021/07/25 06:31:40 DEBUG : file1: vfs cache: starting upload
2021/07/25 06:31:40 DEBUG : : Looking for writers
2021/07/25 06:31:40 DEBUG : file1: reading active writers
2021/07/25 06:31:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2021/07/25 06:31:40 DEBUG : file1: Uploading chunk 1/1
2021/07/25 06:31:40 DEBUG : : Looking for writers
2021/07/25 06:31:40 DEBUG : file1: reading active writers
2021/07/25 06:31:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2021/07/25 06:31:40 DEBUG : : Looking for writers
2021/07/25 06:31:40 DEBUG : file1: reading active writers
2021/07/25 06:31:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2021/07/25 06:31:40 DEBUG : file1: Uploading chunk 2/1
2021/07/25 06:31:40 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/file1" to batch
2021/07/25 06:31:41 DEBUG : : Looking for writers
2021/07/25 06:31:41 DEBUG : file1: reading active writers
2021/07/25 06:31:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2021/07/25 06:31:41 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:31:41 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/file1
2021/07/25 06:31:41 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:31:42 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:31:42 DEBUG : : Looking for writers
2021/07/25 06:31:42 DEBUG : file1: reading active writers
2021/07/25 06:31:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2021/07/25 06:31:42 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:31:42 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:31:43 DEBUG : : Looking for writers
2021/07/25 06:31:43 DEBUG : file1: reading active writers
2021/07/25 06:31:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2021/07/25 06:31:43 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:31:44 DEBUG : : Looking for writers
2021/07/25 06:31:44 DEBUG : file1: reading active writers
2021/07/25 06:31:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2021/07/25 06:31:44 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:31:45 DEBUG : : Looking for writers
2021/07/25 06:31:45 DEBUG : file1: reading active writers
2021/07/25 06:31:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2021/07/25 06:31:46 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/file1
2021/07/25 06:31:46 DEBUG : file1: dropbox = 9595c9df90075148eb06860365df33584b75bff782a510c6cd4883a419833d50 OK
2021/07/25 06:31:46 INFO  : file1: Copied (new)
2021/07/25 06:31:46 DEBUG : file1: vfs cache: fingerprint now "5,2021-07-25 06:31:40 +0000 UTC,9595c9df90075148eb06860365df33584b75bff782a510c6cd4883a419833d50"
2021/07/25 06:31:46 DEBUG : file1: vfs cache: writeback object to VFS layer
2021/07/25 06:31:46 DEBUG : : Added virtual directory entry vAddFile: "file1"
2021/07/25 06:31:46 INFO  : file1: vfs cache: upload succeeded try #1
2021/07/25 06:31:46 DEBUG : : Looking for writers
2021/07/25 06:31:46 DEBUG : file1: reading active writers
2021/07/25 06:31:46 DEBUG : >WaitForWriters: 
2021/07/25 06:31:46 DEBUG : vfs cache: cleaner exiting
--- PASS: TestRWFileHandleSizeCreateNew (8.57s)
=== RUN   TestVFSNew
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:31:48 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Re-using VFS from active cache
2021/07/25 06:31:48 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:31:48 DEBUG : : Looking for writers
2021/07/25 06:31:48 DEBUG : >WaitForWriters: 
--- PASS: TestVFSNew (0.55s)
=== RUN   TestVFSStat
    run.go:176: Remote "Dropbox root 'rclone-test-qaburap2kecevav5jolirud2'", Local "Local file system at /tmp/rclone215041942", Modify Window "1s"
2021/07/25 06:31:49 DEBUG : file1: Uploading chunk 1/1
2021/07/25 06:31:49 DEBUG : file1: Uploading chunk 2/1
2021/07/25 06:31:50 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/file1" to batch
2021/07/25 06:31:50 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:31:50 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/file1
2021/07/25 06:31:50 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:31:51 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:31:51 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:31:52 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:31:53 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:31:54 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:31:55 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/file1
2021/07/25 06:31:55 DEBUG : dir/file2: Uploading chunk 1/1
2021/07/25 06:31:55 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Checking for changes on remote
2021/07/25 06:31:56 DEBUG : dir/file2: Uploading chunk 2/1
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/file2", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/subdir/file3", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/subdir", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/virtualFile", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/virtualDir/testFile", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/virtualDir", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/file1", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir/sub", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="dir", type=1
2021/07/25 06:31:56 DEBUG : : invalidating directory cache
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : : changeNotify: relativePath="file1", type=1
2021/07/25 06:31:56 DEBUG : : >changeNotify: 
2021/07/25 06:31:56 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Adding "/rclone-test-qaburap2kecevav5jolirud2/dir/file2" to batch
2021/07/25 06:31:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Batch idle for 500ms so committing
2021/07/25 06:31:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committing sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file2
2021/07/25 06:31:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 100ms after status: "in_progress": try 1/120
2021/07/25 06:31:57 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 200ms after status: "in_progress": try 2/120
2021/07/25 06:31:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 400ms after status: "in_progress": try 3/120
2021/07/25 06:31:58 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 800ms after status: "in_progress": try 4/120
2021/07/25 06:31:59 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 5/120
2021/07/25 06:32:00 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 6/120
2021/07/25 06:32:01 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 7/120
2021/07/25 06:32:02 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 8/120
2021/07/25 06:32:04 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Wait for batch: sleeping for 1s after status: "in_progress": try 9/120
2021/07/25 06:32:05 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Committed sync batch length 1 starting with: /rclone-test-qaburap2kecevav5jolirud2/dir/file2
2021/07/25 06:32:06 DEBUG : WaitForWriters: timeout=10s
2021/07/25 06:32:06 DEBUG : dir: Looking for writers
2021/07/25 06:32:06 DEBUG : file2: reading active writers
2021/07/25 06:32:06 DEBUG : : Looking for writers
2021/07/25 06:32:06 DEBUG : dir: reading active writers
2021/07/25 06:32:06 DEBUG : file1: reading active writers
2021/07/25 06:32:06 DEBUG : >WaitForWriters: 
--- PASS: TestVFSStat (22.00s)
PASS
2021/07/25 06:32:10 DEBUG : Dropbox root 'rclone-test-qaburap2kecevav5jolirud2': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestDirMkdir|TestDirReadDirAll|TestDirSetModTime|TestDirWalk|TestRWFileHandleSizeCreateNew|TestRcGetVFS|TestVFSNew|TestVFSStat)$'" - Finished OK in 2m16.406526442s (try 2/5)