"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPcloud: -verbose" - Starting (try 1/5)
2021/05/09 05:18:07 DEBUG : Creating backend with remote "TestPcloud:rclone-test-dovimeh2hugenem6nubequh2"
2021/05/09 05:18:07 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/05/09 05:18:07 DEBUG : Creating backend with remote "/tmp/rclone042987924"
=== RUN   TestDirHandleMethods
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:07 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:07 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:08 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:08 DEBUG : dir: Looking for writers
2021/05/09 05:18:08 DEBUG : : Looking for writers
2021/05/09 05:18:08 DEBUG : dir: reading active writers
2021/05/09 05:18:08 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (1.26s)
=== RUN   TestDirHandleReaddir
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:08 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:08 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:10 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:10 DEBUG : dir/subdir: Looking for writers
2021/05/09 05:18:10 DEBUG : dir: Looking for writers
2021/05/09 05:18:10 DEBUG : file2: reading active writers
2021/05/09 05:18:10 DEBUG : subdir: reading active writers
2021/05/09 05:18:10 DEBUG : file1: reading active writers
2021/05/09 05:18:10 DEBUG : : Looking for writers
2021/05/09 05:18:10 DEBUG : dir: reading active writers
2021/05/09 05:18:10 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (2.16s)
=== RUN   TestDirHandleReaddirnames
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:11 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:11 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:11 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:11 DEBUG : dir: Looking for writers
2021/05/09 05:18:11 DEBUG : file1: reading active writers
2021/05/09 05:18:11 DEBUG : : Looking for writers
2021/05/09 05:18:11 DEBUG : dir: reading active writers
2021/05/09 05:18:11 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddirnames (1.14s)
=== RUN   TestDirMethods
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:12 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:12 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:12 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:12 DEBUG : dir: Looking for writers
2021/05/09 05:18:12 DEBUG : : Looking for writers
2021/05/09 05:18:12 DEBUG : dir: reading active writers
2021/05/09 05:18:12 DEBUG : >WaitForWriters: 
--- PASS: TestDirMethods (1.06s)
=== RUN   TestDirForgetAll
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:13 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:13 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:13 DEBUG : dir: forgetting directory cache
2021/05/09 05:18:13 DEBUG : : forgetting directory cache
2021/05/09 05:18:13 DEBUG : dir: forgetting directory cache
2021/05/09 05:18:13 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:13 DEBUG : : Looking for writers
2021/05/09 05:18:13 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetAll (1.15s)
=== RUN   TestDirForgetPath
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:14 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:14 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:15 DEBUG : : ForgetPath: relativePath="dir/notfound", type=3
2021/05/09 05:18:15 DEBUG : dir: invalidating directory cache
2021/05/09 05:18:15 DEBUG : : >ForgetPath: 
2021/05/09 05:18:15 DEBUG : : ForgetPath: relativePath="dir", type=2
2021/05/09 05:18:15 DEBUG : : invalidating directory cache
2021/05/09 05:18:15 DEBUG : dir: forgetting directory cache
2021/05/09 05:18:15 DEBUG : : >ForgetPath: 
2021/05/09 05:18:15 DEBUG : : ForgetPath: relativePath="not/in/cache", type=2
2021/05/09 05:18:15 DEBUG : : >ForgetPath: 
2021/05/09 05:18:15 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:15 DEBUG : dir: Looking for writers
2021/05/09 05:18:15 DEBUG : : Looking for writers
2021/05/09 05:18:15 DEBUG : dir: reading active writers
2021/05/09 05:18:15 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetPath (1.16s)
=== RUN   TestDirWalk
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:15 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:15 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:17 DEBUG : : forgetting directory cache
2021/05/09 05:18:17 DEBUG : dir: forgetting directory cache
2021/05/09 05:18:17 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:17 DEBUG : dir: Looking for writers
2021/05/09 05:18:17 DEBUG : fil/a/b: Looking for writers
2021/05/09 05:18:17 DEBUG : fil/a: Looking for writers
2021/05/09 05:18:17 DEBUG : b: reading active writers
2021/05/09 05:18:17 DEBUG : fil: Looking for writers
2021/05/09 05:18:17 DEBUG : a: reading active writers
2021/05/09 05:18:17 DEBUG : : Looking for writers
2021/05/09 05:18:17 DEBUG : fil: reading active writers
2021/05/09 05:18:17 DEBUG : dir: reading active writers
2021/05/09 05:18:17 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (2.98s)
=== RUN   TestDirSetModTime
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:18 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:18 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:19 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:19 DEBUG : dir: Looking for writers
2021/05/09 05:18:19 DEBUG : : Looking for writers
2021/05/09 05:18:19 DEBUG : dir: reading active writers
2021/05/09 05:18:19 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (1.08s)
=== RUN   TestDirStat
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:19 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:19 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:18:20 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:20 DEBUG : dir: Looking for writers
2021/05/09 05:18:20 DEBUG : file1: reading active writers
2021/05/09 05:18:20 DEBUG : : Looking for writers
2021/05/09 05:18:20 DEBUG : dir: reading active writers
2021/05/09 05:18:20 DEBUG : >WaitForWriters: 
--- PASS: TestDirStat (1.20s)
=== RUN   TestDirReadDirAll
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:20 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:20 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
=== RUN   TestDirReadDirAll/Virtual
2021/05/09 05:18:22 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2021/05/09 05:18:22 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2021/05/09 05:18:22 DEBUG : dir: Added virtual directory entry vDel: "file2"
2021/05/09 05:18:22 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2021/05/09 05:18:22 DEBUG : dir: invalidating directory cache
2021/05/09 05:18:23 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2021/05/09 05:18:23 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2021/05/09 05:18:23 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2021/05/09 05:18:23 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
    dir_test.go:252: 
        	Error Trace:	dir_test.go:252
        	            				dir_test.go:303
        	Error:      	Not equal: 
        	            	expected: []string{"file1,14,false", "virtualDir,0,true", "virtualFile,20,false"}
        	            	actual  : []string{"file1,14,false", "subdir,0,true", "virtualDir,0,true", "virtualFile,20,false"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,3 +1,4 @@
        	            	-([]string) (len=3) {
        	            	+([]string) (len=4) {
        	            	  (string) (len=14) "file1,14,false",
        	            	+ (string) (len=13) "subdir,0,true",
        	            	  (string) (len=17) "virtualDir,0,true",
        	Test:       	TestDirReadDirAll/Virtual
2021/05/09 05:18:23 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2021/05/09 05:18:23 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2021/05/09 05:18:23 DEBUG : dir: Added virtual directory entry vDel: "file1"
    dir_test.go:252: 
        	Error Trace:	dir_test.go:252
        	            				dir_test.go:316
        	Error:      	Not equal: 
        	            	expected: []string{"virtualDir,0,true", "virtualDir2,0,true", "virtualFile,20,false", "virtualFile2,100,false"}
        	            	actual  : []string{"subdir,0,true", "virtualDir,0,true", "virtualDir2,0,true", "virtualFile,20,false", "virtualFile2,100,false"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,2 +1,3 @@
        	            	-([]string) (len=4) {
        	            	+([]string) (len=5) {
        	            	+ (string) (len=13) "subdir,0,true",
        	            	  (string) (len=17) "virtualDir,0,true",
        	Test:       	TestDirReadDirAll/Virtual
2021/05/09 05:18:23 DEBUG : dir: invalidating directory cache
2021/05/09 05:18:23 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2"
2021/05/09 05:18:23 DEBUG : dir: Removed virtual directory entry vDel: "file1"
    dir_test.go:252: 
        	Error Trace:	dir_test.go:252
        	            				dir_test.go:327
        	Error:      	Not equal: 
        	            	expected: []string{"file1,14,false", "virtualDir,0,true", "virtualFile,20,false", "virtualFile2,100,false"}
        	            	actual  : []string{"file1,14,false", "subdir,0,true", "virtualDir,0,true", "virtualFile,20,false", "virtualFile2,100,false"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,3 +1,4 @@
        	            	-([]string) (len=4) {
        	            	+([]string) (len=5) {
        	            	  (string) (len=14) "file1,14,false",
        	            	+ (string) (len=13) "subdir,0,true",
        	            	  (string) (len=17) "virtualDir,0,true",
        	Test:       	TestDirReadDirAll/Virtual
2021/05/09 05:18:23 DEBUG : : forgetting directory cache
2021/05/09 05:18:23 DEBUG : dir: forgetting directory cache
2021/05/09 05:18:23 DEBUG : dir/virtualDir: forgetting directory cache
2021/05/09 05:18:23 DEBUG : dir/subdir: forgetting directory cache
2021/05/09 05:18:23 DEBUG : WaitForWriters: timeout=10s
2021/05/09 05:18:23 DEBUG : dir/virtualDir: Looking for writers
2021/05/09 05:18:23 DEBUG : dir: Looking for writers
2021/05/09 05:18:23 DEBUG : file1: reading active writers
2021/05/09 05:18:23 DEBUG : virtualFile2: reading active writers
2021/05/09 05:18:23 DEBUG : virtualFile: reading active writers
2021/05/09 05:18:23 DEBUG : virtualDir: reading active writers
2021/05/09 05:18:23 DEBUG : : Looking for writers
2021/05/09 05:18:23 DEBUG : dir: reading active writers
2021/05/09 05:18:23 DEBUG : >WaitForWriters: 
2021/05/09 05:18:24 ERROR : dir/virtualDir: error listing: couldn't list files: pcloud error: Directory does not exist. (2005)
=== CONT  TestDirReadDirAll
    fstest.go:283: Error listing: couldn't list files: pcloud error: Directory does not exist. (2005)
--- FAIL: TestDirReadDirAll (3.39s)
    --- FAIL: TestDirReadDirAll/Virtual (0.95s)
=== RUN   TestDirOpen
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 05:18:24 INFO  : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': poll-interval is not supported by this remote
2021/05/09 05:18:24 NOTICE: pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/05/09 05:23:24 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:23:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2021/05/09 05:23:24 DEBUG : pacer: Reducing sleep to 15ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 1/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:28:26 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": read tcp 167.172.51.213:38656->45.131.244.12:443: i/o timeout)
2021/05/09 05:28:26 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2021/05/09 05:28:26 DEBUG : pacer: Reducing sleep to 22.5ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 2/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": read tcp 167.172.51.213:38656->45.131.244.12:443: i/o timeout)
2021/05/09 05:33:28 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:33:28 DEBUG : pacer: Rate limited, increasing sleep to 45ms
2021/05/09 05:33:28 DEBUG : pacer: Reducing sleep to 33.75ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 3/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:38:30 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:38:30 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
2021/05/09 05:38:30 DEBUG : pacer: Reducing sleep to 50.625ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 4/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:43:32 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:43:32 DEBUG : pacer: Rate limited, increasing sleep to 101.25ms
2021/05/09 05:43:32 DEBUG : pacer: Reducing sleep to 75.9375ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 5/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:48:35 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:48:35 DEBUG : pacer: Rate limited, increasing sleep to 151.875ms
2021/05/09 05:48:35 DEBUG : pacer: Reducing sleep to 113.90625ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 6/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:53:37 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": read tcp 167.172.51.213:48968->45.131.244.12:443: i/o timeout)
2021/05/09 05:53:37 DEBUG : pacer: Rate limited, increasing sleep to 227.8125ms
2021/05/09 05:53:37 DEBUG : pacer: Reducing sleep to 170.859375ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 7/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": read tcp 167.172.51.213:48968->45.131.244.12:443: i/o timeout)
2021/05/09 05:58:39 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 05:58:39 DEBUG : pacer: Rate limited, increasing sleep to 341.71875ms
2021/05/09 05:58:39 DEBUG : pacer: Reducing sleep to 256.289062ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 8/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 06:03:41 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 06:03:41 DEBUG : pacer: Rate limited, increasing sleep to 512.578124ms
2021/05/09 06:03:41 DEBUG : pacer: Reducing sleep to 384.433593ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 9/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 06:08:43 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers)
2021/05/09 06:08:43 DEBUG : pacer: Rate limited, increasing sleep to 768.867186ms
2021/05/09 06:08:43 DEBUG : pacer: Reducing sleep to 576.650389ms
    run.go:282: Failed to put "dir/file1" to "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'": Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": net/http: timeout awaiting response headers
--- FAIL: TestDirOpen (3019.53s)
=== RUN   TestDirCreate
    run.go:176: Remote "pcloud root 'rclone-test-dovimeh2hugenem6nubequh2'", Local "Local file system at /tmp/rclone042987924", Modify Window "1s"
2021/05/09 06:08:43 DEBUG : pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': Re-using VFS from active cache
2021/05/09 06:13:44 DEBUG : pacer: low level retry 1/1 (error Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": read tcp 167.172.51.213:40092->45.131.244.12:443: i/o timeout)
2021/05/09 06:13:44 DEBUG : pacer: Rate limited, increasing sleep to 1.153300778s
2021/05/09 06:13:44 DEBUG : pacer: Reducing sleep to 864.975583ms
    run.go:278: Retry Put of "dir/file1" to pcloud root 'rclone-test-dovimeh2hugenem6nubequh2': 1/10 (Put "https://eapi.pcloud.com/uploadfile?filename=file1&folderid=736707491&mtime=981173106&nopartial=1": read tcp 167.172.51.213:40092->45.131.244.12:443: i/o timeout)
panic: test timed out after 1h0m0s

goroutine 2000 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1618 +0xe5
created by time.goFunc
	/usr/local/go/src/time/sleep.go:167 +0x45

goroutine 1 [chan receive, 10 minutes]:
testing.(*T).Run(0xc000591500, 0x1cc3c59, 0xd, 0x1d6bd20, 0x49c300)
	/usr/local/go/src/testing/testing.go:1169 +0x2da
testing.runTests.func1(0xc0004f7e00)
	/usr/local/go/src/testing/testing.go:1439 +0x78
testing.tRunner(0xc0004f7e00, 0xc000b07d48)
	/usr/local/go/src/testing/testing.go:1123 +0xef
testing.runTests(0xc0007b18c0, 0x2b33cc0, 0x49, 0x49, 0xc01dfd87e3f65557, 0x3464d7e9162, 0x2b43f60, 0xc00079edc0)
	/usr/local/go/src/testing/testing.go:1437 +0x2fe
testing.(*M).Run(0xc00046ae00, 0x0)
	/usr/local/go/src/testing/testing.go:1345 +0x1eb
github.com/rclone/rclone/fstest.TestMain(0xc00046ae00)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:68 +0x9f
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:37
main.main()
	_testmain.go:191 +0x165

goroutine 22 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc00017d780)
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:276 +0x105
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 +0x68

goroutine 29 [chan receive, 60 minutes]:
github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0003dbb00)
	/home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:39 +0x59
created by github.com/rclone/rclone/lib/oauthutil.NewRenew
	/home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:28 +0x85

goroutine 2007 [select, 5 minutes]:
net/http.(*persistConn).writeLoop(0xc0008b8240)
	/usr/local/go/src/net/http/transport.go:2340 +0x11c
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1709 +0xcdc

goroutine 2006 [IO wait, 5 minutes]:
internal/poll.runtime_pollWait(0x7f33cad3e6f8, 0x72, 0x1f9b2c0)
	/usr/local/go/src/runtime/netpoll.go:220 +0x55
internal/poll.(*pollDesc).wait(0xc00017cb98, 0x72, 0x1f9b200, 0x2a9dbb8, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00017cb80, 0xc00048c600, 0x107b, 0x107b, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:159 +0x1a5
net.(*netFD).Read(0xc00017cb80, 0xc00048c600, 0x107b, 0x107b, 0xc00017cb80, 0xc0000e3b00, 0x205)
	/usr/local/go/src/net/fd_posix.go:55 +0x4f
net.(*conn).Read(0xc000120068, 0xc00048c600, 0x107b, 0x107b, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:182 +0x8e
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000130c60, 0xc00048c600, 0x107b, 0x107b, 0xc000130c60, 0xc0000e3b00, 0x7f33f39c9cb8)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:98 +0x55
crypto/tls.(*atLeastReader).Read(0xc0007353a0, 0xc00048c600, 0x107b, 0x107b, 0xc000130cc0, 0xc0000e3b00, 0xc0000b8668)
	/usr/local/go/src/crypto/tls/conn.go:779 +0x62
bytes.(*Buffer).ReadFrom(0xc000129b00, 0x1f93c40, 0xc0007353a0, 0x40d3c5, 0x19fa720, 0x1b629e0)
	/usr/local/go/src/bytes/buffer.go:204 +0xb1
crypto/tls.(*Conn).readFromUntil(0xc000129880, 0x7f33ca22d218, 0xc000130c60, 0x5, 0xc000130c60, 0x7f33ca22d218)
	/usr/local/go/src/crypto/tls/conn.go:801 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc000129880, 0x0, 0x0, 0x6c7b0d)
	/usr/local/go/src/crypto/tls/conn.go:608 +0x115
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:576
crypto/tls.(*Conn).Read(0xc000129880, 0xc00095d000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:1252 +0x15f
net/http.(*persistConn).Read(0xc0008b8240, 0xc00095d000, 0x1000, 0x1000, 0x407490, 0x60, 0x0)
	/usr/local/go/src/net/http/transport.go:1887 +0x77
bufio.(*Reader).fill(0xc0005ab620)
	/usr/local/go/src/bufio/bufio.go:101 +0x105
bufio.(*Reader).Peek(0xc0005ab620, 0x1, 0xc00004d980, 0x1cb5bf2, 0x3, 0xc00044b420, 0xf)
	/usr/local/go/src/bufio/bufio.go:139 +0x4f
net/http.(*persistConn).readLoop(0xc0008b8240)
	/usr/local/go/src/net/http/transport.go:2040 +0x1a8
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1708 +0xcb7

goroutine 1980 [select, 5 minutes]:
net/http.(*persistConn).roundTrip(0xc0008b8240, 0xc0003ea880, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/transport.go:2565 +0x779
net/http.(*Transport).roundTrip(0xc0001ed680, 0xc0004ee100, 0x1cbed41, 0xa, 0xc0000c6638)
	/usr/local/go/src/net/http/transport.go:582 +0xa65
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:17
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc0004c60c0, 0xc0004ee100, 0x0, 0x0, 0x160)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:271 +0x2f3
golang.org/x/oauth2.(*Transport).RoundTrip(0xc0001311c0, 0xc0004ee000, 0x0, 0x0, 0x0)
	/home/rclone/go/pkg/mod/golang.org/x/oauth2@v0.0.0-20210413134643-5e61552d6c78/transport.go:55 +0x159
net/http.send(0xc0004ee000, 0x1f95de0, 0xc0001311c0, 0x0, 0x0, 0x0, 0xc00055a058, 0x203000, 0x1, 0x0)
	/usr/local/go/src/net/http/client.go:252 +0x453
net/http.(*Client).send(0xc0003dba70, 0xc0004ee000, 0x0, 0x0, 0x0, 0xc00055a058, 0x0, 0x1, 0x20)
	/usr/local/go/src/net/http/client.go:176 +0xff
net/http.(*Client).do(0xc0003dba70, 0xc0004ee000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/client.go:718 +0x45f
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:586
github.com/rclone/rclone/lib/rest.(*Client).Call(0xc000091d60, 0x1fc9360, 0xc00011c010, 0xc0008b8120, 0x0, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:279 +0x886
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc000091d60, 0x1fc9360, 0xc00011c010, 0xc0008b8120, 0x0, 0x0, 0x19a04e0, 0xc0008d7080, 0x1d69a90, 0x1d6bcb8, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:476 +0x230
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:419
github.com/rclone/rclone/backend/pcloud.(*Object).Update.func1(0x100000000000160, 0x7f33f39c9548, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/backend/pcloud/pcloud.go:1155 +0xd5
github.com/rclone/rclone/fs.pacerInvoker(0x1, 0x1, 0xc0003ea780, 0x800000000000009, 0xc0005217a8, 0x410018)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1579 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00007fa40, 0xc0003ea780, 0x1, 0x5, 0xc0000c6230)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x90
github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:225
github.com/rclone/rclone/backend/pcloud.(*Object).Update(0xc00017c980, 0x1fc9360, 0xc00011c010, 0x1f93a60, 0xc000594120, 0x1fd91e0, 0xc000234320, 0x0, 0x0, 0x0, ...)
	/home/rclone/go/src/github.com/rclone/rclone/backend/pcloud/pcloud.go:1154 +0x8e6
github.com/rclone/rclone/backend/pcloud.(*Fs).Put(0xc000210a80, 0x1fc9360, 0xc00011c010, 0x1f93a60, 0xc000594120, 0x1fd91e0, 0xc000234320, 0x0, 0x0, 0x0, ...)
	/home/rclone/go/src/github.com/rclone/rclone/backend/pcloud/pcloud.go:567 +0x1f6
github.com/rclone/rclone/fstest.(*Run).WriteObjectTo(0xc0008d6ae0, 0x1fc9360, 0xc00011c010, 0x1fe0180, 0xc000210a80, 0x1cbd751, 0x9, 0x1cc5e7c, 0xe, 0x1dcd64ff, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:272 +0x364
github.com/rclone/rclone/fstest.(*Run).WriteObject(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:289
github.com/rclone/rclone/vfs.dirCreate(0xc000591500, 0xf, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:21 +0x148
github.com/rclone/rclone/vfs.TestDirCreate(0xc000591500)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:351 +0x57
testing.tRunner(0xc000591500, 0x1d6bd20)
	/usr/local/go/src/testing/testing.go:1123 +0xef
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1168 +0x2b3
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPcloud: -verbose" - Finished ERROR in 1h0m0.502033184s (try 1/5): exit status 2: Failed [TestDirReadDirAll/Virtual TestDirOpen]