"./operations.test -test.v -test.timeout 30m0s -remote TestSharefile: -verbose" - Starting (try 1/5) === RUN TestDoMultiThreadCopy --- PASS: TestDoMultiThreadCopy (0.00s) === RUN TestMultithreadCalculateChunks === RUN TestMultithreadCalculateChunks/{size:1_streams:10_wantPartSize:65536_wantStreams:1} === RUN TestMultithreadCalculateChunks/{size:1048576_streams:1_wantPartSize:1048576_wantStreams:1} === RUN TestMultithreadCalculateChunks/{size:1048576_streams:2_wantPartSize:524288_wantStreams:2} === RUN TestMultithreadCalculateChunks/{size:1048577_streams:2_wantPartSize:589824_wantStreams:2} === RUN TestMultithreadCalculateChunks/{size:1048575_streams:2_wantPartSize:524288_wantStreams:2} --- PASS: TestMultithreadCalculateChunks (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1_streams:10_wantPartSize:65536_wantStreams:1} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048576_streams:1_wantPartSize:1048576_wantStreams:1} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048576_streams:2_wantPartSize:524288_wantStreams:2} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048577_streams:2_wantPartSize:589824_wantStreams:2} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048575_streams:2_wantPartSize:524288_wantStreams:2} (0.00s) === RUN TestMultithreadCopy === RUN TestMultithreadCopy/{size:131071_streams:2} 2019/10/02 06:18:05 DEBUG : file1: Starting multi-thread copy with 2 parts of size 64k 2019/10/02 06:18:05 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131071) size 63.999k starting 2019/10/02 06:18:05 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k starting 2019/10/02 06:18:08 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k finished 2019/10/02 06:18:08 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131071) size 63.999k finished 2019/10/02 06:18:08 DEBUG : file1: Finished multi-thread copy with 2 parts of size 64k === RUN TestMultithreadCopy/{size:131072_streams:2} 2019/10/02 06:18:24 DEBUG : file1: Starting multi-thread copy with 2 parts of size 64k 2019/10/02 06:18:24 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131072) size 64k starting 2019/10/02 06:18:24 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k starting 2019/10/02 06:18:27 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131072) size 64k finished 2019/10/02 06:18:27 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k finished 2019/10/02 06:18:27 DEBUG : file1: Finished multi-thread copy with 2 parts of size 64k === RUN TestMultithreadCopy/{size:131073_streams:2} 2019/10/02 06:18:46 DEBUG : file1: Starting multi-thread copy with 2 parts of size 128k 2019/10/02 06:18:46 DEBUG : file1: multi-thread copy: stream 2/2 (131072-131073) size 1 starting 2019/10/02 06:18:46 DEBUG : file1: multi-thread copy: stream 1/2 (0-131072) size 128k starting 2019/10/02 06:18:48 DEBUG : file1: multi-thread copy: stream 1/2 (0-131072) size 128k finished 2019/10/02 06:18:48 DEBUG : file1: multi-thread copy: stream 2/2 (131072-131073) size 1 finished 2019/10/02 06:18:48 DEBUG : file1: Finished multi-thread copy with 2 parts of size 128k --- PASS: TestMultithreadCopy (69.36s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" --- PASS: TestMultithreadCopy/{size:131071_streams:2} (21.37s) --- PASS: TestMultithreadCopy/{size:131072_streams:2} (19.95s) --- PASS: TestMultithreadCopy/{size:131073_streams:2} (20.42s) === RUN TestSizeDiffers --- PASS: TestSizeDiffers (0.00s) === RUN TestReOpen === RUN TestReOpen/Seek === RUN TestReOpen/Seek/Basics === RUN TestReOpen/Seek/ErrorAtStart === RUN TestReOpen/Seek/WithErrors 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Seek/TooManyErrors 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2019/10/02 06:18:57 DEBUG : potato: Reopen failed after 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/Range === RUN TestReOpen/Range/Basics === RUN TestReOpen/Range/ErrorAtStart === RUN TestReOpen/Range/WithErrors 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Range/TooManyErrors 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2019/10/02 06:18:57 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2019/10/02 06:18:57 DEBUG : potato: Reopen failed after 6 bytes read: failed to reopen: too many retries --- PASS: TestReOpen (0.00s) --- PASS: TestReOpen/Seek (0.00s) --- PASS: TestReOpen/Seek/Basics (0.00s) --- PASS: TestReOpen/Seek/ErrorAtStart (0.00s) --- PASS: TestReOpen/Seek/WithErrors (0.00s) --- PASS: TestReOpen/Seek/TooManyErrors (0.00s) --- PASS: TestReOpen/Range (0.00s) --- PASS: TestReOpen/Range/Basics (0.00s) --- PASS: TestReOpen/Range/ErrorAtStart (0.00s) --- PASS: TestReOpen/Range/WithErrors (0.00s) --- PASS: TestReOpen/Range/TooManyErrors (0.00s) === RUN TestDeduplicateInteractive --- SKIP: TestDeduplicateInteractive (3.89s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateSkip --- SKIP: TestDeduplicateSkip (2.62s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateFirst --- SKIP: TestDeduplicateFirst (2.65s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateNewest --- SKIP: TestDeduplicateNewest (3.36s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateOldest --- SKIP: TestDeduplicateOldest (2.30s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateLargest --- SKIP: TestDeduplicateLargest (2.58s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateRename --- SKIP: TestDeduplicateRename (2.73s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:19: Can't test deduplicate - no duplicate files possible === RUN TestMergeDirs --- SKIP: TestMergeDirs (2.17s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" dedupe_test.go:197: Can't merge directories === RUN TestListDirSorted 2019/10/02 06:20:57 DEBUG : a.txt: Excluded 2019/10/02 06:21:00 DEBUG : sub dir/hello world2: Excluded 2019/10/02 06:21:00 DEBUG : sub dir/hello world: Excluded 2019/10/02 06:21:03 DEBUG : sub dir/ignore dir: Excluded 2019/10/02 06:21:04 DEBUG : sub dir/hello world2: Excluded 2019/10/02 06:21:04 DEBUG : sub dir/hello world: Excluded 2019/10/02 06:21:05 DEBUG : sub dir/ignore dir: Excluded --- PASS: TestListDirSorted (172.95s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestMkdir 2019/10/02 06:22:12 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': Making directory 2019/10/02 06:22:13 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': Making directory --- PASS: TestMkdir (2.63s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestLsd --- PASS: TestLsd (29.01s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestLs --- FAIL: TestLs (128.56s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" run.go:282: Failed to put "empty space" to "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'": upload failed: Value cannot be null. Parameter name: source (500) === RUN TestLsWithFilesFrom 2019/10/02 06:25:09 DEBUG : empty space: Excluded --- PASS: TestLsWithFilesFrom (26.40s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestLsLong --- PASS: TestLsLong (26.94s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestHashSums --- PASS: TestHashSums (32.71s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestSuffixName --- PASS: TestSuffixName (0.00s) === RUN TestCount --- PASS: TestCount (48.48s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestDelete 2019/10/02 06:27:37 INFO : Waiting for deletions to finish 2019/10/02 06:27:39 DEBUG : large: Excluded 2019/10/02 06:27:42 INFO : small: Deleted 2019/10/02 06:27:42 INFO : medium: Deleted --- PASS: TestDelete (41.10s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCheck 2019/10/02 06:28:01 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 1: Starting check test 2019/10/02 06:28:02 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 2: Starting check test 2019/10/02 06:28:12 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 3: Starting check test 2019/10/02 06:28:23 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 4: Starting check test 2019/10/02 06:28:24 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 5: Starting check test 2019/10/02 06:28:36 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 6: Starting check test 2019/10/02 06:28:38 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 7: Starting check test --- PASS: TestCheck (63.06s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCheckFsError 2019/10/02 06:28:51 INFO : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: Waiting for checks to finish 2019/10/02 06:28:51 ERROR : : error reading source directory: directory not found 2019/10/02 06:28:51 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: 1 differences found --- PASS: TestCheckFsError (0.00s) === RUN TestCheckDownload 2019/10/02 06:29:02 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 1: Starting check test 2019/10/02 06:29:05 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 2: Starting check test 2019/10/02 06:29:20 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 3: Starting check test 2019/10/02 06:29:37 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 4: Starting check test 2019/10/02 06:29:43 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 5: Starting check test 2019/10/02 06:30:04 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 6: Starting check test 2019/10/02 06:30:13 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 7: Starting check test --- PASS: TestCheckDownload (103.74s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCheckSizeOnly 2019/10/02 06:30:45 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 1: Starting check test 2019/10/02 06:30:46 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 2: Starting check test 2019/10/02 06:30:58 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 3: Starting check test 2019/10/02 06:31:10 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 4: Starting check test 2019/10/02 06:31:11 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 5: Starting check test 2019/10/02 06:31:24 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 6: Starting check test 2019/10/02 06:31:25 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': 7: Starting check test --- PASS: TestCheckSizeOnly (67.09s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCat --- PASS: TestCat (64.62s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestPurge 2019/10/02 06:32:47 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2019/10/02 06:33:22 DEBUG : A2: Making directory 2019/10/02 06:33:31 DEBUG : A1/B2: Making directory 2019/10/02 06:33:36 DEBUG : A1/B2/C2: Making directory 2019/10/02 06:33:44 DEBUG : A1/B1/C3: Making directory 2019/10/02 06:33:50 DEBUG : A3: Making directory 2019/10/02 06:33:54 DEBUG : A3/B3: Making directory 2019/10/02 06:34:00 DEBUG : A3/B3/C4: Making directory 2019/10/02 06:34:27 INFO : Waiting for deletions to finish 2019/10/02 06:34:33 INFO : A1/B1/C1/one: Deleted 2019/10/02 06:34:38 DEBUG : A1/B1/C3: Removing directory 2019/10/02 06:34:42 DEBUG : A1/B1/C1: Removing directory 2019/10/02 06:34:45 DEBUG : A1/B1: Removing directory 2019/10/02 06:35:01 ERROR : : error listing: directory not found 2019/10/02 06:35:01 DEBUG : sharefile root 'rclone-test-zutexut5giyifez3yaqoyeh4': Purge remote 2019/10/02 06:35:02 purge failed: directory not found --- PASS: TestPurge (135.00s) run.go:176: Remote "sharefile root 'rclone-test-zutexut5giyifez3yaqoyeh4'", Local "Local file system at /tmp/rclone072048821", Modify Window "1s" === RUN TestRmdirsNoLeaveRoot 2019/10/02 06:35:28 DEBUG : A2: Making directory 2019/10/02 06:35:37 DEBUG : A1/B2: Making directory 2019/10/02 06:35:50 DEBUG : A1/B2/C2: Making directory 2019/10/02 06:35:55 DEBUG : A1/B1/C3: Making directory 2019/10/02 06:36:05 DEBUG : A3: Making directory 2019/10/02 06:36:14 DEBUG : A3/B3: Making directory 2019/10/02 06:36:18 DEBUG : A3/B3/C4: Making directory 2019/10/02 06:36:45 DEBUG : A3/B3/C4: Removing directory 2019/10/02 06:37:06 DEBUG : A3/B3: Removing directory 2019/10/02 06:37:15 DEBUG : A3: Removing directory 2019/10/02 06:37:21 DEBUG : A2: Removing directory 2019/10/02 06:37:26 DEBUG : A1/B2/C2: Removing directory 2019/10/02 06:37:29 DEBUG : A1/B2: Removing directory 2019/10/02 06:37:32 DEBUG : A1/B1/C3: Removing directory --- PASS: TestRmdirsNoLeaveRoot (190.87s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestRmdirsLeaveRoot 2019/10/02 06:38:13 DEBUG : A1: Making directory 2019/10/02 06:38:17 DEBUG : A1/B1: Making directory 2019/10/02 06:38:22 DEBUG : A1/B1/C1: Making directory 2019/10/02 06:38:42 DEBUG : A1/B1/C1: Removing directory 2019/10/02 06:38:47 DEBUG : A1/B1: Removing directory --- PASS: TestRmdirsLeaveRoot (55.29s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCopyURL --- PASS: TestCopyURL (50.83s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestMoveFile 2019/10/02 06:40:00 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 06:40:13 DEBUG : file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK 2019/10/02 06:40:13 INFO : file1: Copied (new) 2019/10/02 06:40:13 INFO : file1: Deleted 2019/10/02 06:40:17 DEBUG : file1: Size and modification time the same (differ by 1ns, within tolerance 1s) 2019/10/02 06:40:17 DEBUG : file1: Unchanged skipping 2019/10/02 06:40:17 INFO : file1: Deleted 2019/10/02 06:40:20 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': don't need to copy/move sub/file2, it is already at target location --- PASS: TestMoveFile (33.43s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCaseInsensitiveMoveFile 2019/10/02 06:40:34 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 06:40:51 DEBUG : file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK 2019/10/02 06:40:51 INFO : file1: Copied (new) 2019/10/02 06:40:51 INFO : file1: Deleted 2019/10/02 06:40:58 DEBUG : file1: Size and modification time the same (differ by 1ns, within tolerance 1s) 2019/10/02 06:40:58 DEBUG : file1: Unchanged skipping 2019/10/02 06:40:58 INFO : file1: Deleted 2019/10/02 06:41:09 INFO : sub/file2: Moved (server side) 2019/10/02 06:41:13 INFO : sub/File2-rclone-move-gehuwaj9: Moved (server side) --- PASS: TestCaseInsensitiveMoveFile (53.61s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestMoveFileBackupDir 2019/10/02 06:41:51 DEBUG : dst/file1: Sizes differ (src 14 vs dst 18) 2019/10/02 06:42:07 INFO : dst/file1: Moved (server side) 2019/10/02 06:42:16 DEBUG : dst/file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK 2019/10/02 06:42:16 INFO : dst/file1: Copied (new) 2019/10/02 06:42:16 INFO : dst/file1: Deleted --- PASS: TestMoveFileBackupDir (131.85s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCopyFile 2019/10/02 06:43:39 DEBUG : file1: Couldn't find file - need to transfer 2019/10/02 06:43:52 DEBUG : file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK 2019/10/02 06:43:52 INFO : file1: Copied (new) 2019/10/02 06:43:56 DEBUG : file1: Size and modification time the same (differ by 1ns, within tolerance 1s) 2019/10/02 06:43:56 DEBUG : file1: Unchanged skipping 2019/10/02 06:43:59 DEBUG : sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1': don't need to copy/move sub/file2, it is already at target location --- PASS: TestCopyFile (35.61s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCopyFileBackupDir 2019/10/02 06:44:33 DEBUG : dst/file1: Sizes differ (src 14 vs dst 18) 2019/10/02 06:44:46 INFO : dst/file1: Moved (server side) 2019/10/02 06:44:54 DEBUG : dst/file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK 2019/10/02 06:44:54 INFO : dst/file1: Copied (new) --- PASS: TestCopyFileBackupDir (75.39s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCopyFileCompareDest 2019/10/02 06:45:40 DEBUG : one: Couldn't find file - need to transfer 2019/10/02 06:45:52 DEBUG : one: MD5 = f97c5d29941bfb1b2fdab0874906ab82 OK 2019/10/02 06:45:52 INFO : one: Copied (new) 2019/10/02 06:46:00 DEBUG : one: Sizes differ (src 5 vs dst 3) 2019/10/02 06:46:07 DEBUG : one: MD5 = 07912d142f5d63ee918b34796b5a2432 OK 2019/10/02 06:46:07 INFO : one: Copied (replaced existing) 2019/10/02 06:46:39 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:46:39 DEBUG : one: Destination found in --compare-dest, skipping 2019/10/02 06:46:54 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:46:54 DEBUG : two: Destination found in --compare-dest, skipping 2019/10/02 06:46:57 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:46:57 DEBUG : two: Destination found in --compare-dest, skipping 2019/10/02 06:47:06 DEBUG : two: Sizes differ (src 5 vs dst 3) 2019/10/02 06:47:06 DEBUG : two: Couldn't find file - need to transfer 2019/10/02 06:47:14 DEBUG : two: MD5 = 2379e4ce8c3380e996ab0509f17069ad OK 2019/10/02 06:47:14 INFO : two: Copied (new) --- PASS: TestCopyFileCompareDest (128.52s) run.go:176: Remote "sharefile root 'rclone-test-gimacad5hubabaz2yuboyox1'", Local "Local file system at /tmp/rclone575241291", Modify Window "1s" === RUN TestCopyFileCopyDest panic: test timed out after 30m0s goroutine 4410 [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]: testing.(*T).Run(0xc000104700, 0x14c42bb, 0x14, 0x151bbf0, 0x4c2c01) /usr/local/go/src/testing/testing.go:961 +0x377 testing.runTests.func1(0xc00050c100) /usr/local/go/src/testing/testing.go:1202 +0x78 testing.tRunner(0xc00050c100, 0xc0007ebd78) /usr/local/go/src/testing/testing.go:909 +0xc9 testing.runTests(0xc000120b40, 0x20f9920, 0x3f, 0x3f, 0x7988d5) /usr/local/go/src/testing/testing.go:1200 +0x2a7 testing.(*M).Run(0xc000125300, 0x0) /usr/local/go/src/testing/testing.go:1117 +0x176 github.com/rclone/rclone/fstest.TestMain(0xc000125300) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:68 +0x92 github.com/rclone/rclone/fs/operations_test.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations_test.go:58 main.main() _testmain.go:168 +0x136 goroutine 18 [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 20 [select]: github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.(*worker).start(0xc000136be0) /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 21 [chan receive, 30 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000487110) /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 1497 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000125d80, 0xc000837aa0, 0xc0004a5a20) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1717 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e180, 0xc00059e840, 0xc0003a4c10) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 4384 [select]: net/http.(*persistConn).roundTrip(0xc0004d8c60, 0xc0008cad80, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/transport.go:2417 +0x770 net/http.(*Transport).roundTrip(0xc00062d180, 0xc000671500, 0x14b6731, 0xa, 0xc000725ee0) /usr/local/go/src/net/http/transport.go:535 +0x8f8 net/http.(*Transport).RoundTrip(...) /usr/local/go/src/net/http/roundtrip.go:17 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc00031b1a0, 0xc000671500, 0xc000671500, 0x0, 0xc00051a620) /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(0xc0003720c0, 0xc000671400, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/vendor/golang.org/x/oauth2/transport.go:56 +0x124 net/http.send(0xc000671400, 0x173ac00, 0xc0003720c0, 0x0, 0x0, 0x0, 0xc0000100e0, 0x203000, 0x1, 0x0) /usr/local/go/src/net/http/client.go:250 +0x43a net/http.(*Client).send(0xc0003720f0, 0xc000671400, 0x0, 0x0, 0x0, 0xc0000100e0, 0x0, 0x1, 0x148a360) /usr/local/go/src/net/http/client.go:174 +0xfa net/http.(*Client).do(0xc0003720f0, 0xc000671400, 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(0xc0004c9310, 0x175cb60, 0xc000038070, 0xc00036ea20, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:270 +0x78a github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc0004c9310, 0x175cb60, 0xc000038070, 0xc00036ea20, 0x0, 0x0, 0x11c4c60, 0xc0003aac80, 0x151b1c8, 0x151bee8, ...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:454 +0x206 github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:397 github.com/rclone/rclone/backend/sharefile.(*Fs).readMetaDataForIDPath.func1(0xc00051af30, 0x8, 0x30) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:309 +0xba github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc000192d40, 0xc000192d40, 0x1, 0x24) /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1394 +0x3c github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0008de420, 0xc000192d40, 0xa, 0x40, 0x13f7180) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x8b github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0008de420, 0xc000192d40, 0x14afb64, 0x4) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a github.com/rclone/rclone/backend/sharefile.(*Fs).readMetaDataForIDPath(0xc0003aaa00, 0x175cb60, 0xc000038070, 0xc0008dd740, 0x24, 0xc00083038e, 0x24, 0xc000360001, 0x30, 0xc00051b2b8, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:308 +0x2cc github.com/rclone/rclone/backend/sharefile.(*Fs).FindLeaf(0xc0003aaa00, 0x175cb60, 0xc000038070, 0xc0008dd740, 0x24, 0xc00083038e, 0x24, 0x0, 0x0, 0x0, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:585 +0xbb github.com/rclone/rclone/lib/dircache.(*DirCache)._findDir(0xc000461e60, 0x175cb60, 0xc000038070, 0xc00083038e, 0x24, 0x0, 0xc00051b368, 0x8e2e08, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:209 +0x169 github.com/rclone/rclone/lib/dircache.(*DirCache).FindRoot(0xc000461e60, 0x175cb60, 0xc000038070, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:261 +0xe5 github.com/rclone/rclone/backend/sharefile.NewFs(0xc000830380, 0xd, 0xc00083038e, 0x2d, 0x174ae80, 0xc000487ec0, 0x2d, 0xc000487ec0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:492 +0xa3a github.com/rclone/rclone/fs.NewFs(0xc000830380, 0x3b, 0xc00051b698, 0x8e2862, 0xc000644b40, 0x175cb60) /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1266 +0xb5 github.com/rclone/rclone/fs/cache.GetFn.func1(0xc000830380, 0x3b, 0xc000830380, 0x3b, 0x2121960, 0x10c7700, 0x173a6c0) /home/rclone/go/src/github.com/rclone/rclone/fs/cache/cache.go:17 +0x3d github.com/rclone/rclone/lib/cache.(*Cache).Get(0xc00003f050, 0xc000830380, 0x3b, 0xc00051b760, 0x0, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/cache/cache.go:60 +0x181 github.com/rclone/rclone/fs/cache.GetFn(0xc000830380, 0x3b, 0x151b920, 0x175cb60, 0xc000038070, 0x173a6c0, 0xc00000e640) /home/rclone/go/src/github.com/rclone/rclone/fs/cache/cache.go:16 +0x76 github.com/rclone/rclone/fs/cache.Get(...) /home/rclone/go/src/github.com/rclone/rclone/fs/cache/cache.go:29 github.com/rclone/rclone/fs/operations.GetCopyDest(0x1770260, 0xc0005a8aa0, 0xc00000e640, 0x14af001, 0x3, 0x0) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1414 +0x5e github.com/rclone/rclone/fs/operations.moveOrCopyFile(0x175cb60, 0xc000038070, 0x1770260, 0xc0005a8aa0, 0x176f760, 0xc0000f6080, 0x14af0b7, 0x3, 0x14af0b7, 0x3, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1721 +0x91d github.com/rclone/rclone/fs/operations.CopyFile(...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1759 github.com/rclone/rclone/fs/operations_test.TestCopyFileCopyDest(0xc000104700) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations_test.go:911 +0x3a7 testing.tRunner(0xc000104700, 0x151bbf0) /usr/local/go/src/testing/testing.go:909 +0xc9 created by testing.(*T).Run /usr/local/go/src/testing/testing.go:960 +0x350 goroutine 1649 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006de600, 0xc0008de900, 0xc00011a3f0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1797 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000124200, 0xc00069e000, 0xc0007d21d0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1442 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006de300, 0xc00059e6c0, 0xc00011aac0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1415 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000124300, 0xc00069e1e0, 0xc000038a50) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1621 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e400, 0xc000837020, 0xc0004a5280) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 2171 [chan receive (nil chan), 17 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000124080, 0xc0003d4b40, 0xc000362bc0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 3545 [chan receive, 6 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc00031b350) /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 4228 [IO wait, 1 minutes]: internal/poll.runtime_pollWait(0x7f23d57e0900, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc000829918, 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(0xc000829900, 0xc000744000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc000829900, 0xc000744000, 0xe62, 0xe62, 0x4de32d39fe1abb06, 0x620f8206e3b97290, 0x1000000a75b310c) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc000343738, 0xc000744000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc00000fae0, 0xc000813888, 0xc000744000, 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(0xc00000fae0, 0xc000744000, 0xe62, 0xe62, 0xc00074400d, 0xf5, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0000fd500, 0xc000744000, 0xe62, 0xe62, 0x112, 0x1739620, 0xc000813970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc0004785d8, 0x1739400, 0xc0000fd500, 0x40bfa5, 0x12c94e0, 0x13d9b00) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000478380, 0x7f23d57e9868, 0xc00000fae0, 0x5, 0xc00000fae0, 0xf5) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000478380, 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(0xc000478380, 0xc00079c000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc0008deea0, 0xc00022e658, 0x9, 0x9, 0xc000813d10, 0x0, 0x7324c2) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1739240, 0xc0008deea0, 0xc00022e658, 0x9, 0x9, 0x9, 0xc000068060, 0x0, 0x1739620) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc00022e658, 0x9, 0x9, 0x1739240, 0xc0008deea0, 0x0, 0x0, 0xc0007c0c30, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc00022e620, 0xc0007c0c30, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc000813fb8, 0x70c40d, 0xc0003d54a0) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc000802600) /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 1582 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000124680, 0xc00069e6c0, 0xc0003637b0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1550 [chan receive (nil chan), 19 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e100, 0xc000836960, 0xc0004a47d0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 2129 [chan receive (nil chan), 17 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006de100, 0xc000836cc0, 0xc0004a52d0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1362 [chan receive (nil chan), 20 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006deb00, 0xc00069ff20, 0xc0007d3980) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 3998 [chan receive, 2 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0003722d0) /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 1965 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e380, 0xc00069faa0, 0xc0007d3830) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1763 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006de080, 0xc00007d5c0, 0xc000038ea0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 3983 [chan receive, 3 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000110450) /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 2422 [chan receive, 15 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000108480) /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 1845 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e400, 0xc00007d140, 0xc000038ef0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 1894 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e900, 0xc000836fc0, 0xc0003a43a0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 2188 [chan receive (nil chan), 17 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0004a8c00, 0xc00059ef00, 0xc0000394a0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 4424 [select]: net/http.(*persistConn).writeLoop(0xc0004d8c60) /usr/local/go/src/net/http/transport.go:2196 +0x123 created by net/http.(*Transport).dialConn /usr/local/go/src/net/http/transport.go:1567 +0xb23 goroutine 2018 [chan receive (nil chan), 18 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006dec00, 0xc00059fa40, 0xc0004a5740) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 4385 [chan receive]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0001b73e0) /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 4423 [IO wait]: internal/poll.runtime_pollWait(0x7f23d57e0d10, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc0000f6e18, 0x72, 0xe00, 0xe59, 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(0xc0000f6e00, 0xc0002dc000, 0xe59, 0xe59, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc0000f6e00, 0xc0002dc000, 0xe59, 0xe59, 0xf1369b8d0dab9ef7, 0x26104fa5079c808f, 0x100000016322703) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc0003436d0, 0xc0002dc000, 0xe59, 0xe59, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc000370e20, 0xc0002627b8, 0xc0002dc000, 0xe59, 0xe59, 0x203000, 0x0, 0xe4c) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000370e20, 0xc0002dc000, 0xe59, 0xe59, 0xc000262848, 0x471d11, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0003055e0, 0xc0002dc000, 0xe59, 0xe59, 0x3, 0x8, 0xc0002628a0) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc0003a0258, 0x1739400, 0xc0003055e0, 0x40bfa5, 0x12c94e0, 0x13d9b00) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc0003a0000, 0x7f23d57e9868, 0xc000370e20, 0x5, 0xc000370e20, 0x18) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc0003a0000, 0x0, 0x0, 0x3) /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(0xc0003a0000, 0xc0002dd000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 net/http.(*persistConn).Read(0xc0004d8c60, 0xc0002dd000, 0x1000, 0x1000, 0xc000580960, 0xc000262c20, 0x406975) /usr/local/go/src/net/http/transport.go:1744 +0x75 bufio.(*Reader).fill(0xc00071d800) /usr/local/go/src/bufio/bufio.go:100 +0x103 bufio.(*Reader).Peek(0xc00071d800, 0x1, 0x0, 0x0, 0x1, 0xc000094900, 0x0) /usr/local/go/src/bufio/bufio.go:138 +0x4f net/http.(*persistConn).readLoop(0xc0004d8c60) /usr/local/go/src/net/http/transport.go:1897 +0x1d6 created by net/http.(*Transport).dialConn /usr/local/go/src/net/http/transport.go:1566 +0xafe goroutine 4452 [chan receive]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0003722a0) /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 2111 [chan receive (nil chan), 17 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00011e880, 0xc00059e180, 0xc0007d3020) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 2655 [IO wait]: internal/poll.runtime_pollWait(0x7f23d57e0c40, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc0006df398, 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(0xc0006df380, 0xc000648000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc0006df380, 0xc000648000, 0xe62, 0xe62, 0x17bbe14588ce697b, 0x40ac1b, 0xc000347650) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc000343760, 0xc000648000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0000fd700, 0xc000062888, 0xc000648000, 0xe62, 0xe62, 0x203000, 0x13d10a0, 0xc00019ea80) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0000fd700, 0xc000648000, 0xe62, 0xe62, 0xf6242fc3ec5e5525, 0xc000062908, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc000370d80, 0xc000648000, 0xe62, 0xe62, 0xc0000629b8, 0x41027e, 0xc000062970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc0000573d8, 0x1739400, 0xc000370d80, 0x40bfa5, 0x12c94e0, 0x13d9b00) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000057180, 0x7f23d57e9868, 0xc0000fd700, 0x5, 0xc0000fd700, 0x203000) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000057180, 0x0, 0x0, 0x40dacc) /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(0xc000057180, 0xc00069c000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc000837440, 0xc00001a2d8, 0x9, 0x9, 0xc000062d10, 0x0, 0x7324c2) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1739240, 0xc000837440, 0xc00001a2d8, 0x9, 0x9, 0x9, 0xc000068060, 0x0, 0x1739620) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc00001a2d8, 0x9, 0x9, 0x1739240, 0xc000837440, 0x0, 0x0, 0xc00003fd40, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc00001a2a0, 0xc00003fd40, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc000062fb8, 0x151dc00, 0xc0003d7b40) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc000707380) /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 2295 [chan receive (nil chan), 16 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000124300, 0xc000836900, 0xc00011a6b0) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 2280 [chan receive (nil chan), 16 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc000124c80, 0xc000836180, 0xc00011a290) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 2245 [chan receive (nil chan), 17 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0004a8d80, 0xc00069e480, 0xc0004a4870) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 3890 [chan receive, 3 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0007c16e0) /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 "./operations.test -test.v -test.timeout 30m0s -remote TestSharefile: -verbose" - Finished ERROR in 30m4.371801039s (try 1/5): exit status 2: Failed [TestLs]