"./vfs.test -test.v -test.timeout 1h0m0s -remote TestIA:rclone-integration-test -verbose" - Starting (try 1/5)
2022/06/17 05:03:02 DEBUG : Creating backend with remote "TestIA:rclone-integration-test/rclone-test-busigut5taperuz2dozufeb6"
2022/06/17 05:03:02 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/06/17 05:03:03 DEBUG : Creating backend with remote "/tmp/rclone1602337825"
=== RUN   TestDirHandleMethods
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:03:03 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:03:03 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:05:03 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:05:03 DEBUG : dir: Looking for writers
2022/06/17 05:05:03 DEBUG : : Looking for writers
2022/06/17 05:05:03 DEBUG : dir: reading active writers
2022/06/17 05:05:03 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (133.46s)
=== RUN   TestDirHandleReaddir
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:05:17 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:05:17 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:08:06 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:08:06 DEBUG : dir/subdir: Looking for writers
2022/06/17 05:08:06 DEBUG : dir: Looking for writers
2022/06/17 05:08:06 DEBUG : file1: reading active writers
2022/06/17 05:08:06 DEBUG : file2: reading active writers
2022/06/17 05:08:06 DEBUG : subdir: reading active writers
2022/06/17 05:08:06 DEBUG : : Looking for writers
2022/06/17 05:08:06 DEBUG : dir: reading active writers
2022/06/17 05:08:06 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (218.88s)
=== RUN   TestDirHandleReaddirnames
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:08:55 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:08:55 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:09:53 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:09:53 DEBUG : dir: Looking for writers
2022/06/17 05:09:53 DEBUG : file1: reading active writers
2022/06/17 05:09:53 DEBUG : : Looking for writers
2022/06/17 05:09:53 DEBUG : dir: reading active writers
2022/06/17 05:09:53 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddirnames (81.04s)
=== RUN   TestDirMethods
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:10:16 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:10:16 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:11:16 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:11:16 DEBUG : dir: Looking for writers
2022/06/17 05:11:16 DEBUG : : Looking for writers
2022/06/17 05:11:16 DEBUG : dir: reading active writers
2022/06/17 05:11:16 DEBUG : >WaitForWriters: 
--- PASS: TestDirMethods (73.73s)
=== RUN   TestDirForgetAll
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:11:30 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:11:30 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:12:28 DEBUG : dir: forgetting directory cache
2022/06/17 05:12:28 DEBUG : : forgetting directory cache
2022/06/17 05:12:28 DEBUG : dir: forgetting directory cache
2022/06/17 05:12:28 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:12:28 DEBUG : : Looking for writers
2022/06/17 05:12:28 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetAll (71.82s)
=== RUN   TestDirForgetPath
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:12:42 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:12:42 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:13:39 DEBUG : : ForgetPath: relativePath="dir/notfound", type=1
2022/06/17 05:13:39 DEBUG : dir: invalidating directory cache
2022/06/17 05:13:39 DEBUG : : >ForgetPath: 
2022/06/17 05:13:39 DEBUG : : ForgetPath: relativePath="dir", type=0
2022/06/17 05:13:39 DEBUG : : invalidating directory cache
2022/06/17 05:13:39 DEBUG : dir: forgetting directory cache
2022/06/17 05:13:39 DEBUG : : >ForgetPath: 
2022/06/17 05:13:39 DEBUG : : ForgetPath: relativePath="not/in/cache", type=0
2022/06/17 05:13:39 DEBUG : : >ForgetPath: 
2022/06/17 05:13:39 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:13:39 DEBUG : dir: Looking for writers
2022/06/17 05:13:39 DEBUG : : Looking for writers
2022/06/17 05:13:39 DEBUG : dir: reading active writers
2022/06/17 05:13:39 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetPath (70.18s)
=== RUN   TestDirWalk
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:13:52 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:13:52 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:15:45 DEBUG : : forgetting directory cache
2022/06/17 05:15:45 DEBUG : dir: forgetting directory cache
2022/06/17 05:15:46 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:15:46 DEBUG : fil/a/b: Looking for writers
2022/06/17 05:15:46 DEBUG : fil/a: Looking for writers
2022/06/17 05:15:46 DEBUG : b: reading active writers
2022/06/17 05:15:46 DEBUG : fil: Looking for writers
2022/06/17 05:15:46 DEBUG : a: reading active writers
2022/06/17 05:15:46 DEBUG : dir: Looking for writers
2022/06/17 05:15:46 DEBUG : : Looking for writers
2022/06/17 05:15:46 DEBUG : dir: reading active writers
2022/06/17 05:15:46 DEBUG : fil: reading active writers
2022/06/17 05:15:46 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (161.71s)
=== RUN   TestDirSetModTime
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:16:34 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:16:34 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:17:41 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:17:41 DEBUG : dir: Looking for writers
2022/06/17 05:17:41 DEBUG : : Looking for writers
2022/06/17 05:17:41 DEBUG : dir: reading active writers
2022/06/17 05:17:41 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (80.70s)
=== RUN   TestDirStat
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:17:55 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:17:55 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:19:13 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:19:13 DEBUG : dir: Looking for writers
2022/06/17 05:19:13 DEBUG : file1: reading active writers
2022/06/17 05:19:13 DEBUG : : Looking for writers
2022/06/17 05:19:13 DEBUG : dir: reading active writers
2022/06/17 05:19:13 DEBUG : >WaitForWriters: 
--- PASS: TestDirStat (103.19s)
=== RUN   TestDirReadDirAll
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:19:38 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:19:38 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
=== RUN   TestDirReadDirAll/Virtual
2022/06/17 05:22:37 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2022/06/17 05:22:37 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2022/06/17 05:22:37 DEBUG : dir: Added virtual directory entry vDel: "file2"
2022/06/17 05:22:37 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2022/06/17 05:25:34 DEBUG : Waiting for deletions to finish
2022/06/17 05:25:58 INFO  : dir/subdir/file3: Deleted
2022/06/17 05:25:58 INFO  : dir/subdir: Removing directory
2022/06/17 05:25:58 DEBUG : dir: invalidating directory cache
2022/06/17 05:25:59 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2022/06/17 05:25:59 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2022/06/17 05:25:59 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2022/06/17 05:25:59 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2022/06/17 05:25:59 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2022/06/17 05:25:59 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2022/06/17 05:25:59 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 05:25:59 DEBUG : dir: invalidating directory cache
2022/06/17 05:26:01 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2022/06/17 05:26:01 DEBUG : : forgetting directory cache
2022/06/17 05:26:01 DEBUG : dir: forgetting directory cache
2022/06/17 05:26:01 DEBUG : dir/virtualDir2: forgetting directory cache
2022/06/17 05:26:01 DEBUG : dir/virtualDir: forgetting directory cache
2022/06/17 05:26:01 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:26:01 DEBUG : dir/virtualDir2: Looking for writers
2022/06/17 05:26:01 DEBUG : dir/virtualDir: Looking for writers
2022/06/17 05:26:01 DEBUG : dir: Looking for writers
2022/06/17 05:26:01 DEBUG : virtualFile: reading active writers
2022/06/17 05:26:01 DEBUG : virtualDir: reading active writers
2022/06/17 05:26:01 DEBUG : file1: reading active writers
2022/06/17 05:26:01 DEBUG : virtualFile2: reading active writers
2022/06/17 05:26:01 DEBUG : virtualDir2: reading active writers
2022/06/17 05:26:01 DEBUG : : Looking for writers
2022/06/17 05:26:01 DEBUG : dir: reading active writers
2022/06/17 05:26:01 DEBUG : >WaitForWriters: 
--- PASS: TestDirReadDirAll (454.65s)
    --- PASS: TestDirReadDirAll/Virtual (204.34s)
=== RUN   TestDirOpen
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:27:12 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:27:12 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:28:20 ERROR : dir/: Can only open directories read only
2022/06/17 05:28:20 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:28:20 DEBUG : dir: Looking for writers
2022/06/17 05:28:20 DEBUG : : Looking for writers
2022/06/17 05:28:20 DEBUG : dir: reading active writers
2022/06/17 05:28:20 DEBUG : >WaitForWriters: 
--- PASS: TestDirOpen (156.01s)
=== RUN   TestDirCreate
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:29:48 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:29:48 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:31:07 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2022/06/17 05:31:07 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/06/17 05:31:07 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2022/06/17 05:31:07 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/06/17 05:31:07 DEBUG : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: File to upload is small (5 bytes), uploading instead of streaming
2022/06/17 05:32:34 DEBUG : dir/potato: md5 = 5d41402abc4b2a76b9719d911017c592 OK
2022/06/17 05:32:34 INFO  : dir/potato: Copied (new)
2022/06/17 05:32:34 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/06/17 05:32:34 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:32:34 DEBUG : dir: Looking for writers
2022/06/17 05:32:34 DEBUG : file1: reading active writers
2022/06/17 05:32:34 DEBUG : potato: reading active writers
2022/06/17 05:32:34 DEBUG : : Looking for writers
2022/06/17 05:32:34 DEBUG : dir: reading active writers
2022/06/17 05:32:34 DEBUG : >WaitForWriters: 
--- PASS: TestDirCreate (288.74s)
=== RUN   TestDirMkdir
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:34:37 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:34:37 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:35:13 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
    fstest.go:251: Filtering empty directory "dir/sub"
2022/06/17 05:35:14 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:35:14 DEBUG : dir/sub: Looking for writers
2022/06/17 05:35:14 DEBUG : dir: Looking for writers
2022/06/17 05:35:14 DEBUG : file1: reading active writers
2022/06/17 05:35:14 DEBUG : sub: reading active writers
2022/06/17 05:35:14 DEBUG : : Looking for writers
2022/06/17 05:35:14 DEBUG : dir: reading active writers
2022/06/17 05:35:14 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdir (71.05s)
=== RUN   TestDirMkdirSub
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:35:48 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:35:48 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:36:24 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2022/06/17 05:36:24 DEBUG : dir/sub: Added virtual directory entry vAddDir: "subsub"
    fstest.go:251: Filtering empty directory "dir/sub"
    fstest.go:251: Filtering empty directory "dir/sub/subsub"
2022/06/17 05:36:24 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:36:24 DEBUG : dir/sub/subsub: Looking for writers
2022/06/17 05:36:24 DEBUG : dir/sub: Looking for writers
2022/06/17 05:36:24 DEBUG : subsub: reading active writers
2022/06/17 05:36:24 DEBUG : dir: Looking for writers
2022/06/17 05:36:24 DEBUG : file1: reading active writers
2022/06/17 05:36:24 DEBUG : sub: reading active writers
2022/06/17 05:36:24 DEBUG : : Looking for writers
2022/06/17 05:36:24 DEBUG : dir: reading active writers
2022/06/17 05:36:24 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdirSub (59.82s)
=== RUN   TestDirRemove
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:36:48 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:36:48 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:38:07 ERROR : dir/: Dir.Remove not empty
2022/06/17 05:38:07 DEBUG : dir/file1: Remove: 
2022/06/17 05:38:07 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 05:39:35 DEBUG : dir/file1: >Remove: err=<nil>
2022/06/17 05:39:35 DEBUG : : Added virtual directory entry vDel: "dir"
2022/06/17 05:39:36 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:39:36 DEBUG : : Looking for writers
2022/06/17 05:39:36 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemove (168.57s)
=== RUN   TestDirRemoveAll
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:39:37 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:39:37 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:40:12 DEBUG : dir/file1: Remove: 
2022/06/17 05:40:12 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 05:40:46 DEBUG : dir/file1: >Remove: err=<nil>
2022/06/17 05:40:46 DEBUG : : Added virtual directory entry vDel: "dir"
2022/06/17 05:40:46 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:40:46 DEBUG : : Looking for writers
2022/06/17 05:40:46 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveAll (69.79s)
=== RUN   TestDirRemoveName
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:40:46 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:40:46 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:41:32 DEBUG : dir/file1: Remove: 
2022/06/17 05:41:32 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 05:42:06 DEBUG : dir/file1: >Remove: err=<nil>
    fstest.go:251: Filtering empty directory "dir"
2022/06/17 05:42:06 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:42:06 DEBUG : dir: Looking for writers
2022/06/17 05:42:06 DEBUG : : Looking for writers
2022/06/17 05:42:06 DEBUG : dir: reading active writers
2022/06/17 05:42:06 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveName (80.11s)
=== RUN   TestDirRename
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:42:07 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:42:07 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:43:16 ERROR : dir/not found: Dir.Rename error: file does not exist
2022/06/17 05:43:51 DEBUG : dir/file3: md5 = ea32138586c9d4e9533ef6cf95e9ec4b OK
2022/06/17 05:43:51 INFO  : dir/file3: Copied (server-side copy) to: dir2/file3
2022/06/17 05:43:51 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2022/06/17 05:43:51 INFO  : dir/file1: Copied (server-side copy) to: dir2/file1
2022/06/17 05:44:14 INFO  : dir/file3: Deleted
2022/06/17 05:44:25 INFO  : dir/file1: Deleted
2022/06/17 05:44:25 DEBUG : dir: Updating dir with dir2 0xc0009f6d80
2022/06/17 05:44:25 DEBUG : dir: forgetting directory cache
2022/06/17 05:44:25 DEBUG : : Added virtual directory entry vDel: "dir"
2022/06/17 05:44:25 DEBUG : : Added virtual directory entry vAddDir: "dir2"
2022/06/17 05:45:22 DEBUG : dir2/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2022/06/17 05:45:22 INFO  : dir2/file1: Copied (server-side copy) to: file2
2022/06/17 05:45:45 INFO  : dir2/file1: Deleted
2022/06/17 05:45:45 DEBUG : file2: Updating file with file2 0xc000290b40
2022/06/17 05:45:45 DEBUG : dir2: Added virtual directory entry vDel: "file1"
2022/06/17 05:45:45 DEBUG : : Added virtual directory entry vAddFile: "file2"
2022/06/17 05:55:48 DEBUG : file2: Dst hash empty - aborting Src hash check
2022/06/17 05:55:48 INFO  : file2: Copied (server-side copy) to: dir2/file3
2022/06/17 05:56:32 INFO  : file2: Deleted
2022/06/17 05:56:32 DEBUG : dir2/file3: Updating file with dir2/file3 0xc000290b40
2022/06/17 05:56:32 DEBUG : : Added virtual directory entry vDel: "file2"
2022/06/17 05:56:32 DEBUG : dir2: Added virtual directory entry vAddFile: "file3"
2022/06/17 05:56:32 DEBUG : : Re-reading directory (13m51.167278866s old)
2022/06/17 05:56:33 DEBUG : : Removed virtual directory entry vDel: "dir"
2022/06/17 05:56:33 DEBUG : : Removed virtual directory entry vDel: "file2"
2022/06/17 05:56:33 DEBUG : : Removed virtual directory entry vAddDir: "dir2"
2022/06/17 05:56:33 DEBUG : dir2: Re-reading directory (12m7.634280602s old)
2022/06/17 05:56:33 DEBUG : dir2: Removed virtual directory entry vDel: "file1"
2022/06/17 05:56:33 DEBUG : dir2: Removed virtual directory entry vAddFile: "file3"
2022/06/17 05:56:33 DEBUG : : Added virtual directory entry vAddDir: "empty directory"
2022/06/17 05:56:33 DEBUG : empty directory: Updating dir with renamed empty directory 0xc0009f6cc0
2022/06/17 05:56:33 DEBUG : empty directory: forgetting directory cache
2022/06/17 05:56:33 DEBUG : : Added virtual directory entry vDel: "empty directory"
2022/06/17 05:56:33 DEBUG : : Added virtual directory entry vAddDir: "renamed empty directory"
2022/06/17 05:56:33 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:56:33 DEBUG : renamed empty directory: Looking for writers
2022/06/17 05:56:33 DEBUG : dir2: Looking for writers
2022/06/17 05:56:33 DEBUG : file3: reading active writers
2022/06/17 05:56:33 DEBUG : : Looking for writers
2022/06/17 05:56:33 DEBUG : dir2: reading active writers
2022/06/17 05:56:33 DEBUG : renamed empty directory: reading active writers
2022/06/17 05:56:33 DEBUG : >WaitForWriters: 
--- PASS: TestDirRename (890.05s)
=== RUN   TestErrorError
--- PASS: TestErrorError (0.00s)
=== RUN   TestFileMethods
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:56:57 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:56:57 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 05:57:21 DEBUG : WaitForWriters: timeout=30s
2022/06/17 05:57:21 DEBUG : dir: Looking for writers
2022/06/17 05:57:21 DEBUG : file1: reading active writers
2022/06/17 05:57:21 DEBUG : : Looking for writers
2022/06/17 05:57:21 DEBUG : dir: reading active writers
2022/06/17 05:57:21 DEBUG : >WaitForWriters: 
--- PASS: TestFileMethods (69.78s)
=== RUN   TestFileSetModTime
=== RUN   TestFileSetModTime/cache=off,open=false,write=false
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 05:58:06 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 05:58:06 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:00:33 DEBUG : Can set mod time: true
2022/06/17 06:00:33 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2022/06/17 06:00:34 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:00:34 DEBUG : dir: Looking for writers
2022/06/17 06:00:34 DEBUG : file1: reading active writers
2022/06/17 06:00:34 DEBUG : : Looking for writers
2022/06/17 06:00:34 DEBUG : dir: reading active writers
2022/06/17 06:00:34 DEBUG : >WaitForWriters: 
=== RUN   TestFileSetModTime/cache=off,open=true,write=false
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6", Local "Local file system at /tmp/rclone1602337825", Modify Window "1ns"
2022/06/17 06:02:45 INFO  : Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: poll-interval is not supported by this remote
2022/06/17 06:02:45 NOTICE: Internet Archive item rclone-integration-test path rclone-test-busigut5taperuz2dozufeb6: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
panic: test timed out after 1h0m0s

goroutine 1832 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1788 +0x8e
created by time.goFunc
	/usr/local/go/src/time/sleep.go:180 +0x31

goroutine 1 [chan receive, 4 minutes]:
testing.(*T).Run(0xc0000e21a0, {0x1a43994, 0x46f653}, 0x1af5e00)
	/usr/local/go/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc00088ef00)
	/usr/local/go/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc0000e21a0, 0xc0009d7ca0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
testing.runTests(0xc0000b6f00, {0x2bdaac0, 0x4a, 0x4a}, {0xf4fe20, 0xc00016ade0, 0x2becac0})
	/usr/local/go/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc0000b6f00)
	/usr/local/go/src/testing/testing.go:1504 +0x51d
github.com/rclone/rclone/fstest.TestMain(0xc0000001a0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:70 +0x9e
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:37
main.main()
	_testmain.go:193 +0x166

goroutine 3 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000b6800)
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:276 +0xb9
created by go.opencensus.io/stats/view.init.0
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:34 +0x92

goroutine 1667 [chan receive]:
testing.(*T).Run(0xc00054ad00, {0xc000a040a0, 0xc00006ff30}, 0xc0009e19e0)
	/usr/local/go/src/testing/testing.go:1307 +0x375
github.com/rclone/rclone/vfs.TestFileSetModTime(0xc0008c0faf)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:159 +0x22d
testing.tRunner(0xc00054ad00, 0x1af5e00)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a

goroutine 28 [IO wait]:
internal/poll.runtime_pollWait(0x7f0a105fbfb0, 0x72)
	/usr/local/go/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc00018b300, 0xc0005e0000, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc00018b300, {0xc0005e0000, 0x10200, 0x10200})
	/usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc00018b300, {0xc0005e0000, 0xc000484a00, 0xc0005ed0b3})
	/usr/local/go/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc000354010, {0xc0005e0000, 0xc0005ed0b3, 0x19})
	/usr/local/go/src/net/net.go:183 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0001342d0, {0xc0005e0000, 0xd, 0x10000c0001ea7a0})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:104 +0x32
crypto/tls.(*atLeastReader).Read(0xc000a22438, {0xc0005e0000, 0x0, 0x40bb8d})
	/usr/local/go/src/crypto/tls/conn.go:777 +0x3d
bytes.(*Buffer).ReadFrom(0xc000491af8, {0x1e12b20, 0xc000a22438})
	/usr/local/go/src/bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc000491880, {0x7f0a10632298, 0xc0001342d0}, 0x315a)
	/usr/local/go/src/crypto/tls/conn.go:799 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc000491880, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:606 +0x112
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:574
crypto/tls.(*Conn).Read(0xc000491880, {0xc000a3b000, 0x1000, 0x6e6857})
	/usr/local/go/src/crypto/tls/conn.go:1277 +0x16f
bufio.(*Reader).Read(0xc000381f20, {0xc000322f18, 0x9, 0xc0001990b0})
	/usr/local/go/src/bufio/bufio.go:227 +0x1b4
io.ReadAtLeast({0x1e128e0, 0xc000381f20}, {0xc000322f18, 0x9, 0x9}, 0x9)
	/usr/local/go/src/io/io.go:328 +0x9a
io.ReadFull(...)
	/usr/local/go/src/io/io.go:347
net/http.http2readFrameHeader({0xc000322f18, 0x9, 0xc0009e86c0}, {0x1e128e0, 0xc000381f20})
	/usr/local/go/src/net/http/h2_bundle.go:1555 +0x6e
net/http.(*http2Framer).ReadFrame(0xc000322ee0)
	/usr/local/go/src/net/http/h2_bundle.go:1813 +0x95
net/http.(*http2clientConnReadLoop).run(0xc00006df98)
	/usr/local/go/src/net/http/h2_bundle.go:8583 +0x130
net/http.(*http2ClientConn).readLoop(0xc000198900)
	/usr/local/go/src/net/http/h2_bundle.go:8506 +0x6f
created by net/http.(*http2Transport).newClientConn
	/usr/local/go/src/net/http/h2_bundle.go:7317 +0xb85

goroutine 1402 [sleep]:
time.Sleep(0x2540be400)
	/usr/local/go/src/runtime/time.go:193 +0x12e
github.com/rclone/rclone/backend/internetarchive.(*Fs).waitFileUpload.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:885 +0x153
created by github.com/rclone/rclone/backend/internetarchive.(*Fs).waitFileUpload
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:879 +0x47b

goroutine 1844 [sleep]:
time.Sleep(0x2540be400)
	/usr/local/go/src/runtime/time.go:193 +0x12e
github.com/rclone/rclone/backend/internetarchive.(*Fs).waitFileUpload.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:885 +0x153
created by github.com/rclone/rclone/backend/internetarchive.(*Fs).waitFileUpload
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:879 +0x47b

goroutine 1820 [select]:
github.com/rclone/rclone/backend/internetarchive.(*Fs).waitFileUpload(0xc0000e7b80, {0x1e4d548, 0xc00013c000}, {0x1a32a9a, 0x9}, {0xc000a04180, 0x20}, 0xe)
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:943 +0x506
github.com/rclone/rclone/backend/internetarchive.(*Object).Update(0xc00026f6c0, {0x1e4d548, 0xc00013c000}, {0x1e12920, 0xc0006d2ea0}, {0x1e67530, 0xc00075ed20}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:721 +0x9c5
github.com/rclone/rclone/backend/internetarchive.(*Fs).Put(0xc0000e7b80, {0x1e4d548, 0xc00013c000}, {0x1e12920, 0xc0006d2ea0}, {0x1e67530, 0xc00075ed20}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:444 +0x1d6
github.com/rclone/rclone/fstest.(*Run).WriteObjectTo(0xc00026f650, {0x1e4d548, 0xc00013c000}, {0x1e7fb08, 0xc0000e7b80}, {0x1a32a9a, 0x9}, {0x1a3b993, 0xe}, {0x1dcd64ff, ...}, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:277 +0x432
github.com/rclone/rclone/fstest.(*Run).WriteObject(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:294
github.com/rclone/rclone/vfs.fileCreate(0x1f6ac13, 0xf)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:26 +0x128
github.com/rclone/rclone/vfs.testFileSetModTime(0xc00054b860, 0x0, 0x1, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:95 +0xea
github.com/rclone/rclone/vfs.TestFileSetModTime.func1(0xc0008befaf)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:160 +0x2f
testing.tRunner(0xc00054b860, 0xc0009e19e0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestIA:rclone-integration-test -verbose" - Finished ERROR in 1h0m1.30311319s (try 1/5): exit status 2: Failed []