"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bSHA1HashS3: -verbose -size-limit 1024 -test.run '^(TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt)$'" - Starting (try 4/5)
=== RUN   TestRWFileHandleMethodsWrite
    run.go:176: Remote "Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1'", Local "Local file system at /tmp/rclone155734662", Modify Window "1ns"
2020/08/16 05:21:15 INFO  : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': poll-interval is not supported by this remote
2020/08/16 05:21:15 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bSHA1HashS3/rclone-test-wusacaz8hajolam0xozemid1"
2020/08/16 05:21:15 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bSHA1HashS3/rclone-test-wusacaz8hajolam0xozemid1"
2020/08/16 05:21:15 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:21:15 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/08/16 05:21:15 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:21:15 DEBUG : file1: newRWFileHandle: 
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): openPending: 
2020/08/16 05:21:15 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 05:21:15 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): >openPending: err=<nil>
2020/08/16 05:21:15 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 05:21:15 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:21:15 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 05:21:15 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): _writeAt: size=5, off=0
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): >_writeAt: n=5, err=<nil>
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): _writeAt: size=7, off=5
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): >_writeAt: n=7, err=<nil>
2020/08/16 05:21:15 DEBUG : file1: vfs cache: truncate to size=11
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): close: 
2020/08/16 05:21:15 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 05:21:15.176818893 +0000 UTC m=+0.136974785
2020/08/16 05:21:15 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): >close: err=<nil>
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): close: 
2020/08/16 05:21:15 DEBUG : file1(0xc00021c940): >close: err=file already closed
2020/08/16 05:21:15 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:21:15 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:21:15 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>22FF0CA6F0603D2C</RequestId><HostId>Ihh8nJ929VTNEfcB39aEHpXuJeIxv94s5/0xyNUrvwOQds5C20EofG/OMMcPmG1dLLzsBSaCvYA=</HostId></Error>
2020/08/16 05:21:15 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>22FF0CA6F0603D2C</RequestId><HostId>Ihh8nJ929VTNEfcB39aEHpXuJeIxv94s5/0xyNUrvwOQds5C20EofG/OMMcPmG1dLLzsBSaCvYA=</HostId></Error>
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:21:15 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:15 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>591F34DD77094991</RequestId><HostId>60q3eAvVcdMEoKPsB7GEnMelYHN8YkQcvPU0T2V4DgAP/GDw2PmMcB8Z+3hJ4Yhu+DKsFBPWVGc=</HostId></Error>
2020/08/16 05:21:15 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>591F34DD77094991</RequestId><HostId>60q3eAvVcdMEoKPsB7GEnMelYHN8YkQcvPU0T2V4DgAP/GDw2PmMcB8Z+3hJ4Yhu+DKsFBPWVGc=</HostId></Error>
2020/08/16 05:21:15 DEBUG : : Looking for writers
2020/08/16 05:21:15 DEBUG : file1: reading active writers
2020/08/16 05:21:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:21:16 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:16 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>B549EFD4ABFBFDD7</RequestId><HostId>FjBkM75X5h4db8Bu4ugeYqJyBMC7w0/XTZ9CoVu+XL9Cqe2k6xMKL7b5aCAqrsZbPv4ty83PwA0=</HostId></Error>
2020/08/16 05:21:16 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>B549EFD4ABFBFDD7</RequestId><HostId>FjBkM75X5h4db8Bu4ugeYqJyBMC7w0/XTZ9CoVu+XL9Cqe2k6xMKL7b5aCAqrsZbPv4ty83PwA0=</HostId></Error>
2020/08/16 05:21:16 DEBUG : : Looking for writers
2020/08/16 05:21:16 DEBUG : file1: reading active writers
2020/08/16 05:21:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:16 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:16 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EMAV8M5G0X1T1T2R</RequestId><HostId>WTaX0rNBzRk3FuHcEJ3H+aoTofDXykenmoAiSsb5XeZQR/Mg3u/jZdtL+GuCaLZ8jq51zYe2elE=</HostId></Error>
2020/08/16 05:21:16 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EMAV8M5G0X1T1T2R</RequestId><HostId>WTaX0rNBzRk3FuHcEJ3H+aoTofDXykenmoAiSsb5XeZQR/Mg3u/jZdtL+GuCaLZ8jq51zYe2elE=</HostId></Error>
2020/08/16 05:21:17 DEBUG : : Looking for writers
2020/08/16 05:21:17 DEBUG : file1: reading active writers
2020/08/16 05:21:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:18 DEBUG : : Looking for writers
2020/08/16 05:21:18 DEBUG : file1: reading active writers
2020/08/16 05:21:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:18 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:18 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>0AEFA820991A7368</RequestId><HostId>fKgY3I0zNwxAtzEKdMYyjB+ephPv+Jm4tCn8pxi0oeNZlusiwur8xaf8bSqtJ5KHx/XpT1+LVW0=</HostId></Error>
2020/08/16 05:21:18 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>0AEFA820991A7368</RequestId><HostId>fKgY3I0zNwxAtzEKdMYyjB+ephPv+Jm4tCn8pxi0oeNZlusiwur8xaf8bSqtJ5KHx/XpT1+LVW0=</HostId></Error>
2020/08/16 05:21:19 DEBUG : : Looking for writers
2020/08/16 05:21:19 DEBUG : file1: reading active writers
2020/08/16 05:21:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:20 DEBUG : : Looking for writers
2020/08/16 05:21:20 DEBUG : file1: reading active writers
2020/08/16 05:21:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:21 DEBUG : : Looking for writers
2020/08/16 05:21:21 DEBUG : file1: reading active writers
2020/08/16 05:21:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:21 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:21 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>0T3N2WEY9HDK3JBR</RequestId><HostId>Z46U76EDMPMuymMZTk7fCMDirzklS5ylhFF4pq9knYBdS8Cx36NMPGcamf/unfxNXdTO3EaT0cQ=</HostId></Error>
2020/08/16 05:21:21 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>0T3N2WEY9HDK3JBR</RequestId><HostId>Z46U76EDMPMuymMZTk7fCMDirzklS5ylhFF4pq9knYBdS8Cx36NMPGcamf/unfxNXdTO3EaT0cQ=</HostId></Error>
2020/08/16 05:21:22 DEBUG : : Looking for writers
2020/08/16 05:21:22 DEBUG : file1: reading active writers
2020/08/16 05:21:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:23 DEBUG : : Looking for writers
2020/08/16 05:21:23 DEBUG : file1: reading active writers
2020/08/16 05:21:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:24 DEBUG : : Looking for writers
2020/08/16 05:21:24 DEBUG : file1: reading active writers
2020/08/16 05:21:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:25 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc000164120 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818761564228301 ext:136974785 loc:0x25a1860} ATime:{wall:13818818761564241406 ext:136987860 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:21:25 DEBUG : >WaitForWriters: 
    fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
2020/08/16 05:21:28 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:28 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>A834B5468D24FE0D</RequestId><HostId>Rad6YU5RRTtjRShzWDk9mVs7BOX4n/ZgpbgMMIEuCs5IDkO1tdTDbhEQh8oqcxevh0hh2HYqQDE=</HostId></Error>
2020/08/16 05:21:28 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>A834B5468D24FE0D</RequestId><HostId>Rad6YU5RRTtjRShzWDk9mVs7BOX4n/ZgpbgMMIEuCs5IDkO1tdTDbhEQh8oqcxevh0hh2HYqQDE=</HostId></Error>
    fstest.go:302: 
        	Error Trace:	fstest.go:302
        	            				fstest.go:335
        	            				read_write_test.go:344
        	Error:      	Should be true
        	Test:       	TestRWFileHandleMethodsWrite
        	Messages:   	listing wrong, want
        	            	  file1 (11) got
        	            	  
    fstest.go:200: Not found "file1"
    fstest.go:203: 
        	Error Trace:	fstest.go:203
        	            				fstest.go:307
        	            				fstest.go:335
        	            				read_write_test.go:344
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestRWFileHandleMethodsWrite
        	Messages:   	1 objects not found
2020/08/16 05:21:32 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:21:32 DEBUG : : Looking for writers
2020/08/16 05:21:32 DEBUG : file1: reading active writers
2020/08/16 05:21:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:21:33 DEBUG : : Looking for writers
2020/08/16 05:21:33 DEBUG : file1: reading active writers
2020/08/16 05:21:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:34 DEBUG : : Looking for writers
2020/08/16 05:21:34 DEBUG : file1: reading active writers
2020/08/16 05:21:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:35 DEBUG : : Looking for writers
2020/08/16 05:21:35 DEBUG : file1: reading active writers
2020/08/16 05:21:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:36 DEBUG : : Looking for writers
2020/08/16 05:21:36 DEBUG : file1: reading active writers
2020/08/16 05:21:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:37 DEBUG : : Looking for writers
2020/08/16 05:21:37 DEBUG : file1: reading active writers
2020/08/16 05:21:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:38 DEBUG : : Looking for writers
2020/08/16 05:21:38 DEBUG : file1: reading active writers
2020/08/16 05:21:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:39 DEBUG : : Looking for writers
2020/08/16 05:21:39 DEBUG : file1: reading active writers
2020/08/16 05:21:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:40 DEBUG : : Looking for writers
2020/08/16 05:21:40 DEBUG : file1: reading active writers
2020/08/16 05:21:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:41 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:41 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>8DBA730755903D57</RequestId><HostId>SaOjdwTOKF4lwvWik5OEyVIH8VPzoctQRSgrjr1cDhd0a+Ho+jfuqKd4NuiCPacQSqatEiSasQA=</HostId></Error>
2020/08/16 05:21:41 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>8DBA730755903D57</RequestId><HostId>SaOjdwTOKF4lwvWik5OEyVIH8VPzoctQRSgrjr1cDhd0a+Ho+jfuqKd4NuiCPacQSqatEiSasQA=</HostId></Error>
2020/08/16 05:21:41 DEBUG : : Looking for writers
2020/08/16 05:21:41 DEBUG : file1: reading active writers
2020/08/16 05:21:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:42 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc000164120 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818761564228301 ext:136974785 loc:0x25a1860} ATime:{wall:13818818761564241406 ext:136987860 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:21:42 DEBUG : >WaitForWriters: 
2020/08/16 05:21:42 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestRWFileHandleMethodsWrite (27.21s)
=== RUN   TestRWFileHandleWriteAt
    run.go:176: Remote "Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1'", Local "Local file system at /tmp/rclone155734662", Modify Window "1ns"
2020/08/16 05:21:42 INFO  : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': poll-interval is not supported by this remote
2020/08/16 05:21:42 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bSHA1HashS3/rclone-test-wusacaz8hajolam0xozemid1"
2020/08/16 05:21:42 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bSHA1HashS3/rclone-test-wusacaz8hajolam0xozemid1"
2020/08/16 05:21:42 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:21:42 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/08/16 05:21:42 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:21:42 DEBUG : file1: newRWFileHandle: 
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): openPending: 
2020/08/16 05:21:42 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 05:21:42 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): >openPending: err=<nil>
2020/08/16 05:21:42 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 05:21:42 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:21:42 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 05:21:42 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): _writeAt: size=7, off=0
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): >_writeAt: n=7, err=<nil>
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): _writeAt: size=6, off=5
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): >_writeAt: n=6, err=<nil>
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): close: 
2020/08/16 05:21:42 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 05:21:42.28552823 +0000 UTC m=+27.245684078
2020/08/16 05:21:42 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): >close: err=<nil>
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): _writeAt: size=5, off=0
2020/08/16 05:21:42 DEBUG : file1(0xc0002d93c0): >_writeAt: n=0, err=file already closed
2020/08/16 05:21:42 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:21:42 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:42 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>1E99774B19566431</RequestId><HostId>TpGMzN8ZYOaloP4/rY2csWyJKxqgKdnmitPyZhabh4tnrwU6+di7NLf8k8eGZ4P9oFsta5CCvfY=</HostId></Error>
2020/08/16 05:21:42 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>1E99774B19566431</RequestId><HostId>TpGMzN8ZYOaloP4/rY2csWyJKxqgKdnmitPyZhabh4tnrwU6+di7NLf8k8eGZ4P9oFsta5CCvfY=</HostId></Error>
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:21:42 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:42 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>4GAM9XCZ8N3WEZ2Y</RequestId><HostId>7QmeadjWw7Cfe1GXiSE/WAUqCcv2xWt9jn34qxFxOPU3Sy2NGoVEpNN4GqlYfVA3aojJBrEO+ts=</HostId></Error>
2020/08/16 05:21:42 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>4GAM9XCZ8N3WEZ2Y</RequestId><HostId>7QmeadjWw7Cfe1GXiSE/WAUqCcv2xWt9jn34qxFxOPU3Sy2NGoVEpNN4GqlYfVA3aojJBrEO+ts=</HostId></Error>
2020/08/16 05:21:42 DEBUG : : Looking for writers
2020/08/16 05:21:42 DEBUG : file1: reading active writers
2020/08/16 05:21:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:21:43 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:43 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>AC35FA63CAED145C</RequestId><HostId>btsoG53lrGGBNQKBjH9+V6FiB3NY5wLqhHrQtKX+/ymYB0FgqTUSXMxGGFMSW8cAQHuCKrZazJc=</HostId></Error>
2020/08/16 05:21:43 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>AC35FA63CAED145C</RequestId><HostId>btsoG53lrGGBNQKBjH9+V6FiB3NY5wLqhHrQtKX+/ymYB0FgqTUSXMxGGFMSW8cAQHuCKrZazJc=</HostId></Error>
2020/08/16 05:21:43 DEBUG : : Looking for writers
2020/08/16 05:21:43 DEBUG : file1: reading active writers
2020/08/16 05:21:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:43 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:43 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>E8FDDA06415333F4</RequestId><HostId>G+J+xedPFjpiH22sLMON7Qz4KQFZEmfM4F704kSBjZU3aaGBY+oQQbr5Jnf+VS2p4jL5Yq1Mglw=</HostId></Error>
2020/08/16 05:21:43 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>E8FDDA06415333F4</RequestId><HostId>G+J+xedPFjpiH22sLMON7Qz4KQFZEmfM4F704kSBjZU3aaGBY+oQQbr5Jnf+VS2p4jL5Yq1Mglw=</HostId></Error>
2020/08/16 05:21:44 DEBUG : : Looking for writers
2020/08/16 05:21:44 DEBUG : file1: reading active writers
2020/08/16 05:21:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:45 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:45 DEBUG : : Looking for writers
2020/08/16 05:21:45 DEBUG : file1: reading active writers
2020/08/16 05:21:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:45 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>A6A6C2791F32F025</RequestId><HostId>MilIsKWjCMAqbcj+OM9yxOoSkTp7faqYIOQ2dV5XvcNG7LnE9Ix7O4WKYf5eR7REG6YDNfFhHv0=</HostId></Error>
2020/08/16 05:21:45 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>A6A6C2791F32F025</RequestId><HostId>MilIsKWjCMAqbcj+OM9yxOoSkTp7faqYIOQ2dV5XvcNG7LnE9Ix7O4WKYf5eR7REG6YDNfFhHv0=</HostId></Error>
2020/08/16 05:21:46 DEBUG : : Looking for writers
2020/08/16 05:21:46 DEBUG : file1: reading active writers
2020/08/16 05:21:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:47 DEBUG : : Looking for writers
2020/08/16 05:21:47 DEBUG : file1: reading active writers
2020/08/16 05:21:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:48 DEBUG : : Looking for writers
2020/08/16 05:21:48 DEBUG : file1: reading active writers
2020/08/16 05:21:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:48 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:48 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3551E525B178C869</RequestId><HostId>xVPi1rvR16NVBJE38Qka3CdjpA6i/FBmD7MRB3lfEYrS3GpYQn3Y2Lijx9z328lNGX2E/73Llzw=</HostId></Error>
2020/08/16 05:21:48 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3551E525B178C869</RequestId><HostId>xVPi1rvR16NVBJE38Qka3CdjpA6i/FBmD7MRB3lfEYrS3GpYQn3Y2Lijx9z328lNGX2E/73Llzw=</HostId></Error>
2020/08/16 05:21:49 DEBUG : : Looking for writers
2020/08/16 05:21:49 DEBUG : file1: reading active writers
2020/08/16 05:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:50 DEBUG : : Looking for writers
2020/08/16 05:21:50 DEBUG : file1: reading active writers
2020/08/16 05:21:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:51 DEBUG : : Looking for writers
2020/08/16 05:21:51 DEBUG : file1: reading active writers
2020/08/16 05:21:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:21:52 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc0005b21b0 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818790663966886 ext:27245684078 loc:0x25a1860} ATime:{wall:13818818790664002583 ext:27245719790 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:21:52 DEBUG : >WaitForWriters: 
    fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
2020/08/16 05:21:55 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:21:55 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>9D98BDB105BA479E</RequestId><HostId>cZm07NN4vlCglexMNxgA5jwe5q10unqpC4wQKqIPzBZZi2+HAbtKNP0MgN7QZ9g8IlGzXz0H/Gw=</HostId></Error>
2020/08/16 05:21:55 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>9D98BDB105BA479E</RequestId><HostId>cZm07NN4vlCglexMNxgA5jwe5q10unqpC4wQKqIPzBZZi2+HAbtKNP0MgN7QZ9g8IlGzXz0H/Gw=</HostId></Error>
    fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:302: 
        	Error Trace:	fstest.go:302
        	            				fstest.go:335
        	            				read_write_test.go:392
        	Error:      	Should be true
        	Test:       	TestRWFileHandleWriteAt
        	Messages:   	listing wrong, want
        	            	  file1 (11) got
        	            	  
    fstest.go:200: Not found "file1"
    fstest.go:203: 
        	Error Trace:	fstest.go:203
        	            				fstest.go:307
        	            				fstest.go:335
        	            				read_write_test.go:392
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestRWFileHandleWriteAt
        	Messages:   	1 objects not found
2020/08/16 05:21:59 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:21:59 DEBUG : : Looking for writers
2020/08/16 05:21:59 DEBUG : file1: reading active writers
2020/08/16 05:21:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:22:00 DEBUG : : Looking for writers
2020/08/16 05:22:00 DEBUG : file1: reading active writers
2020/08/16 05:22:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:01 DEBUG : : Looking for writers
2020/08/16 05:22:01 DEBUG : file1: reading active writers
2020/08/16 05:22:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:02 DEBUG : : Looking for writers
2020/08/16 05:22:02 DEBUG : file1: reading active writers
2020/08/16 05:22:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:03 DEBUG : : Looking for writers
2020/08/16 05:22:03 DEBUG : file1: reading active writers
2020/08/16 05:22:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:04 DEBUG : : Looking for writers
2020/08/16 05:22:04 DEBUG : file1: reading active writers
2020/08/16 05:22:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:05 DEBUG : : Looking for writers
2020/08/16 05:22:05 DEBUG : file1: reading active writers
2020/08/16 05:22:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:06 DEBUG : : Looking for writers
2020/08/16 05:22:06 DEBUG : file1: reading active writers
2020/08/16 05:22:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:07 DEBUG : : Looking for writers
2020/08/16 05:22:07 DEBUG : file1: reading active writers
2020/08/16 05:22:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:08 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:08 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>D28193D35F36F823</RequestId><HostId>aLrexZLFkk1RdA/joamqfLs8qlx7v3cekFcuhMZLZeVLmer/rZejTdLOJxNlfsqy1XXfTP8fpIM=</HostId></Error>
2020/08/16 05:22:08 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>D28193D35F36F823</RequestId><HostId>aLrexZLFkk1RdA/joamqfLs8qlx7v3cekFcuhMZLZeVLmer/rZejTdLOJxNlfsqy1XXfTP8fpIM=</HostId></Error>
2020/08/16 05:22:08 DEBUG : : Looking for writers
2020/08/16 05:22:08 DEBUG : file1: reading active writers
2020/08/16 05:22:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:22:09 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc0005b21b0 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818790663966886 ext:27245684078 loc:0x25a1860} ATime:{wall:13818818790664002583 ext:27245719790 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:22:09 DEBUG : >WaitForWriters: 
2020/08/16 05:22:09 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestRWFileHandleWriteAt (27.11s)
=== RUN   TestRWFileHandleWriteNoWrite
    run.go:176: Remote "Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1'", Local "Local file system at /tmp/rclone155734662", Modify Window "1ns"
2020/08/16 05:22:09 INFO  : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': poll-interval is not supported by this remote
2020/08/16 05:22:09 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bSHA1HashS3/rclone-test-wusacaz8hajolam0xozemid1"
2020/08/16 05:22:09 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bSHA1HashS3/rclone-test-wusacaz8hajolam0xozemid1"
2020/08/16 05:22:09 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:22:09 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/08/16 05:22:09 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:22:09 DEBUG : file1: newRWFileHandle: 
2020/08/16 05:22:09 DEBUG : file1(0xc0001164c0): openPending: 
2020/08/16 05:22:09 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 05:22:09 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:09 DEBUG : file1(0xc0001164c0): >openPending: err=<nil>
2020/08/16 05:22:09 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 05:22:09 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:09 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 05:22:09 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 05:22:09 DEBUG : file1(0xc0001164c0): close: 
2020/08/16 05:22:09 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 05:22:09.399831293 +0000 UTC m=+54.359987151
2020/08/16 05:22:09 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:22:09 DEBUG : file1(0xc0001164c0): >close: err=<nil>
2020/08/16 05:22:09 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2020/08/16 05:22:09 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/08/16 05:22:09 DEBUG : file2: newRWFileHandle: 
2020/08/16 05:22:09 DEBUG : file2(0xc0001165c0): openPending: 
2020/08/16 05:22:09 DEBUG : file2: vfs cache: truncate to size=0
2020/08/16 05:22:09 DEBUG : : Added virtual directory entry vAdd: "file2"
2020/08/16 05:22:09 DEBUG : file2(0xc0001165c0): >openPending: err=<nil>
2020/08/16 05:22:09 DEBUG : file2: >newRWFileHandle: err=<nil>
2020/08/16 05:22:09 DEBUG : : Added virtual directory entry vAdd: "file2"
2020/08/16 05:22:09 DEBUG : file2: >Open: fd=file2 (rw), err=<nil>
2020/08/16 05:22:09 DEBUG : file2: >OpenFile: fd=file2 (rw), err=<nil>
2020/08/16 05:22:09 DEBUG : file2(0xc0001165c0): RWFileHandle.Flush
2020/08/16 05:22:09 DEBUG : file2(0xc0001165c0): RWFileHandle.Release
2020/08/16 05:22:09 DEBUG : file2(0xc0001165c0): close: 
2020/08/16 05:22:09 DEBUG : file2: vfs cache: setting modification time to 2020-08-16 05:22:09.40063025 +0000 UTC m=+54.360786118
2020/08/16 05:22:09 INFO  : file2: vfs cache: queuing for upload in 100ms
2020/08/16 05:22:09 DEBUG : file2(0xc0001165c0): >close: err=<nil>
2020/08/16 05:22:09 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:22:09 DEBUG : : Looking for writers
2020/08/16 05:22:09 DEBUG : file1: reading active writers
2020/08/16 05:22:09 DEBUG : file2: reading active writers
2020/08/16 05:22:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms
2020/08/16 05:22:09 DEBUG : : Looking for writers
2020/08/16 05:22:09 DEBUG : file1: reading active writers
2020/08/16 05:22:09 DEBUG : file2: reading active writers
2020/08/16 05:22:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms
2020/08/16 05:22:09 DEBUG : : Looking for writers
2020/08/16 05:22:09 DEBUG : file1: reading active writers
2020/08/16 05:22:09 DEBUG : file2: reading active writers
2020/08/16 05:22:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms
2020/08/16 05:22:09 DEBUG : : Looking for writers
2020/08/16 05:22:09 DEBUG : file1: reading active writers
2020/08/16 05:22:09 DEBUG : file2: reading active writers
2020/08/16 05:22:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms
2020/08/16 05:22:09 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:09 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:09 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>D978BEFBA97DC0BE</RequestId><HostId>Z6U43djJyKFqdXnJ+Qedsj/6p8VfKXNB2wj06gbqK0s1Gxb2mnxtURgkqcM5DhNAM4pkcfobPkw=</HostId></Error>
2020/08/16 05:22:09 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>D978BEFBA97DC0BE</RequestId><HostId>Z6U43djJyKFqdXnJ+Qedsj/6p8VfKXNB2wj06gbqK0s1Gxb2mnxtURgkqcM5DhNAM4pkcfobPkw=</HostId></Error>
2020/08/16 05:22:09 DEBUG : : Looking for writers
2020/08/16 05:22:09 DEBUG : file1: reading active writers
2020/08/16 05:22:09 DEBUG : file2: reading active writers
2020/08/16 05:22:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms
2020/08/16 05:22:09 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>1N0MAXCT2S6RCGBJ</RequestId><HostId>o7zT0/+zqpqDmU+0V0DJzB4xcUrVLEhkE2KQ7c6QPsn00qG3mQ1GlUThNGxss4oCHzWXLCGwOig=</HostId></Error>
2020/08/16 05:22:09 ERROR : file2: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>1N0MAXCT2S6RCGBJ</RequestId><HostId>o7zT0/+zqpqDmU+0V0DJzB4xcUrVLEhkE2KQ7c6QPsn00qG3mQ1GlUThNGxss4oCHzWXLCGwOig=</HostId></Error>
2020/08/16 05:22:09 DEBUG : : Looking for writers
2020/08/16 05:22:09 DEBUG : file2: reading active writers
2020/08/16 05:22:09 DEBUG : file1: reading active writers
2020/08/16 05:22:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms
2020/08/16 05:22:09 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:09 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:09 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>009178421E5BBEF2</RequestId><HostId>PQJ+6laUE4ZcRqdBl0eNQQSHVXNBBfJHMD/XEOzcUoVIb/7DGlW10WMm8FS9NZBPZrgRCayqw0s=</HostId></Error>
2020/08/16 05:22:09 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>009178421E5BBEF2</RequestId><HostId>PQJ+6laUE4ZcRqdBl0eNQQSHVXNBBfJHMD/XEOzcUoVIb/7DGlW10WMm8FS9NZBPZrgRCayqw0s=</HostId></Error>
2020/08/16 05:22:09 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>718F3203C89E6193</RequestId><HostId>9NO4kKo/IGzO6f/C32VPHzW2Oj6NWdXTQKyhhPqtYrX2eupEcyiBHGW46hYv6DWAkFNAM2sQF9g=</HostId></Error>
2020/08/16 05:22:09 ERROR : file2: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>718F3203C89E6193</RequestId><HostId>9NO4kKo/IGzO6f/C32VPHzW2Oj6NWdXTQKyhhPqtYrX2eupEcyiBHGW46hYv6DWAkFNAM2sQF9g=</HostId></Error>
2020/08/16 05:22:10 DEBUG : : Looking for writers
2020/08/16 05:22:10 DEBUG : file1: reading active writers
2020/08/16 05:22:10 DEBUG : file2: reading active writers
2020/08/16 05:22:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms
2020/08/16 05:22:10 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:10 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EC86EA7CCAF639EC</RequestId><HostId>srarmywklEa0XWW7ZQwaPxhDsE6mzDCrEyc1+VzwKw8mXIihRcVBnAxSgK0nHvPOQmqqJxe+sGI=</HostId></Error>
2020/08/16 05:22:10 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EC86EA7CCAF639EC</RequestId><HostId>srarmywklEa0XWW7ZQwaPxhDsE6mzDCrEyc1+VzwKw8mXIihRcVBnAxSgK0nHvPOQmqqJxe+sGI=</HostId></Error>
2020/08/16 05:22:10 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:10 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>D3CBCF5C409DF4A0</RequestId><HostId>ejldfjudVq13YdYwVSwlnwIEkIEK8v1EQeHvWHeygpchTYVfu9/HMsbBNANy7bQHQxY2jym8pBo=</HostId></Error>
2020/08/16 05:22:10 ERROR : file2: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>D3CBCF5C409DF4A0</RequestId><HostId>ejldfjudVq13YdYwVSwlnwIEkIEK8v1EQeHvWHeygpchTYVfu9/HMsbBNANy7bQHQxY2jym8pBo=</HostId></Error>
2020/08/16 05:22:10 DEBUG : : Looking for writers
2020/08/16 05:22:10 DEBUG : file1: reading active writers
2020/08/16 05:22:10 DEBUG : file2: reading active writers
2020/08/16 05:22:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:10 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:11 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>F6FA8E9F4BCE6B2F</RequestId><HostId>Fv7/8vOknKZ5CY/Y6ip7KML7H0GngDjcZPr140Htdcg/iHdPj1e7O5DDVipDvT3PYlfl8j1/iQo=</HostId></Error>
2020/08/16 05:22:11 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>F6FA8E9F4BCE6B2F</RequestId><HostId>Fv7/8vOknKZ5CY/Y6ip7KML7H0GngDjcZPr140Htdcg/iHdPj1e7O5DDVipDvT3PYlfl8j1/iQo=</HostId></Error>
2020/08/16 05:22:11 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:11 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>753A233108CE7B7A</RequestId><HostId>ukG/4SjysI/dTu3brOSwvjglyjdH+iW4HEAqWVAcI/HLCt2djkQj5wWI5WCzmfJUjOOwfRd+GGs=</HostId></Error>
2020/08/16 05:22:11 ERROR : file2: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>753A233108CE7B7A</RequestId><HostId>ukG/4SjysI/dTu3brOSwvjglyjdH+iW4HEAqWVAcI/HLCt2djkQj5wWI5WCzmfJUjOOwfRd+GGs=</HostId></Error>
2020/08/16 05:22:11 DEBUG : : Looking for writers
2020/08/16 05:22:11 DEBUG : file1: reading active writers
2020/08/16 05:22:11 DEBUG : file2: reading active writers
2020/08/16 05:22:11 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:12 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:12 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>58EB7EEE77FCF789</RequestId><HostId>3SuPRsC5lMZrgfhaGAg9o7AMzj9eRSTWG9WYrK+8c2apoqQBt3f2JQt/44sX6T72Vl9TDbcsVcw=</HostId></Error>
2020/08/16 05:22:12 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>58EB7EEE77FCF789</RequestId><HostId>3SuPRsC5lMZrgfhaGAg9o7AMzj9eRSTWG9WYrK+8c2apoqQBt3f2JQt/44sX6T72Vl9TDbcsVcw=</HostId></Error>
2020/08/16 05:22:12 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:12 DEBUG : : Looking for writers
2020/08/16 05:22:12 DEBUG : file1: reading active writers
2020/08/16 05:22:12 DEBUG : file2: reading active writers
2020/08/16 05:22:12 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:12 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>940A2F1C7E33152A</RequestId><HostId>aZMyK0dPU4QruVO3f3DmuS51bryXj4kVDoijBJgB32hs5xIUqEawejquArJUZfpaZXvWBU7K8aE=</HostId></Error>
2020/08/16 05:22:12 ERROR : file2: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>940A2F1C7E33152A</RequestId><HostId>aZMyK0dPU4QruVO3f3DmuS51bryXj4kVDoijBJgB32hs5xIUqEawejquArJUZfpaZXvWBU7K8aE=</HostId></Error>
2020/08/16 05:22:13 DEBUG : : Looking for writers
2020/08/16 05:22:13 DEBUG : file1: reading active writers
2020/08/16 05:22:13 DEBUG : file2: reading active writers
2020/08/16 05:22:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:14 DEBUG : : Looking for writers
2020/08/16 05:22:14 DEBUG : file1: reading active writers
2020/08/16 05:22:14 DEBUG : file2: reading active writers
2020/08/16 05:22:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:15 DEBUG : : Looking for writers
2020/08/16 05:22:15 DEBUG : file1: reading active writers
2020/08/16 05:22:15 DEBUG : file2: reading active writers
2020/08/16 05:22:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:15 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:15 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:15 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>1D61D86066865E5B</RequestId><HostId>36bGyjeSYNSsAvLIE9BXJpp+NE0morRD4wia0YdLMMPdQy6PnmEb2z/BrZrsMiaaYZNqREaXdho=</HostId></Error>
2020/08/16 05:22:15 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>1D61D86066865E5B</RequestId><HostId>36bGyjeSYNSsAvLIE9BXJpp+NE0morRD4wia0YdLMMPdQy6PnmEb2z/BrZrsMiaaYZNqREaXdho=</HostId></Error>
2020/08/16 05:22:15 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3E5EA19A11D2AB5C</RequestId><HostId>zB25yrX3FajoyUWuXTjmllSWc8MYHdZKy5ZXcRX32h912nRRB2/Ir8PXD1JDT5FDL2p6xKIm6DY=</HostId></Error>
2020/08/16 05:22:15 ERROR : file2: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3E5EA19A11D2AB5C</RequestId><HostId>zB25yrX3FajoyUWuXTjmllSWc8MYHdZKy5ZXcRX32h912nRRB2/Ir8PXD1JDT5FDL2p6xKIm6DY=</HostId></Error>
2020/08/16 05:22:16 DEBUG : : Looking for writers
2020/08/16 05:22:16 DEBUG : file2: reading active writers
2020/08/16 05:22:16 DEBUG : file1: reading active writers
2020/08/16 05:22:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:17 DEBUG : : Looking for writers
2020/08/16 05:22:17 DEBUG : file1: reading active writers
2020/08/16 05:22:17 DEBUG : file2: reading active writers
2020/08/16 05:22:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:18 DEBUG : : Looking for writers
2020/08/16 05:22:18 DEBUG : file1: reading active writers
2020/08/16 05:22:18 DEBUG : file2: reading active writers
2020/08/16 05:22:18 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:19 ERROR : Exiting even though 0 writers active and 2 cache items in use after 10s
Cache{
	"file2": &{c:0xc0005b2750 mu:{state:0 sema:0} name:file2 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818819770098154 ext:54360786118 loc:0x25a1860} ATime:{wall:13818818819770206019 ext:54360893975 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2},
	"file1": &{c:0xc0005b2750 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818819769299197 ext:54359987151 loc:0x25a1860} ATime:{wall:13818818819769453190 ext:54360141148 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:22:19 DEBUG : >WaitForWriters: 
    fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
2020/08/16 05:22:22 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:22 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:22 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>4672AD14615F4D17</RequestId><HostId>eOG7pCHV8/ThaiWyhgzyO4lg/RoHtcQv6iA33EB4Y/AOXSRDo3OrIHuA8H8oZm+gDT14ty0h/vM=</HostId></Error>
2020/08/16 05:22:22 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>4672AD14615F4D17</RequestId><HostId>eOG7pCHV8/ThaiWyhgzyO4lg/RoHtcQv6iA33EB4Y/AOXSRDo3OrIHuA8H8oZm+gDT14ty0h/vM=</HostId></Error>
2020/08/16 05:22:22 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>F454D2BE0360108D</RequestId><HostId>h19SR9YCTHrwgt0URf2vRj4xHjYXhPZ7SAmmYBm1GQ5loLGXMuAKkh86G+wfJgOdhlyym5rYRco=</HostId></Error>
2020/08/16 05:22:22 ERROR : file2: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>F454D2BE0360108D</RequestId><HostId>h19SR9YCTHrwgt0URf2vRj4xHjYXhPZ7SAmmYBm1GQ5loLGXMuAKkh86G+wfJgOdhlyym5rYRco=</HostId></Error>
    fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:302: 
        	Error Trace:	fstest.go:302
        	            				fstest.go:335
        	            				read_write_test.go:426
        	Error:      	Should be true
        	Test:       	TestRWFileHandleWriteNoWrite
        	Messages:   	listing wrong, want
        	            	  file1 (0), file2 (0) got
        	            	  
    fstest.go:200: Not found "file1"
    fstest.go:200: Not found "file2"
    fstest.go:203: 
        	Error Trace:	fstest.go:203
        	            				fstest.go:307
        	            				fstest.go:335
        	            				read_write_test.go:426
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 2
        	Test:       	TestRWFileHandleWriteNoWrite
        	Messages:   	2 objects not found
2020/08/16 05:22:26 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:22:26 DEBUG : : Looking for writers
2020/08/16 05:22:26 DEBUG : file1: reading active writers
2020/08/16 05:22:26 DEBUG : file2: reading active writers
2020/08/16 05:22:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms
2020/08/16 05:22:26 DEBUG : : Looking for writers
2020/08/16 05:22:26 DEBUG : file1: reading active writers
2020/08/16 05:22:26 DEBUG : file2: reading active writers
2020/08/16 05:22:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms
2020/08/16 05:22:26 DEBUG : : Looking for writers
2020/08/16 05:22:26 DEBUG : file1: reading active writers
2020/08/16 05:22:26 DEBUG : file2: reading active writers
2020/08/16 05:22:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms
2020/08/16 05:22:26 DEBUG : : Looking for writers
2020/08/16 05:22:26 DEBUG : file1: reading active writers
2020/08/16 05:22:26 DEBUG : file2: reading active writers
2020/08/16 05:22:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms
2020/08/16 05:22:26 DEBUG : : Looking for writers
2020/08/16 05:22:26 DEBUG : file1: reading active writers
2020/08/16 05:22:26 DEBUG : file2: reading active writers
2020/08/16 05:22:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms
2020/08/16 05:22:26 DEBUG : : Looking for writers
2020/08/16 05:22:26 DEBUG : file1: reading active writers
2020/08/16 05:22:26 DEBUG : file2: reading active writers
2020/08/16 05:22:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms
2020/08/16 05:22:27 DEBUG : : Looking for writers
2020/08/16 05:22:27 DEBUG : file1: reading active writers
2020/08/16 05:22:27 DEBUG : file2: reading active writers
2020/08/16 05:22:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms
2020/08/16 05:22:27 DEBUG : : Looking for writers
2020/08/16 05:22:27 DEBUG : file2: reading active writers
2020/08/16 05:22:27 DEBUG : file1: reading active writers
2020/08/16 05:22:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:28 DEBUG : : Looking for writers
2020/08/16 05:22:28 DEBUG : file1: reading active writers
2020/08/16 05:22:28 DEBUG : file2: reading active writers
2020/08/16 05:22:28 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:29 DEBUG : : Looking for writers
2020/08/16 05:22:29 DEBUG : file1: reading active writers
2020/08/16 05:22:29 DEBUG : file2: reading active writers
2020/08/16 05:22:29 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:30 DEBUG : : Looking for writers
2020/08/16 05:22:30 DEBUG : file1: reading active writers
2020/08/16 05:22:30 DEBUG : file2: reading active writers
2020/08/16 05:22:30 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:31 DEBUG : : Looking for writers
2020/08/16 05:22:31 DEBUG : file1: reading active writers
2020/08/16 05:22:31 DEBUG : file2: reading active writers
2020/08/16 05:22:31 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:32 DEBUG : : Looking for writers
2020/08/16 05:22:32 DEBUG : file1: reading active writers
2020/08/16 05:22:32 DEBUG : file2: reading active writers
2020/08/16 05:22:32 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:33 DEBUG : : Looking for writers
2020/08/16 05:22:33 DEBUG : file1: reading active writers
2020/08/16 05:22:33 DEBUG : file2: reading active writers
2020/08/16 05:22:33 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:34 DEBUG : : Looking for writers
2020/08/16 05:22:34 DEBUG : file1: reading active writers
2020/08/16 05:22:34 DEBUG : file2: reading active writers
2020/08/16 05:22:34 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:35 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:22:35 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:22:35 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>6M6N9PAM5Z9J6HDY</RequestId><HostId>oF6+/R+VLAOnZr0EG1nwVdg5/lr/oD0X/zNXFMUXyKmIURYf1ZeWcbPvZ/A0WNg65GJWDmsTlQQ=</HostId></Error>
2020/08/16 05:22:35 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>6M6N9PAM5Z9J6HDY</RequestId><HostId>oF6+/R+VLAOnZr0EG1nwVdg5/lr/oD0X/zNXFMUXyKmIURYf1ZeWcbPvZ/A0WNg65GJWDmsTlQQ=</HostId></Error>
2020/08/16 05:22:35 ERROR : file2: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>B4BEF8EEFD7CF69D</RequestId><HostId>lnVqghxlPZqgc5jmkdW9ng6SNw4zKMCH+8PyrEndc4W4BF5ZwJFa6o9QsyMPL0O1IKJa8bub2Zo=</HostId></Error>
2020/08/16 05:22:35 ERROR : file2: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>B4BEF8EEFD7CF69D</RequestId><HostId>lnVqghxlPZqgc5jmkdW9ng6SNw4zKMCH+8PyrEndc4W4BF5ZwJFa6o9QsyMPL0O1IKJa8bub2Zo=</HostId></Error>
2020/08/16 05:22:35 DEBUG : : Looking for writers
2020/08/16 05:22:35 DEBUG : file1: reading active writers
2020/08/16 05:22:35 DEBUG : file2: reading active writers
2020/08/16 05:22:35 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:22:36 ERROR : Exiting even though 0 writers active and 2 cache items in use after 10s
Cache{
	"file1": &{c:0xc0005b2750 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818819769299197 ext:54359987151 loc:0x25a1860} ATime:{wall:13818818819769453190 ext:54360141148 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1},
	"file2": &{c:0xc0005b2750 mu:{state:0 sema:0} name:file2 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818818819770098154 ext:54360786118 loc:0x25a1860} ATime:{wall:13818818819770206019 ext:54360893975 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2},
}
2020/08/16 05:22:36 DEBUG : >WaitForWriters: 
2020/08/16 05:22:36 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestRWFileHandleWriteNoWrite (27.03s)
=== RUN   TestWriteFileHandleMethods
    run.go:176: Remote "Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1'", Local "Local file system at /tmp/rclone155734662", Modify Window "1ns"
2020/08/16 05:22:36 INFO  : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': poll-interval is not supported by this remote
2020/08/16 05:22:36 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:22:36 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:22:36 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:36 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:22:36 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:22:36 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:36 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal
2020/08/16 05:22:36 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal
2020/08/16 05:22:36 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes
2020/08/16 05:22:36 DEBUG : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': File to upload is small (5 bytes), uploading instead of streaming
2020/08/16 05:22:36 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>C86DF761B4F35CD8</RequestId><HostId>mu35tfjFUILVzVKm0yzrq2aEE7rEauqKJidgeZxcosqxoE0M1mgQ/41xT9PsJxqdBNWlj56C74Q=</HostId></Error>
2020/08/16 05:22:36 ERROR : file1: WriteFileHandle.New Rcat failed: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>C86DF761B4F35CD8</RequestId><HostId>mu35tfjFUILVzVKm0yzrq2aEE7rEauqKJidgeZxcosqxoE0M1mgQ/41xT9PsJxqdBNWlj56C74Q=</HostId></Error>
    write_test.go:84: 
        	Error Trace:	write_test.go:84
        	Error:      	Received unexpected error:
        	            	s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
        	            	<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>C86DF761B4F35CD8</RequestId><HostId>mu35tfjFUILVzVKm0yzrq2aEE7rEauqKJidgeZxcosqxoE0M1mgQ/41xT9PsJxqdBNWlj56C74Q=</HostId></Error>
        	Test:       	TestWriteFileHandleMethods
    fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:302: 
        	Error Trace:	fstest.go:302
        	            				fstest.go:335
        	            				write_test.go:97
        	Error:      	Should be true
        	Test:       	TestWriteFileHandleMethods
        	Messages:   	listing wrong, want
        	            	  file1 (5) got
        	            	  
    fstest.go:200: Not found "file1"
    fstest.go:203: 
        	Error Trace:	fstest.go:203
        	            				fstest.go:307
        	            				fstest.go:335
        	            				write_test.go:97
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestWriteFileHandleMethods
        	Messages:   	1 objects not found
2020/08/16 05:22:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:22:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:22:43 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:43 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:22:43 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:22:43 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:43 DEBUG : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': File to upload is small (0 bytes), uploading instead of streaming
2020/08/16 05:22:43 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3Z0P5R3KBH5H6GBW</RequestId><HostId>GMxZ/m+fPESKn8mKDlwjiGRVViiaimYS7CZpKOeOBIFLKqf1HRCwxnLP9ff7JSkGPWx6WYHhmHs=</HostId></Error>
2020/08/16 05:22:43 ERROR : file1: WriteFileHandle.New Rcat failed: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3Z0P5R3KBH5H6GBW</RequestId><HostId>GMxZ/m+fPESKn8mKDlwjiGRVViiaimYS7CZpKOeOBIFLKqf1HRCwxnLP9ff7JSkGPWx6WYHhmHs=</HostId></Error>
    write_test.go:103: 
        	Error Trace:	write_test.go:103
        	Error:      	Received unexpected error:
        	            	s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
        	            	<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>3Z0P5R3KBH5H6GBW</RequestId><HostId>GMxZ/m+fPESKn8mKDlwjiGRVViiaimYS7CZpKOeOBIFLKqf1HRCwxnLP9ff7JSkGPWx6WYHhmHs=</HostId></Error>
        	Test:       	TestWriteFileHandleMethods
    dir_test.go:252: 
        	Error Trace:	dir_test.go:252
        	            				write_test.go:104
        	Error:      	Not equal: 
        	            	expected: []string{"file1,5,false"}
        	            	actual  : []string{"file1,0,false"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,3 +1,3 @@
        	            	 ([]string) (len=1) {
        	            	- (string) (len=13) "file1,5,false"
        	            	+ (string) (len=13) "file1,0,false"
        	            	 }
        	Test:       	TestWriteFileHandleMethods
2020/08/16 05:22:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:22:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:22:43 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:43 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:22:43 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:22:43 DEBUG : : Added virtual directory entry vAdd: "file1"
    write_test.go:111: 
        	Error Trace:	write_test.go:111
        	Error:      	Not equal: 
        	            	expected: *errors.errorString(&errors.errorString{s:"permission denied"})
        	            	actual  : <nil>(<nil>)
        	Test:       	TestWriteFileHandleMethods
2020/08/16 05:22:43 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:22:43 DEBUG : : Looking for writers
2020/08/16 05:22:43 DEBUG : file1: reading active writers
2020/08/16 05:22:43 DEBUG : file1: active writers 1
2020/08/16 05:22:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms
2020/08/16 05:22:43 DEBUG : : Looking for writers
2020/08/16 05:22:43 DEBUG : file1: reading active writers
2020/08/16 05:22:43 DEBUG : file1: active writers 1
2020/08/16 05:22:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms
2020/08/16 05:22:43 DEBUG : : Looking for writers
2020/08/16 05:22:43 DEBUG : file1: reading active writers
2020/08/16 05:22:43 DEBUG : file1: active writers 1
2020/08/16 05:22:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms
2020/08/16 05:22:43 DEBUG : : Looking for writers
2020/08/16 05:22:43 DEBUG : file1: reading active writers
2020/08/16 05:22:43 DEBUG : file1: active writers 1
2020/08/16 05:22:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms
2020/08/16 05:22:43 DEBUG : : Looking for writers
2020/08/16 05:22:43 DEBUG : file1: reading active writers
2020/08/16 05:22:43 DEBUG : file1: active writers 1
2020/08/16 05:22:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms
2020/08/16 05:22:43 DEBUG : : Looking for writers
2020/08/16 05:22:43 DEBUG : file1: reading active writers
2020/08/16 05:22:43 DEBUG : file1: active writers 1
2020/08/16 05:22:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms
2020/08/16 05:22:44 DEBUG : : Looking for writers
2020/08/16 05:22:44 DEBUG : file1: reading active writers
2020/08/16 05:22:44 DEBUG : file1: active writers 1
2020/08/16 05:22:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms
2020/08/16 05:22:44 DEBUG : : Looking for writers
2020/08/16 05:22:44 DEBUG : file1: reading active writers
2020/08/16 05:22:44 DEBUG : file1: active writers 1
2020/08/16 05:22:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:45 DEBUG : : Looking for writers
2020/08/16 05:22:45 DEBUG : file1: reading active writers
2020/08/16 05:22:45 DEBUG : file1: active writers 1
2020/08/16 05:22:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:46 DEBUG : : Looking for writers
2020/08/16 05:22:46 DEBUG : file1: reading active writers
2020/08/16 05:22:46 DEBUG : file1: active writers 1
2020/08/16 05:22:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:47 DEBUG : : Looking for writers
2020/08/16 05:22:47 DEBUG : file1: reading active writers
2020/08/16 05:22:47 DEBUG : file1: active writers 1
2020/08/16 05:22:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:48 DEBUG : : Looking for writers
2020/08/16 05:22:48 DEBUG : file1: reading active writers
2020/08/16 05:22:48 DEBUG : file1: active writers 1
2020/08/16 05:22:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:49 DEBUG : : Looking for writers
2020/08/16 05:22:49 DEBUG : file1: reading active writers
2020/08/16 05:22:49 DEBUG : file1: active writers 1
2020/08/16 05:22:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:50 DEBUG : : Looking for writers
2020/08/16 05:22:50 DEBUG : file1: reading active writers
2020/08/16 05:22:50 DEBUG : file1: active writers 1
2020/08/16 05:22:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:51 DEBUG : : Looking for writers
2020/08/16 05:22:51 DEBUG : file1: reading active writers
2020/08/16 05:22:51 DEBUG : file1: active writers 1
2020/08/16 05:22:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:52 DEBUG : : Looking for writers
2020/08/16 05:22:52 DEBUG : file1: reading active writers
2020/08/16 05:22:52 DEBUG : file1: active writers 1
2020/08/16 05:22:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:22:53 ERROR : Exiting even though 1 writers active and 0 cache items in use after 10s
Cache: <nil>
2020/08/16 05:22:53 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileHandleMethods (17.11s)
=== RUN   TestWriteFileHandleWriteAt
    run.go:176: Remote "Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1'", Local "Local file system at /tmp/rclone155734662", Modify Window "1ns"
2020/08/16 05:22:53 INFO  : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': poll-interval is not supported by this remote
2020/08/16 05:22:53 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:22:53 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:22:53 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:53 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:22:53 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:22:53 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:22:53 DEBUG : file1: waiting for in-sequence write to 100 for 1s
2020/08/16 05:22:54 DEBUG : file1: aborting in-sequence write wait, off=100
2020/08/16 05:22:54 DEBUG : file1: failed to wait for in-sequence write to 100
2020/08/16 05:22:54 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes
2020/08/16 05:22:54 DEBUG : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': File to upload is small (11 bytes), uploading instead of streaming
2020/08/16 05:22:54 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EBDBECEEA25532FC</RequestId><HostId>Rj8mhDFvHOZWYW2yLOv7CEPp2rLNxuKyf2b5rgI1GaVibAmgDSlmlhaEjj17J+L3Clok/0a4aFU=</HostId></Error>
2020/08/16 05:22:54 ERROR : file1: WriteFileHandle.New Rcat failed: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EBDBECEEA25532FC</RequestId><HostId>Rj8mhDFvHOZWYW2yLOv7CEPp2rLNxuKyf2b5rgI1GaVibAmgDSlmlhaEjj17J+L3Clok/0a4aFU=</HostId></Error>
    write_test.go:162: 
        	Error Trace:	write_test.go:162
        	Error:      	Received unexpected error:
        	            	s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
        	            	<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>EBDBECEEA25532FC</RequestId><HostId>Rj8mhDFvHOZWYW2yLOv7CEPp2rLNxuKyf2b5rgI1GaVibAmgDSlmlhaEjj17J+L3Clok/0a4aFU=</HostId></Error>
        	Test:       	TestWriteFileHandleWriteAt
2020/08/16 05:22:54 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor
    fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:302: 
        	Error Trace:	fstest.go:302
        	            				fstest.go:335
        	            				write_test.go:176
        	Error:      	Should be true
        	Test:       	TestWriteFileHandleWriteAt
        	Messages:   	listing wrong, want
        	            	  file1 (11) got
        	            	  
    fstest.go:200: Not found "file1"
    fstest.go:203: 
        	Error Trace:	fstest.go:203
        	            				fstest.go:307
        	            				fstest.go:335
        	            				write_test.go:176
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestWriteFileHandleWriteAt
        	Messages:   	1 objects not found
2020/08/16 05:23:01 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:23:01 DEBUG : : Looking for writers
2020/08/16 05:23:01 DEBUG : file1: reading active writers
2020/08/16 05:23:01 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileHandleWriteAt (8.07s)
=== RUN   TestWriteFileHandleFlush
    run.go:176: Remote "Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1'", Local "Local file system at /tmp/rclone155734662", Modify Window "1ns"
2020/08/16 05:23:01 INFO  : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': poll-interval is not supported by this remote
2020/08/16 05:23:01 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:23:01 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:23:01 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:23:01 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:23:01 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:23:01 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2020/08/16 05:23:01 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:23:01 DEBUG : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': File to upload is small (5 bytes), uploading instead of streaming
2020/08/16 05:23:01 ERROR : file1: Failed to copy: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>AWAP9ZDVEW3GFJ1R</RequestId><HostId>uz1TmmYMKscEP1LnpN9BMWV65/LfdDMmDGN5Q5yAeDTZhtB/AaAoaNNHGakbnq0MxPwv6E5vR0I=</HostId></Error>
2020/08/16 05:23:01 ERROR : file1: WriteFileHandle.New Rcat failed: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>AWAP9ZDVEW3GFJ1R</RequestId><HostId>uz1TmmYMKscEP1LnpN9BMWV65/LfdDMmDGN5Q5yAeDTZhtB/AaAoaNNHGakbnq0MxPwv6E5vR0I=</HostId></Error>
2020/08/16 05:23:01 ERROR : file1: WriteFileHandle.Flush error: s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>AWAP9ZDVEW3GFJ1R</RequestId><HostId>uz1TmmYMKscEP1LnpN9BMWV65/LfdDMmDGN5Q5yAeDTZhtB/AaAoaNNHGakbnq0MxPwv6E5vR0I=</HostId></Error>
    write_test.go:198: 
        	Error Trace:	write_test.go:198
        	Error:      	Received unexpected error:
        	            	s3 upload: 404 Not Found: <?xml version="1.0" encoding="UTF-8"?>
        	            	<Error><Code>NoSuchBucket</Code><Message>The specified bucket does not exist</Message><BucketName>rclone-test-wusacaz8hajolam0xozemid1</BucketName><RequestId>AWAP9ZDVEW3GFJ1R</RequestId><HostId>uz1TmmYMKscEP1LnpN9BMWV65/LfdDMmDGN5Q5yAeDTZhtB/AaAoaNNHGakbnq0MxPwv6E5vR0I=</HostId></Error>
        	Test:       	TestWriteFileHandleFlush
2020/08/16 05:23:01 DEBUG : file1: WriteFileHandle.Flush nothing to do
2020/08/16 05:23:01 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:23:01 DEBUG : : Looking for writers
2020/08/16 05:23:01 DEBUG : file1: reading active writers
2020/08/16 05:23:01 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileHandleFlush (0.05s)
FAIL
2020/08/16 05:23:01 DEBUG : Chunked 'TestChunkerChunk50bSHA1HashS3:rclone-test-wusacaz8hajolam0xozemid1': Purge dir ""
2020/08/16 05:23:01 purge failed to rmdir "": NoSuchBucket: The specified bucket does not exist
	status code: 404, request id: CB8C1D19A7D898F0, host id: GsLz5RfGwRSXDb8heawhho6V3FB1AK6ubgs6PBiDZ2LqFSSzIClBIp+LFDB23X98tXJjNAYOI5o=
2020/08/16 05:23:01 purge failed: directory not found
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bSHA1HashS3: -verbose -size-limit 1024 -test.run '^(TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt)$'" - Finished ERROR in 1m46.655903091s (try 4/5): exit status 1: Failed [TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush]