"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestFileRename|TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestReadFileHandleMethods|TestReadFileHandleSeek|TestVFSStat)$/^(full,forceCache=false|minimal,forceCache=true|writes,forceCache=false)$'" - Starting (try 3/5)
2020/12/27 07:23:05 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:23:06 DEBUG : Starting OpenDrive session with ID: 1d741dd36514c35205671a5017d829e13597911e6911d6d34efacad6b857b2d0
2020/12/27 07:23:07 DEBUG : Creating backend with remote "/tmp/rclone864081020"
=== RUN   TestFileRename
=== RUN   TestFileRename/minimal,forceCache=true
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:23:07 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:23:07 NOTICE: OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2020/12/27 07:23:07 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:23:07 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:23:07 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:23:07 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:23:11 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/12/27 07:23:17 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2020/12/27 07:23:17 DEBUG : dir/file1: newRWFileHandle: 
2020/12/27 07:23:17 DEBUG : dir/file1(0xc00007dd80): openPending: 
2020/12/27 07:23:17 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2020/12/27 07:23:17 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/12/27 07:23:17 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:23:17 DEBUG : dir/file1(0xc00007dd80): >openPending: err=<nil>
2020/12/27 07:23:17 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/12/27 07:23:17 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/12/27 07:23:17 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:23:17 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/12/27 07:23:17 DEBUG : dir/file1(0xc00007dd80): _writeAt: size=14, off=0
2020/12/27 07:23:17 DEBUG : dir/file1(0xc00007dd80): >_writeAt: n=14, err=<nil>
2020/12/27 07:23:17 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2020/12/27 07:23:17 DEBUG : dir/file1(0xc00007dd80): close: 
2020/12/27 07:23:17 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/12/27 07:23:17 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2020/12/27 07:23:17 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/12/27 07:23:17 DEBUG : dir/file1(0xc00007dd80): >close: err=<nil>
2020/12/27 07:23:17 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:23:17 DEBUG : dir/file1: vfs cache: starting upload
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:23:17 DEBUG : dir: Looking for writers
2020/12/27 07:23:17 DEBUG : file1: reading active writers
2020/12/27 07:23:17 DEBUG : : Looking for writers
2020/12/27 07:23:17 DEBUG : dir: reading active writers
2020/12/27 07:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:23:17 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/12/27 07:23:18 DEBUG : dir: Looking for writers
2020/12/27 07:23:18 DEBUG : file1: reading active writers
2020/12/27 07:23:18 DEBUG : : Looking for writers
2020/12/27 07:23:18 DEBUG : dir: reading active writers
2020/12/27 07:23:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:19 DEBUG : dir: Looking for writers
2020/12/27 07:23:19 DEBUG : file1: reading active writers
2020/12/27 07:23:19 DEBUG : : Looking for writers
2020/12/27 07:23:19 DEBUG : dir: reading active writers
2020/12/27 07:23:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:20 DEBUG : dir: Looking for writers
2020/12/27 07:23:20 DEBUG : file1: reading active writers
2020/12/27 07:23:20 DEBUG : : Looking for writers
2020/12/27 07:23:20 DEBUG : dir: reading active writers
2020/12/27 07:23:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:21 INFO  : dir/file1: Copied (replaced existing)
2020/12/27 07:23:21 DEBUG : dir/file1: vfs cache: fingerprint now "14,2001-02-03 04:05:06 +0000 UTC,"
2020/12/27 07:23:21 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2020/12/27 07:23:21 DEBUG : dir: Looking for writers
2020/12/27 07:23:21 DEBUG : file1: reading active writers
2020/12/27 07:23:21 DEBUG : : Looking for writers
2020/12/27 07:23:21 DEBUG : dir: reading active writers
2020/12/27 07:23:21 DEBUG : >WaitForWriters: 
2020/12/27 07:23:21 DEBUG : dir/file1: Applied pending mod time 2001-02-03 04:05:06.499999999 +0000 UTC OK
2020/12/27 07:23:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:23:21 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/12/27 07:23:21 DEBUG : dir/file1: newRWFileHandle: 
2020/12/27 07:23:21 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/12/27 07:23:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/12/27 07:23:21 INFO  : dir/file1: vfs cache: upload succeeded try #1
2020/12/27 07:23:21 DEBUG : dir/file1(0xc00089afc0): _readAt: size=512, off=0
2020/12/27 07:23:21 DEBUG : dir/file1(0xc00089afc0): openPending: 
2020/12/27 07:23:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC," against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,"
2020/12/27 07:23:21 DEBUG : dir/file1: vfs cache: removing cached entry as stale (remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC," != cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,")
2020/12/27 07:23:21 INFO  : dir/file1: vfs cache: removed cache file as stale (remote is different)
2020/12/27 07:23:21 DEBUG : dir/file1: vfs cache: removed metadata from cache as stale (remote is different)
2020/12/27 07:23:21 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/12/27 07:23:21 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:23:21 DEBUG : dir/file1(0xc00089afc0): >openPending: err=<nil>
2020/12/27 07:23:21 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [] - present false
2020/12/27 07:23:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1
2020/12/27 07:23:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2020/12/27 07:23:21 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/12/27 07:23:22 DEBUG : dir/file1(0xc00089afc0): >_readAt: n=14, err=EOF
2020/12/27 07:23:22 DEBUG : dir/file1(0xc00089afc0): close: 
2020/12/27 07:23:22 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2020/12/27 07:23:22 DEBUG : dir/file1(0xc00089afc0): >close: err=<nil>
2020/12/27 07:23:25 INFO  : dir/file1: Moved (server-side) to: newLeaf
2020/12/27 07:23:25 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/12/27 07:23:25 DEBUG : newLeaf: Updating file with newLeaf 0xc000296840
2020/12/27 07:23:25 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/12/27 07:23:25 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:23:27 INFO  : newLeaf: Moved (server-side) to: dir/file1
2020/12/27 07:23:27 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/12/27 07:23:27 DEBUG : dir/file1: Updating file with dir/file1 0xc000296840
2020/12/27 07:23:27 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/12/27 07:23:27 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:23:29 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/12/27 07:23:29 DEBUG : dir/file1: newRWFileHandle: 
2020/12/27 07:23:29 DEBUG : dir/file1(0xc000192a40): openPending: 
2020/12/27 07:23:29 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,0001-01-01 00:00:00 +0000 UTC," against cached fingerprint ""
2020/12/27 07:23:29 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/12/27 07:23:29 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:23:29 DEBUG : dir/file1(0xc000192a40): >openPending: err=<nil>
2020/12/27 07:23:29 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/12/27 07:23:29 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/12/27 07:23:29 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/12/27 07:23:29 DEBUG : dir/file1(0xc000192a40): _writeAt: size=25, off=0
2020/12/27 07:23:29 DEBUG : dir/file1(0xc000192a40): >_writeAt: n=25, err=<nil>
2020/12/27 07:23:30 INFO  : dir/file1: Moved (server-side) to: newLeaf
2020/12/27 07:23:30 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/12/27 07:23:30 DEBUG : newLeaf: Updating file with newLeaf 0xc000296840
2020/12/27 07:23:30 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/12/27 07:23:30 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:23:30 DEBUG : newLeaf(0xc000192a40): close: 
2020/12/27 07:23:30 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/12/27 07:23:30 DEBUG : newLeaf: vfs cache: setting modification time to 2020-12-27 07:23:29.073117088 +0000 UTC m=+23.403790028
2020/12/27 07:23:30 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/12/27 07:23:30 DEBUG : newLeaf(0xc000192a40): >close: err=<nil>
2020/12/27 07:23:30 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:23:30 DEBUG : dir: Looking for writers
2020/12/27 07:23:30 DEBUG : : Looking for writers
2020/12/27 07:23:30 DEBUG : dir: reading active writers
2020/12/27 07:23:30 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:23:30 DEBUG : dir: Looking for writers
2020/12/27 07:23:30 DEBUG : : Looking for writers
2020/12/27 07:23:30 DEBUG : dir: reading active writers
2020/12/27 07:23:30 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:23:30 DEBUG : dir: Looking for writers
2020/12/27 07:23:30 DEBUG : : Looking for writers
2020/12/27 07:23:30 DEBUG : dir: reading active writers
2020/12/27 07:23:30 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:23:30 DEBUG : dir: Looking for writers
2020/12/27 07:23:30 DEBUG : : Looking for writers
2020/12/27 07:23:30 DEBUG : dir: reading active writers
2020/12/27 07:23:30 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:23:30 DEBUG : newLeaf: vfs cache: starting upload
2020/12/27 07:23:30 DEBUG : dir: Looking for writers
2020/12/27 07:23:30 DEBUG : : Looking for writers
2020/12/27 07:23:30 DEBUG : dir: reading active writers
2020/12/27 07:23:30 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:23:31 DEBUG : dir: Looking for writers
2020/12/27 07:23:31 DEBUG : : Looking for writers
2020/12/27 07:23:31 DEBUG : dir: reading active writers
2020/12/27 07:23:31 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:23:31 DEBUG : dir: Looking for writers
2020/12/27 07:23:31 DEBUG : : Looking for writers
2020/12/27 07:23:31 DEBUG : dir: reading active writers
2020/12/27 07:23:31 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:23:31 DEBUG : newLeaf: Uploading chunk 0, size=25, remain=0
2020/12/27 07:23:32 DEBUG : dir: Looking for writers
2020/12/27 07:23:32 DEBUG : : Looking for writers
2020/12/27 07:23:32 DEBUG : dir: reading active writers
2020/12/27 07:23:32 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:33 DEBUG : dir: Looking for writers
2020/12/27 07:23:33 DEBUG : : Looking for writers
2020/12/27 07:23:33 DEBUG : dir: reading active writers
2020/12/27 07:23:33 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:34 DEBUG : dir: Looking for writers
2020/12/27 07:23:34 DEBUG : : Looking for writers
2020/12/27 07:23:34 DEBUG : dir: reading active writers
2020/12/27 07:23:34 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:35 DEBUG : dir: Looking for writers
2020/12/27 07:23:35 DEBUG : : Looking for writers
2020/12/27 07:23:35 DEBUG : dir: reading active writers
2020/12/27 07:23:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:36 DEBUG : dir: Looking for writers
2020/12/27 07:23:36 DEBUG : : Looking for writers
2020/12/27 07:23:36 DEBUG : dir: reading active writers
2020/12/27 07:23:36 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:37 DEBUG : dir: Looking for writers
2020/12/27 07:23:37 DEBUG : : Looking for writers
2020/12/27 07:23:37 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:37 DEBUG : dir: reading active writers
2020/12/27 07:23:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:38 DEBUG : dir: Looking for writers
2020/12/27 07:23:38 DEBUG : : Looking for writers
2020/12/27 07:23:38 DEBUG : dir: reading active writers
2020/12/27 07:23:38 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:39 DEBUG : dir: Looking for writers
2020/12/27 07:23:39 DEBUG : : Looking for writers
2020/12/27 07:23:39 DEBUG : dir: reading active writers
2020/12/27 07:23:39 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:40 DEBUG : dir: Looking for writers
2020/12/27 07:23:40 DEBUG : : Looking for writers
2020/12/27 07:23:40 DEBUG : dir: reading active writers
2020/12/27 07:23:40 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:40 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"newLeaf": &{c:0xc0000d83c0 mu:{state:0 sema:0} cond:0xc00007dd40 name:newLeaf opens:0 downloaders:<nil> o:0xc000833080 fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165218331012512 ext:23403790028 loc:0x26d8980} ATime:{wall:13831165220113131101 ext:25112166790 loc:0x26d8980} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint:14,0001-01-01 00:00:00 +0000 UTC, Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:23:40 DEBUG : >WaitForWriters: 
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:300: Flushing the directory cache
    fstest.go:304: 
        	Error Trace:	fstest.go:304
        	            				fstest.go:337
        	            				file_test.go:343
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/minimal,forceCache=true
        	Messages:   	listing wrong, want
        	            	  newLeaf (25) got
        	            	  newLeaf (14)
    fstest.go:142: 
        	Error Trace:	fstest.go:142
        	            				fstest.go:148
        	            				fstest.go:194
        	            				fstest.go:307
        	            				fstest.go:337
        	            				file_test.go:343
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/minimal,forceCache=true
        	Messages:   	OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'/newLeaf: MD5 hash incorrect - expecting "c7247bead226dfd7bd970c17229f4044" got "0ef726ce9b1a7692357ff70dd321d595"
    fstest.go:149: 
        	Error Trace:	fstest.go:149
        	            				fstest.go:194
        	            				fstest.go:307
        	            				fstest.go:337
        	            				file_test.go:343
        	            				file_test.go:360
        	Error:      	Not equal: 
        	            	expected: 25
        	            	actual  : 14
        	Test:       	TestFileRename/minimal,forceCache=true
        	Messages:   	newLeaf: size incorrect file=25 vs obj=14
2020/12/27 07:23:54 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:23:54 DEBUG : dir: Looking for writers
2020/12/27 07:23:54 DEBUG : : Looking for writers
2020/12/27 07:23:54 DEBUG : dir: reading active writers
2020/12/27 07:23:54 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:23:55 DEBUG : dir: Looking for writers
2020/12/27 07:23:55 DEBUG : : Looking for writers
2020/12/27 07:23:55 DEBUG : dir: reading active writers
2020/12/27 07:23:55 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:56 DEBUG : dir: Looking for writers
2020/12/27 07:23:56 DEBUG : : Looking for writers
2020/12/27 07:23:56 DEBUG : dir: reading active writers
2020/12/27 07:23:56 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:57 DEBUG : dir: Looking for writers
2020/12/27 07:23:57 DEBUG : : Looking for writers
2020/12/27 07:23:57 DEBUG : dir: reading active writers
2020/12/27 07:23:57 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:58 DEBUG : dir: Looking for writers
2020/12/27 07:23:58 DEBUG : : Looking for writers
2020/12/27 07:23:58 DEBUG : dir: reading active writers
2020/12/27 07:23:58 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:23:59 DEBUG : dir: Looking for writers
2020/12/27 07:23:59 DEBUG : : Looking for writers
2020/12/27 07:23:59 DEBUG : newLeaf: reading active writers
2020/12/27 07:23:59 DEBUG : dir: reading active writers
2020/12/27 07:23:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:24:00 DEBUG : dir: Looking for writers
2020/12/27 07:24:00 DEBUG : : Looking for writers
2020/12/27 07:24:00 DEBUG : dir: reading active writers
2020/12/27 07:24:00 DEBUG : newLeaf: reading active writers
2020/12/27 07:24:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:24:01 DEBUG : dir: Looking for writers
2020/12/27 07:24:01 DEBUG : : Looking for writers
2020/12/27 07:24:01 DEBUG : dir: reading active writers
2020/12/27 07:24:01 DEBUG : newLeaf: reading active writers
2020/12/27 07:24:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:24:02 DEBUG : dir: Looking for writers
2020/12/27 07:24:02 DEBUG : : Looking for writers
2020/12/27 07:24:02 DEBUG : dir: reading active writers
2020/12/27 07:24:02 DEBUG : newLeaf: reading active writers
2020/12/27 07:24:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:24:03 DEBUG : dir: Looking for writers
2020/12/27 07:24:03 DEBUG : : Looking for writers
2020/12/27 07:24:03 DEBUG : dir: reading active writers
2020/12/27 07:24:03 DEBUG : newLeaf: reading active writers
2020/12/27 07:24:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:24:04 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"newLeaf": &{c:0xc0000d83c0 mu:{state:0 sema:0} cond:0xc00007dd40 name:newLeaf opens:0 downloaders:<nil> o:0xc000833080 fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165218331012512 ext:23403790028 loc:0x26d8980} ATime:{wall:13831165220113131101 ext:25112166790 loc:0x26d8980} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint:14,0001-01-01 00:00:00 +0000 UTC, Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:24:04 DEBUG : >WaitForWriters: 
2020/12/27 07:24:04 DEBUG : vfs cache: cleaner exiting
2020/12/27 07:24:04 ERROR : newLeaf: Failed to copy: failed to create file: Post "https://dev.opendrive.com/api/v1/upload/close_file_upload.json": context canceled
2020/12/27 07:24:04 INFO  : newLeaf: vfs cache: upload canceled
=== RUN   TestFileRename/writes,forceCache=false
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:24:08 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:24:08 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:24:08 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:24:08 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:24:08 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:25:08 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:25:39 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/12/27 07:26:02 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:26:02 DEBUG : dir: Looking for writers
2020/12/27 07:26:02 DEBUG : file1: reading active writers
2020/12/27 07:26:02 DEBUG : : Looking for writers
2020/12/27 07:26:02 DEBUG : dir: reading active writers
2020/12/27 07:26:02 DEBUG : >WaitForWriters: 
2020/12/27 07:26:05 INFO  : dir/file1: Moved (server-side) to: newLeaf
2020/12/27 07:26:05 DEBUG : newLeaf: Updating file with newLeaf 0xc0000d8840
2020/12/27 07:26:05 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/12/27 07:26:05 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:26:08 INFO  : newLeaf: Moved (server-side) to: dir/file1
2020/12/27 07:26:08 DEBUG : dir/file1: Updating file with dir/file1 0xc0000d8840
2020/12/27 07:26:08 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/12/27 07:26:08 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:26:08 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item newLeaf not removed, freed 0 bytes
2020/12/27 07:26:08 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2020/12/27 07:26:08 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:26:09 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/12/27 07:26:09 DEBUG : dir/file1: newRWFileHandle: 
2020/12/27 07:26:09 DEBUG : dir/file1(0xc000256c00): openPending: 
2020/12/27 07:26:09 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,0001-01-01 00:00:00 +0000 UTC," against cached fingerprint ""
2020/12/27 07:26:09 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/12/27 07:26:09 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:26:09 DEBUG : dir/file1(0xc000256c00): >openPending: err=<nil>
2020/12/27 07:26:09 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/12/27 07:26:09 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/12/27 07:26:09 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/12/27 07:26:09 DEBUG : dir/file1(0xc000256c00): _writeAt: size=25, off=0
2020/12/27 07:26:09 DEBUG : dir/file1(0xc000256c00): >_writeAt: n=25, err=<nil>
2020/12/27 07:26:10 INFO  : dir/file1: Moved (server-side) to: newLeaf
2020/12/27 07:26:10 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/12/27 07:26:10 DEBUG : newLeaf: Updating file with newLeaf 0xc0000d8840
2020/12/27 07:26:10 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/12/27 07:26:10 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:26:10 DEBUG : newLeaf(0xc000256c00): close: 
2020/12/27 07:26:10 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/12/27 07:26:10 DEBUG : newLeaf: vfs cache: setting modification time to 2020-12-27 07:26:09.155594567 +0000 UTC m=+183.486267489
2020/12/27 07:26:10 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/12/27 07:26:10 DEBUG : newLeaf(0xc000256c00): >close: err=<nil>
2020/12/27 07:26:10 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:26:10 DEBUG : dir: Looking for writers
2020/12/27 07:26:10 DEBUG : : Looking for writers
2020/12/27 07:26:10 DEBUG : dir: reading active writers
2020/12/27 07:26:10 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:26:10 DEBUG : dir: Looking for writers
2020/12/27 07:26:10 DEBUG : : Looking for writers
2020/12/27 07:26:10 DEBUG : dir: reading active writers
2020/12/27 07:26:10 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:26:10 DEBUG : dir: Looking for writers
2020/12/27 07:26:10 DEBUG : : Looking for writers
2020/12/27 07:26:10 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:10 DEBUG : dir: reading active writers
2020/12/27 07:26:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:26:10 DEBUG : dir: Looking for writers
2020/12/27 07:26:10 DEBUG : : Looking for writers
2020/12/27 07:26:10 DEBUG : dir: reading active writers
2020/12/27 07:26:10 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:26:11 DEBUG : newLeaf: vfs cache: starting upload
2020/12/27 07:26:11 DEBUG : dir: Looking for writers
2020/12/27 07:26:11 DEBUG : : Looking for writers
2020/12/27 07:26:11 DEBUG : dir: reading active writers
2020/12/27 07:26:11 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:26:11 DEBUG : dir: Looking for writers
2020/12/27 07:26:11 DEBUG : : Looking for writers
2020/12/27 07:26:11 DEBUG : dir: reading active writers
2020/12/27 07:26:11 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:26:11 DEBUG : dir: Looking for writers
2020/12/27 07:26:11 DEBUG : : Looking for writers
2020/12/27 07:26:11 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:11 DEBUG : dir: reading active writers
2020/12/27 07:26:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:26:11 DEBUG : newLeaf: Uploading chunk 0, size=25, remain=0
2020/12/27 07:26:12 DEBUG : dir: Looking for writers
2020/12/27 07:26:12 DEBUG : : Looking for writers
2020/12/27 07:26:12 DEBUG : dir: reading active writers
2020/12/27 07:26:12 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:13 DEBUG : dir: Looking for writers
2020/12/27 07:26:13 DEBUG : : Looking for writers
2020/12/27 07:26:13 DEBUG : dir: reading active writers
2020/12/27 07:26:13 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:14 DEBUG : dir: Looking for writers
2020/12/27 07:26:14 DEBUG : : Looking for writers
2020/12/27 07:26:14 DEBUG : dir: reading active writers
2020/12/27 07:26:14 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:15 DEBUG : dir: Looking for writers
2020/12/27 07:26:15 DEBUG : : Looking for writers
2020/12/27 07:26:15 DEBUG : dir: reading active writers
2020/12/27 07:26:15 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:16 DEBUG : dir: Looking for writers
2020/12/27 07:26:16 DEBUG : : Looking for writers
2020/12/27 07:26:16 DEBUG : dir: reading active writers
2020/12/27 07:26:16 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:17 DEBUG : dir: Looking for writers
2020/12/27 07:26:17 DEBUG : : Looking for writers
2020/12/27 07:26:17 DEBUG : dir: reading active writers
2020/12/27 07:26:17 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:18 DEBUG : dir: Looking for writers
2020/12/27 07:26:18 DEBUG : : Looking for writers
2020/12/27 07:26:18 DEBUG : dir: reading active writers
2020/12/27 07:26:18 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:19 DEBUG : dir: Looking for writers
2020/12/27 07:26:19 DEBUG : : Looking for writers
2020/12/27 07:26:19 DEBUG : dir: reading active writers
2020/12/27 07:26:19 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:20 DEBUG : dir: Looking for writers
2020/12/27 07:26:20 DEBUG : : Looking for writers
2020/12/27 07:26:20 DEBUG : dir: reading active writers
2020/12/27 07:26:20 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:20 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"newLeaf": &{c:0xc000296fc0 mu:{state:0 sema:0} cond:0xc00089ba80 name:newLeaf opens:0 downloaders:<nil> o:0xc000865c20 fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165390212181831 ext:183486267489 loc:0x26d8980} ATime:{wall:13831165392052857162 ext:185253200986 loc:0x26d8980} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint:14,0001-01-01 00:00:00 +0000 UTC, Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:26:20 DEBUG : >WaitForWriters: 
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:300: Flushing the directory cache
    fstest.go:304: 
        	Error Trace:	fstest.go:304
        	            				fstest.go:337
        	            				file_test.go:343
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/writes,forceCache=false
        	Messages:   	listing wrong, want
        	            	  newLeaf (25) got
        	            	  newLeaf (14)
    fstest.go:142: 
        	Error Trace:	fstest.go:142
        	            				fstest.go:148
        	            				fstest.go:194
        	            				fstest.go:307
        	            				fstest.go:337
        	            				file_test.go:343
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/writes,forceCache=false
        	Messages:   	OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'/newLeaf: MD5 hash incorrect - expecting "c7247bead226dfd7bd970c17229f4044" got "0ef726ce9b1a7692357ff70dd321d595"
    fstest.go:149: 
        	Error Trace:	fstest.go:149
        	            				fstest.go:194
        	            				fstest.go:307
        	            				fstest.go:337
        	            				file_test.go:343
        	            				file_test.go:360
        	Error:      	Not equal: 
        	            	expected: 25
        	            	actual  : 14
        	Test:       	TestFileRename/writes,forceCache=false
        	Messages:   	newLeaf: size incorrect file=25 vs obj=14
2020/12/27 07:26:35 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:26:35 DEBUG : dir: Looking for writers
2020/12/27 07:26:35 DEBUG : : Looking for writers
2020/12/27 07:26:35 DEBUG : dir: reading active writers
2020/12/27 07:26:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:26:35 DEBUG : dir: Looking for writers
2020/12/27 07:26:35 DEBUG : : Looking for writers
2020/12/27 07:26:35 DEBUG : dir: reading active writers
2020/12/27 07:26:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:26:35 DEBUG : dir: Looking for writers
2020/12/27 07:26:35 DEBUG : : Looking for writers
2020/12/27 07:26:35 DEBUG : dir: reading active writers
2020/12/27 07:26:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:26:35 DEBUG : dir: Looking for writers
2020/12/27 07:26:35 DEBUG : : Looking for writers
2020/12/27 07:26:35 DEBUG : dir: reading active writers
2020/12/27 07:26:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:26:35 DEBUG : dir: Looking for writers
2020/12/27 07:26:35 DEBUG : : Looking for writers
2020/12/27 07:26:35 DEBUG : dir: reading active writers
2020/12/27 07:26:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:26:35 DEBUG : dir: Looking for writers
2020/12/27 07:26:35 DEBUG : : Looking for writers
2020/12/27 07:26:35 DEBUG : dir: reading active writers
2020/12/27 07:26:35 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:26:36 DEBUG : dir: Looking for writers
2020/12/27 07:26:36 DEBUG : : Looking for writers
2020/12/27 07:26:36 DEBUG : dir: reading active writers
2020/12/27 07:26:36 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:26:36 DEBUG : dir: Looking for writers
2020/12/27 07:26:36 DEBUG : : Looking for writers
2020/12/27 07:26:36 DEBUG : dir: reading active writers
2020/12/27 07:26:36 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:37 DEBUG : dir: Looking for writers
2020/12/27 07:26:37 DEBUG : : Looking for writers
2020/12/27 07:26:37 DEBUG : dir: reading active writers
2020/12/27 07:26:37 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:38 DEBUG : dir: Looking for writers
2020/12/27 07:26:38 DEBUG : : Looking for writers
2020/12/27 07:26:38 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:38 DEBUG : dir: reading active writers
2020/12/27 07:26:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:39 DEBUG : dir: Looking for writers
2020/12/27 07:26:39 DEBUG : : Looking for writers
2020/12/27 07:26:39 DEBUG : dir: reading active writers
2020/12/27 07:26:39 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:40 DEBUG : dir: Looking for writers
2020/12/27 07:26:40 DEBUG : : Looking for writers
2020/12/27 07:26:40 DEBUG : dir: reading active writers
2020/12/27 07:26:40 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:41 DEBUG : dir: Looking for writers
2020/12/27 07:26:41 DEBUG : : Looking for writers
2020/12/27 07:26:41 DEBUG : dir: reading active writers
2020/12/27 07:26:41 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:42 DEBUG : dir: Looking for writers
2020/12/27 07:26:42 DEBUG : : Looking for writers
2020/12/27 07:26:42 DEBUG : dir: reading active writers
2020/12/27 07:26:42 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:43 DEBUG : dir: Looking for writers
2020/12/27 07:26:43 DEBUG : : Looking for writers
2020/12/27 07:26:43 DEBUG : dir: reading active writers
2020/12/27 07:26:43 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:44 DEBUG : dir: Looking for writers
2020/12/27 07:26:44 DEBUG : : Looking for writers
2020/12/27 07:26:44 DEBUG : dir: reading active writers
2020/12/27 07:26:44 DEBUG : newLeaf: reading active writers
2020/12/27 07:26:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:26:45 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"newLeaf": &{c:0xc000296fc0 mu:{state:0 sema:0} cond:0xc00089ba80 name:newLeaf opens:0 downloaders:<nil> o:0xc000865c20 fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165390212181831 ext:183486267489 loc:0x26d8980} ATime:{wall:13831165392052857162 ext:185253200986 loc:0x26d8980} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint:14,0001-01-01 00:00:00 +0000 UTC, Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:26:45 DEBUG : >WaitForWriters: 
2020/12/27 07:26:45 ERROR : newLeaf: Failed to copy: failed to create file: Post "https://dev.opendrive.com/api/v1/upload/close_file_upload.json": context canceled
2020/12/27 07:26:45 DEBUG : vfs cache: cleaner exiting
2020/12/27 07:26:45 INFO  : newLeaf: vfs cache: upload canceled
=== RUN   TestFileRename/full,forceCache=false
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:26:49 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:26:49 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:26:49 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:26:49 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:26:49 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:27:49 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:28:24 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
2020/12/27 07:28:49 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:300: Flushing the directory cache
    fstest.go:304: 
        	Error Trace:	fstest.go:304
        	            				fstest.go:337
        	            				fstest.go:349
        	            				file_test.go:27
        	            				file_test.go:248
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/full,forceCache=false
        	Messages:   	listing wrong, want
        	            	  dir/file1 (14) got
        	            	  dir/file1 (14), newLeaf (25)
    fstest.go:190: 
        	Error Trace:	fstest.go:190
        	            				fstest.go:307
        	            				fstest.go:337
        	            				fstest.go:349
        	            				file_test.go:27
        	            				file_test.go:248
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/full,forceCache=false
        	Messages:   	Unexpected file "newLeaf"
2020/12/27 07:28:58 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:28:58 DEBUG : dir: Looking for writers
2020/12/27 07:28:58 DEBUG : file1: reading active writers
2020/12/27 07:28:58 DEBUG : : Looking for writers
2020/12/27 07:28:58 DEBUG : dir: reading active writers
2020/12/27 07:28:58 DEBUG : newLeaf: reading active writers
2020/12/27 07:28:58 DEBUG : >WaitForWriters: 
2020/12/27 07:28:58 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/12/27 07:28:58 DEBUG : dir/file1: newRWFileHandle: 
2020/12/27 07:28:58 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/12/27 07:28:58 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/12/27 07:28:58 DEBUG : dir/file1(0xc000495c00): _readAt: size=512, off=0
2020/12/27 07:28:58 DEBUG : dir/file1(0xc000495c00): openPending: 
2020/12/27 07:28:58 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2020/12/27 07:28:58 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/12/27 07:28:58 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:28:58 DEBUG : dir/file1(0xc000495c00): >openPending: err=<nil>
2020/12/27 07:28:58 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [] - present false
2020/12/27 07:28:58 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1
2020/12/27 07:28:58 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2020/12/27 07:28:58 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/12/27 07:28:58 DEBUG : dir/file1(0xc000495c00): >_readAt: n=14, err=EOF
2020/12/27 07:28:58 DEBUG : dir/file1(0xc000495c00): close: 
2020/12/27 07:28:58 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC
2020/12/27 07:28:58 DEBUG : dir/file1(0xc000495c00): >close: err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:300: Flushing the directory cache
    fstest.go:304: 
        	Error Trace:	fstest.go:304
        	            				fstest.go:337
        	            				fstest.go:349
        	            				file_test.go:285
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/full,forceCache=false
        	Messages:   	listing wrong, want
        	            	  dir/file1 (14) got
        	            	  dir/file1 (14), newLeaf (25)
    fstest.go:190: 
        	Error Trace:	fstest.go:190
        	            				fstest.go:307
        	            				fstest.go:337
        	            				fstest.go:349
        	            				file_test.go:285
        	            				file_test.go:360
        	Error:      	Should be true
        	Test:       	TestFileRename/full,forceCache=false
        	Messages:   	Unexpected file "newLeaf"
2020/12/27 07:29:47 INFO  : newLeaf: Deleted
2020/12/27 07:29:49 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2020/12/27 07:29:49 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14)
2020/12/27 07:29:49 INFO  : dir/file1: Moved (server-side) to: newLeaf
2020/12/27 07:29:49 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/12/27 07:29:49 DEBUG : newLeaf: Updating file with newLeaf 0xc000297080
2020/12/27 07:29:49 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/12/27 07:29:49 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:29:53 INFO  : newLeaf: Moved (server-side) to: dir/file1
2020/12/27 07:29:53 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/12/27 07:29:53 DEBUG : dir/file1: Updating file with dir/file1 0xc000297080
2020/12/27 07:29:53 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/12/27 07:29:53 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:29:54 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/12/27 07:29:54 DEBUG : dir/file1: newRWFileHandle: 
2020/12/27 07:29:54 DEBUG : dir/file1(0xc00150eb40): openPending: 
2020/12/27 07:29:54 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,0001-01-01 00:00:00 +0000 UTC," against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/12/27 07:29:54 DEBUG : dir/file1: vfs cache: removing cached entry as stale (remote fingerprint "14,0001-01-01 00:00:00 +0000 UTC," != cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595")
2020/12/27 07:29:54 INFO  : dir/file1: vfs cache: removed cache file as stale (remote is different)
2020/12/27 07:29:54 DEBUG : dir/file1: vfs cache: removed metadata from cache as stale (remote is different)
2020/12/27 07:29:54 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/12/27 07:29:54 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2020/12/27 07:29:54 DEBUG : dir/file1(0xc00150eb40): >openPending: err=<nil>
2020/12/27 07:29:54 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/12/27 07:29:54 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/12/27 07:29:54 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/12/27 07:29:54 DEBUG : dir/file1(0xc00150eb40): _writeAt: size=25, off=0
2020/12/27 07:29:54 DEBUG : dir/file1(0xc00150eb40): >_writeAt: n=25, err=<nil>
2020/12/27 07:29:57 INFO  : dir/file1: Moved (server-side) to: newLeaf
2020/12/27 07:29:57 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/12/27 07:29:57 DEBUG : newLeaf: Updating file with newLeaf 0xc000297080
2020/12/27 07:29:57 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/12/27 07:29:57 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:29:57 DEBUG : newLeaf(0xc00150eb40): close: 
2020/12/27 07:29:57 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/12/27 07:29:57 DEBUG : newLeaf: vfs cache: setting modification time to 2020-12-27 07:29:54.96807304 +0000 UTC m=+409.298745953
2020/12/27 07:29:57 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/12/27 07:29:57 DEBUG : newLeaf(0xc00150eb40): >close: err=<nil>
2020/12/27 07:29:57 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:29:57 DEBUG : dir: Looking for writers
2020/12/27 07:29:57 DEBUG : : Looking for writers
2020/12/27 07:29:57 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:57 DEBUG : dir: reading active writers
2020/12/27 07:29:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:29:57 DEBUG : dir: Looking for writers
2020/12/27 07:29:57 DEBUG : : Looking for writers
2020/12/27 07:29:57 DEBUG : dir: reading active writers
2020/12/27 07:29:57 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:29:57 DEBUG : dir: Looking for writers
2020/12/27 07:29:57 DEBUG : : Looking for writers
2020/12/27 07:29:57 DEBUG : dir: reading active writers
2020/12/27 07:29:57 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:29:57 DEBUG : dir: Looking for writers
2020/12/27 07:29:57 DEBUG : : Looking for writers
2020/12/27 07:29:57 DEBUG : dir: reading active writers
2020/12/27 07:29:57 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:29:57 DEBUG : newLeaf: vfs cache: starting upload
2020/12/27 07:29:57 DEBUG : dir: Looking for writers
2020/12/27 07:29:57 DEBUG : : Looking for writers
2020/12/27 07:29:57 DEBUG : dir: reading active writers
2020/12/27 07:29:57 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:29:58 DEBUG : dir: Looking for writers
2020/12/27 07:29:58 DEBUG : : Looking for writers
2020/12/27 07:29:58 DEBUG : dir: reading active writers
2020/12/27 07:29:58 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:29:58 DEBUG : dir: Looking for writers
2020/12/27 07:29:58 DEBUG : : Looking for writers
2020/12/27 07:29:58 DEBUG : dir: reading active writers
2020/12/27 07:29:58 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:29:58 DEBUG : newLeaf: Uploading chunk 0, size=25, remain=0
2020/12/27 07:29:58 DEBUG : dir: Looking for writers
2020/12/27 07:29:58 DEBUG : : Looking for writers
2020/12/27 07:29:58 DEBUG : dir: reading active writers
2020/12/27 07:29:58 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:29:59 DEBUG : dir: Looking for writers
2020/12/27 07:29:59 DEBUG : : Looking for writers
2020/12/27 07:29:59 DEBUG : dir: reading active writers
2020/12/27 07:29:59 DEBUG : newLeaf: reading active writers
2020/12/27 07:29:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:00 DEBUG : dir: Looking for writers
2020/12/27 07:30:00 DEBUG : : Looking for writers
2020/12/27 07:30:00 DEBUG : dir: reading active writers
2020/12/27 07:30:00 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:01 DEBUG : dir: Looking for writers
2020/12/27 07:30:01 DEBUG : : Looking for writers
2020/12/27 07:30:01 DEBUG : dir: reading active writers
2020/12/27 07:30:01 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:02 DEBUG : dir: Looking for writers
2020/12/27 07:30:02 DEBUG : : Looking for writers
2020/12/27 07:30:02 DEBUG : dir: reading active writers
2020/12/27 07:30:02 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:03 DEBUG : dir: Looking for writers
2020/12/27 07:30:03 DEBUG : : Looking for writers
2020/12/27 07:30:03 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:03 DEBUG : dir: reading active writers
2020/12/27 07:30:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:04 DEBUG : dir: Looking for writers
2020/12/27 07:30:04 DEBUG : : Looking for writers
2020/12/27 07:30:04 DEBUG : dir: reading active writers
2020/12/27 07:30:04 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:05 DEBUG : dir: Looking for writers
2020/12/27 07:30:05 DEBUG : : Looking for writers
2020/12/27 07:30:05 DEBUG : dir: reading active writers
2020/12/27 07:30:05 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:06 DEBUG : dir: Looking for writers
2020/12/27 07:30:06 DEBUG : : Looking for writers
2020/12/27 07:30:06 DEBUG : dir: reading active writers
2020/12/27 07:30:06 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:30:07 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"newLeaf": &{c:0xc0000d9080 mu:{state:0 sema:0} cond:0xc000495bc0 name:newLeaf opens:0 downloaders:<nil> o:0xc001636480 fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165632616570704 ext:409298745953 loc:0x26d8980} ATime:{wall:13831165635591847191 ext:412052796949 loc:0x26d8980} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:30:07 DEBUG : >WaitForWriters: 
2020/12/27 07:30:08 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:30:08 DEBUG : dir: Looking for writers
2020/12/27 07:30:08 DEBUG : : Looking for writers
2020/12/27 07:30:08 DEBUG : dir: reading active writers
2020/12/27 07:30:08 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:30:08 DEBUG : dir: Looking for writers
2020/12/27 07:30:08 DEBUG : : Looking for writers
2020/12/27 07:30:08 DEBUG : dir: reading active writers
2020/12/27 07:30:08 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:30:08 DEBUG : dir: Looking for writers
2020/12/27 07:30:08 DEBUG : : Looking for writers
2020/12/27 07:30:08 DEBUG : dir: reading active writers
2020/12/27 07:30:08 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:30:08 DEBUG : dir: Looking for writers
2020/12/27 07:30:08 DEBUG : : Looking for writers
2020/12/27 07:30:08 DEBUG : dir: reading active writers
2020/12/27 07:30:08 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:30:09 DEBUG : dir: Looking for writers
2020/12/27 07:30:09 DEBUG : : Looking for writers
2020/12/27 07:30:09 DEBUG : dir: reading active writers
2020/12/27 07:30:09 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:30:09 DEBUG : dir: Looking for writers
2020/12/27 07:30:09 DEBUG : : Looking for writers
2020/12/27 07:30:09 DEBUG : dir: reading active writers
2020/12/27 07:30:09 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:30:09 DEBUG : dir: Looking for writers
2020/12/27 07:30:09 DEBUG : : Looking for writers
2020/12/27 07:30:09 DEBUG : dir: reading active writers
2020/12/27 07:30:09 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:30:09 INFO  : newLeaf: Copied (replaced existing)
2020/12/27 07:30:09 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-12-27 07:29:54 +0000 UTC,"
2020/12/27 07:30:09 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/12/27 07:30:09 DEBUG : : Added virtual directory entry vAddFile: "newLeaf"
2020/12/27 07:30:09 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/12/27 07:30:10 DEBUG : dir: Looking for writers
2020/12/27 07:30:10 DEBUG : : Looking for writers
2020/12/27 07:30:10 DEBUG : dir: reading active writers
2020/12/27 07:30:10 DEBUG : newLeaf: reading active writers
2020/12/27 07:30:10 DEBUG : >WaitForWriters: 
2020/12/27 07:30:10 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestFileRename (426.52s)
    --- FAIL: TestFileRename/minimal,forceCache=true (60.85s)
    --- FAIL: TestFileRename/writes,forceCache=false (161.20s)
    --- FAIL: TestFileRename/full,forceCache=false (204.47s)
=== RUN   TestReadFileHandleMethods
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:30:14 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:30:14 NOTICE: OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2020/12/27 07:30:17 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/12/27 07:31:06 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/12/27 07:31:07 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/12/27 07:31:07 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/12/27 07:31:07 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/12/27 07:31:07 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/12/27 07:31:24 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2020/12/27 07:31:24 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728
2020/12/27 07:31:24 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:31:24 DEBUG : dir: Looking for writers
2020/12/27 07:31:24 DEBUG : file1: reading active writers
2020/12/27 07:31:24 DEBUG : : Looking for writers
2020/12/27 07:31:24 DEBUG : dir: reading active writers
2020/12/27 07:31:24 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleMethods (78.78s)
=== RUN   TestReadFileHandleSeek
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:31:32 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:31:32 NOTICE: OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2020/12/27 07:32:20 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/12/27 07:32:40 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/12/27 07:32:42 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/12/27 07:32:42 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/12/27 07:32:42 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/12/27 07:32:42 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/12/27 07:32:42 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2020/12/27 07:32:42 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms
2020/12/27 07:32:42 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2020/12/27 07:32:42 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2020/12/27 07:32:42 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2020/12/27 07:32:42 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2020/12/27 07:32:42 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2020/12/27 07:32:42 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2020/12/27 07:32:43 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker)
2020/12/27 07:32:43 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1
2020/12/27 07:32:43 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728
2020/12/27 07:32:43 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728
2020/12/27 07:32:43 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker)
2020/12/27 07:32:43 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1
2020/12/27 07:32:43 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728
2020/12/27 07:32:43 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728
2020/12/27 07:32:44 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:32:44 DEBUG : dir: Looking for writers
2020/12/27 07:32:44 DEBUG : file1: reading active writers
2020/12/27 07:32:44 DEBUG : : Looking for writers
2020/12/27 07:32:44 DEBUG : dir: reading active writers
2020/12/27 07:32:44 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleSeek (75.14s)
=== RUN   TestRWFileHandleMethodsWrite
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:32:47 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:32:47 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:32:47 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:32:47 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:32:47 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/12/27 07:32:47 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:32:48 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/12/27 07:32:48 DEBUG : file1: newRWFileHandle: 
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): openPending: 
2020/12/27 07:32:48 DEBUG : file1: vfs cache: truncate to size=0
2020/12/27 07:32:48 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): >openPending: err=<nil>
2020/12/27 07:32:48 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/12/27 07:32:48 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:32:48 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/12/27 07:32:48 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): _writeAt: size=5, off=0
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): >_writeAt: n=5, err=<nil>
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): _writeAt: size=7, off=5
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): >_writeAt: n=7, err=<nil>
2020/12/27 07:32:48 DEBUG : file1: vfs cache: truncate to size=11
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): close: 
2020/12/27 07:32:48 DEBUG : file1: vfs cache: setting modification time to 2020-12-27 07:32:48.537389099 +0000 UTC m=+582.868061996
2020/12/27 07:32:48 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): >close: err=<nil>
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): close: 
2020/12/27 07:32:48 DEBUG : file1(0xc000256c80): >close: err=file already closed
2020/12/27 07:32:48 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:32:48 DEBUG : : Looking for writers
2020/12/27 07:32:48 DEBUG : file1: reading active writers
2020/12/27 07:32:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:32:48 DEBUG : : Looking for writers
2020/12/27 07:32:48 DEBUG : file1: reading active writers
2020/12/27 07:32:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:32:48 DEBUG : : Looking for writers
2020/12/27 07:32:48 DEBUG : file1: reading active writers
2020/12/27 07:32:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:32:48 DEBUG : : Looking for writers
2020/12/27 07:32:48 DEBUG : file1: reading active writers
2020/12/27 07:32:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:32:48 DEBUG : file1: vfs cache: starting upload
2020/12/27 07:32:48 DEBUG : : Looking for writers
2020/12/27 07:32:48 DEBUG : file1: reading active writers
2020/12/27 07:32:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:32:48 DEBUG : : Looking for writers
2020/12/27 07:32:48 DEBUG : file1: reading active writers
2020/12/27 07:32:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:32:49 DEBUG : : Looking for writers
2020/12/27 07:32:49 DEBUG : file1: reading active writers
2020/12/27 07:32:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:32:49 DEBUG : : Looking for writers
2020/12/27 07:32:49 DEBUG : file1: reading active writers
2020/12/27 07:32:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:50 DEBUG : file1: Uploading chunk 0, size=11, remain=0
2020/12/27 07:32:50 DEBUG : : Looking for writers
2020/12/27 07:32:50 DEBUG : file1: reading active writers
2020/12/27 07:32:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:51 DEBUG : : Looking for writers
2020/12/27 07:32:51 DEBUG : file1: reading active writers
2020/12/27 07:32:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:52 DEBUG : : Looking for writers
2020/12/27 07:32:52 DEBUG : file1: reading active writers
2020/12/27 07:32:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:53 DEBUG : : Looking for writers
2020/12/27 07:32:53 DEBUG : file1: reading active writers
2020/12/27 07:32:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:54 DEBUG : : Looking for writers
2020/12/27 07:32:54 DEBUG : file1: reading active writers
2020/12/27 07:32:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:55 DEBUG : : Looking for writers
2020/12/27 07:32:55 DEBUG : file1: reading active writers
2020/12/27 07:32:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:56 DEBUG : : Looking for writers
2020/12/27 07:32:56 DEBUG : file1: reading active writers
2020/12/27 07:32:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:57 DEBUG : : Looking for writers
2020/12/27 07:32:57 DEBUG : file1: reading active writers
2020/12/27 07:32:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:32:58 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc0000d9500 mu:{state:0 sema:0} cond:0xc000256b40 name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165819016964139 ext:582868061996 loc:0x26d8980} ATime:{wall:13831165819017054420 ext:582868152282 loc:0x26d8980} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:32:58 DEBUG : >WaitForWriters: 
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
    fstest.go:291: Sleeping for 6s just to make sure
2020/12/27 07:33:06 INFO  : file1: Copied (new)
2020/12/27 07:33:06 DEBUG : file1: vfs cache: fingerprint now "11,2020-12-27 07:32:48 +0000 UTC,"
2020/12/27 07:33:06 DEBUG : file1: vfs cache: writeback object to VFS layer
2020/12/27 07:33:06 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:33:06 INFO  : file1: vfs cache: upload succeeded try #1
2020/12/27 07:33:10 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:33:10 DEBUG : : Looking for writers
2020/12/27 07:33:10 DEBUG : file1: reading active writers
2020/12/27 07:33:10 DEBUG : >WaitForWriters: 
2020/12/27 07:33:10 DEBUG : vfs cache: cleaner exiting
--- PASS: TestRWFileHandleMethodsWrite (24.42s)
=== RUN   TestRWFileHandleWriteAt
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:33:12 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:33:12 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:33:12 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:33:12 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:33:12 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/12/27 07:33:12 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:33:12 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/12/27 07:33:12 DEBUG : file1: newRWFileHandle: 
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): openPending: 
2020/12/27 07:33:12 DEBUG : file1: vfs cache: truncate to size=0
2020/12/27 07:33:12 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): >openPending: err=<nil>
2020/12/27 07:33:12 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/12/27 07:33:12 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:33:12 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/12/27 07:33:12 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): _writeAt: size=7, off=0
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): >_writeAt: n=7, err=<nil>
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): _writeAt: size=6, off=5
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): >_writeAt: n=6, err=<nil>
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): close: 
2020/12/27 07:33:12 DEBUG : file1: vfs cache: setting modification time to 2020-12-27 07:33:12.951539055 +0000 UTC m=+607.282211948
2020/12/27 07:33:12 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): >close: err=<nil>
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): _writeAt: size=5, off=0
2020/12/27 07:33:12 DEBUG : file1(0xc000495f80): >_writeAt: n=0, err=file already closed
2020/12/27 07:33:12 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:33:12 DEBUG : : Looking for writers
2020/12/27 07:33:12 DEBUG : file1: reading active writers
2020/12/27 07:33:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:33:12 DEBUG : : Looking for writers
2020/12/27 07:33:12 DEBUG : file1: reading active writers
2020/12/27 07:33:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:33:12 DEBUG : : Looking for writers
2020/12/27 07:33:12 DEBUG : file1: reading active writers
2020/12/27 07:33:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:33:13 DEBUG : : Looking for writers
2020/12/27 07:33:13 DEBUG : file1: reading active writers
2020/12/27 07:33:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:33:13 DEBUG : file1: vfs cache: starting upload
2020/12/27 07:33:13 DEBUG : : Looking for writers
2020/12/27 07:33:13 DEBUG : file1: reading active writers
2020/12/27 07:33:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:33:13 DEBUG : : Looking for writers
2020/12/27 07:33:13 DEBUG : file1: reading active writers
2020/12/27 07:33:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:33:13 DEBUG : : Looking for writers
2020/12/27 07:33:13 DEBUG : file1: reading active writers
2020/12/27 07:33:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:33:14 DEBUG : : Looking for writers
2020/12/27 07:33:14 DEBUG : file1: reading active writers
2020/12/27 07:33:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:33:14 DEBUG : file1: Uploading chunk 0, size=11, remain=0
2020/12/27 07:33:15 DEBUG : : Looking for writers
2020/12/27 07:33:15 DEBUG : file1: reading active writers
2020/12/27 07:33:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:33:16 DEBUG : : Looking for writers
2020/12/27 07:33:16 DEBUG : file1: reading active writers
2020/12/27 07:33:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:33:17 DEBUG : : Looking for writers
2020/12/27 07:33:17 DEBUG : file1: reading active writers
2020/12/27 07:33:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:33:17 INFO  : file1: Copied (new)
2020/12/27 07:33:17 DEBUG : file1: vfs cache: fingerprint now "11,2020-12-27 07:33:12 +0000 UTC,"
2020/12/27 07:33:17 DEBUG : file1: vfs cache: writeback object to VFS layer
2020/12/27 07:33:17 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:33:17 INFO  : file1: vfs cache: upload succeeded try #1
2020/12/27 07:33:18 DEBUG : : Looking for writers
2020/12/27 07:33:18 DEBUG : file1: reading active writers
2020/12/27 07:33:18 DEBUG : >WaitForWriters: 
2020/12/27 07:33:18 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:33:18 DEBUG : : Looking for writers
2020/12/27 07:33:18 DEBUG : file1: reading active writers
2020/12/27 07:33:18 DEBUG : >WaitForWriters: 
2020/12/27 07:33:18 DEBUG : vfs cache: cleaner exiting
--- PASS: TestRWFileHandleWriteAt (8.13s)
=== RUN   TestRWFileHandleWriteNoWrite
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:33:20 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:33:20 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:33:20 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:33:20 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:33:20 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/12/27 07:33:20 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:33:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/12/27 07:33:21 DEBUG : file1: newRWFileHandle: 
2020/12/27 07:33:21 DEBUG : file1(0xc00150efc0): openPending: 
2020/12/27 07:33:21 DEBUG : file1: vfs cache: truncate to size=0
2020/12/27 07:33:21 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:33:21 DEBUG : file1(0xc00150efc0): >openPending: err=<nil>
2020/12/27 07:33:21 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/12/27 07:33:21 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:33:21 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/12/27 07:33:21 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/12/27 07:33:21 DEBUG : file1(0xc00150efc0): close: 
2020/12/27 07:33:21 DEBUG : file1: vfs cache: setting modification time to 2020-12-27 07:33:21.075677502 +0000 UTC m=+615.406350403
2020/12/27 07:33:21 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/12/27 07:33:21 DEBUG : file1(0xc00150efc0): >close: err=<nil>
2020/12/27 07:33:21 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2020/12/27 07:33:21 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/12/27 07:33:21 DEBUG : file2: newRWFileHandle: 
2020/12/27 07:33:21 DEBUG : file2(0xc00150f0c0): openPending: 
2020/12/27 07:33:21 DEBUG : file2: vfs cache: truncate to size=0
2020/12/27 07:33:21 DEBUG : : Added virtual directory entry vAddFile: "file2"
2020/12/27 07:33:21 DEBUG : file2(0xc00150f0c0): >openPending: err=<nil>
2020/12/27 07:33:21 DEBUG : file2: >newRWFileHandle: err=<nil>
2020/12/27 07:33:21 DEBUG : : Added virtual directory entry vAddFile: "file2"
2020/12/27 07:33:21 DEBUG : file2: >Open: fd=file2 (rw), err=<nil>
2020/12/27 07:33:21 DEBUG : file2: >OpenFile: fd=file2 (rw), err=<nil>
2020/12/27 07:33:21 DEBUG : file2(0xc00150f0c0): RWFileHandle.Flush
2020/12/27 07:33:21 DEBUG : file2(0xc00150f0c0): RWFileHandle.Release
2020/12/27 07:33:21 DEBUG : file2(0xc00150f0c0): close: 
2020/12/27 07:33:21 DEBUG : file2: vfs cache: setting modification time to 2020-12-27 07:33:21.077305889 +0000 UTC m=+615.407978793
2020/12/27 07:33:21 INFO  : file2: vfs cache: queuing for upload in 100ms
2020/12/27 07:33:21 DEBUG : file2(0xc00150f0c0): >close: err=<nil>
2020/12/27 07:33:21 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms
2020/12/27 07:33:21 DEBUG : file1: vfs cache: starting upload
2020/12/27 07:33:21 DEBUG : file2: vfs cache: starting upload
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms
2020/12/27 07:33:21 DEBUG : : Looking for writers
2020/12/27 07:33:21 DEBUG : file1: reading active writers
2020/12/27 07:33:21 DEBUG : file2: reading active writers
2020/12/27 07:33:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms
2020/12/27 07:33:22 DEBUG : : Looking for writers
2020/12/27 07:33:22 DEBUG : file1: reading active writers
2020/12/27 07:33:22 DEBUG : file2: reading active writers
2020/12/27 07:33:22 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:23 DEBUG : : Looking for writers
2020/12/27 07:33:23 DEBUG : file1: reading active writers
2020/12/27 07:33:23 DEBUG : file2: reading active writers
2020/12/27 07:33:23 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:24 DEBUG : : Looking for writers
2020/12/27 07:33:24 DEBUG : file1: reading active writers
2020/12/27 07:33:24 DEBUG : file2: reading active writers
2020/12/27 07:33:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:25 DEBUG : : Looking for writers
2020/12/27 07:33:25 DEBUG : file1: reading active writers
2020/12/27 07:33:25 DEBUG : file2: reading active writers
2020/12/27 07:33:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:26 DEBUG : : Looking for writers
2020/12/27 07:33:26 DEBUG : file1: reading active writers
2020/12/27 07:33:26 DEBUG : file2: reading active writers
2020/12/27 07:33:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:27 DEBUG : : Looking for writers
2020/12/27 07:33:27 DEBUG : file1: reading active writers
2020/12/27 07:33:27 DEBUG : file2: reading active writers
2020/12/27 07:33:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:28 DEBUG : : Looking for writers
2020/12/27 07:33:28 DEBUG : file1: reading active writers
2020/12/27 07:33:28 DEBUG : file2: reading active writers
2020/12/27 07:33:28 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:29 DEBUG : : Looking for writers
2020/12/27 07:33:29 DEBUG : file1: reading active writers
2020/12/27 07:33:29 DEBUG : file2: reading active writers
2020/12/27 07:33:29 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:30 DEBUG : : Looking for writers
2020/12/27 07:33:30 DEBUG : file1: reading active writers
2020/12/27 07:33:30 DEBUG : file2: reading active writers
2020/12/27 07:33:30 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:31 ERROR : Exiting even though 0 writers active and 2 cache items in use after 10s
Cache{
	"file1": &{c:0xc000296c00 mu:{state:0 sema:0} cond:0xc00150ef80 name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165853988732734 ext:615406350403 loc:0x26d8980} ATime:{wall:13831165853989306635 ext:615406924315 loc:0x26d8980} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
	"file2": &{c:0xc000296c00 mu:{state:0 sema:0} cond:0xc00150f080 name:file2 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165853990361121 ext:615407978793 loc:0x26d8980} ATime:{wall:13831165853990856756 ext:615408474428 loc:0x26d8980} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:33:31 DEBUG : >WaitForWriters: 
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
    fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:300: Flushing the directory cache
    fstest.go:304: 
        	Error Trace:	fstest.go:304
        	            				fstest.go:337
        	            				read_write_test.go:426
        	Error:      	Should be true
        	Test:       	TestRWFileHandleWriteNoWrite
        	Messages:   	listing wrong, want
        	            	  file1 (0), file2 (0) got
        	            	  
    fstest.go:202: Not found "file2"
    fstest.go:202: Not found "file1"
    fstest.go:205: 
        	Error Trace:	fstest.go:205
        	            				fstest.go:309
        	            				fstest.go:337
        	            				read_write_test.go:426
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 2
        	Test:       	TestRWFileHandleWriteNoWrite
        	Messages:   	2 objects not found
2020/12/27 07:33:51 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:33:51 DEBUG : : Looking for writers
2020/12/27 07:33:51 DEBUG : file1: reading active writers
2020/12/27 07:33:51 DEBUG : file2: reading active writers
2020/12/27 07:33:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms
2020/12/27 07:33:51 DEBUG : : Looking for writers
2020/12/27 07:33:51 DEBUG : file1: reading active writers
2020/12/27 07:33:51 DEBUG : file2: reading active writers
2020/12/27 07:33:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms
2020/12/27 07:33:52 DEBUG : : Looking for writers
2020/12/27 07:33:52 DEBUG : file1: reading active writers
2020/12/27 07:33:52 DEBUG : file2: reading active writers
2020/12/27 07:33:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms
2020/12/27 07:33:52 DEBUG : : Looking for writers
2020/12/27 07:33:52 DEBUG : file1: reading active writers
2020/12/27 07:33:52 DEBUG : file2: reading active writers
2020/12/27 07:33:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms
2020/12/27 07:33:52 DEBUG : : Looking for writers
2020/12/27 07:33:52 DEBUG : file1: reading active writers
2020/12/27 07:33:52 DEBUG : file2: reading active writers
2020/12/27 07:33:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms
2020/12/27 07:33:52 DEBUG : : Looking for writers
2020/12/27 07:33:52 DEBUG : file2: reading active writers
2020/12/27 07:33:52 DEBUG : file1: reading active writers
2020/12/27 07:33:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms
2020/12/27 07:33:52 DEBUG : : Looking for writers
2020/12/27 07:33:52 DEBUG : file1: reading active writers
2020/12/27 07:33:52 DEBUG : file2: reading active writers
2020/12/27 07:33:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms
2020/12/27 07:33:53 DEBUG : : Looking for writers
2020/12/27 07:33:53 DEBUG : file1: reading active writers
2020/12/27 07:33:53 DEBUG : file2: reading active writers
2020/12/27 07:33:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:54 DEBUG : : Looking for writers
2020/12/27 07:33:54 DEBUG : file1: reading active writers
2020/12/27 07:33:54 DEBUG : file2: reading active writers
2020/12/27 07:33:54 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:55 DEBUG : : Looking for writers
2020/12/27 07:33:55 DEBUG : file1: reading active writers
2020/12/27 07:33:55 DEBUG : file2: reading active writers
2020/12/27 07:33:55 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:56 DEBUG : : Looking for writers
2020/12/27 07:33:56 DEBUG : file1: reading active writers
2020/12/27 07:33:56 DEBUG : file2: reading active writers
2020/12/27 07:33:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:57 DEBUG : : Looking for writers
2020/12/27 07:33:57 DEBUG : file1: reading active writers
2020/12/27 07:33:57 DEBUG : file2: reading active writers
2020/12/27 07:33:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:58 DEBUG : : Looking for writers
2020/12/27 07:33:58 DEBUG : file1: reading active writers
2020/12/27 07:33:58 DEBUG : file2: reading active writers
2020/12/27 07:33:58 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:33:59 DEBUG : : Looking for writers
2020/12/27 07:33:59 DEBUG : file1: reading active writers
2020/12/27 07:33:59 DEBUG : file2: reading active writers
2020/12/27 07:33:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:34:00 DEBUG : : Looking for writers
2020/12/27 07:34:00 DEBUG : file1: reading active writers
2020/12/27 07:34:00 DEBUG : file2: reading active writers
2020/12/27 07:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/12/27 07:34:00 INFO  : file1: Copied (new)
2020/12/27 07:34:00 DEBUG : file1: vfs cache: fingerprint now "0,2020-12-27 07:33:21 +0000 UTC,"
2020/12/27 07:34:00 DEBUG : file1: vfs cache: writeback object to VFS layer
2020/12/27 07:34:00 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:34:00 INFO  : file1: vfs cache: upload succeeded try #1
2020/12/27 07:34:01 DEBUG : : Looking for writers
2020/12/27 07:34:01 DEBUG : file1: reading active writers
2020/12/27 07:34:01 DEBUG : file2: reading active writers
2020/12/27 07:34:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:34:01 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file2": &{c:0xc000296c00 mu:{state:0 sema:0} cond:0xc00150f080 name:file2 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165853990361121 ext:615407978793 loc:0x26d8980} ATime:{wall:13831165853990856756 ext:615408474428 loc:0x26d8980} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false},
	"file1": &{c:0xc000296c00 mu:{state:0 sema:0} cond:0xc00150ef80 name:file1 opens:0 downloaders:<nil> o:0xc000849f80 fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13831165853988732734 ext:615406350403 loc:0x26d8980} ATime:{wall:13831165853989306635 ext:615406924315 loc:0x26d8980} Size:0 Rs:[] Fingerprint:0,2020-12-27 07:33:21 +0000 UTC, Dirty:false} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:34:01 DEBUG : >WaitForWriters: 
2020/12/27 07:34:01 DEBUG : vfs cache: cleaner exiting
2020/12/27 07:34:01 ERROR : file2: Failed to copy: failed to get folder list: Get "https://dev.opendrive.com/api/v1/folder/itembyname.json/1d741dd36514c35205671a5017d829e13597911e6911d6d34efacad6b857b2d0/ODFfMjg1NDUzNF9DRFpieA?name=file2": context canceled
2020/12/27 07:34:01 INFO  : file2: vfs cache: upload canceled
--- FAIL: TestRWFileHandleWriteNoWrite (43.77s)
=== RUN   TestRWFileModTimeWithOpenWriters
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:34:04 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:34:04 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:34:04 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:34:04 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-demasen8bokajah3gutihut1"
2020/12/27 07:34:04 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/12/27 07:34:04 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:34:04 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/12/27 07:34:04 DEBUG : file1: newRWFileHandle: 
2020/12/27 07:34:04 DEBUG : file1(0xc000257380): openPending: 
2020/12/27 07:34:04 DEBUG : file1: vfs cache: truncate to size=0
2020/12/27 07:34:04 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:34:04 DEBUG : file1(0xc000257380): >openPending: err=<nil>
2020/12/27 07:34:04 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/12/27 07:34:04 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:34:04 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/12/27 07:34:04 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/12/27 07:34:54 DEBUG : time_test: Uploading chunk 0, size=5, remain=0
2020/12/27 07:35:04 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes
2020/12/27 07:35:04 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:36:04 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes
2020/12/27 07:36:04 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:37:04 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes
2020/12/27 07:37:04 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 0 (was 0)
2020/12/27 07:37:56 DEBUG : Can set mod time: true
2020/12/27 07:37:56 DEBUG : file1(0xc000257380): _writeAt: size=2, off=0
2020/12/27 07:37:56 DEBUG : file1(0xc000257380): >_writeAt: n=2, err=<nil>
2020/12/27 07:37:56 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC
2020/12/27 07:37:56 DEBUG : file1(0xc000257380): RWFileHandle.Flush
2020/12/27 07:37:56 DEBUG : file1(0xc000257380): RWFileHandle.Release
2020/12/27 07:37:56 DEBUG : file1(0xc000257380): close: 
2020/12/27 07:37:56 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC
2020/12/27 07:37:56 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/12/27 07:37:56 DEBUG : file1(0xc000257380): >close: err=<nil>
2020/12/27 07:37:56 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:37:56 DEBUG : file1: vfs cache: starting upload
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/12/27 07:37:56 DEBUG : : Looking for writers
2020/12/27 07:37:56 DEBUG : file1: reading active writers
2020/12/27 07:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/12/27 07:37:57 DEBUG : : Looking for writers
2020/12/27 07:37:57 DEBUG : file1: reading active writers
2020/12/27 07:37:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:37:57 DEBUG : file1: Uploading chunk 0, size=2, remain=0
2020/12/27 07:37:58 DEBUG : : Looking for writers
2020/12/27 07:37:58 DEBUG : file1: reading active writers
2020/12/27 07:37:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:37:59 DEBUG : : Looking for writers
2020/12/27 07:37:59 DEBUG : file1: reading active writers
2020/12/27 07:37:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:00 DEBUG : : Looking for writers
2020/12/27 07:38:00 DEBUG : file1: reading active writers
2020/12/27 07:38:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:01 DEBUG : : Looking for writers
2020/12/27 07:38:01 DEBUG : file1: reading active writers
2020/12/27 07:38:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:02 DEBUG : : Looking for writers
2020/12/27 07:38:02 DEBUG : file1: reading active writers
2020/12/27 07:38:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:03 DEBUG : : Looking for writers
2020/12/27 07:38:03 DEBUG : file1: reading active writers
2020/12/27 07:38:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:04 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes
2020/12/27 07:38:04 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 1, total size 2 (was 2)
2020/12/27 07:38:04 DEBUG : : Looking for writers
2020/12/27 07:38:04 DEBUG : file1: reading active writers
2020/12/27 07:38:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:05 DEBUG : : Looking for writers
2020/12/27 07:38:05 DEBUG : file1: reading active writers
2020/12/27 07:38:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/12/27 07:38:06 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc0000d8a80 mu:{state:0 sema:0} cond:0xc000257300 name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:0 ext:63488856751 loc:<nil>} ATime:{wall:13831166149281308457 ext:890419924619 loc:0x26d8980} Size:2 Rs:[{Pos:0 Size:2}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false},
}
2020/12/27 07:38:06 DEBUG : >WaitForWriters: 
2020/12/27 07:38:06 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:38:06 DEBUG : : Looking for writers
2020/12/27 07:38:06 DEBUG : file1: reading active writers
2020/12/27 07:38:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/12/27 07:38:06 DEBUG : : Looking for writers
2020/12/27 07:38:06 DEBUG : file1: reading active writers
2020/12/27 07:38:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/12/27 07:38:06 DEBUG : : Looking for writers
2020/12/27 07:38:06 DEBUG : file1: reading active writers
2020/12/27 07:38:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/12/27 07:38:06 DEBUG : : Looking for writers
2020/12/27 07:38:06 DEBUG : file1: reading active writers
2020/12/27 07:38:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/12/27 07:38:06 DEBUG : : Looking for writers
2020/12/27 07:38:06 DEBUG : file1: reading active writers
2020/12/27 07:38:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/12/27 07:38:06 INFO  : file1: Copied (new)
2020/12/27 07:38:06 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC,"
2020/12/27 07:38:06 DEBUG : file1: vfs cache: writeback object to VFS layer
2020/12/27 07:38:06 DEBUG : : Looking for writers
2020/12/27 07:38:06 DEBUG : file1: reading active writers
2020/12/27 07:38:06 DEBUG : >WaitForWriters: 
2020/12/27 07:38:06 DEBUG : vfs cache: cleaner exiting
2020/12/27 07:38:07 DEBUG : file1: Applied pending mod time 2012-11-18 17:32:31 +0000 UTC OK
2020/12/27 07:38:07 DEBUG : : Added virtual directory entry vAddFile: "file1"
2020/12/27 07:38:07 INFO  : file1: vfs cache: upload succeeded try #1
--- PASS: TestRWFileModTimeWithOpenWriters (244.40s)
=== RUN   TestVFSStat
    run.go:176: Remote "OpenDrive root 'rclone-test-demasen8bokajah3gutihut1'", Local "Local file system at /tmp/rclone864081020", Modify Window "1s"
2020/12/27 07:38:08 INFO  : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': poll-interval is not supported by this remote
2020/12/27 07:38:08 NOTICE: OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2020/12/27 07:38:11 DEBUG : file1: Uploading chunk 0, size=14, remain=0
2020/12/27 07:38:17 DEBUG : dir/file2: Uploading chunk 0, size=14, remain=0
2020/12/27 07:38:22 DEBUG : WaitForWriters: timeout=10s
2020/12/27 07:38:22 DEBUG : dir: Looking for writers
2020/12/27 07:38:22 DEBUG : file2: reading active writers
2020/12/27 07:38:22 DEBUG : : Looking for writers
2020/12/27 07:38:22 DEBUG : dir: reading active writers
2020/12/27 07:38:22 DEBUG : file1: reading active writers
2020/12/27 07:38:22 DEBUG : >WaitForWriters: 
--- PASS: TestVFSStat (18.11s)
FAIL
2020/12/27 07:38:26 DEBUG : OpenDrive root 'rclone-test-demasen8bokajah3gutihut1': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestFileRename|TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestReadFileHandleMethods|TestReadFileHandleSeek|TestVFSStat)$/^(full,forceCache=false|minimal,forceCache=true|writes,forceCache=false)$'" - Finished ERROR in 15m22.311019568s (try 3/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=false TestFileRename/full,forceCache=false TestRWFileHandleWriteNoWrite]