"./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -test.run '^TestRWFileModTimeWithOpenWriters$'" - Starting (try 5/5)
=== RUN   TestRWFileModTimeWithOpenWriters
    run.go:176: Remote "B2 bucket rclone-test-jomuxup2lupokop3nowuxoc7", Local "Local file system at /tmp/rclone058576352", Modify Window "1ms"
2020/08/16 06:14:06 INFO  : B2 bucket rclone-test-jomuxup2lupokop3nowuxoc7: poll-interval is not supported by this remote
2020/08/16 06:14:06 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-jomuxup2lupokop3nowuxoc7"
2020/08/16 06:14:06 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-jomuxup2lupokop3nowuxoc7"
2020/08/16 06:14:06 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/08/16 06:14:06 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/08/16 06:14:06 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/08/16 06:14:06 DEBUG : file1: newRWFileHandle: 
2020/08/16 06:14:06 DEBUG : file1(0xc00016a280): openPending: 
2020/08/16 06:14:06 DEBUG : file1: vfs cache: truncate to size=0
2020/08/16 06:14:06 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 06:14:06 DEBUG : file1(0xc00016a280): >openPending: err=<nil>
2020/08/16 06:14:06 DEBUG : file1: >newRWFileHandle: err=<nil>
2020/08/16 06:14:06 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 06:14:06 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/08/16 06:14:06 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/08/16 06:14:13 DEBUG : Can set mod time: true
2020/08/16 06:14:13 DEBUG : file1(0xc00016a280): _writeAt: size=2, off=0
2020/08/16 06:14:13 DEBUG : file1(0xc00016a280): >_writeAt: n=2, err=<nil>
2020/08/16 06:14:13 DEBUG : file1(0xc00016a280): RWFileHandle.Flush
2020/08/16 06:14:13 DEBUG : file1(0xc00016a280): RWFileHandle.Release
2020/08/16 06:14:13 DEBUG : file1(0xc00016a280): close: 
2020/08/16 06:14:13 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:14:13.933364575 +0000 UTC m=+8.504265406
2020/08/16 06:14:13 INFO  : file1: vfs cache: queuing for upload in 100ms
2020/08/16 06:14:13 DEBUG : file1(0xc00016a280): >close: err=<nil>
2020/08/16 06:14:13 DEBUG : WaitForWriters: timeout=10s
2020/08/16 06:14:13 DEBUG : : Looking for writers
2020/08/16 06:14:13 DEBUG : file1: reading active writers
2020/08/16 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 06:14:13 DEBUG : : Looking for writers
2020/08/16 06:14:13 DEBUG : file1: reading active writers
2020/08/16 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 06:14:13 DEBUG : : Looking for writers
2020/08/16 06:14:13 DEBUG : file1: reading active writers
2020/08/16 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 06:14:14 DEBUG : : Looking for writers
2020/08/16 06:14:14 DEBUG : file1: reading active writers
2020/08/16 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 06:14:14 DEBUG : file1: vfs cache: starting upload
2020/08/16 06:14:14 DEBUG : : Looking for writers
2020/08/16 06:14:14 DEBUG : file1: reading active writers
2020/08/16 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 06:14:14 DEBUG : : Looking for writers
2020/08/16 06:14:14 DEBUG : file1: reading active writers
2020/08/16 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2020/08/16 06:14:14 DEBUG : : Looking for writers
2020/08/16 06:14:14 DEBUG : file1: reading active writers
2020/08/16 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2020/08/16 06:14:15 DEBUG : : Looking for writers
2020/08/16 06:14:15 DEBUG : file1: reading active writers
2020/08/16 06:14:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 06:14:16 DEBUG : : Looking for writers
2020/08/16 06:14:16 DEBUG : file1: reading active writers
2020/08/16 06:14:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2020/08/16 06:14:16 DEBUG : file1: SHA-1 = c22b5f9178342609428d6f51b2c5af4c0bde6a42 OK
2020/08/16 06:14:16 INFO  : file1: Copied (new)
2020/08/16 06:14:16 DEBUG : file1: vfs cache: fingerprint now "2,2020-08-16 06:14:13.933 +0000 UTC,c22b5f9178342609428d6f51b2c5af4c0bde6a42"
2020/08/16 06:14:16 DEBUG : file1: vfs cache: writeback object to VFS layer
2020/08/16 06:14:17 DEBUG : : Looking for writers
2020/08/16 06:14:17 DEBUG : file1: reading active writers
2020/08/16 06:14:17 DEBUG : >WaitForWriters: 
2020/08/16 06:14:17 DEBUG : file1: File._applyPendingModTime OK
2020/08/16 06:14:17 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC,c22b5f9178342609428d6f51b2c5af4c0bde6a42"
2020/08/16 06:14:17 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC
2020/08/16 06:14:17 DEBUG : : Added virtual directory entry vAdd: "file1"
2020/08/16 06:14:17 INFO  : file1: vfs cache: upload succeeded try #1
2020/08/16 06:14:17 DEBUG : WaitForWriters: timeout=10s
2020/08/16 06:14:17 DEBUG : : Looking for writers
2020/08/16 06:14:17 DEBUG : file1: reading active writers
2020/08/16 06:14:17 DEBUG : >WaitForWriters: 
2020/08/16 06:14:17 DEBUG : vfs cache: cleaner exiting
--- PASS: TestRWFileModTimeWithOpenWriters (16.49s)
PASS
2020/08/16 06:14:22 DEBUG : B2 bucket rclone-test-jomuxup2lupokop3nowuxoc7: Purge remote
2020/08/16 06:14:22 DEBUG : file1: Deleting (id "4_z0fd25db3e07dfb5b7f380e1b_f10763f0e7341c112_d20200816_m061418_c001_v0001144_t0048")
2020/08/16 06:14:22 DEBUG : file1: Deleting (id "4_z0fd25db3e07dfb5b7f380e1b_f106b03ea594f3116_d20200816_m061417_c001_v0001008_t0001")
2020/08/16 06:14:22 DEBUG : file1: Deleting (id "4_z0fd25db3e07dfb5b7f380e1b_f1007511da5260ea9_d20200816_m061414_c001_v0001120_t0059")
2020/08/16 06:14:22 DEBUG : time_test: Deleting (id "4_z0fd25db3e07dfb5b7f380e1b_f114eb0714c36e23a_d20200816_m061409_c001_v0001144_t0031")
2020/08/16 06:14:22 DEBUG : time_test: Deleting (id "4_z0fd25db3e07dfb5b7f380e1b_f11532c88ee65ca1d_d20200816_m061408_c001_v0001136_t0016")
2020/08/16 06:14:22 DEBUG : time_test: Deleting (id "4_z0fd25db3e07dfb5b7f380e1b_f1007511da5260e8f_d20200816_m061407_c001_v0001120_t0059")
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -test.run '^TestRWFileModTimeWithOpenWriters$'" - Finished OK in 18.330515462s (try 5/5)