"./vfs.test -test.v -test.timeout 1h0m0s -remote TestIA:rclone-integration-test -verbose" - Starting (try 2/5)
2022/06/17 06:03:48 DEBUG : Creating backend with remote "TestIA:rclone-integration-test/rclone-test-xehoxib3xasefar6guyujex8"
2022/06/17 06:03:48 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/06/17 06:03:49 DEBUG : Creating backend with remote "/tmp/rclone2778854663"
=== RUN   TestDirHandleMethods
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:03:49 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:03:49 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:04:45 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:04:45 DEBUG : dir: Looking for writers
2022/06/17 06:04:45 DEBUG : : Looking for writers
2022/06/17 06:04:45 DEBUG : dir: reading active writers
2022/06/17 06:04:45 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (80.45s)
=== RUN   TestDirHandleReaddir
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:05:09 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:05:09 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:07:16 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:07:16 DEBUG : dir/subdir: Looking for writers
2022/06/17 06:07:16 DEBUG : dir: Looking for writers
2022/06/17 06:07:16 DEBUG : file1: reading active writers
2022/06/17 06:07:16 DEBUG : file2: reading active writers
2022/06/17 06:07:16 DEBUG : subdir: reading active writers
2022/06/17 06:07:16 DEBUG : : Looking for writers
2022/06/17 06:07:16 DEBUG : dir: reading active writers
2022/06/17 06:07:16 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (207.60s)
=== RUN   TestDirHandleReaddirnames
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:08:37 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:08:37 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:09:55 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:09:55 DEBUG : dir: Looking for writers
2022/06/17 06:09:55 DEBUG : file1: reading active writers
2022/06/17 06:09:55 DEBUG : : Looking for writers
2022/06/17 06:09:55 DEBUG : dir: reading active writers
2022/06/17 06:09:55 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddirnames (112.62s)
=== RUN   TestDirMethods
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:10:29 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:10:29 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:11:47 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:11:47 DEBUG : dir: Looking for writers
2022/06/17 06:11:47 DEBUG : : Looking for writers
2022/06/17 06:11:47 DEBUG : dir: reading active writers
2022/06/17 06:11:47 DEBUG : >WaitForWriters: 
--- PASS: TestDirMethods (155.24s)
=== RUN   TestDirForgetAll
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:13:05 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:13:05 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:14:02 DEBUG : dir: forgetting directory cache
2022/06/17 06:14:02 DEBUG : : forgetting directory cache
2022/06/17 06:14:02 DEBUG : dir: forgetting directory cache
2022/06/17 06:14:02 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:14:02 DEBUG : : Looking for writers
2022/06/17 06:14:02 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetAll (156.37s)
=== RUN   TestDirForgetPath
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:15:41 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:15:41 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:16:38 DEBUG : : ForgetPath: relativePath="dir/notfound", type=1
2022/06/17 06:16:38 DEBUG : dir: invalidating directory cache
2022/06/17 06:16:38 DEBUG : : >ForgetPath: 
2022/06/17 06:16:38 DEBUG : : ForgetPath: relativePath="dir", type=0
2022/06/17 06:16:38 DEBUG : : invalidating directory cache
2022/06/17 06:16:38 DEBUG : dir: forgetting directory cache
2022/06/17 06:16:38 DEBUG : : >ForgetPath: 
2022/06/17 06:16:38 DEBUG : : ForgetPath: relativePath="not/in/cache", type=0
2022/06/17 06:16:38 DEBUG : : >ForgetPath: 
2022/06/17 06:16:38 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:16:38 DEBUG : dir: Looking for writers
2022/06/17 06:16:38 DEBUG : : Looking for writers
2022/06/17 06:16:38 DEBUG : dir: reading active writers
2022/06/17 06:16:38 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetPath (113.21s)
=== RUN   TestDirWalk
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:17:34 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:17:34 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:20:12 DEBUG : : forgetting directory cache
2022/06/17 06:20:12 DEBUG : dir: forgetting directory cache
2022/06/17 06:20:13 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:20:13 DEBUG : dir: Looking for writers
2022/06/17 06:20:13 DEBUG : fil/a/b: Looking for writers
2022/06/17 06:20:13 DEBUG : fil/a: Looking for writers
2022/06/17 06:20:13 DEBUG : b: reading active writers
2022/06/17 06:20:13 DEBUG : fil: Looking for writers
2022/06/17 06:20:13 DEBUG : a: reading active writers
2022/06/17 06:20:13 DEBUG : : Looking for writers
2022/06/17 06:20:13 DEBUG : dir: reading active writers
2022/06/17 06:20:13 DEBUG : fil: reading active writers
2022/06/17 06:20:13 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (294.35s)
=== RUN   TestDirSetModTime
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:22:29 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:22:29 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:23:40 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:23:40 DEBUG : dir: Looking for writers
2022/06/17 06:23:40 DEBUG : : Looking for writers
2022/06/17 06:23:40 DEBUG : dir: reading active writers
2022/06/17 06:23:40 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (105.71s)
=== RUN   TestDirStat
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:24:14 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:24:14 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:24:50 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:24:50 DEBUG : dir: Looking for writers
2022/06/17 06:24:50 DEBUG : file1: reading active writers
2022/06/17 06:24:50 DEBUG : : Looking for writers
2022/06/17 06:24:50 DEBUG : dir: reading active writers
2022/06/17 06:24:50 DEBUG : >WaitForWriters: 
--- PASS: TestDirStat (70.40s)
=== RUN   TestDirReadDirAll
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:25:25 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:25:25 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
=== RUN   TestDirReadDirAll/Virtual
2022/06/17 06:27:55 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2022/06/17 06:27:55 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2022/06/17 06:27:55 DEBUG : dir: Added virtual directory entry vDel: "file2"
2022/06/17 06:27:55 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2022/06/17 06:31:04 DEBUG : Waiting for deletions to finish
2022/06/17 06:31:49 INFO  : dir/subdir/file3: Deleted
2022/06/17 06:31:49 INFO  : dir/subdir: Removing directory
2022/06/17 06:31:49 DEBUG : dir: invalidating directory cache
2022/06/17 06:31:50 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2022/06/17 06:31:50 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2022/06/17 06:31:50 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2022/06/17 06:31:50 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2022/06/17 06:31:50 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2022/06/17 06:31:50 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2022/06/17 06:31:50 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 06:31:50 DEBUG : dir: invalidating directory cache
2022/06/17 06:31:53 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2022/06/17 06:31:53 DEBUG : : forgetting directory cache
2022/06/17 06:31:53 DEBUG : dir: forgetting directory cache
2022/06/17 06:31:53 DEBUG : dir/virtualDir: forgetting directory cache
2022/06/17 06:31:53 DEBUG : dir/virtualDir2: forgetting directory cache
2022/06/17 06:31:53 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:31:53 DEBUG : dir/virtualDir2: Looking for writers
2022/06/17 06:31:53 DEBUG : dir/virtualDir: Looking for writers
2022/06/17 06:31:53 DEBUG : dir: Looking for writers
2022/06/17 06:31:53 DEBUG : file1: reading active writers
2022/06/17 06:31:53 DEBUG : virtualFile2: reading active writers
2022/06/17 06:31:53 DEBUG : virtualDir2: reading active writers
2022/06/17 06:31:53 DEBUG : virtualFile: reading active writers
2022/06/17 06:31:53 DEBUG : virtualDir: reading active writers
2022/06/17 06:31:53 DEBUG : : Looking for writers
2022/06/17 06:31:53 DEBUG : dir: reading active writers
2022/06/17 06:31:53 DEBUG : >WaitForWriters: 
--- PASS: TestDirReadDirAll (628.39s)
    --- PASS: TestDirReadDirAll/Virtual (237.86s)
=== RUN   TestDirOpen
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:35:53 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:35:53 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:37:00 ERROR : dir/: Can only open directories read only
2022/06/17 06:37:00 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:37:00 DEBUG : dir: Looking for writers
2022/06/17 06:37:00 DEBUG : : Looking for writers
2022/06/17 06:37:00 DEBUG : dir: reading active writers
2022/06/17 06:37:00 DEBUG : >WaitForWriters: 
--- PASS: TestDirOpen (90.93s)
=== RUN   TestDirCreate
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:37:24 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:37:24 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:38:54 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2022/06/17 06:38:54 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/06/17 06:38:54 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2022/06/17 06:38:54 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/06/17 06:38:54 DEBUG : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: File to upload is small (5 bytes), uploading instead of streaming
2022/06/17 06:40:22 DEBUG : dir/potato: md5 = 5d41402abc4b2a76b9719d911017c592 OK
2022/06/17 06:40:22 INFO  : dir/potato: Copied (new)
2022/06/17 06:40:22 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/06/17 06:40:22 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:40:22 DEBUG : dir: Looking for writers
2022/06/17 06:40:22 DEBUG : file1: reading active writers
2022/06/17 06:40:22 DEBUG : potato: reading active writers
2022/06/17 06:40:22 DEBUG : : Looking for writers
2022/06/17 06:40:22 DEBUG : dir: reading active writers
2022/06/17 06:40:22 DEBUG : >WaitForWriters: 
--- PASS: TestDirCreate (248.47s)
=== RUN   TestDirMkdir
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:41:32 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:41:32 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:42:40 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
    fstest.go:251: Filtering empty directory "dir/sub"
2022/06/17 06:42:41 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:42:41 DEBUG : dir/sub: Looking for writers
2022/06/17 06:42:41 DEBUG : dir: Looking for writers
2022/06/17 06:42:41 DEBUG : file1: reading active writers
2022/06/17 06:42:41 DEBUG : sub: reading active writers
2022/06/17 06:42:41 DEBUG : : Looking for writers
2022/06/17 06:42:41 DEBUG : dir: reading active writers
2022/06/17 06:42:41 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdir (103.06s)
=== RUN   TestDirMkdirSub
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:43:15 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:43:15 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:44:02 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2022/06/17 06:44:03 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 06:44:04 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:44:04 DEBUG : dir/sub/subsub: Looking for writers
2022/06/17 06:44:04 DEBUG : dir/sub: Looking for writers
2022/06/17 06:44:04 DEBUG : subsub: reading active writers
2022/06/17 06:44:04 DEBUG : dir: Looking for writers
2022/06/17 06:44:04 DEBUG : file1: reading active writers
2022/06/17 06:44:04 DEBUG : sub: reading active writers
2022/06/17 06:44:04 DEBUG : : Looking for writers
2022/06/17 06:44:04 DEBUG : dir: reading active writers
2022/06/17 06:44:04 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdirSub (93.30s)
=== RUN   TestDirRemove
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:44:49 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:44:49 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:45:50 ERROR : dir/: Dir.Remove not empty
2022/06/17 06:45:50 DEBUG : dir/file1: Remove: 
2022/06/17 06:45:50 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 06:46:03 DEBUG : dir/file1: >Remove: err=<nil>
2022/06/17 06:46:03 DEBUG : : Added virtual directory entry vDel: "dir"
2022/06/17 06:46:03 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:46:03 DEBUG : : Looking for writers
2022/06/17 06:46:03 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemove (74.59s)
=== RUN   TestDirRemoveAll
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:46:03 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:46:03 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:47:10 DEBUG : dir/file1: Remove: 
2022/06/17 06:47:10 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 06:47:44 DEBUG : dir/file1: >Remove: err=<nil>
2022/06/17 06:47:44 DEBUG : : Added virtual directory entry vDel: "dir"
2022/06/17 06:47:44 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:47:44 DEBUG : : Looking for writers
2022/06/17 06:47:44 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveAll (101.14s)
=== RUN   TestDirRemoveName
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:47:44 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:47:44 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:48:41 DEBUG : dir/file1: Remove: 
2022/06/17 06:48:41 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/06/17 06:49:25 DEBUG : dir/file1: >Remove: err=<nil>
    fstest.go:251: Filtering empty directory "dir"
2022/06/17 06:49:25 DEBUG : WaitForWriters: timeout=30s
2022/06/17 06:49:25 DEBUG : dir: Looking for writers
2022/06/17 06:49:25 DEBUG : : Looking for writers
2022/06/17 06:49:25 DEBUG : dir: reading active writers
2022/06/17 06:49:25 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveName (101.48s)
=== RUN   TestDirRename
    run.go:181: Remote "Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8", Local "Local file system at /tmp/rclone2778854663", Modify Window "1ns"
2022/06/17 06:49:26 INFO  : Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: poll-interval is not supported by this remote
2022/06/17 06:49:26 NOTICE: Internet Archive item rclone-integration-test path rclone-test-xehoxib3xasefar6guyujex8: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/06/17 06:51:31 ERROR : dir/not found: Dir.Rename error: file does not exist
2022/06/17 06:52:18 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2022/06/17 06:52:18 INFO  : dir/file1: Copied (server-side copy) to: dir2/file1
2022/06/17 06:52:28 DEBUG : dir/file3: md5 = ea32138586c9d4e9533ef6cf95e9ec4b OK
2022/06/17 06:52:28 INFO  : dir/file3: Copied (server-side copy) to: dir2/file3
2022/06/17 06:53:23 INFO  : dir/file3: Deleted
2022/06/17 06:53:23 INFO  : dir/file1: Deleted
2022/06/17 06:53:23 DEBUG : dir: Updating dir with dir2 0xc000445140
2022/06/17 06:53:23 DEBUG : dir: forgetting directory cache
2022/06/17 06:53:23 DEBUG : : Added virtual directory entry vDel: "dir"
2022/06/17 06:53:23 DEBUG : : Added virtual directory entry vAddDir: "dir2"
2022/06/17 06:55:13 DEBUG : dir2/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2022/06/17 06:55:13 INFO  : dir2/file1: Copied (server-side copy) to: file2
2022/06/17 06:55:58 INFO  : dir2/file1: Deleted
2022/06/17 06:55:58 DEBUG : file2: Updating file with file2 0xc000578000
2022/06/17 06:55:58 DEBUG : dir2: Added virtual directory entry vDel: "file1"
2022/06/17 06:55:58 DEBUG : : Added virtual directory entry vAddFile: "file2"
2022/06/17 06:55:58 DEBUG : : Re-reading directory (5m35.199589384s old)
2022/06/17 06:55:58 DEBUG : : Removed virtual directory entry vDel: "dir"
2022/06/17 06:55:58 DEBUG : : Removed virtual directory entry vAddFile: "file2"
2022/06/17 06:55:58 DEBUG : : Removed virtual directory entry vAddDir: "dir2"
panic: test timed out after 1h0m0s

goroutine 1608 [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, 14 minutes]:
testing.(*T).Run(0xc000102ea0, {0x1a39571, 0x46f653}, 0x1af5d88)
	/usr/local/go/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc000b10c30)
	/usr/local/go/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc000102ea0, 0xc00091fca0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
testing.runTests(0xc000146300, {0x2bdaac0, 0x4a, 0x4a}, {0xf4fe20, 0xc0002c1620, 0x2becac0})
	/usr/local/go/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc000146300)
	/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 6 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000b8800)
	/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 39 [IO wait]:
internal/poll.runtime_pollWait(0x7fbb54e036b0, 0x72)
	/usr/local/go/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc0000b8d00, 0xc000a30000, 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(0xc0000b8d00, {0xc000a30000, 0xf108, 0xf108})
	/usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0000b8d00, {0xc000a30000, 0xc00034d540, 0xc000a3d1fe})
	/usr/local/go/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc00012e008, {0xc000a30000, 0xc000a3d1fe, 0x19})
	/usr/local/go/src/net/net.go:183 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc00000e0c0, {0xc000a30000, 0xd, 0x10000c0009fcf60})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:104 +0x32
crypto/tls.(*atLeastReader).Read(0xc0005bc240, {0xc000a30000, 0x0, 0x40bb8d})
	/usr/local/go/src/crypto/tls/conn.go:777 +0x3d
bytes.(*Buffer).ReadFrom(0xc00009e278, {0x1e12b20, 0xc0005bc240})
	/usr/local/go/src/bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc00009e000, {0x7fbb545ae5e8, 0xc00000e0c0}, 0x1f17)
	/usr/local/go/src/crypto/tls/conn.go:799 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc00009e000, 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(0xc00009e000, {0xc000a15000, 0x1000, 0x6e6857})
	/usr/local/go/src/crypto/tls/conn.go:1277 +0x16f
bufio.(*Reader).Read(0xc000a100c0, {0xc000a16038, 0x9, 0xc000728330})
	/usr/local/go/src/bufio/bufio.go:227 +0x1b4
io.ReadAtLeast({0x1e128e0, 0xc000a100c0}, {0xc000a16038, 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({0xc000a16038, 0x9, 0xc0007b46f0}, {0x1e128e0, 0xc000a100c0})
	/usr/local/go/src/net/http/h2_bundle.go:1555 +0x6e
net/http.(*http2Framer).ReadFrame(0xc000a16000)
	/usr/local/go/src/net/http/h2_bundle.go:1813 +0x95
net/http.(*http2clientConnReadLoop).run(0xc000888f98)
	/usr/local/go/src/net/http/h2_bundle.go:8583 +0x130
net/http.(*http2ClientConn).readLoop(0xc00002e900)
	/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 1317 [select, 7 minutes]:
github.com/rclone/rclone/backend/internetarchive.(*Fs).waitFileUpload(0xc00002dad0, {0x1e4d548, 0xc0001b2008}, {0xc0007b635d, 0xa}, {0xc000a0f4c0, 0x20}, 0xe)
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:943 +0x506
github.com/rclone/rclone/backend/internetarchive.(*Fs).Copy(0xc00002dad0, {0x1e4d548, 0xc0001b2008}, {0x1e7fb78, 0xc0001235e0}, {0xc0007f5330, 0xa})
	/home/rclone/go/src/github.com/rclone/rclone/backend/internetarchive/internetarchive.go:522 +0xad4
github.com/rclone/rclone/fs/operations.Copy({0x1e4d548, 0xc0001b2008}, {0x1e7fb08, 0xc00002dad0}, {0x1e7fb78, 0xc0006b6930}, {0xc0007f5330, 0xc0000399b0}, {0x1e7fb78, 0xc0001235e0})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:418 +0x657
github.com/rclone/rclone/fs/operations.Move({0x1e4d548, 0xc0001b2008}, {0x1e7fb08, 0xc00002dad0}, {0x1e7fb78, 0xc0006b6930}, {0xc0007f5330, 0xa}, {0x1e7fb78, 0xc0001235e0})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:639 +0x773
github.com/rclone/rclone/vfs.(*File).rename.func1({0x1e4d548, 0xc0001b2008})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file.go:201 +0x26a
github.com/rclone/rclone/vfs.(*File).rename(0xc000578000, {0x1e4d548, 0xc0001b2008}, 0xc000445140, {0x1a2c58d, 0x5})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file.go:254 +0x48e
github.com/rclone/rclone/vfs.(*Dir).Rename(0xc000445080, {0x1a2c588, 0x5}, {0x1a2c58d, 0x5}, 0xc000445140)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir.go:1000 +0x4e7
github.com/rclone/rclone/vfs.TestDirRename(0xc0005ab6c0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:565 +0xa90
testing.tRunner(0xc0005ab6c0, 0x1af5d88)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a

goroutine 1529 [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 1523 [select]:
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xc0000e9400)
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:212 +0x10a
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:110 +0x44f
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestIA:rclone-integration-test -verbose" - Finished ERROR in 1h0m1.064427149s (try 2/5): exit status 2: Failed []