"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bMD5HashS3: -verbose -size-limit 1024 -test.run '^(TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt)$'" - Starting (try 4/5)
=== RUN   TestRWFileHandleMethodsWrite
    run.go:176: Remote "Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2'", Local "Local file system at /tmp/rclone831060863", Modify Window "1ns"
2020/08/16 05:06:02 INFO  : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': poll-interval is not supported by this remote
2020/08/16 05:06:02 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMD5HashS3/rclone-test-kizivof6tikogud8faxenem2"
2020/08/16 05:06:02 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMD5HashS3/rclone-test-kizivof6tikogud8faxenem2"
2020/08/16 05:06:02 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:06:02 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:06:02 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:06:02 DEBUG : file1: newRWFileHandle: 
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): openPending: 
2020/08/16 05:06:02 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 05:06:02 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): >openPending: err=<nil>
2020/08/16 05:06:02 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 05:06:02 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:06:02 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 05:06:02 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): _writeAt: size=5, off=0
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): >_writeAt: n=5, err=<nil>
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): _writeAt: size=7, off=5
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): >_writeAt: n=7, err=<nil>
2020/08/16 05:06:02 DEBUG : file1: vfs cache: truncate to size=11
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): close: 
2020/08/16 05:06:02 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 05:06:02.29067925 +0000 UTC m=+0.129317003
2020/08/16 05:06:02 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): >close: err=<nil>
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): close: 
2020/08/16 05:06:02 DEBUG : file1(0xc0005f2200): >close: err=file already closed
2020/08/16 05:06:02 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:06:02 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:02 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-kizivof6tikogud8faxenem2</BucketName><RequestId>4AFF920856A577C9</RequestId><HostId>HUvCb+Cn54YHXLzYYInh1QbiA/mVHXeictxbJmzmNMyiNeakzZkeTC+b/ix3+sQvjGdru3RxYvk=</HostId></Error>
2020/08/16 05:06:02 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-kizivof6tikogud8faxenem2</BucketName><RequestId>4AFF920856A577C9</RequestId><HostId>HUvCb+Cn54YHXLzYYInh1QbiA/mVHXeictxbJmzmNMyiNeakzZkeTC+b/ix3+sQvjGdru3RxYvk=</HostId></Error>
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:06:02 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:02 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-kizivof6tikogud8faxenem2</BucketName><RequestId>EK9Z6Y1W1HFT3J5T</RequestId><HostId>RPFovrWA2GUp1nTLIMiamrRhpQC7/ghloBlV5BkgTPuocog156FsnujOle0oYKos3EF80UUmX30=</HostId></Error>
2020/08/16 05:06:02 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-kizivof6tikogud8faxenem2</BucketName><RequestId>EK9Z6Y1W1HFT3J5T</RequestId><HostId>RPFovrWA2GUp1nTLIMiamrRhpQC7/ghloBlV5BkgTPuocog156FsnujOle0oYKos3EF80UUmX30=</HostId></Error>
2020/08/16 05:06:02 DEBUG : : Looking for writers
2020/08/16 05:06:02 DEBUG : file1: reading active writers
2020/08/16 05:06:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:06:03 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>BF96ECF860F09F14</RequestId><HostId>9xhtLTNhpS5NalkuvG/fIjmDJ5BYbIYkl545wlNdEjD/msS6PUslJzdujw8Z/lVpUFz7SPdmjHI=</HostId></Error>
2020/08/16 05:06:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>BF96ECF860F09F14</RequestId><HostId>9xhtLTNhpS5NalkuvG/fIjmDJ5BYbIYkl545wlNdEjD/msS6PUslJzdujw8Z/lVpUFz7SPdmjHI=</HostId></Error>
2020/08/16 05:06:03 DEBUG : : Looking for writers
2020/08/16 05:06:03 DEBUG : file1: reading active writers
2020/08/16 05:06:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:03 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>03D4F0A64A1274D7</RequestId><HostId>uLreh28FWHhC8OudZCpATOLkcoxZ3w3AI+uWqv3mRQoaIv4sbsUeQR+4+LRNLtXRZD2vgwgQlkc=</HostId></Error>
2020/08/16 05:06:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>03D4F0A64A1274D7</RequestId><HostId>uLreh28FWHhC8OudZCpATOLkcoxZ3w3AI+uWqv3mRQoaIv4sbsUeQR+4+LRNLtXRZD2vgwgQlkc=</HostId></Error>
2020/08/16 05:06:04 DEBUG : : Looking for writers
2020/08/16 05:06:04 DEBUG : file1: reading active writers
2020/08/16 05:06:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:05 DEBUG : : Looking for writers
2020/08/16 05:06:05 DEBUG : file1: reading active writers
2020/08/16 05:06:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:05 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:05 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-kizivof6tikogud8faxenem2</BucketName><RequestId>05E9691D30EC6B88</RequestId><HostId>6ooQOkN8N+T4utQQwfrQRMCGnqKWyjS7oe8iiOxA5FJu5UvhX6/yeU1l/HO4cKSWFuZflJfpMp4=</HostId></Error>
2020/08/16 05:06:05 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-kizivof6tikogud8faxenem2</BucketName><RequestId>05E9691D30EC6B88</RequestId><HostId>6ooQOkN8N+T4utQQwfrQRMCGnqKWyjS7oe8iiOxA5FJu5UvhX6/yeU1l/HO4cKSWFuZflJfpMp4=</HostId></Error>
2020/08/16 05:06:06 DEBUG : : Looking for writers
2020/08/16 05:06:06 DEBUG : file1: reading active writers
2020/08/16 05:06:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:07 DEBUG : : Looking for writers
2020/08/16 05:06:07 DEBUG : file1: reading active writers
2020/08/16 05:06:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:08 DEBUG : : Looking for writers
2020/08/16 05:06:08 DEBUG : file1: reading active writers
2020/08/16 05:06:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:08 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06: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-kizivof6tikogud8faxenem2</BucketName><RequestId>21DE9681C4C5D235</RequestId><HostId>4VPB6XsCYTeCtvcyQdy3xl1Ghu12QX4Gahn2GpS1acDEXt9tlSSR8OWomsZYIqmTCq+Pxw8M0pI=</HostId></Error>
2020/08/16 05:06:08 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-kizivof6tikogud8faxenem2</BucketName><RequestId>21DE9681C4C5D235</RequestId><HostId>4VPB6XsCYTeCtvcyQdy3xl1Ghu12QX4Gahn2GpS1acDEXt9tlSSR8OWomsZYIqmTCq+Pxw8M0pI=</HostId></Error>
2020/08/16 05:06:09 DEBUG : : Looking for writers
2020/08/16 05:06:09 DEBUG : file1: reading active writers
2020/08/16 05:06:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:10 DEBUG : : Looking for writers
2020/08/16 05:06:10 DEBUG : file1: reading active writers
2020/08/16 05:06:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:11 DEBUG : : Looking for writers
2020/08/16 05:06:11 DEBUG : file1: reading active writers
2020/08/16 05:06:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:12 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc0000cd680 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817781351803346 ext:129317003 loc:0x25a1860} ATime:{wall:13818817781351822442 ext:129336103 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:06:12 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:06:15 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06: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-kizivof6tikogud8faxenem2</BucketName><RequestId>A77836BCBE5A91B7</RequestId><HostId>wrDZlyEynnmXYmK/omZ4PV6q5Yb0Nh2NFJWQ3birulPaqWaE24wlZJbyJpUfvcVe2uEqDL+1h80=</HostId></Error>
2020/08/16 05:06:15 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-kizivof6tikogud8faxenem2</BucketName><RequestId>A77836BCBE5A91B7</RequestId><HostId>wrDZlyEynnmXYmK/omZ4PV6q5Yb0Nh2NFJWQ3birulPaqWaE24wlZJbyJpUfvcVe2uEqDL+1h80=</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: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:06:19 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:06:19 DEBUG : : Looking for writers
2020/08/16 05:06:19 DEBUG : file1: reading active writers
2020/08/16 05:06:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:06:19 DEBUG : : Looking for writers
2020/08/16 05:06:19 DEBUG : file1: reading active writers
2020/08/16 05:06:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:06:19 DEBUG : : Looking for writers
2020/08/16 05:06:19 DEBUG : file1: reading active writers
2020/08/16 05:06:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:06:19 DEBUG : : Looking for writers
2020/08/16 05:06:19 DEBUG : file1: reading active writers
2020/08/16 05:06:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:06:19 DEBUG : : Looking for writers
2020/08/16 05:06:19 DEBUG : file1: reading active writers
2020/08/16 05:06:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:06:19 DEBUG : : Looking for writers
2020/08/16 05:06:19 DEBUG : file1: reading active writers
2020/08/16 05:06:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:06:20 DEBUG : : Looking for writers
2020/08/16 05:06:20 DEBUG : file1: reading active writers
2020/08/16 05:06:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:06:20 DEBUG : : Looking for writers
2020/08/16 05:06:20 DEBUG : file1: reading active writers
2020/08/16 05:06:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:21 DEBUG : : Looking for writers
2020/08/16 05:06:21 DEBUG : file1: reading active writers
2020/08/16 05:06:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:22 DEBUG : : Looking for writers
2020/08/16 05:06:22 DEBUG : file1: reading active writers
2020/08/16 05:06:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:23 DEBUG : : Looking for writers
2020/08/16 05:06:23 DEBUG : file1: reading active writers
2020/08/16 05:06:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:24 DEBUG : : Looking for writers
2020/08/16 05:06:24 DEBUG : file1: reading active writers
2020/08/16 05:06:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:25 DEBUG : : Looking for writers
2020/08/16 05:06:25 DEBUG : file1: reading active writers
2020/08/16 05:06:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:26 DEBUG : : Looking for writers
2020/08/16 05:06:26 DEBUG : file1: reading active writers
2020/08/16 05:06:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:27 DEBUG : : Looking for writers
2020/08/16 05:06:27 DEBUG : file1: reading active writers
2020/08/16 05:06:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:28 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06: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-kizivof6tikogud8faxenem2</BucketName><RequestId>0JEW1WAM3H7XDZBJ</RequestId><HostId>EVG+3jS1yJZSjgJZPpM9kuH/KxfMPP01KZUp0ZrnRPYNZ6P+Znp61cMAeDoBuhYctvPagywFN0c=</HostId></Error>
2020/08/16 05:06:28 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-kizivof6tikogud8faxenem2</BucketName><RequestId>0JEW1WAM3H7XDZBJ</RequestId><HostId>EVG+3jS1yJZSjgJZPpM9kuH/KxfMPP01KZUp0ZrnRPYNZ6P+Znp61cMAeDoBuhYctvPagywFN0c=</HostId></Error>
2020/08/16 05:06:28 DEBUG : : Looking for writers
2020/08/16 05:06:28 DEBUG : file1: reading active writers
2020/08/16 05:06:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:29 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc0000cd680 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817781351803346 ext:129317003 loc:0x25a1860} ATime:{wall:13818817781351822442 ext:129336103 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:06:29 DEBUG : >WaitForWriters: 
2020/08/16 05:06:29 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestRWFileHandleMethodsWrite (27.23s)
=== RUN   TestRWFileHandleWriteAt
    run.go:176: Remote "Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2'", Local "Local file system at /tmp/rclone831060863", Modify Window "1ns"
2020/08/16 05:06:29 INFO  : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': poll-interval is not supported by this remote
2020/08/16 05:06:29 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMD5HashS3/rclone-test-kizivof6tikogud8faxenem2"
2020/08/16 05:06:29 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMD5HashS3/rclone-test-kizivof6tikogud8faxenem2"
2020/08/16 05:06:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:06:29 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:06:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:06:29 DEBUG : file1: newRWFileHandle: 
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): openPending: 
2020/08/16 05:06:29 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 05:06:29 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): >openPending: err=<nil>
2020/08/16 05:06:29 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 05:06:29 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:06:29 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 05:06:29 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): _writeAt: size=7, off=0
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): >_writeAt: n=7, err=<nil>
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): _writeAt: size=6, off=5
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): >_writeAt: n=6, err=<nil>
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): close: 
2020/08/16 05:06:29 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 05:06:29.425109759 +0000 UTC m=+27.263747515
2020/08/16 05:06:29 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): >close: err=<nil>
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): _writeAt: size=5, off=0
2020/08/16 05:06:29 DEBUG : file1(0xc000a040c0): >_writeAt: n=0, err=file already closed
2020/08/16 05:06:29 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:06:29 DEBUG : : Looking for writers
2020/08/16 05:06:29 DEBUG : file1: reading active writers
2020/08/16 05:06:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:06:29 DEBUG : : Looking for writers
2020/08/16 05:06:29 DEBUG : file1: reading active writers
2020/08/16 05:06:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:06:29 DEBUG : : Looking for writers
2020/08/16 05:06:29 DEBUG : file1: reading active writers
2020/08/16 05:06:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:06:29 DEBUG : : Looking for writers
2020/08/16 05:06:29 DEBUG : file1: reading active writers
2020/08/16 05:06:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:06:29 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:29 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-kizivof6tikogud8faxenem2</BucketName><RequestId>8Y3S4KFJBM8PFT9G</RequestId><HostId>pgl6Iv9W01XbJBiwUvXJW1L2MdgAuM6YrvuSKcMAzT8cGemGrwvDzJDHZmasPHoKJsAf8CXD+/I=</HostId></Error>
2020/08/16 05:06:29 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-kizivof6tikogud8faxenem2</BucketName><RequestId>8Y3S4KFJBM8PFT9G</RequestId><HostId>pgl6Iv9W01XbJBiwUvXJW1L2MdgAuM6YrvuSKcMAzT8cGemGrwvDzJDHZmasPHoKJsAf8CXD+/I=</HostId></Error>
2020/08/16 05:06:29 DEBUG : : Looking for writers
2020/08/16 05:06:29 DEBUG : file1: reading active writers
2020/08/16 05:06:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:06:29 DEBUG : : Looking for writers
2020/08/16 05:06:29 DEBUG : file1: reading active writers
2020/08/16 05:06:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:06:29 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:29 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-kizivof6tikogud8faxenem2</BucketName><RequestId>0A391964A6C1A459</RequestId><HostId>3Ex2jwCPh7QhN+LpTu3odpaVfcFrWLZiQ5dunX8M255G6QbnQBin/VTdv9EeoC4+6hk1lg0e7Xs=</HostId></Error>
2020/08/16 05:06:29 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-kizivof6tikogud8faxenem2</BucketName><RequestId>0A391964A6C1A459</RequestId><HostId>3Ex2jwCPh7QhN+LpTu3odpaVfcFrWLZiQ5dunX8M255G6QbnQBin/VTdv9EeoC4+6hk1lg0e7Xs=</HostId></Error>
2020/08/16 05:06:30 DEBUG : : Looking for writers
2020/08/16 05:06:30 DEBUG : file1: reading active writers
2020/08/16 05:06:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:06:30 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:30 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-kizivof6tikogud8faxenem2</BucketName><RequestId>256DDC4A8029DC46</RequestId><HostId>NNuPCF5l3tTXEchY2aJ9vva0x2TVl1q8Y3l3Wik6LuUM0GlraS87kVjS5MKtoafzmNgfPSfFXic=</HostId></Error>
2020/08/16 05:06:30 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-kizivof6tikogud8faxenem2</BucketName><RequestId>256DDC4A8029DC46</RequestId><HostId>NNuPCF5l3tTXEchY2aJ9vva0x2TVl1q8Y3l3Wik6LuUM0GlraS87kVjS5MKtoafzmNgfPSfFXic=</HostId></Error>
2020/08/16 05:06:30 DEBUG : : Looking for writers
2020/08/16 05:06:30 DEBUG : file1: reading active writers
2020/08/16 05:06:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:31 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:31 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-kizivof6tikogud8faxenem2</BucketName><RequestId>C0FD7678DB72773A</RequestId><HostId>dzKf3RvMEsApl0/Q0HLmN/FFor4gLYZaTy2vocBpnW63/r3u2PPFFM+YzmAa/TV//9qkgvuW7TM=</HostId></Error>
2020/08/16 05:06:31 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-kizivof6tikogud8faxenem2</BucketName><RequestId>C0FD7678DB72773A</RequestId><HostId>dzKf3RvMEsApl0/Q0HLmN/FFor4gLYZaTy2vocBpnW63/r3u2PPFFM+YzmAa/TV//9qkgvuW7TM=</HostId></Error>
2020/08/16 05:06:31 DEBUG : : Looking for writers
2020/08/16 05:06:31 DEBUG : file1: reading active writers
2020/08/16 05:06:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:32 DEBUG : : Looking for writers
2020/08/16 05:06:32 DEBUG : file1: reading active writers
2020/08/16 05:06:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:32 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:32 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-kizivof6tikogud8faxenem2</BucketName><RequestId>0C5E51A32EE76A01</RequestId><HostId>qX9mOfxBKoHppuVdpr/4eYkhJOlquzN03NZTaDfSsZ71PuHCIifdsd1T5JlgyDC+IBivOCAd3KI=</HostId></Error>
2020/08/16 05:06:32 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-kizivof6tikogud8faxenem2</BucketName><RequestId>0C5E51A32EE76A01</RequestId><HostId>qX9mOfxBKoHppuVdpr/4eYkhJOlquzN03NZTaDfSsZ71PuHCIifdsd1T5JlgyDC+IBivOCAd3KI=</HostId></Error>
2020/08/16 05:06:33 DEBUG : : Looking for writers
2020/08/16 05:06:33 DEBUG : file1: reading active writers
2020/08/16 05:06:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:34 DEBUG : : Looking for writers
2020/08/16 05:06:34 DEBUG : file1: reading active writers
2020/08/16 05:06:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:35 DEBUG : : Looking for writers
2020/08/16 05:06:35 DEBUG : file1: reading active writers
2020/08/16 05:06:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:35 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06: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-kizivof6tikogud8faxenem2</BucketName><RequestId>2FC8016FD6AF765D</RequestId><HostId>ivoYLqGady1I9oIU+y/nVSrc/oQvOqbCx8RW6aA9Wz8oY2/+QC2fnuncj7oRb1Vmr9u5thyuyPA=</HostId></Error>
2020/08/16 05:06:36 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-kizivof6tikogud8faxenem2</BucketName><RequestId>2FC8016FD6AF765D</RequestId><HostId>ivoYLqGady1I9oIU+y/nVSrc/oQvOqbCx8RW6aA9Wz8oY2/+QC2fnuncj7oRb1Vmr9u5thyuyPA=</HostId></Error>
2020/08/16 05:06:36 DEBUG : : Looking for writers
2020/08/16 05:06:36 DEBUG : file1: reading active writers
2020/08/16 05:06:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:37 DEBUG : : Looking for writers
2020/08/16 05:06:37 DEBUG : file1: reading active writers
2020/08/16 05:06:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:38 DEBUG : : Looking for writers
2020/08/16 05:06:38 DEBUG : file1: reading active writers
2020/08/16 05:06:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:39 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc000150ea0 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817810477263103 ext:27263747515 loc:0x25a1860} ATime:{wall:13818817810477287476 ext:27263771882 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:06:39 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:06:42 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06: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-kizivof6tikogud8faxenem2</BucketName><RequestId>B193F711A5EDD3A6</RequestId><HostId>AYUr84hhOG3G0faO0fPLYF2HI3c48Rra6sHp/ppLqNvhk2+bwUBr1DKPRl/o9dgTqle+nv1NbWc=</HostId></Error>
2020/08/16 05:06:42 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-kizivof6tikogud8faxenem2</BucketName><RequestId>B193F711A5EDD3A6</RequestId><HostId>AYUr84hhOG3G0faO0fPLYF2HI3c48Rra6sHp/ppLqNvhk2+bwUBr1DKPRl/o9dgTqle+nv1NbWc=</HostId></Error>
    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:06:46 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:06:46 DEBUG : : Looking for writers
2020/08/16 05:06:46 DEBUG : file1: reading active writers
2020/08/16 05:06:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:06:46 DEBUG : : Looking for writers
2020/08/16 05:06:46 DEBUG : file1: reading active writers
2020/08/16 05:06:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:06:46 DEBUG : : Looking for writers
2020/08/16 05:06:46 DEBUG : file1: reading active writers
2020/08/16 05:06:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:06:46 DEBUG : : Looking for writers
2020/08/16 05:06:46 DEBUG : file1: reading active writers
2020/08/16 05:06:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:06:46 DEBUG : : Looking for writers
2020/08/16 05:06:46 DEBUG : file1: reading active writers
2020/08/16 05:06:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:06:46 DEBUG : : Looking for writers
2020/08/16 05:06:46 DEBUG : file1: reading active writers
2020/08/16 05:06:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:06:47 DEBUG : : Looking for writers
2020/08/16 05:06:47 DEBUG : file1: reading active writers
2020/08/16 05:06:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:06:47 DEBUG : : Looking for writers
2020/08/16 05:06:47 DEBUG : file1: reading active writers
2020/08/16 05:06:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:48 DEBUG : : Looking for writers
2020/08/16 05:06:48 DEBUG : file1: reading active writers
2020/08/16 05:06:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:49 DEBUG : : Looking for writers
2020/08/16 05:06:49 DEBUG : file1: reading active writers
2020/08/16 05:06:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:50 DEBUG : : Looking for writers
2020/08/16 05:06:50 DEBUG : file1: reading active writers
2020/08/16 05:06:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:51 DEBUG : : Looking for writers
2020/08/16 05:06:51 DEBUG : file1: reading active writers
2020/08/16 05:06:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:52 DEBUG : : Looking for writers
2020/08/16 05:06:52 DEBUG : file1: reading active writers
2020/08/16 05:06:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:53 DEBUG : : Looking for writers
2020/08/16 05:06:53 DEBUG : file1: reading active writers
2020/08/16 05:06:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:54 DEBUG : : Looking for writers
2020/08/16 05:06:54 DEBUG : file1: reading active writers
2020/08/16 05:06:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:55 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06: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-kizivof6tikogud8faxenem2</BucketName><RequestId>D3F54E631E4A5E17</RequestId><HostId>nW9CxqYDQ8/p4gy0FE/7bIrTBvEpKuMdgyx5WxFO3C3KMELmLk7+JeO6q27HXn6WzaNB9NDUtKY=</HostId></Error>
2020/08/16 05:06:55 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-kizivof6tikogud8faxenem2</BucketName><RequestId>D3F54E631E4A5E17</RequestId><HostId>nW9CxqYDQ8/p4gy0FE/7bIrTBvEpKuMdgyx5WxFO3C3KMELmLk7+JeO6q27HXn6WzaNB9NDUtKY=</HostId></Error>
2020/08/16 05:06:55 DEBUG : : Looking for writers
2020/08/16 05:06:55 DEBUG : file1: reading active writers
2020/08/16 05:06:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:06:56 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s
Cache{
	"file1": &{c:0xc000150ea0 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817810477263103 ext:27263747515 loc:0x25a1860} ATime:{wall:13818817810477287476 ext:27263771882 loc:0x25a1860} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1},
}
2020/08/16 05:06:56 DEBUG : >WaitForWriters: 
2020/08/16 05:06:56 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestRWFileHandleWriteAt (27.09s)
=== RUN   TestRWFileHandleWriteNoWrite
    run.go:176: Remote "Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2'", Local "Local file system at /tmp/rclone831060863", Modify Window "1ns"
2020/08/16 05:06:56 INFO  : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': poll-interval is not supported by this remote
2020/08/16 05:06:56 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMD5HashS3/rclone-test-kizivof6tikogud8faxenem2"
2020/08/16 05:06:56 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMD5HashS3/rclone-test-kizivof6tikogud8faxenem2"
2020/08/16 05:06:56 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:06:56 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:06:56 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:06:56 DEBUG : file1: newRWFileHandle: 
2020/08/16 05:06:56 DEBUG : file1(0xc000737c40): openPending: 
2020/08/16 05:06:56 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 05:06:56 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:06:56 DEBUG : file1(0xc000737c40): >openPending: err=<nil>
2020/08/16 05:06:56 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 05:06:56 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:06:56 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 05:06:56 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 05:06:56 DEBUG : file1(0xc000737c40): close: 
2020/08/16 05:06:56 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 05:06:56.514270675 +0000 UTC m=+54.352908430
2020/08/16 05:06:56 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:06:56 DEBUG : file1(0xc000737c40): >close: err=<nil>
2020/08/16 05:06:56 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2020/08/16 05:06:56 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/08/16 05:06:56 DEBUG : file2: newRWFileHandle: 
2020/08/16 05:06:56 DEBUG : file2(0xc000737d00): openPending: 
2020/08/16 05:06:56 DEBUG : file2: vfs cache: truncate to size=0
2020/08/16 05:06:56 DEBUG : : Added virtual directory entry vAdd: "file2"
2020/08/16 05:06:56 DEBUG : file2(0xc000737d00): >openPending: err=<nil>
2020/08/16 05:06:56 DEBUG : file2: >newRWFileHandle: err=<nil>
2020/08/16 05:06:56 DEBUG : : Added virtual directory entry vAdd: "file2"
2020/08/16 05:06:56 DEBUG : file2: >Open: fd=file2 (rw), err=<nil>
2020/08/16 05:06:56 DEBUG : file2: >OpenFile: fd=file2 (rw), err=<nil>
2020/08/16 05:06:56 DEBUG : file2(0xc000737d00): RWFileHandle.Flush
2020/08/16 05:06:56 DEBUG : file2(0xc000737d00): RWFileHandle.Release
2020/08/16 05:06:56 DEBUG : file2(0xc000737d00): close: 
2020/08/16 05:06:56 DEBUG : file2: vfs cache: setting modification time to 2020-08-16 05:06:56.514856318 +0000 UTC m=+54.353494074
2020/08/16 05:06:56 INFO  : file2: vfs cache: queuing for upload in 100ms
2020/08/16 05:06:56 DEBUG : file2(0xc000737d00): >close: err=<nil>
2020/08/16 05:06:56 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:06:56 DEBUG : : Looking for writers
2020/08/16 05:06:56 DEBUG : file1: reading active writers
2020/08/16 05:06:56 DEBUG : file2: reading active writers
2020/08/16 05:06:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms
2020/08/16 05:06:56 DEBUG : : Looking for writers
2020/08/16 05:06:56 DEBUG : file1: reading active writers
2020/08/16 05:06:56 DEBUG : file2: reading active writers
2020/08/16 05:06:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms
2020/08/16 05:06:56 DEBUG : : Looking for writers
2020/08/16 05:06:56 DEBUG : file1: reading active writers
2020/08/16 05:06:56 DEBUG : file2: reading active writers
2020/08/16 05:06:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms
2020/08/16 05:06:56 DEBUG : : Looking for writers
2020/08/16 05:06:56 DEBUG : file1: reading active writers
2020/08/16 05:06:56 DEBUG : file2: reading active writers
2020/08/16 05:06:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms
2020/08/16 05:06:56 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:56 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>D73DBDE98E5C563B</RequestId><HostId>nHwTsqM0q9a4joGr0fxn48t7/zwvTEZuOy+luKP4+CvUr/lXO4AmDhxKm3J6kZV80efB5Z5r6W0=</HostId></Error>
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>D73DBDE98E5C563B</RequestId><HostId>nHwTsqM0q9a4joGr0fxn48t7/zwvTEZuOy+luKP4+CvUr/lXO4AmDhxKm3J6kZV80efB5Z5r6W0=</HostId></Error>
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>DE0CC90B70E3C1C4</RequestId><HostId>fLmhhEyIEIln3Ia05xXMKOmowKpxlcZA0ghzWQ4h77jBi5zQHOSWuO9UMsx/exF86IzNIZyQ2bk=</HostId></Error>
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>DE0CC90B70E3C1C4</RequestId><HostId>fLmhhEyIEIln3Ia05xXMKOmowKpxlcZA0ghzWQ4h77jBi5zQHOSWuO9UMsx/exF86IzNIZyQ2bk=</HostId></Error>
2020/08/16 05:06:56 DEBUG : : Looking for writers
2020/08/16 05:06:56 DEBUG : file1: reading active writers
2020/08/16 05:06:56 DEBUG : file2: reading active writers
2020/08/16 05:06:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms
2020/08/16 05:06:56 DEBUG : : Looking for writers
2020/08/16 05:06:56 DEBUG : file1: reading active writers
2020/08/16 05:06:56 DEBUG : file2: reading active writers
2020/08/16 05:06:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms
2020/08/16 05:06:56 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:56 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>2W0J0VAP0WFT4W4G</RequestId><HostId>yw6JkkGzpBKb19MN8hXOAvHtLXDg8WzNFIAkhEx+djR6GLA4LGeiVaswGtr2hx24VxMN8d2VJ98=</HostId></Error>
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>2W0J0VAP0WFT4W4G</RequestId><HostId>yw6JkkGzpBKb19MN8hXOAvHtLXDg8WzNFIAkhEx+djR6GLA4LGeiVaswGtr2hx24VxMN8d2VJ98=</HostId></Error>
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>A41EF2FB793CEDB9</RequestId><HostId>WsesPPaNPbCNkyrvT+e6/3ZqqfrTYwuyYC2oya86l939+6l69H5XBFHYQUaA050bH3I/j9MyXmE=</HostId></Error>
2020/08/16 05:06:56 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-kizivof6tikogud8faxenem2</BucketName><RequestId>A41EF2FB793CEDB9</RequestId><HostId>WsesPPaNPbCNkyrvT+e6/3ZqqfrTYwuyYC2oya86l939+6l69H5XBFHYQUaA050bH3I/j9MyXmE=</HostId></Error>
2020/08/16 05:06:57 DEBUG : : Looking for writers
2020/08/16 05:06:57 DEBUG : file2: reading active writers
2020/08/16 05:06:57 DEBUG : file1: reading active writers
2020/08/16 05:06:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms
2020/08/16 05:06:57 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:57 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-kizivof6tikogud8faxenem2</BucketName><RequestId>E816A38878022578</RequestId><HostId>pDLvT430z9OLEM6Coac8+ta2YzZ3an6G3sEqiH+/MVqRVdRKMIZXnchd9ODrU16hG0ApBSs5I2c=</HostId></Error>
2020/08/16 05:06:57 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-kizivof6tikogud8faxenem2</BucketName><RequestId>E816A38878022578</RequestId><HostId>pDLvT430z9OLEM6Coac8+ta2YzZ3an6G3sEqiH+/MVqRVdRKMIZXnchd9ODrU16hG0ApBSs5I2c=</HostId></Error>
2020/08/16 05:06:57 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:06:57 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-kizivof6tikogud8faxenem2</BucketName><RequestId>31D5032A893044AF</RequestId><HostId>gDQ100cleC1/gLtNid+VohYkbGIL1wt+v4PQ4cB1pCGC7JmHpTQT37pUGxVzteQTj+IuITf8sSU=</HostId></Error>
2020/08/16 05:06:57 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-kizivof6tikogud8faxenem2</BucketName><RequestId>31D5032A893044AF</RequestId><HostId>gDQ100cleC1/gLtNid+VohYkbGIL1wt+v4PQ4cB1pCGC7JmHpTQT37pUGxVzteQTj+IuITf8sSU=</HostId></Error>
2020/08/16 05:06:57 DEBUG : : Looking for writers
2020/08/16 05:06:57 DEBUG : file1: reading active writers
2020/08/16 05:06:57 DEBUG : file2: reading active writers
2020/08/16 05:06:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:06:58 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:58 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:06:58 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-kizivof6tikogud8faxenem2</BucketName><RequestId>B5B2CD36C8DB8005</RequestId><HostId>fyRJULWUsL8SanQCeBVC+RjHQHJ/UY/lOg8aY8z12GN9mFdr8X5kmkph8welPzBuW0JVEMxZJhE=</HostId></Error>
2020/08/16 05:06:58 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-kizivof6tikogud8faxenem2</BucketName><RequestId>B5B2CD36C8DB8005</RequestId><HostId>fyRJULWUsL8SanQCeBVC+RjHQHJ/UY/lOg8aY8z12GN9mFdr8X5kmkph8welPzBuW0JVEMxZJhE=</HostId></Error>
2020/08/16 05:06:58 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-kizivof6tikogud8faxenem2</BucketName><RequestId>5BD49A091B6813E6</RequestId><HostId>8Cg/9R9qKXdHyIseCd4D4eoahBuzDJWgxlsg+fofkZcWLHwKvq/u22yJCe6iMbw8T7t/cWpfuDQ=</HostId></Error>
2020/08/16 05:06:58 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-kizivof6tikogud8faxenem2</BucketName><RequestId>5BD49A091B6813E6</RequestId><HostId>8Cg/9R9qKXdHyIseCd4D4eoahBuzDJWgxlsg+fofkZcWLHwKvq/u22yJCe6iMbw8T7t/cWpfuDQ=</HostId></Error>
2020/08/16 05:06:58 DEBUG : : Looking for writers
2020/08/16 05:06:58 DEBUG : file1: reading active writers
2020/08/16 05:06:58 DEBUG : file2: reading active writers
2020/08/16 05:06:58 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:06:59 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:06:59 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:06:59 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-kizivof6tikogud8faxenem2</BucketName><RequestId>FVEH5J8XDXFS4QFP</RequestId><HostId>k8t4aXASyDUhcPakYn8/vZ0Wf1hLf/Aax2ZWnkigvUW69UzIuOVcEpn/Gka9VhLuKGT6f335HcU=</HostId></Error>
2020/08/16 05:06:59 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-kizivof6tikogud8faxenem2</BucketName><RequestId>FVEH5J8XDXFS4QFP</RequestId><HostId>k8t4aXASyDUhcPakYn8/vZ0Wf1hLf/Aax2ZWnkigvUW69UzIuOVcEpn/Gka9VhLuKGT6f335HcU=</HostId></Error>
2020/08/16 05:06:59 DEBUG : : Looking for writers
2020/08/16 05:06:59 DEBUG : file1: reading active writers
2020/08/16 05:06:59 DEBUG : file2: reading active writers
2020/08/16 05:06:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:06:59 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-kizivof6tikogud8faxenem2</BucketName><RequestId>A781D3A5FC5B2AA5</RequestId><HostId>7x9T9vCme1cVh8BBfKYIuFcfzfJDoauxqrHYZ1lWq18Vbuv7a7ebQzKOH3KHHwCYjsCzKpHnBFM=</HostId></Error>
2020/08/16 05:06:59 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-kizivof6tikogud8faxenem2</BucketName><RequestId>A781D3A5FC5B2AA5</RequestId><HostId>7x9T9vCme1cVh8BBfKYIuFcfzfJDoauxqrHYZ1lWq18Vbuv7a7ebQzKOH3KHHwCYjsCzKpHnBFM=</HostId></Error>
2020/08/16 05:07:00 DEBUG : : Looking for writers
2020/08/16 05:07:00 DEBUG : file1: reading active writers
2020/08/16 05:07:00 DEBUG : file2: reading active writers
2020/08/16 05:07:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:01 DEBUG : : Looking for writers
2020/08/16 05:07:01 DEBUG : file1: reading active writers
2020/08/16 05:07:01 DEBUG : file2: reading active writers
2020/08/16 05:07:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:02 DEBUG : : Looking for writers
2020/08/16 05:07:02 DEBUG : file2: reading active writers
2020/08/16 05:07:02 DEBUG : file1: reading active writers
2020/08/16 05:07:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:02 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:07:02 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:07:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>AE545E467B833AF9</RequestId><HostId>Nck1clts5vFe8LfGq+7XjilWKHfv1WlipDkFU3KdReWCZBwaYBmj8xYHaO3zQ2A9KBmm8Y1d548=</HostId></Error>
2020/08/16 05:07:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>AE545E467B833AF9</RequestId><HostId>Nck1clts5vFe8LfGq+7XjilWKHfv1WlipDkFU3KdReWCZBwaYBmj8xYHaO3zQ2A9KBmm8Y1d548=</HostId></Error>
2020/08/16 05:07:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>DA467EAB8003813E</RequestId><HostId>hKMCsWRPkxtVJIcQYv0J71bP1XXiGoo7QWYHLMJyWRc503AxAMQOXTVoNVYnR5X4hzislClJuSY=</HostId></Error>
2020/08/16 05:07:03 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-kizivof6tikogud8faxenem2</BucketName><RequestId>DA467EAB8003813E</RequestId><HostId>hKMCsWRPkxtVJIcQYv0J71bP1XXiGoo7QWYHLMJyWRc503AxAMQOXTVoNVYnR5X4hzislClJuSY=</HostId></Error>
2020/08/16 05:07:03 DEBUG : : Looking for writers
2020/08/16 05:07:03 DEBUG : file2: reading active writers
2020/08/16 05:07:03 DEBUG : file1: reading active writers
2020/08/16 05:07:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:04 DEBUG : : Looking for writers
2020/08/16 05:07:04 DEBUG : file1: reading active writers
2020/08/16 05:07:04 DEBUG : file2: reading active writers
2020/08/16 05:07:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:05 DEBUG : : Looking for writers
2020/08/16 05:07:05 DEBUG : file1: reading active writers
2020/08/16 05:07:05 DEBUG : file2: reading active writers
2020/08/16 05:07:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:06 ERROR : Exiting even though 0 writers active and 2 cache items in use after 10s
Cache{
	"file1": &{c:0xc000150120 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817839557453267 ext:54352908430 loc:0x25a1860} ATime:{wall:13818817839557584365 ext:54353039526 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1},
	"file2": &{c:0xc000150120 mu:{state:0 sema:0} name:file2 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817839558038910 ext:54353494074 loc:0x25a1860} ATime:{wall:13818817839558149198 ext:54353604361 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2},
}
2020/08/16 05:07:06 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:07:09 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:07:09 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:07: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-kizivof6tikogud8faxenem2</BucketName><RequestId>61C556CCE09B2BBB</RequestId><HostId>wCDcj9jviwoc/tIy4/iTelLixBVGxDyqhhjj375cu+XBJkE0c4pafvg1KqVRaPkQ7xLQJM/CCfw=</HostId></Error>
2020/08/16 05:07:09 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-kizivof6tikogud8faxenem2</BucketName><RequestId>61C556CCE09B2BBB</RequestId><HostId>wCDcj9jviwoc/tIy4/iTelLixBVGxDyqhhjj375cu+XBJkE0c4pafvg1KqVRaPkQ7xLQJM/CCfw=</HostId></Error>
2020/08/16 05:07: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-kizivof6tikogud8faxenem2</BucketName><RequestId>9F610495C1439EA6</RequestId><HostId>1E3BtX92kpsn7lxEdXcWDjWkC03eMSAZj+Iceq1PUwQPXBHcShpaGxZG6yt5kYaKskp+DHha8E8=</HostId></Error>
2020/08/16 05:07:09 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-kizivof6tikogud8faxenem2</BucketName><RequestId>9F610495C1439EA6</RequestId><HostId>1E3BtX92kpsn7lxEdXcWDjWkC03eMSAZj+Iceq1PUwQPXBHcShpaGxZG6yt5kYaKskp+DHha8E8=</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 "file2"
    fstest.go:200: Not found "file1"
    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:07:13 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:07:13 DEBUG : : Looking for writers
2020/08/16 05:07:13 DEBUG : file1: reading active writers
2020/08/16 05:07:13 DEBUG : file2: reading active writers
2020/08/16 05:07:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms
2020/08/16 05:07:13 DEBUG : : Looking for writers
2020/08/16 05:07:13 DEBUG : file1: reading active writers
2020/08/16 05:07:13 DEBUG : file2: reading active writers
2020/08/16 05:07:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms
2020/08/16 05:07:13 DEBUG : : Looking for writers
2020/08/16 05:07:13 DEBUG : file1: reading active writers
2020/08/16 05:07:13 DEBUG : file2: reading active writers
2020/08/16 05:07:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms
2020/08/16 05:07:13 DEBUG : : Looking for writers
2020/08/16 05:07:13 DEBUG : file1: reading active writers
2020/08/16 05:07:13 DEBUG : file2: reading active writers
2020/08/16 05:07:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms
2020/08/16 05:07:13 DEBUG : : Looking for writers
2020/08/16 05:07:13 DEBUG : file1: reading active writers
2020/08/16 05:07:13 DEBUG : file2: reading active writers
2020/08/16 05:07:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms
2020/08/16 05:07:13 DEBUG : : Looking for writers
2020/08/16 05:07:13 DEBUG : file1: reading active writers
2020/08/16 05:07:13 DEBUG : file2: reading active writers
2020/08/16 05:07:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms
2020/08/16 05:07:14 DEBUG : : Looking for writers
2020/08/16 05:07:14 DEBUG : file1: reading active writers
2020/08/16 05:07:14 DEBUG : file2: reading active writers
2020/08/16 05:07:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms
2020/08/16 05:07:14 DEBUG : : Looking for writers
2020/08/16 05:07:14 DEBUG : file1: reading active writers
2020/08/16 05:07:14 DEBUG : file2: reading active writers
2020/08/16 05:07:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:15 DEBUG : : Looking for writers
2020/08/16 05:07:15 DEBUG : file1: reading active writers
2020/08/16 05:07:15 DEBUG : file2: reading active writers
2020/08/16 05:07:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:16 DEBUG : : Looking for writers
2020/08/16 05:07:16 DEBUG : file1: reading active writers
2020/08/16 05:07:16 DEBUG : file2: reading active writers
2020/08/16 05:07:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:17 DEBUG : : Looking for writers
2020/08/16 05:07:17 DEBUG : file1: reading active writers
2020/08/16 05:07:17 DEBUG : file2: reading active writers
2020/08/16 05:07:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:18 DEBUG : : Looking for writers
2020/08/16 05:07:18 DEBUG : file1: reading active writers
2020/08/16 05:07:18 DEBUG : file2: reading active writers
2020/08/16 05:07:18 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:19 DEBUG : : Looking for writers
2020/08/16 05:07:19 DEBUG : file1: reading active writers
2020/08/16 05:07:19 DEBUG : file2: reading active writers
2020/08/16 05:07:19 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:20 DEBUG : : Looking for writers
2020/08/16 05:07:20 DEBUG : file2: reading active writers
2020/08/16 05:07:20 DEBUG : file1: reading active writers
2020/08/16 05:07:20 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:21 DEBUG : : Looking for writers
2020/08/16 05:07:21 DEBUG : file1: reading active writers
2020/08/16 05:07:21 DEBUG : file2: reading active writers
2020/08/16 05:07:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:22 DEBUG : file1: vfs cache: starting upload
2020/08/16 05:07:22 DEBUG : file2: vfs cache: starting upload
2020/08/16 05:07: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-kizivof6tikogud8faxenem2</BucketName><RequestId>70C85EEF778CC722</RequestId><HostId>suXQcSmCzI/EqB+a+5655PEbmfCiRz2qBTkxxni6T+L6yZWGsYGAysudTatowzMYgtRaydumqxc=</HostId></Error>
2020/08/16 05:07:22 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-kizivof6tikogud8faxenem2</BucketName><RequestId>70C85EEF778CC722</RequestId><HostId>suXQcSmCzI/EqB+a+5655PEbmfCiRz2qBTkxxni6T+L6yZWGsYGAysudTatowzMYgtRaydumqxc=</HostId></Error>
2020/08/16 05:07: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-kizivof6tikogud8faxenem2</BucketName><RequestId>2C9D71698BDDC4EE</RequestId><HostId>d/6cXu/mq4fXM0RaNQ1wR2UkFzKRUpGGlpP3Osx/M5NyiCQPuezeSIkJZWfCx9RgwsfqUeP3VRs=</HostId></Error>
2020/08/16 05:07:22 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-kizivof6tikogud8faxenem2</BucketName><RequestId>2C9D71698BDDC4EE</RequestId><HostId>d/6cXu/mq4fXM0RaNQ1wR2UkFzKRUpGGlpP3Osx/M5NyiCQPuezeSIkJZWfCx9RgwsfqUeP3VRs=</HostId></Error>
2020/08/16 05:07:22 DEBUG : : Looking for writers
2020/08/16 05:07:22 DEBUG : file1: reading active writers
2020/08/16 05:07:22 DEBUG : file2: reading active writers
2020/08/16 05:07:22 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s
2020/08/16 05:07:23 ERROR : Exiting even though 0 writers active and 2 cache items in use after 10s
Cache{
	"file1": &{c:0xc000150120 mu:{state:0 sema:0} name:file1 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817839557453267 ext:54352908430 loc:0x25a1860} ATime:{wall:13818817839557584365 ext:54353039526 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1},
	"file2": &{c:0xc000150120 mu:{state:0 sema:0} name:file2 opens:0 downloaders:<nil> o:<nil> fd:<nil> metaDirty:false modified:false info:{ModTime:{wall:13818817839558038910 ext:54353494074 loc:0x25a1860} ATime:{wall:13818817839558149198 ext:54353604361 loc:0x25a1860} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2},
}
2020/08/16 05:07:23 DEBUG : >WaitForWriters: 
2020/08/16 05:07:23 DEBUG : vfs cache: cleaner exiting
--- FAIL: TestRWFileHandleWriteNoWrite (27.03s)
=== RUN   TestWriteFileHandleMethods
    run.go:176: Remote "Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2'", Local "Local file system at /tmp/rclone831060863", Modify Window "1ns"
2020/08/16 05:07:23 INFO  : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': poll-interval is not supported by this remote
2020/08/16 05:07:23 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:07:23 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:07:23 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:23 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:07:23 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:07:23 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:23 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal
2020/08/16 05:07:23 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal
2020/08/16 05:07:23 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes
2020/08/16 05:07:23 DEBUG : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': File to upload is small (5 bytes), uploading instead of streaming
2020/08/16 05:07:23 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-kizivof6tikogud8faxenem2</BucketName><RequestId>995D522135C1D2DB</RequestId><HostId>zqfnywNfhOiS6KnA9vfcgYOEaNu2WihTsd+l2ab9ivgQCQYgJu5bT2TpgyEngDsWD7xD4FXO8i0=</HostId></Error>
2020/08/16 05:07:23 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-kizivof6tikogud8faxenem2</BucketName><RequestId>995D522135C1D2DB</RequestId><HostId>zqfnywNfhOiS6KnA9vfcgYOEaNu2WihTsd+l2ab9ivgQCQYgJu5bT2TpgyEngDsWD7xD4FXO8i0=</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-kizivof6tikogud8faxenem2</BucketName><RequestId>995D522135C1D2DB</RequestId><HostId>zqfnywNfhOiS6KnA9vfcgYOEaNu2WihTsd+l2ab9ivgQCQYgJu5bT2TpgyEngDsWD7xD4FXO8i0=</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:07:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:07:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:07:30 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:30 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:07:30 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:07:30 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:30 DEBUG : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': File to upload is small (0 bytes), uploading instead of streaming
2020/08/16 05:07:30 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-kizivof6tikogud8faxenem2</BucketName><RequestId>62521E03EE403AE1</RequestId><HostId>x7nyCSt/e9VAtVaPv3ln9Ge7w+zLfpgRg2zHlARVbPvIvWPVUNZpniwrp1SZlu2H+UBoocelbfk=</HostId></Error>
2020/08/16 05:07:30 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-kizivof6tikogud8faxenem2</BucketName><RequestId>62521E03EE403AE1</RequestId><HostId>x7nyCSt/e9VAtVaPv3ln9Ge7w+zLfpgRg2zHlARVbPvIvWPVUNZpniwrp1SZlu2H+UBoocelbfk=</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-kizivof6tikogud8faxenem2</BucketName><RequestId>62521E03EE403AE1</RequestId><HostId>x7nyCSt/e9VAtVaPv3ln9Ge7w+zLfpgRg2zHlARVbPvIvWPVUNZpniwrp1SZlu2H+UBoocelbfk=</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:07:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:07:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:07:30 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:30 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:07:30 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:07:30 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:07:30 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:07:30 DEBUG : : Looking for writers
2020/08/16 05:07:30 DEBUG : file1: reading active writers
2020/08/16 05:07:30 DEBUG : file1: active writers 1
2020/08/16 05:07:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms
2020/08/16 05:07:30 DEBUG : : Looking for writers
2020/08/16 05:07:30 DEBUG : file1: reading active writers
2020/08/16 05:07:30 DEBUG : file1: active writers 1
2020/08/16 05:07:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms
2020/08/16 05:07:30 DEBUG : : Looking for writers
2020/08/16 05:07:30 DEBUG : file1: reading active writers
2020/08/16 05:07:30 DEBUG : file1: active writers 1
2020/08/16 05:07:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms
2020/08/16 05:07:30 DEBUG : : Looking for writers
2020/08/16 05:07:30 DEBUG : file1: reading active writers
2020/08/16 05:07:30 DEBUG : file1: active writers 1
2020/08/16 05:07:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms
2020/08/16 05:07:30 DEBUG : : Looking for writers
2020/08/16 05:07:30 DEBUG : file1: reading active writers
2020/08/16 05:07:30 DEBUG : file1: active writers 1
2020/08/16 05:07:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms
2020/08/16 05:07:30 DEBUG : : Looking for writers
2020/08/16 05:07:30 DEBUG : file1: reading active writers
2020/08/16 05:07:30 DEBUG : file1: active writers 1
2020/08/16 05:07:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms
2020/08/16 05:07:31 DEBUG : : Looking for writers
2020/08/16 05:07:31 DEBUG : file1: reading active writers
2020/08/16 05:07:31 DEBUG : file1: active writers 1
2020/08/16 05:07:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms
2020/08/16 05:07:31 DEBUG : : Looking for writers
2020/08/16 05:07:31 DEBUG : file1: reading active writers
2020/08/16 05:07:31 DEBUG : file1: active writers 1
2020/08/16 05:07:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:32 DEBUG : : Looking for writers
2020/08/16 05:07:32 DEBUG : file1: reading active writers
2020/08/16 05:07:32 DEBUG : file1: active writers 1
2020/08/16 05:07:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:33 DEBUG : : Looking for writers
2020/08/16 05:07:33 DEBUG : file1: reading active writers
2020/08/16 05:07:33 DEBUG : file1: active writers 1
2020/08/16 05:07:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:34 DEBUG : : Looking for writers
2020/08/16 05:07:34 DEBUG : file1: reading active writers
2020/08/16 05:07:34 DEBUG : file1: active writers 1
2020/08/16 05:07:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:35 DEBUG : : Looking for writers
2020/08/16 05:07:35 DEBUG : file1: reading active writers
2020/08/16 05:07:35 DEBUG : file1: active writers 1
2020/08/16 05:07:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:36 DEBUG : : Looking for writers
2020/08/16 05:07:36 DEBUG : file1: reading active writers
2020/08/16 05:07:36 DEBUG : file1: active writers 1
2020/08/16 05:07:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:37 DEBUG : : Looking for writers
2020/08/16 05:07:37 DEBUG : file1: reading active writers
2020/08/16 05:07:37 DEBUG : file1: active writers 1
2020/08/16 05:07:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:38 DEBUG : : Looking for writers
2020/08/16 05:07:38 DEBUG : file1: reading active writers
2020/08/16 05:07:38 DEBUG : file1: active writers 1
2020/08/16 05:07:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:39 DEBUG : : Looking for writers
2020/08/16 05:07:39 DEBUG : file1: reading active writers
2020/08/16 05:07:39 DEBUG : file1: active writers 1
2020/08/16 05:07:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2020/08/16 05:07:40 ERROR : Exiting even though 1 writers active and 0 cache items in use after 10s
Cache: <nil>
2020/08/16 05:07:40 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileHandleMethods (17.10s)
=== RUN   TestWriteFileHandleWriteAt
    run.go:176: Remote "Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2'", Local "Local file system at /tmp/rclone831060863", Modify Window "1ns"
2020/08/16 05:07:40 INFO  : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': poll-interval is not supported by this remote
2020/08/16 05:07:40 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:07:40 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:07:40 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:40 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:07:40 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:07:40 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:40 DEBUG : file1: waiting for in-sequence write to 100 for 1s
2020/08/16 05:07:41 DEBUG : file1: aborting in-sequence write wait, off=100
2020/08/16 05:07:41 DEBUG : file1: failed to wait for in-sequence write to 100
2020/08/16 05:07:41 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes
2020/08/16 05:07:41 DEBUG : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': File to upload is small (11 bytes), uploading instead of streaming
2020/08/16 05:07: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-kizivof6tikogud8faxenem2</BucketName><RequestId>6B6F8F1968672E22</RequestId><HostId>prFSoszBwGX0cOR6xY3RzsDcCtJRk6MPNey8zz5T6Po5KUoBqF3HMsBZSDsJyI0awdshWxDzaaY=</HostId></Error>
2020/08/16 05:07:41 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-kizivof6tikogud8faxenem2</BucketName><RequestId>6B6F8F1968672E22</RequestId><HostId>prFSoszBwGX0cOR6xY3RzsDcCtJRk6MPNey8zz5T6Po5KUoBqF3HMsBZSDsJyI0awdshWxDzaaY=</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-kizivof6tikogud8faxenem2</BucketName><RequestId>6B6F8F1968672E22</RequestId><HostId>prFSoszBwGX0cOR6xY3RzsDcCtJRk6MPNey8zz5T6Po5KUoBqF3HMsBZSDsJyI0awdshWxDzaaY=</HostId></Error>
        	Test:       	TestWriteFileHandleWriteAt
2020/08/16 05:07:41 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:07:48 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:07:48 DEBUG : : Looking for writers
2020/08/16 05:07:48 DEBUG : file1: reading active writers
2020/08/16 05:07:48 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileHandleWriteAt (8.07s)
=== RUN   TestWriteFileHandleFlush
    run.go:176: Remote "Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2'", Local "Local file system at /tmp/rclone831060863", Modify Window "1ns"
2020/08/16 05:07:48 INFO  : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': poll-interval is not supported by this remote
2020/08/16 05:07:48 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 05:07:48 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 05:07:48 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:48 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2020/08/16 05:07:48 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2020/08/16 05:07:48 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2020/08/16 05:07:48 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 05:07:48 DEBUG : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': File to upload is small (5 bytes), uploading instead of streaming
2020/08/16 05:07: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-kizivof6tikogud8faxenem2</BucketName><RequestId>2602CBF928C4159A</RequestId><HostId>fwlz89EeWTTJ8WjJAWHdU8lcMb/aDUnPLPqX2COTFzpi+hZky7XFZU9IDWEr3FSILZBSEzZtng4=</HostId></Error>
2020/08/16 05:07:48 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-kizivof6tikogud8faxenem2</BucketName><RequestId>2602CBF928C4159A</RequestId><HostId>fwlz89EeWTTJ8WjJAWHdU8lcMb/aDUnPLPqX2COTFzpi+hZky7XFZU9IDWEr3FSILZBSEzZtng4=</HostId></Error>
2020/08/16 05:07:48 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-kizivof6tikogud8faxenem2</BucketName><RequestId>2602CBF928C4159A</RequestId><HostId>fwlz89EeWTTJ8WjJAWHdU8lcMb/aDUnPLPqX2COTFzpi+hZky7XFZU9IDWEr3FSILZBSEzZtng4=</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-kizivof6tikogud8faxenem2</BucketName><RequestId>2602CBF928C4159A</RequestId><HostId>fwlz89EeWTTJ8WjJAWHdU8lcMb/aDUnPLPqX2COTFzpi+hZky7XFZU9IDWEr3FSILZBSEzZtng4=</HostId></Error>
        	Test:       	TestWriteFileHandleFlush
2020/08/16 05:07:48 DEBUG : file1: WriteFileHandle.Flush nothing to do
2020/08/16 05:07:48 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:07:48 DEBUG : : Looking for writers
2020/08/16 05:07:48 DEBUG : file1: reading active writers
2020/08/16 05:07:48 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileHandleFlush (0.06s)
FAIL
2020/08/16 05:07:48 DEBUG : Chunked 'TestChunkerChunk50bMD5HashS3:rclone-test-kizivof6tikogud8faxenem2': Purge dir ""
2020/08/16 05:07:48 purge failed to rmdir "": NoSuchBucket: The specified bucket does not exist
	status code: 404, request id: F9A1223F19AF7327, host id: NbQi8wPONR25RQQ2uiM/wGAapcegL4oRP6J7JGXc5RfbOJR0BlcTNQmt6vmGFzeA8LXvq6jKQ9M=
2020/08/16 05:07:48 purge failed: directory not found
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bMD5HashS3: -verbose -size-limit 1024 -test.run '^(TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt)$'" - Finished ERROR in 1m46.639063391s (try 4/5): exit status 1: Failed [TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush]