"./vfs.test -test.v -test.timeout 30m0s -remote TestSharefile: -verbose" - Starting (try 1/5) 2019/10/02 05:02:06 DEBUG : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': Token expired but no uploads in progress - doing nothing 2019/10/02 05:02:06 DEBUG : TestSharefile: Loaded invalid token from config file - ignoring 2019/10/02 05:02:08 DEBUG : TestSharefile: Saved new token in config file === RUN TestCacheModeString --- PASS: TestCacheModeString (0.00s) === RUN TestCacheModeSet --- PASS: TestCacheModeSet (0.00s) === RUN TestCacheModeType --- PASS: TestCacheModeType (0.00s) === RUN TestCacheNew 2019/10/02 05:02:15 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:02:15 DEBUG : Cache cleaning thread disabled because poll interval <= 0 2019/10/02 05:02:15 DEBUG : potato: updateTime: setting atime to 2019-10-02 06:02:15.271543731 +0000 UTC m=+3609.205655904 2019/10/02 05:02:15 DEBUG : potato: updateTime: setting atime to 2019-10-02 05:02:15.268948218 +0000 UTC 2019/10/02 05:02:15 DEBUG : potato: updateTime: setting atime to 2019-10-02 05:02:15.268948218 +0000 UTC 2019/10/02 05:02:15 DEBUG : potato: updateTime: setting atime to 2019-10-02 06:02:15.271543731 +0000 UTC m=+3609.205655904 2019/10/02 05:02:15 INFO : potato: Removed from cache 2019/10/02 05:02:15 DEBUG : : Removed empty directory 2019/10/02 05:02:15 INFO : Cleaned the cache: objects 0 (was 1), total size 0 (was 5) 2019/10/02 05:02:16 ERROR : : error listing: directory not found --- PASS: TestCacheNew (0.92s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestCacheOpens 2019/10/02 05:02:16 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:02:16 DEBUG : cache cleaner exiting 2019/10/02 05:02:17 ERROR : : error listing: directory not found --- PASS: TestCacheOpens (1.05s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestCacheOpenMkdir 2019/10/02 05:02:17 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:02:17 DEBUG : Cache cleaning thread disabled because poll interval <= 0 2019/10/02 05:02:17 INFO : sub/potato: Removed from cache 2019/10/02 05:02:17 DEBUG : sub: Removed empty directory 2019/10/02 05:02:17 DEBUG : : Removed empty directory 2019/10/02 05:02:18 ERROR : : error listing: directory not found --- PASS: TestCacheOpenMkdir (0.94s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestCacheCacheDir 2019/10/02 05:02:18 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:02:18 DEBUG : cache cleaner exiting 2019/10/02 05:02:19 ERROR : : error listing: directory not found --- PASS: TestCacheCacheDir (1.03s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestCachePurgeOld 2019/10/02 05:02:19 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:02:19 DEBUG : cache cleaner exiting 2019/10/02 05:02:19 ERROR : : error listing: directory not found --- PASS: TestCachePurgeOld (0.75s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestCachePurgeOverQuota 2019/10/02 05:02:19 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:02:19 DEBUG : Cache cleaning thread disabled because poll interval <= 0 2019/10/02 05:02:19 DEBUG : sub/dir2/potato2: updateTime: setting atime to 2019-10-02 05:02:29.967200885 +0000 UTC m=+23.901313095 2019/10/02 05:02:19 INFO : sub/dir/potato: Removed from cache 2019/10/02 05:02:19 DEBUG : sub/dir/potato: updateTime: setting atime to 2019-10-02 05:02:49.967200885 +0000 UTC m=+43.901313095 2019/10/02 05:02:19 INFO : sub/dir2/potato2: Removed from cache 2019/10/02 05:02:19 DEBUG : sub/dir2: Removed empty directory 2019/10/02 05:02:19 INFO : sub/dir/potato: Removed from cache 2019/10/02 05:02:19 DEBUG : sub/dir: Removed empty directory 2019/10/02 05:02:19 DEBUG : sub: Removed empty directory 2019/10/02 05:02:19 DEBUG : : Removed empty directory 2019/10/02 05:02:21 ERROR : : error listing: directory not found --- PASS: TestCachePurgeOverQuota (1.09s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirHandleMethods 2019/10/02 05:02:21 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:02:21 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:02:21 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:02:21 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirHandleMethods (37.39s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirHandleReaddir 2019/10/02 05:02:58 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:02:58 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:02:58 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:02:58 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirHandleReaddir (67.58s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirHandleReaddirnames 2019/10/02 05:04:06 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:04:06 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:04:06 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:04:06 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirHandleReaddirnames (28.04s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirMethods 2019/10/02 05:04:34 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:04:34 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:04:34 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:04:34 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirMethods (28.93s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirForgetAll 2019/10/02 05:05:02 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:05:02 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:05:02 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:05:02 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:05:24 DEBUG : : invalidating directory cache 2019/10/02 05:05:24 DEBUG : dir: forgetting directory cache 2019/10/02 05:05:24 DEBUG : dir: forgetting directory cache 2019/10/02 05:05:24 DEBUG : : forgetting directory cache --- PASS: TestDirForgetAll (46.03s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirForgetPath 2019/10/02 05:05:49 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:05:49 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:05:49 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:05:49 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:06:09 DEBUG : dir: invalidating directory cache 2019/10/02 05:06:09 DEBUG : : invalidating directory cache 2019/10/02 05:06:09 DEBUG : dir: forgetting directory cache --- PASS: TestDirForgetPath (32.23s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirWalk 2019/10/02 05:06:21 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:06:21 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:06:21 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:06:21 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:07:07 DEBUG : dir: forgetting directory cache 2019/10/02 05:07:07 DEBUG : : forgetting directory cache --- PASS: TestDirWalk (73.36s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirSetModTime 2019/10/02 05:07:34 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:07:34 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:07:34 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:07:34 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirSetModTime (26.82s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirStat 2019/10/02 05:08:01 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:08:01 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:08:01 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:08:01 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirStat (31.77s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirReadDirAll 2019/10/02 05:08:33 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:08:33 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:08:33 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:08:33 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirReadDirAll (60.66s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirOpen 2019/10/02 05:09:33 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:09:33 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:09:33 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:09:33 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:09:50 ERROR : dir/: Can only open directories read only --- PASS: TestDirOpen (27.12s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirCreate 2019/10/02 05:10:00 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:10:00 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:10:00 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:10:00 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:10:19 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:10:19 DEBUG : dir/potato: >Open: fd=dir/potato (w), err= 2019/10/02 05:10:19 DEBUG : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': File to upload is small (5 bytes), uploading instead of streaming 2019/10/02 05:10:26 DEBUG : dir/potato: MD5 = 5d41402abc4b2a76b9719d911017c592 OK 2019/10/02 05:10:26 INFO : dir/potato: Copied (new) --- PASS: TestDirCreate (40.82s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirMkdir 2019/10/02 05:10:41 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:10:41 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:10:41 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:10:41 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirMkdir (45.30s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirMkdirSub 2019/10/02 05:11:27 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:11:27 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:11:27 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:11:27 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirMkdirSub (57.38s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirRemove 2019/10/02 05:12:24 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:12:24 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:12:24 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:12:24 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:12:46 ERROR : dir/: Dir.Remove not empty --- PASS: TestDirRemove (32.26s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirRemoveAll 2019/10/02 05:12:56 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:12:56 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:12:56 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:12:56 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirRemoveAll (33.30s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirRemoveName 2019/10/02 05:13:30 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:13:30 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:13:30 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:13:30 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestDirRemoveName (30.88s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestDirRename 2019/10/02 05:14:00 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:14:00 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:14:00 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:14:00 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:14:35 ERROR : dir/not found: Dir.Rename error: file does not exist 2019/10/02 05:14:39 DEBUG : dir: Updating dir with dir2 0xc00046ba70 2019/10/02 05:14:39 DEBUG : : invalidating directory cache 2019/10/02 05:14:39 DEBUG : dir: forgetting directory cache 2019/10/02 05:14:57 INFO : dir2/file1: Moved (server side) 2019/10/02 05:14:57 DEBUG : dir2/file1: Updating file with file2 0xc0005fc500 2019/10/02 05:15:10 INFO : dir2/file3: Deleted 2019/10/02 05:15:23 INFO : file2: Moved (server side) 2019/10/02 05:15:23 DEBUG : file2: Updating file with dir2/file3 0xc0005fc500 --- PASS: TestDirRename (99.41s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestErrorError --- PASS: TestErrorError (0.00s) === RUN TestFileMethods 2019/10/02 05:15:40 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:15:40 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:15:40 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:15:40 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestFileMethods (37.07s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestFileSetModTime 2019/10/02 05:16:32 DEBUG : Can set mod time: true 2019/10/02 05:16:32 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:16:32 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:16:32 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:16:32 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:16:59 DEBUG : dir/file1: File.applyPendingModTime OK --- PASS: TestFileSetModTime (57.91s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestFileOpenRead 2019/10/02 05:17:15 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:17:15 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:17:15 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:17:15 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:17:45 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:17:48 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728 --- PASS: TestFileOpenRead (44.27s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestFileOpenReadUnknownSize 2019/10/02 05:17:59 INFO : Mock file system at root: poll-interval is not supported by this remote 2019/10/02 05:17:59 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:17:59 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:17:59 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:17:59 DEBUG : file.txt: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:17:59 DEBUG : file.txt: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728 --- PASS: TestFileOpenReadUnknownSize (0.00s) file_test.go:152: gotContents = "file contents" === RUN TestFileOpenWrite 2019/10/02 05:17:59 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:17:59 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:17:59 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:17:59 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:18:22 DEBUG : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': File to upload is small (25 bytes), uploading instead of streaming 2019/10/02 05:19:13 DEBUG : dir/file1: MD5 = c7247bead226dfd7bd970c17229f4044 OK 2019/10/02 05:19:13 INFO : dir/file1: Copied (new) --- PASS: TestFileOpenWrite (87.57s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestFileRemove 2019/10/02 05:19:27 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:19:27 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:19:27 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:19:27 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestFileRemove (36.59s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestFileRemoveAll 2019/10/02 05:20:03 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:20:03 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:20:03 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:20:03 DEBUG : Adding path "vfs/poll-interval" to remote control registry --- PASS: TestFileRemoveAll (42.42s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestFileOpen 2019/10/02 05:20:46 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:20:46 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:20:46 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:20:46 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:21:09 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:21:09 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2019/10/02 05:21:09 DEBUG : dir/file1: Open: flags=O_WRONLY 2019/10/02 05:21:09 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2019/10/02 05:21:09 DEBUG : dir/file1: Open: flags=O_RDWR 2019/10/02 05:21:09 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2019/10/02 05:21:09 DEBUG : dir/file1: Open: flags=0x3 2019/10/02 05:21:09 ERROR : dir/file1: Can't figure out how to open with flags: 0x3 2019/10/02 05:21:09 DEBUG : dir/file1: >Open: fd=, err=permission denied 2019/10/02 05:22:22 DEBUG : pacer: low level retry 1/10 (error A system error occurred.: InternalServerError: Unspecified) 2019/10/02 05:22:22 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2019/10/02 05:22:23 DEBUG : pacer: Reducing sleep to 15ms 2019/10/02 05:22:25 DEBUG : pacer: Reducing sleep to 11.25ms 2019/10/02 05:22:27 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestFileOpen (109.34s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/6: remove: Item not found: The item that you requested could not be found in the system.: NotFound: NotFound run.go:121: removing dir "dir" failed - try 2/6: directory not found run.go:121: removing dir "dir" failed - try 3/6: directory not found run.go:121: removing dir "dir" failed - try 4/6: directory not found run.go:121: removing dir "dir" failed - try 5/6: directory not found run.go:121: removing dir "dir" failed - try 6/6: directory not found run.go:124: removing dir "dir" failed: directory not found === RUN TestReadFileHandleMethods 2019/10/02 05:22:35 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:22:35 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:22:35 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:22:35 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:22:53 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:22:56 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:22:56 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2019/10/02 05:22:56 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2019/10/02 05:22:56 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:22:59 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2019/10/02 05:22:59 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 --- PASS: TestReadFileHandleMethods (32.97s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestReadFileHandleSeek 2019/10/02 05:23:08 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:23:08 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:23:08 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:23:08 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:23:26 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:23:29 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:23:29 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2019/10/02 05:23:29 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2019/10/02 05:23:29 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:23:31 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2019/10/02 05:23:31 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2019/10/02 05:23:31 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2019/10/02 05:23:31 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2019/10/02 05:23:31 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2019/10/02 05:23:34 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker) 2019/10/02 05:23:34 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1 2019/10/02 05:23:34 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728 2019/10/02 05:23:34 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728 2019/10/02 05:23:37 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker) 2019/10/02 05:23:37 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1 2019/10/02 05:23:37 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728 2019/10/02 05:23:37 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728 --- PASS: TestReadFileHandleSeek (43.08s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestReadFileHandleReadAt 2019/10/02 05:23:51 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:23:51 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:23:51 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:23:51 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:24:11 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:24:13 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:24:13 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2019/10/02 05:24:13 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2019/10/02 05:24:13 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:24:17 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2019/10/02 05:24:17 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2019/10/02 05:24:17 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2019/10/02 05:24:17 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2019/10/02 05:24:17 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2019/10/02 05:24:19 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2019/10/02 05:24:19 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2019/10/02 05:24:19 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2019/10/02 05:24:19 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2019/10/02 05:24:21 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2019/10/02 05:24:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2019/10/02 05:24:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2019/10/02 05:24:21 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2019/10/02 05:24:24 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2019/10/02 05:24:24 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2019/10/02 05:24:24 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2019/10/02 05:24:24 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2019/10/02 05:24:26 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2019/10/02 05:24:26 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor --- PASS: TestReadFileHandleReadAt (46.76s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestReadFileHandleFlush 2019/10/02 05:24:38 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:24:38 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:24:38 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:24:38 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:24:55 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:24:59 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:24:59 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2019/10/02 05:24:59 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2019/10/02 05:24:59 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:25:01 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 --- PASS: TestReadFileHandleFlush (35.32s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestReadFileHandleRelease 2019/10/02 05:25:13 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:25:13 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:25:13 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:25:13 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:25:31 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:25:33 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:25:33 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2019/10/02 05:25:33 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2019/10/02 05:25:33 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2019/10/02 05:25:36 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2019/10/02 05:25:36 DEBUG : dir/file1: ReadFileHandle.Release closing 2019/10/02 05:25:36 DEBUG : dir/file1: ReadFileHandle.Release nothing to do --- PASS: TestReadFileHandleRelease (34.90s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleMethodsRead 2019/10/02 05:25:48 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:25:48 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:25:48 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:25:48 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:25:48 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:26:04 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:26:06 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:26:06 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2019/10/02 05:26:06 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2019/10/02 05:26:06 DEBUG : dir/file1: Couldn't find file - need to transfer 2019/10/02 05:26:08 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK 2019/10/02 05:26:08 INFO : dir/file1: Copied (new) 2019/10/02 05:26:08 DEBUG : dir/file1(0xc0000ba900): Opening cached copy with flags=O_RDONLY 2019/10/02 05:26:08 DEBUG : dir/file1(0xc0000ba900): close: 2019/10/02 05:26:08 DEBUG : dir/file1(0xc0000ba900): >close: err= 2019/10/02 05:26:08 DEBUG : dir/file1(0xc0000ba900): close: 2019/10/02 05:26:08 DEBUG : dir/file1(0xc0000ba900): >close: err=file already closed 2019/10/02 05:26:08 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleMethodsRead (31.43s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleSeek 2019/10/02 05:26:19 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:26:19 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:26:19 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:26:19 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:26:19 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:26:35 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:26:38 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:26:38 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2019/10/02 05:26:38 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2019/10/02 05:26:38 DEBUG : dir/file1: Couldn't find file - need to transfer 2019/10/02 05:26:41 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK 2019/10/02 05:26:41 INFO : dir/file1: Copied (new) 2019/10/02 05:26:41 DEBUG : dir/file1(0xc0006b3260): Opening cached copy with flags=O_RDONLY 2019/10/02 05:26:41 DEBUG : dir/file1(0xc0006b3260): close: 2019/10/02 05:26:41 DEBUG : dir/file1(0xc0006b3260): >close: err= 2019/10/02 05:26:41 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleSeek (31.44s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleReadAt 2019/10/02 05:26:51 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:26:51 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:26:51 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:26:51 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:26:51 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:27:09 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:27:13 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:27:13 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2019/10/02 05:27:13 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2019/10/02 05:27:13 DEBUG : dir/file1: Couldn't find file - need to transfer 2019/10/02 05:27:15 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK 2019/10/02 05:27:15 INFO : dir/file1: Copied (new) 2019/10/02 05:27:15 DEBUG : dir/file1(0xc000774360): Opening cached copy with flags=O_RDONLY 2019/10/02 05:27:15 DEBUG : dir/file1(0xc000774360): close: 2019/10/02 05:27:15 DEBUG : dir/file1(0xc000774360): >close: err= 2019/10/02 05:27:15 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleReadAt (36.82s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleFlushRead 2019/10/02 05:27:28 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:27:28 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:27:28 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:27:28 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:27:28 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:27:46 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:27:49 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:27:49 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2019/10/02 05:27:49 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2019/10/02 05:27:49 DEBUG : dir/file1: Couldn't find file - need to transfer 2019/10/02 05:27:51 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK 2019/10/02 05:27:51 INFO : dir/file1: Copied (new) 2019/10/02 05:27:51 DEBUG : dir/file1(0xc00078bf80): Opening cached copy with flags=O_RDONLY 2019/10/02 05:27:51 DEBUG : dir/file1(0xc00078bf80): RWFileHandle.Flush ignoring flush on unwritten handle 2019/10/02 05:27:51 DEBUG : dir/file1(0xc00078bf80): RWFileHandle.Flush ignoring flush on unwritten handle 2019/10/02 05:27:51 DEBUG : dir/file1(0xc00078bf80): close: 2019/10/02 05:27:51 DEBUG : dir/file1(0xc00078bf80): >close: err= 2019/10/02 05:27:51 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleFlushRead (34.12s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleReleaseRead 2019/10/02 05:28:02 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:28:02 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:28:02 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:28:02 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:28:02 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:28:20 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2019/10/02 05:28:22 DEBUG : dir/file1: Open: flags=O_RDONLY 2019/10/02 05:28:22 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2019/10/02 05:28:22 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2019/10/02 05:28:22 DEBUG : dir/file1: Couldn't find file - need to transfer 2019/10/02 05:28:24 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK 2019/10/02 05:28:24 INFO : dir/file1: Copied (new) 2019/10/02 05:28:24 DEBUG : dir/file1(0xc000121500): Opening cached copy with flags=O_RDONLY 2019/10/02 05:28:24 DEBUG : dir/file1(0xc000121500): RWFileHandle.Release closing 2019/10/02 05:28:24 DEBUG : dir/file1(0xc000121500): close: 2019/10/02 05:28:24 DEBUG : dir/file1(0xc000121500): >close: err= 2019/10/02 05:28:24 DEBUG : dir/file1(0xc000121500): RWFileHandle.Release nothing to do 2019/10/02 05:28:24 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleReleaseRead (34.69s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleMethodsWrite 2019/10/02 05:28:37 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:28:37 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:28:37 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:28:37 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:28:37 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:28:37 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:28:38 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:28:38 DEBUG : file1(0xc000774360): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:28:38 DEBUG : file1: >Open: fd=file1 (rw), err= 2019/10/02 05:28:38 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2019/10/02 05:28:40 DEBUG : file1(0xc000774360): close: 2019/10/02 05:28:40 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 05:28:50 DEBUG : file1: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 05:28:50 INFO : file1: Copied (new) 2019/10/02 05:28:50 DEBUG : file1: transferred to remote 2019/10/02 05:28:50 DEBUG : file1(0xc000774360): >close: err= 2019/10/02 05:28:50 DEBUG : file1(0xc000774360): close: 2019/10/02 05:28:50 DEBUG : file1(0xc000774360): >close: err=file already closed 2019/10/02 05:28:51 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleMethodsWrite (21.89s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleWriteAt 2019/10/02 05:28:58 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:28:58 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:28:58 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:28:58 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:28:58 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:28:58 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:29:00 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:29:00 DEBUG : file1(0xc000120de0): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:29:00 DEBUG : file1: >Open: fd=file1 (rw), err= 2019/10/02 05:29:00 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2019/10/02 05:29:00 DEBUG : file1(0xc000120de0): close: 2019/10/02 05:29:00 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 05:29:09 DEBUG : file1: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 05:29:09 INFO : file1: Copied (new) 2019/10/02 05:29:09 DEBUG : file1: transferred to remote 2019/10/02 05:29:09 DEBUG : file1(0xc000120de0): >close: err= 2019/10/02 05:29:10 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleWriteAt (18.16s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleWriteNoWrite 2019/10/02 05:29:17 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:29:17 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:29:17 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:29:17 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:29:17 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:29:17 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:29:18 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:29:18 DEBUG : file1(0xc0006b7b00): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:29:18 DEBUG : file1: >Open: fd=file1 (rw), err= 2019/10/02 05:29:18 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2019/10/02 05:29:18 DEBUG : file1(0xc0006b7b00): close: 2019/10/02 05:29:18 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 05:29:27 DEBUG : file1: MD5 = d41d8cd98f00b204e9800998ecf8427e OK 2019/10/02 05:29:27 INFO : file1: Copied (new) 2019/10/02 05:29:27 DEBUG : file1: transferred to remote 2019/10/02 05:29:27 DEBUG : file1(0xc0006b7b00): >close: err= 2019/10/02 05:29:27 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2019/10/02 05:29:27 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2019/10/02 05:29:27 DEBUG : file2(0xc0000bb2c0): Opening cached copy with flags=O_WRONLY|O_CREATE|O_TRUNC 2019/10/02 05:29:27 DEBUG : file2: >Open: fd=file2 (rw), err= 2019/10/02 05:29:27 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2019/10/02 05:29:27 DEBUG : file2(0xc0000bb2c0): RWFileHandle.Flush ignoring flush on unwritten handle 2019/10/02 05:29:27 DEBUG : file2(0xc0000bb2c0): RWFileHandle.Release closing 2019/10/02 05:29:27 DEBUG : file2(0xc0000bb2c0): close: 2019/10/02 05:29:27 DEBUG : file2: Couldn't find file - need to transfer 2019/10/02 05:29:37 DEBUG : file2: MD5 = d41d8cd98f00b204e9800998ecf8427e OK 2019/10/02 05:29:37 INFO : file2: Copied (new) 2019/10/02 05:29:37 DEBUG : file2: transferred to remote 2019/10/02 05:29:37 DEBUG : file2(0xc0000bb2c0): >close: err= 2019/10/02 05:29:39 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleWriteNoWrite (37.72s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleFlushWrite 2019/10/02 05:29:54 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:29:54 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:29:54 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:29:54 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:29:54 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:29:54 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:29:56 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:29:56 DEBUG : file1(0xc0008913e0): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:29:56 DEBUG : file1: >Open: fd=file1 (rw), err= 2019/10/02 05:29:56 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2019/10/02 05:29:56 DEBUG : file1(0xc0008913e0): close: 2019/10/02 05:29:56 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 05:30:09 DEBUG : file1: MD5 = 5d41402abc4b2a76b9719d911017c592 OK 2019/10/02 05:30:09 INFO : file1: Copied (new) 2019/10/02 05:30:09 DEBUG : file1: transferred to remote 2019/10/02 05:30:09 DEBUG : file1(0xc0008913e0): >close: err= 2019/10/02 05:30:09 DEBUG : file1(0xc0008913e0): RWFileHandle.Flush nothing to do 2019/10/02 05:30:09 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleFlushWrite (20.82s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleReleaseWrite 2019/10/02 05:30:15 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:30:15 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:30:15 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:30:15 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:30:15 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:30:15 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:30:16 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:30:16 DEBUG : file1(0xc00011bc20): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:30:16 DEBUG : file1: >Open: fd=file1 (rw), err= 2019/10/02 05:30:16 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2019/10/02 05:30:16 DEBUG : file1(0xc00011bc20): RWFileHandle.Release closing 2019/10/02 05:30:16 DEBUG : file1(0xc00011bc20): close: 2019/10/02 05:30:16 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 05:30:30 DEBUG : file1: MD5 = 5d41402abc4b2a76b9719d911017c592 OK 2019/10/02 05:30:30 INFO : file1: Copied (new) 2019/10/02 05:30:30 DEBUG : file1: transferred to remote 2019/10/02 05:30:30 DEBUG : file1(0xc00011bc20): >close: err= 2019/10/02 05:30:30 DEBUG : file1(0xc00011bc20): RWFileHandle.Release nothing to do 2019/10/02 05:30:30 DEBUG : cache cleaner exiting --- PASS: TestRWFileHandleReleaseWrite (20.64s) run.go:176: Remote "sharefile root 'rclone-test-wahitat3jamiqun4xanedey0'", Local "Local file system at /tmp/rclone505338433", Modify Window "1s" === RUN TestRWFileHandleOpenTests 2019/10/02 05:30:36 INFO : sharefile root 'rclone-test-wahitat3jamiqun4xanedey0': poll-interval is not supported by this remote 2019/10/02 05:30:36 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestSharefile/rclone-test-wahitat3jamiqun4xanedey0" 2019/10/02 05:30:36 DEBUG : Adding path "vfs/forget" to remote control registry 2019/10/02 05:30:36 DEBUG : Adding path "vfs/refresh" to remote control registry 2019/10/02 05:30:36 DEBUG : Adding path "vfs/poll-interval" to remote control registry 2019/10/02 05:30:37 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=-rw-rw-rw- 2019/10/02 05:30:37 DEBUG : open-test-file: >OpenFile: fd=, err=file does not exist 2019/10/02 05:30:37 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:30:37 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:30:37 DEBUG : open-test-file(0xc00078aea0): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:30:37 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err= 2019/10/02 05:30:37 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err= 2019/10/02 05:30:37 DEBUG : open-test-file(0xc00078aea0): close: 2019/10/02 05:30:37 DEBUG : open-test-file: Couldn't find file - need to transfer 2019/10/02 05:30:46 DEBUG : open-test-file: MD5 = 5d41402abc4b2a76b9719d911017c592 OK 2019/10/02 05:30:46 INFO : open-test-file: Copied (new) 2019/10/02 05:30:46 DEBUG : open-test-file: transferred to remote 2019/10/02 05:30:46 DEBUG : open-test-file(0xc00078aea0): >close: err= 2019/10/02 05:30:46 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=-rw-rw-rw- 2019/10/02 05:30:46 DEBUG : open-test-file: Open: flags=O_RDONLY 2019/10/02 05:30:46 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err= 2019/10/02 05:30:46 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err= 2019/10/02 05:30:46 DEBUG : open-test-file: Size and modification time the same (differ by -335.737µs, within tolerance 1s) 2019/10/02 05:30:46 DEBUG : open-test-file: Unchanged skipping 2019/10/02 05:30:46 DEBUG : open-test-file(0xc0008d8600): Opened existing cached copy with flags=O_RDONLY 2019/10/02 05:30:46 DEBUG : open-test-file(0xc0008d8600): close: 2019/10/02 05:30:46 DEBUG : open-test-file(0xc0008d8600): >close: err= 2019/10/02 05:30:46 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=---------- 2019/10/02 05:30:46 DEBUG : open-test-file: Open: flags=O_RDONLY 2019/10/02 05:30:46 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err= 2019/10/02 05:30:46 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err= 2019/10/02 05:30:46 DEBUG : open-test-file: Size and modification time the same (differ by -335.737µs, within tolerance 1s) 2019/10/02 05:30:46 DEBUG : open-test-file: Unchanged skipping 2019/10/02 05:30:46 DEBUG : open-test-file(0xc0008d8780): Opened existing cached copy with flags=O_RDONLY 2019/10/02 05:30:46 DEBUG : open-test-file(0xc0008d8780): close: 2019/10/02 05:30:46 DEBUG : open-test-file(0xc0008d8780): >close: err= 2019/10/02 05:30:50 INFO : open-test-file: Removed from cache 2019/10/02 05:30:50 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_TRUNC, perm=-rw-rw-rw- 2019/10/02 05:30:50 DEBUG : open-test-file: >OpenFile: fd=, err=invalid argument 2019/10/02 05:30:50 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:30:50 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:30:50 DEBUG : open-test-file(0xc0008d8960): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:30:50 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err= 2019/10/02 05:30:50 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err= 2019/10/02 05:30:50 DEBUG : open-test-file(0xc0008d8960): close: 2019/10/02 05:30:50 DEBUG : open-test-file: Couldn't find file - need to transfer 2019/10/02 05:31:00 DEBUG : open-test-file: MD5 = 5d41402abc4b2a76b9719d911017c592 OK 2019/10/02 05:31:00 INFO : open-test-file: Copied (new) 2019/10/02 05:31:00 DEBUG : open-test-file: transferred to remote 2019/10/02 05:31:00 DEBUG : open-test-file(0xc0008d8960): >close: err= 2019/10/02 05:31:00 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_TRUNC, perm=-rw-rw-rw- 2019/10/02 05:31:00 DEBUG : open-test-file: >OpenFile: fd=, err=invalid argument 2019/10/02 05:31:00 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=---------- 2019/10/02 05:31:00 DEBUG : open-test-file: Open: flags=O_RDONLY 2019/10/02 05:31:00 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err= 2019/10/02 05:31:00 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err= 2019/10/02 05:31:00 DEBUG : open-test-file: Size and modification time the same (differ by -1.144867ms, within tolerance 1s) 2019/10/02 05:31:00 DEBUG : open-test-file: Unchanged skipping 2019/10/02 05:31:00 DEBUG : open-test-file(0xc0006b2900): Opened existing cached copy with flags=O_RDONLY 2019/10/02 05:31:00 DEBUG : open-test-file(0xc0006b2900): close: 2019/10/02 05:31:00 DEBUG : open-test-file(0xc0006b2900): >close: err= 2019/10/02 05:31:02 INFO : open-test-file: Removed from cache 2019/10/02 05:31:02 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_SYNC, perm=-rw-rw-rw- 2019/10/02 05:31:02 DEBUG : open-test-file: >OpenFile: fd=, err=file does not exist 2019/10/02 05:31:02 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2019/10/02 05:31:02 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE 2019/10/02 05:31:02 DEBUG : open-test-file(0xc0008d8c00): Opening cached copy with flags=O_WRONLY|O_CREATE 2019/10/02 05:31:02 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err= 2019/10/02 05:31:02 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err= 2019/10/02 05:31:02 DEBUG : open-test-file(0xc0008d8c00): close: 2019/10/02 05:31:02 DEBUG : open-test-file: Couldn't find file - need to transfer 2019/10/02 05:31:36 DEBUG : open-test-file: updateTime: setting atime to 2019-10-02 05:31:05.227081048 +0000 UTC 2019/10/02 05:31:36 INFO : Cleaned the cache: objects 2 (was 2), total size 5 (was 0) 2019/10/02 05:32:13 ERROR : open-test-file: Failed to copy: upload failed: Value cannot be null. Parameter name: source (500) 2019/10/02 05:32:13 ERROR : open-test-file(0xc0008d8c00): failed to transfer file from cache to remote: upload failed: Value cannot be null. Parameter name: source (500) 2019/10/02 05:32:13 DEBUG : open-test-file(0xc0008d8c00): >close: err=failed to transfer file from cache to remote: upload failed: Value cannot be null. Parameter name: source (500) 2019/10/02 05:32:13 DEBUG : cache cleaner exiting panic: test timed out after 30m0s goroutine 3545 [running]: testing.(*M).startAlarm.func1() /usr/local/go/src/testing/testing.go:1377 +0xdf created by time.goFunc /usr/local/go/src/time/sleep.go:168 +0x44 goroutine 1 [chan receive, 2 minutes]: testing.(*T).Run(0xc0007f2b00, 0x14dc964, 0x19, 0x152fc48, 0x4c2c01) /usr/local/go/src/testing/testing.go:961 +0x377 testing.runTests.func1(0xc000118800) /usr/local/go/src/testing/testing.go:1202 +0x78 testing.tRunner(0xc000118800, 0xc000587d78) /usr/local/go/src/testing/testing.go:909 +0xc9 testing.runTests(0xc00063c840, 0x211dae0, 0x45, 0x45, 0x79a3b5) /usr/local/go/src/testing/testing.go:1200 +0x2a7 testing.(*M).Run(0xc00011f380, 0x0) /usr/local/go/src/testing/testing.go:1117 +0x176 github.com/rclone/rclone/fstest.TestMain(0xc00011f380) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:68 +0x92 github.com/rclone/rclone/vfs.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:28 main.main() _testmain.go:178 +0x136 goroutine 5 [syscall, 30 minutes]: os/signal.signal_recv(0x0) /usr/local/go/src/runtime/sigqueue.go:147 +0x9c os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:23 +0x22 created by os/signal.init.0 /usr/local/go/src/os/signal/signal_unix.go:29 +0x41 goroutine 7 [select, 2 minutes]: github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.(*worker).start(0xc000140be0) /home/rclone/go/src/github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:154 +0x100 created by github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.init.0 /home/rclone/go/src/github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:32 +0x57 goroutine 8 [chan receive, 30 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc00047f3e0) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:39 +0x67 created by github.com/rclone/rclone/lib/oauthutil.NewRenew /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:28 +0x84 goroutine 3516 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3434 [semacquire]: sync.runtime_Semacquire(0xc0005a8718) /usr/local/go/src/runtime/sema.go:56 +0x42 sync.(*WaitGroup).Wait(0xc0005a8710) /usr/local/go/src/sync/waitgroup.go:130 +0x64 github.com/rclone/rclone/fs/walk.walk(0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x0, 0x0, 0xc00079f801, 0xffffffffffffffff, 0xc000596320, 0x152e610, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:440 +0x340 github.com/rclone/rclone/fs/walk.walkListDirSorted(...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:337 github.com/rclone/rclone/fs/walk.Walk(0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x0, 0x0, 0x1399b01, 0xffffffffffffffff, 0xc000596320, 0x28, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:69 +0x16f github.com/rclone/rclone/fs/walk.listRwalk(0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x0, 0x0, 0x8b6c01, 0xffffffffffffffff, 0x40e803, 0xc000320390, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:158 +0xfe github.com/rclone/rclone/fs/walk.ListR(0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x0, 0x0, 0xc0006b2301, 0xffffffffffffffff, 0xc00079fa03, 0xc000320390, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:150 +0xe2 github.com/rclone/rclone/fstest.newRunIndividual.func1() /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:146 +0x127 github.com/rclone/rclone/fstest.(*Run).Finalise(0xc000890060) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:339 +0x2b github.com/rclone/rclone/vfs.cleanup(0xc0007f2b00, 0xc000890060, 0xc0000de000) /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:21 +0x89 runtime.Goexit() /usr/local/go/src/runtime/panic.go:563 +0xec testing.(*common).FailNow(0xc0007f2b00) /usr/local/go/src/testing/testing.go:653 +0x39 github.com/rclone/rclone/vendor/github.com/stretchr/testify/require.NoError(0x1760b60, 0xc0007f2b00, 0x174dfa0, 0xc000596160, 0xc00079fcf8, 0x1, 0x1) /home/rclone/go/src/github.com/rclone/rclone/vendor/github.com/stretchr/testify/require/require.go:974 +0xf0 github.com/rclone/rclone/vfs.testRWFileHandleOpenTest(0xc0007f2b00, 0xc0000de000, 0xc00079fe50) /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:522 +0x482 github.com/rclone/rclone/vfs.TestRWFileHandleOpenTests(0xc0007f2b00) /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:575 +0x1d5 testing.tRunner(0xc0007f2b00, 0x152fc48) /usr/local/go/src/testing/testing.go:909 +0xc9 created by testing.(*T).Run /usr/local/go/src/testing/testing.go:960 +0x350 goroutine 3519 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3518 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3515 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3538 [select]: net/http.(*http2ClientConn).roundTrip(0xc0005a3200, 0xc000152a00, 0x0, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:7573 +0x9a0 net/http.(*http2Transport).RoundTripOpt(0xc00011a1e0, 0xc000152a00, 0xc0001dec00, 0x741d85, 0x0, 0xc00013d9e0) /usr/local/go/src/net/http/h2_bundle.go:6936 +0x172 net/http.(*http2Transport).RoundTrip(...) /usr/local/go/src/net/http/h2_bundle.go:6897 net/http.http2noDialH2RoundTripper.RoundTrip(0xc00011a1e0, 0xc000152a00, 0xc0000b2e80, 0x5, 0xc00013da68) /usr/local/go/src/net/http/h2_bundle.go:9032 +0x3e net/http.(*Transport).roundTrip(0xc0003bd400, 0xc000152a00, 0x14c7057, 0xa, 0xc000193120) /usr/local/go/src/net/http/transport.go:485 +0xd0a net/http.(*Transport).RoundTrip(...) /usr/local/go/src/net/http/roundtrip.go:17 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc00047f170, 0xc000152a00, 0xc000152a00, 0x0, 0x1206220) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:330 +0x1de github.com/rclone/rclone/vendor/golang.org/x/oauth2.(*Transport).RoundTrip(0xc00047f320, 0xc000152600, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/vendor/golang.org/x/oauth2/transport.go:56 +0x124 net/http.send(0xc000152600, 0x174e4a0, 0xc00047f320, 0x0, 0x0, 0x0, 0xc000126050, 0x203000, 0x1, 0x0) /usr/local/go/src/net/http/client.go:250 +0x43a net/http.(*Client).send(0xc00047f350, 0xc000152600, 0x0, 0x0, 0x0, 0xc000126050, 0x0, 0x1, 0x1499f20) /usr/local/go/src/net/http/client.go:174 +0xfa net/http.(*Client).do(0xc00047f350, 0xc000152600, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/client.go:641 +0x3ce net/http.(*Client).Do(...) /usr/local/go/src/net/http/client.go:509 github.com/rclone/rclone/lib/rest.(*Client).Call(0xc000490190, 0x1770480, 0xc0000b4010, 0xc0008f2000, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:270 +0x78a github.com/rclone/rclone/backend/sharefile.(*Fs).remove.func1(0xc0001df850, 0x8, 0x30) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:1484 +0x5f github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc000752300, 0xc000752300, 0x2, 0x1) /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1394 +0x3c github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003c1440, 0xc000752300, 0xa, 0x40, 0x13e6200) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x8b github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003c1440, 0xc000752300, 0x7, 0xc0007549c0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a github.com/rclone/rclone/backend/sharefile.(*Fs).remove(0xc0003b3cc0, 0x1770480, 0xc0000b4010, 0xc0007549c0, 0x24, 0xc000810010, 0x14880c0) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:1483 +0x34a github.com/rclone/rclone/backend/sharefile.(*Object).Remove(0xc0006b26c0, 0x1770480, 0xc0000b4010, 0xc0002ba2c0, 0xf) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:1499 +0xca github.com/rclone/rclone/fstest.newRunIndividual.func1.1.1(0x7f9626fb7460, 0x0) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:150 +0x41 github.com/rclone/rclone/fstest.retry(0xc0007f2b00, 0xc0002ba2c0, 0x1e, 0xc0001dfd18) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:117 +0x13c github.com/rclone/rclone/fstest.newRunIndividual.func1.1(0xc0004fb290, 0x1, 0x1, 0x1327100, 0x7f9626f2d7e0) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:150 +0x20b github.com/rclone/rclone/fs/walk.listRwalk.func1(0x0, 0x0, 0xc0004fb290, 0x1, 0x1, 0x0, 0x0, 0xc0004fb290, 0x1) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:167 +0x17f github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:402 +0x2c1 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3517 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3534 [IO wait]: internal/poll.runtime_pollWait(0x7f9626f1a9c8, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc000133a98, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /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(0xc000133a80, 0xc00002e000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc000133a80, 0xc00002e000, 0xe62, 0xe62, 0x460c11, 0xc00051e7a0, 0xb) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc000126010, 0xc00002e000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0005ac000, 0xc00051e888, 0xc00002e000, 0xe62, 0xe62, 0x203000, 0x13dfe40, 0xc0000d1180) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0005ac000, 0xc00002e000, 0xe62, 0xe62, 0xac6c854384c653d, 0xc00051e908, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc00061a600, 0xc00002e000, 0xe62, 0xe62, 0xc00051e9b8, 0x41027e, 0xc00051e970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc000312258, 0x174cca0, 0xc00061a600, 0x40bfa5, 0x12d8b00, 0x13e87c0) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000312000, 0x7f9626ec7870, 0xc0005ac000, 0x5, 0xc0005ac000, 0x203000) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000312000, 0x0, 0x0, 0xc00061a5c0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc000312000, 0xc0001cc000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc0006b2540, 0xc0004d6ab8, 0x9, 0x9, 0xc00051ed10, 0x0, 0x733fe2) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x174cae0, 0xc0006b2540, 0xc0004d6ab8, 0x9, 0x9, 0x9, 0xc00009c050, 0x0, 0x174cec0) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc0004d6ab8, 0x9, 0x9, 0x174cae0, 0xc0006b2540, 0x0, 0x0, 0xc000379260, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc0004d6a80, 0xc000379260, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc00051efb8, 0x1530748, 0xc0000ea000) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc0005a3200) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 3521 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 goroutine 3509 [IO wait]: internal/poll.runtime_pollWait(0x7f9626f1ad08, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc000572b18, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /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(0xc000572b00, 0xc0005db000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc000572b00, 0xc0005db000, 0xe62, 0xe62, 0xb8f4a593e7311cd0, 0x826ab6078bcaa51c, 0x1000000e59a2d5f) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc0008e6180, 0xc0005db000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0005963e0, 0xc00051f888, 0xc0005db000, 0xe62, 0xe62, 0x203000, 0x0, 0xe55) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0005963e0, 0xc0005db000, 0xe62, 0xe62, 0xc0005db00d, 0x72, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0005960c0, 0xc0005db000, 0xe62, 0xe62, 0x8f, 0x174cec0, 0xc00051f970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc00050bad8, 0x174cca0, 0xc0005960c0, 0x40bfa5, 0x12d8b00, 0x13e87c0) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc00050b880, 0x7f9626ec7870, 0xc0005963e0, 0x5, 0xc0005963e0, 0x72) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc00050b880, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc00050b880, 0xc000839000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc0008d9bc0, 0xc0005ff0d8, 0x9, 0x9, 0xc00051fd10, 0x0, 0x733fe2) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x174cae0, 0xc0008d9bc0, 0xc0005ff0d8, 0x9, 0x9, 0x9, 0xc00009c050, 0x0, 0x174cec0) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc0005ff0d8, 0x9, 0x9, 0x174cae0, 0xc0008d9bc0, 0x0, 0x0, 0xc0003201b0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc0005ff0a0, 0xc0003201b0, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc00051ffb8, 0x1530748, 0xc0007765c0) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc0007c0900) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 3520 [select]: github.com/rclone/rclone/fs/walk.walk.func2(0xc0005a8700, 0xc000121560, 0x152e610, 0x1770480, 0xc0000b4010, 0x1783ce0, 0xc0003b3cc0, 0x209fc01, 0xc0005a8730, 0xc000596320, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:385 +0x122 created by github.com/rclone/rclone/fs/walk.walk /home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:382 +0x278 "./vfs.test -test.v -test.timeout 30m0s -remote TestSharefile: -verbose" - Finished ERROR in 30m9.218280476s (try 1/5): exit status 2: Failed []