"./operations.test -test.v -test.timeout 30m0s -remote TestB2: -verbose -fast-list" - 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} 2020/04/15 05:03:30 DEBUG : file1: Starting multi-thread copy with 2 parts of size 64k 2020/04/15 05:03:30 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131071) size 63.999k starting 2020/04/15 05:03:30 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k starting 2020/04/15 05:03:31 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k finished 2020/04/15 05:03:31 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131071) size 63.999k finished 2020/04/15 05:03:31 DEBUG : file1: Finished multi-thread copy with 2 parts of size 64k === RUN TestMultithreadCopy/{size:131072_streams:2} 2020/04/15 05:03:34 DEBUG : file1: Starting multi-thread copy with 2 parts of size 64k 2020/04/15 05:03:34 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131072) size 64k starting 2020/04/15 05:03:34 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k starting 2020/04/15 05:03:35 DEBUG : file1: multi-thread copy: stream 2/2 (65536-131072) size 64k finished 2020/04/15 05:03:35 DEBUG : file1: multi-thread copy: stream 1/2 (0-65536) size 64k finished 2020/04/15 05:03:35 DEBUG : file1: Finished multi-thread copy with 2 parts of size 64k === RUN TestMultithreadCopy/{size:131073_streams:2} 2020/04/15 05:03:35 DEBUG : file1: Clearing upload URL because of error: c001_v0001136_t0007 is too busy (503 service_unavailable) 2020/04/15 05:03:35 DEBUG : pacer: low level retry 1/1 (error c001_v0001136_t0007 is too busy (503 service_unavailable)) 2020/04/15 05:03:35 DEBUG : pacer: Rate limited, increasing sleep to 1s 2020/04/15 05:03:37 DEBUG : pacer: Reducing sleep to 500ms 2020/04/15 05:03:40 DEBUG : pacer: Reducing sleep to 250ms 2020/04/15 05:03:40 DEBUG : pacer: Reducing sleep to 125ms 2020/04/15 05:03:40 DEBUG : pacer: Reducing sleep to 62.5ms 2020/04/15 05:03:40 DEBUG : file1: Starting multi-thread copy with 2 parts of size 128k 2020/04/15 05:03:40 DEBUG : file1: multi-thread copy: stream 2/2 (131072-131073) size 1 starting 2020/04/15 05:03:40 DEBUG : file1: multi-thread copy: stream 1/2 (0-131072) size 128k starting 2020/04/15 05:03:41 DEBUG : pacer: Reducing sleep to 31.25ms 2020/04/15 05:03:41 DEBUG : file1: multi-thread copy: stream 2/2 (131072-131073) size 1 finished 2020/04/15 05:03:41 DEBUG : pacer: Reducing sleep to 15.625ms 2020/04/15 05:03:41 DEBUG : file1: multi-thread copy: stream 1/2 (0-131072) size 128k finished 2020/04/15 05:03:41 DEBUG : file1: Finished multi-thread copy with 2 parts of size 128k 2020/04/15 05:03:41 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestMultithreadCopy (15.92s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" --- PASS: TestMultithreadCopy/{size:131071_streams:2} (5.10s) --- PASS: TestMultithreadCopy/{size:131072_streams:2} (3.32s) run.go:278: Retry Put of "file1" to B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1/10 (c001_v0001136_t0007 is too busy (503 service_unavailable)) --- PASS: TestMultithreadCopy/{size:131073_streams:2} (6.45s) === RUN TestSizeDiffers --- PASS: TestSizeDiffers (0.00s) === RUN TestReOpen === RUN TestReOpen/Seek === RUN TestReOpen/Seek/Basics === RUN TestReOpen/Seek/ErrorAtStart === RUN TestReOpen/Seek/WithErrors 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Seek/TooManyErrors 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2020/04/15 05:03:42 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 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Range/TooManyErrors 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2020/04/15 05:03:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2020/04/15 05:03:42 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 (0.29s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateSkip --- SKIP: TestDeduplicateSkip (0.29s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateFirst --- SKIP: TestDeduplicateFirst (0.33s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateNewest --- SKIP: TestDeduplicateNewest (0.29s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateOldest --- SKIP: TestDeduplicateOldest (0.29s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateLargest --- SKIP: TestDeduplicateLargest (0.29s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateSmallest --- SKIP: TestDeduplicateSmallest (0.30s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestDeduplicateRename --- SKIP: TestDeduplicateRename (0.30s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:23: Can't test deduplicate - no duplicate files possible === RUN TestMergeDirs --- SKIP: TestMergeDirs (0.31s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" dedupe_test.go:217: Can't merge directories === RUN TestListDirSorted 2020/04/15 05:03:57 DEBUG : a.txt: Excluded 2020/04/15 05:03:57 DEBUG : sub dir/hello world: Excluded 2020/04/15 05:03:57 DEBUG : sub dir/hello world2: Excluded 2020/04/15 05:03:58 DEBUG : sub dir/hello world: Excluded 2020/04/15 05:03:58 DEBUG : sub dir/hello world2: Excluded 2020/04/15 05:03:58 DEBUG : sub dir/ignore dir: Excluded 2020/04/15 05:03:58 DEBUG : sub dir/ignore dir: Excluded --- PASS: TestListDirSorted (21.98s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestMkdir 2020/04/15 05:04:07 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: Making directory 2020/04/15 05:04:07 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: Making directory --- PASS: TestMkdir (0.44s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestLsd --- PASS: TestLsd (3.89s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestLs 2020/04/15 05:04:16 DEBUG : pacer: low level retry 1/10 (error Post https://api001.backblazeb2.com/b2api/v1/b2_list_file_names: EOF) 2020/04/15 05:04:16 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2020/04/15 05:04:17 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestLs (7.02s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestLsWithFilesFrom 2020/04/15 05:05:30 DEBUG : empty space: Excluded from sync (and deletion) --- FAIL: TestLsWithFilesFrom (73.49s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:112 Error: Should be true Test: TestLsWithFilesFrom Messages: listing wrong, want empty space (1), potato2 (60) got empty space (1) fstest.go:194: Not found "potato2" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:112 Error: Not equal: expected: 0 actual : 1 Test: TestLsWithFilesFrom Messages: 1 objects not found operations_test.go:130: Error Trace: operations_test.go:130 Error: Not equal: expected: " 60 potato2\n" actual : "" Diff: --- Expected +++ Actual @@ -1,2 +1 @@ - 60 potato2 Test: TestLsWithFilesFrom operations_test.go:142: Error Trace: operations_test.go:142 Error: Not equal: expected: " 60 potato2\n" actual : "" Diff: --- Expected +++ Actual @@ -1,2 +1 @@ - 60 potato2 Test: TestLsWithFilesFrom === RUN TestLsLong --- PASS: TestLsLong (5.82s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestHashSums --- PASS: TestHashSums (16.34s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestSuffixName --- PASS: TestSuffixName (0.00s) === RUN TestCount --- PASS: TestCount (10.76s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestDelete 2020/04/15 05:06:11 DEBUG : Waiting for deletions to finish 2020/04/15 05:06:11 DEBUG : large: Excluded from sync (and deletion) 2020/04/15 05:06:12 INFO : small: Deleted 2020/04/15 05:06:16 INFO : medium: Deleted --- PASS: TestDelete (12.50s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCheck 2020/04/15 05:06:19 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1: Starting check test 2020/04/15 05:06:19 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 2: Starting check test 2020/04/15 05:06:21 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 3: Starting check test 2020/04/15 05:06:23 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 4: Starting check test 2020/04/15 05:06:23 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 5: Starting check test 2020/04/15 05:06:23 DEBUG : remotepotato: Clearing upload URL because of error: c001_v0001136_t0026 is too busy (503 service_unavailable) 2020/04/15 05:06:23 DEBUG : pacer: low level retry 1/1 (error c001_v0001136_t0026 is too busy (503 service_unavailable)) 2020/04/15 05:06:23 DEBUG : pacer: Rate limited, increasing sleep to 1s 2020/04/15 05:06:25 DEBUG : pacer: Reducing sleep to 500ms 2020/04/15 05:06:34 DEBUG : pacer: Reducing sleep to 250ms 2020/04/15 05:06:34 DEBUG : pacer: Reducing sleep to 125ms 2020/04/15 05:06:34 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 6: Starting check test 2020/04/15 05:06:34 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 7: Starting check test 2020/04/15 05:06:35 DEBUG : pacer: Reducing sleep to 15.625ms 2020/04/15 05:06:43 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestCheck (34.88s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" run.go:278: Retry Put of "remotepotato" to B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1/10 (c001_v0001136_t0026 is too busy (503 service_unavailable)) === RUN TestCheckFsError 2020/04/15 05:06:52 DEBUG : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/non-existent: Waiting for checks to finish 2020/04/15 05:06:52 ERROR : : error reading source directory: directory not found 2020/04/15 05:06:52 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 2020/04/15 05:06:56 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1: Starting check test 2020/04/15 05:06:57 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 2: Starting check test 2020/04/15 05:07:03 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 3: Starting check test 2020/04/15 05:07:20 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 4: Starting check test 2020/04/15 05:07:21 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 5: Starting check test 2020/04/15 05:07:22 DEBUG : remotepotato: Clearing upload URL because of error: c001_v0001039_t0048 is too busy (503 service_unavailable) 2020/04/15 05:07:22 DEBUG : pacer: low level retry 1/1 (error c001_v0001039_t0048 is too busy (503 service_unavailable)) 2020/04/15 05:07:22 DEBUG : pacer: Rate limited, increasing sleep to 1s 2020/04/15 05:07:24 DEBUG : pacer: Reducing sleep to 500ms 2020/04/15 05:07:42 DEBUG : pacer: Reducing sleep to 250ms 2020/04/15 05:07:43 DEBUG : pacer: Reducing sleep to 125ms 2020/04/15 05:07:43 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 6: Starting check test 2020/04/15 05:07:44 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 7: Starting check test --- PASS: TestCheckDownload (62.21s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" run.go:278: Retry Put of "remotepotato" to B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1/10 (c001_v0001039_t0048 is too busy (503 service_unavailable)) === RUN TestCheckSizeOnly 2020/04/15 05:07:55 DEBUG : rutabaga: Clearing upload URL because of error: c001_v0001044_t0015 is too busy (503 service_unavailable) 2020/04/15 05:07:55 DEBUG : pacer: low level retry 1/1 (error c001_v0001044_t0015 is too busy (503 service_unavailable)) 2020/04/15 05:07:55 DEBUG : pacer: Rate limited, increasing sleep to 1s 2020/04/15 05:07:57 DEBUG : pacer: Reducing sleep to 500ms 2020/04/15 05:08:01 DEBUG : pacer: Reducing sleep to 250ms 2020/04/15 05:08:01 DEBUG : pacer: Reducing sleep to 125ms 2020/04/15 05:08:01 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1: Starting check test 2020/04/15 05:08:01 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 2: Starting check test 2020/04/15 05:08:03 DEBUG : pacer: Reducing sleep to 15.625ms 2020/04/15 05:08:04 DEBUG : pacer: Reducing sleep to 10ms 2020/04/15 05:08:04 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 3: Starting check test 2020/04/15 05:08:04 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 4: Starting check test 2020/04/15 05:08:04 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 5: Starting check test 2020/04/15 05:08:06 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 6: Starting check test 2020/04/15 05:08:06 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: 7: Starting check test --- PASS: TestCheckSizeOnly (17.29s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" run.go:278: Retry Put of "rutabaga" to B2 bucket rclone-test-fefesij9cerohub7negihiy0: 1/10 (c001_v0001044_t0015 is too busy (503 service_unavailable)) === RUN TestCat --- PASS: TestCat (6.19s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestPurge 2020/04/15 05:08:18 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2020/04/15 05:08:20 DEBUG : A1/B1/C1/one: Clearing upload URL because of error: c001_v0001044_t0002 is too busy (503 service_unavailable) 2020/04/15 05:08:20 DEBUG : pacer: low level retry 1/1 (error c001_v0001044_t0002 is too busy (503 service_unavailable)) 2020/04/15 05:08:20 DEBUG : pacer: Rate limited, increasing sleep to 1s 2020/04/15 05:08:22 DEBUG : pacer: Reducing sleep to 500ms 2020/04/15 05:08:24 DEBUG : pacer: Reducing sleep to 250ms 2020/04/15 05:08:24 DEBUG : A2: Making directory 2020/04/15 05:08:24 DEBUG : A1/B2: Making directory 2020/04/15 05:08:24 DEBUG : A1/B2/C2: Making directory 2020/04/15 05:08:24 DEBUG : A1/B1/C3: Making directory 2020/04/15 05:08:24 DEBUG : A3: Making directory 2020/04/15 05:08:24 DEBUG : A3/B3: Making directory 2020/04/15 05:08:24 DEBUG : A3/B3/C4: Making directory 2020/04/15 05:08:25 DEBUG : pacer: Reducing sleep to 125ms 2020/04/15 05:08:25 DEBUG : pacer: Reducing sleep to 62.5ms 2020/04/15 05:08:25 DEBUG : Waiting for deletions to finish 2020/04/15 05:08:25 DEBUG : pacer: Reducing sleep to 31.25ms 2020/04/15 05:08:25 DEBUG : pacer: Reducing sleep to 15.625ms 2020/04/15 05:08:25 INFO : A1/B1/C1/one: Deleted 2020/04/15 05:08:26 DEBUG : pacer: Reducing sleep to 10ms 2020/04/15 05:08:26 DEBUG : A1/B1: Removing directory 2020/04/15 05:08:26 DEBUG : A1/B1/C1/one: Deleting (id "4_zef22ed9330cd7bcb7f180e1b_f1197d98027879901_d20200415_m050825_c001_v0001128_t0001") 2020/04/15 05:08:26 DEBUG : A1/B1/C1/one: Deleting (id "4_zef22ed9330cd7bcb7f180e1b_f10425bf4e16528b9_d20200415_m050823_c001_v0001136_t0048") 2020/04/15 05:08:26 DEBUG : A1/two: Deleting (id "4_zef22ed9330cd7bcb7f180e1b_f10425bf4e16528c3_d20200415_m050824_c001_v0001136_t0048") 2020/04/15 05:08:27 DEBUG : B2 bucket rclone-test-puputox5tejevic7tayoren9: Purge remote 2020/04/15 05:08:27 purge failed: directory not found --- PASS: TestPurge (9.29s) run.go:176: Remote "B2 bucket rclone-test-puputox5tejevic7tayoren9", Local "Local file system at /tmp/rclone013795797", Modify Window "1ms" run.go:278: Retry Put of "A1/B1/C1/one" to B2 bucket rclone-test-puputox5tejevic7tayoren9: 1/10 (c001_v0001044_t0002 is too busy (503 service_unavailable)) fstest.go:241: Filtering empty directory "A2" fstest.go:241: Filtering empty directory "A1/B2" fstest.go:241: Filtering empty directory "A1/B2/C2" fstest.go:241: Filtering empty directory "A1/B1/C3" fstest.go:241: Filtering empty directory "A3" fstest.go:241: Filtering empty directory "A3/B3" fstest.go:241: Filtering empty directory "A3/B3/C4" fstest.go:241: Filtering empty directory "A2" fstest.go:241: Filtering empty directory "A1/B2" fstest.go:241: Filtering empty directory "A1/B2/C2" fstest.go:241: Filtering empty directory "A3" fstest.go:241: Filtering empty directory "A3/B3" fstest.go:241: Filtering empty directory "A3/B3/C4" === RUN TestRmdirsNoLeaveRoot 2020/04/15 05:08:32 DEBUG : A2: Making directory 2020/04/15 05:08:32 DEBUG : A1/B2: Making directory 2020/04/15 05:08:32 DEBUG : A1/B2/C2: Making directory 2020/04/15 05:08:32 DEBUG : A1/B1/C3: Making directory 2020/04/15 05:08:32 DEBUG : A3: Making directory 2020/04/15 05:08:32 DEBUG : A3/B3: Making directory 2020/04/15 05:08:32 DEBUG : A3/B3/C4: Making directory 2020/04/15 05:08:32 DEBUG : pacer: low level retry 1/10 (error Post https://api001.backblazeb2.com/b2api/v1/b2_list_file_names: EOF) 2020/04/15 05:08:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2020/04/15 05:08:32 DEBUG : pacer: Reducing sleep to 10ms 2020/04/15 05:08:32 DEBUG : A3/B3/C4: Removing directory --- PASS: TestRmdirsNoLeaveRoot (7.53s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" fstest.go:241: Filtering empty directory "A2" fstest.go:241: Filtering empty directory "A1/B2" fstest.go:241: Filtering empty directory "A1/B2/C2" fstest.go:241: Filtering empty directory "A1/B1/C3" fstest.go:241: Filtering empty directory "A3" fstest.go:241: Filtering empty directory "A3/B3" fstest.go:241: Filtering empty directory "A3/B3/C4" fstest.go:241: Filtering empty directory "A2" fstest.go:241: Filtering empty directory "A1/B2" fstest.go:241: Filtering empty directory "A1/B2/C2" fstest.go:241: Filtering empty directory "A1/B1/C3" fstest.go:241: Filtering empty directory "A3" fstest.go:241: Filtering empty directory "A3/B3" === RUN TestRmdirsLeaveRoot 2020/04/15 05:08:35 DEBUG : A1: Making directory 2020/04/15 05:08:35 DEBUG : A1/B1: Making directory 2020/04/15 05:08:35 DEBUG : A1/B1/C1: Making directory --- PASS: TestRmdirsLeaveRoot (0.77s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" fstest.go:241: Filtering empty directory "A1" fstest.go:241: Filtering empty directory "A1/B1" fstest.go:241: Filtering empty directory "A1/B1/C1" fstest.go:241: Filtering empty directory "A1" === RUN TestCopyURL --- PASS: TestCopyURL (14.98s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCopyURLToWriter --- PASS: TestCopyURLToWriter (0.00s) === RUN TestMoveFile 2020/04/15 05:08:50 DEBUG : file1: Need to transfer - File not found at Destination 2020/04/15 05:08:51 DEBUG : file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/04/15 05:08:51 INFO : file1: Copied (new) 2020/04/15 05:08:51 INFO : file1: Deleted 2020/04/15 05:08:51 DEBUG : file1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2020/04/15 05:08:51 DEBUG : file1: Unchanged skipping 2020/04/15 05:08:51 INFO : file1: Deleted 2020/04/15 05:08:51 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: don't need to copy/move sub/file2, it is already at target location --- PASS: TestMoveFile (2.58s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCaseInsensitiveMoveFile --- PASS: TestCaseInsensitiveMoveFile (0.30s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestMoveFileBackupDir 2020/04/15 05:08:55 DEBUG : dst/file1: Sizes differ (src 14 vs dst 18) 2020/04/15 05:08:56 DEBUG : dst/file1: SHA-1 = 9d125cddbdc7323ccf9db2d2b67af177f781b5c6 OK 2020/04/15 05:08:56 INFO : dst/file1: Copied (server side copy) 2020/04/15 05:08:58 INFO : dst/file1: Deleted 2020/04/15 05:08:58 DEBUG : dst/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/04/15 05:08:58 INFO : dst/file1: Copied (new) 2020/04/15 05:08:58 INFO : dst/file1: Deleted --- PASS: TestMoveFileBackupDir (24.47s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCopyFile 2020/04/15 05:09:18 DEBUG : file1: Need to transfer - File not found at Destination 2020/04/15 05:09:19 DEBUG : file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/04/15 05:09:19 INFO : file1: Copied (new) 2020/04/15 05:09:19 DEBUG : file1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2020/04/15 05:09:19 DEBUG : file1: Unchanged skipping 2020/04/15 05:09:19 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: don't need to copy/move sub/file2, it is already at target location --- PASS: TestCopyFile (2.38s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCopyFileBackupDir 2020/04/15 05:09:22 DEBUG : dst/file1: Sizes differ (src 14 vs dst 18) 2020/04/15 05:09:23 DEBUG : dst/file1: SHA-1 = 9d125cddbdc7323ccf9db2d2b67af177f781b5c6 OK 2020/04/15 05:09:23 INFO : dst/file1: Copied (server side copy) 2020/04/15 05:09:23 INFO : dst/file1: Deleted 2020/04/15 05:09:24 DEBUG : dst/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/04/15 05:09:24 INFO : dst/file1: Copied (new) --- PASS: TestCopyFileBackupDir (5.93s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCopyFileCompareDest 2020/04/15 05:09:27 DEBUG : one: Need to transfer - File not found at Destination 2020/04/15 05:09:30 DEBUG : one: SHA-1 = fe05bcdcdc4928012781a5f1a2a77cbb5398e106 OK 2020/04/15 05:09:30 INFO : one: Copied (new) 2020/04/15 05:09:30 DEBUG : one: Sizes differ (src 5 vs dst 3) 2020/04/15 05:09:31 DEBUG : one: SHA-1 = 7f376fd65843a1267de8f986d40e164e5a321c13 OK 2020/04/15 05:09:31 INFO : one: Copied (replaced existing) 2020/04/15 05:09:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:09:33 DEBUG : one: Destination found in --compare-dest, skipping 2020/04/15 05:09:34 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:09:34 DEBUG : two: Destination found in --compare-dest, skipping 2020/04/15 05:09:35 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:09:35 DEBUG : two: Destination found in --compare-dest, skipping 2020/04/15 05:09:35 DEBUG : two: Sizes differ (src 5 vs dst 3) 2020/04/15 05:09:35 DEBUG : two: Need to transfer - File not found at Destination 2020/04/15 05:09:36 DEBUG : two: SHA-1 = a4be8877ad88f3109a6411985a1f359e10e2d930 OK 2020/04/15 05:09:36 INFO : two: Copied (new) --- PASS: TestCopyFileCompareDest (14.12s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCopyFileCopyDest 2020/04/15 05:09:42 DEBUG : one: Need to transfer - File not found at Destination 2020/04/15 05:09:43 DEBUG : one: SHA-1 = fe05bcdcdc4928012781a5f1a2a77cbb5398e106 OK 2020/04/15 05:09:43 INFO : one: Copied (new) 2020/04/15 05:09:44 DEBUG : one: Sizes differ (src 5 vs dst 3) 2020/04/15 05:09:44 DEBUG : one: SHA-1 = 7f376fd65843a1267de8f986d40e164e5a321c13 OK 2020/04/15 05:09:44 INFO : one: Copied (replaced existing) 2020/04/15 05:09:47 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:09:47 DEBUG : one: Sizes differ (src 5 vs dst 3) 2020/04/15 05:09:49 DEBUG : one: SHA-1 = fe05bcdcdc4928012781a5f1a2a77cbb5398e106 OK 2020/04/15 05:09:49 INFO : one: Copied (server side copy) 2020/04/15 05:09:49 INFO : one: Deleted 2020/04/15 05:09:50 DEBUG : one: SHA-1 = 7f376fd65843a1267de8f986d40e164e5a321c13 OK 2020/04/15 05:09:50 INFO : one: Copied (server side copy) 2020/04/15 05:09:50 DEBUG : one: Destination found in --copy-dest, using server side copy 2020/04/15 05:12:02 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:12:04 DEBUG : two: SHA-1 = ad782ecdac770fc6eb9a62e44f90873fb97fb26b OK 2020/04/15 05:12:04 INFO : two: Copied (server side copy) 2020/04/15 05:12:04 DEBUG : two: Destination found in --copy-dest, using server side copy 2020/04/15 05:13:10 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:13:10 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/04/15 05:13:10 DEBUG : two: Unchanged skipping 2020/04/15 05:15:22 DEBUG : three: Sizes differ (src 7 vs dst 5) 2020/04/15 05:15:22 DEBUG : three: Destination not found in --copy-dest 2020/04/15 05:15:22 DEBUG : three: Need to transfer - File not found at Destination 2020/04/15 05:15:22 DEBUG : three: SHA-1 = 370e613335f3cf2f19b2a2d35a86402f55c659f8 OK 2020/04/15 05:15:22 INFO : three: Copied (new) --- FAIL: TestCopyFileCopyDest (413.78s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:1020 Error: Should be true Test: TestCopyFileCopyDest Messages: listing wrong, want BackupDir/one (3), CopyDest/one (5), dst/one (5) got BackupDir/one (3), CopyDest/one (5) fstest.go:194: Not found "dst/one" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:1020 Error: Not equal: expected: 0 actual : 1 Test: TestCopyFileCopyDest Messages: 1 objects not found fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:1026 Error: Should be true Test: TestCopyFileCopyDest Messages: listing wrong, want BackupDir/one (3), CopyDest/one (5), CopyDest/two (3), dst/one (5) got BackupDir/one (3), CopyDest/one (5), CopyDest/two (3) fstest.go:194: Not found "dst/one" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:1026 Error: Not equal: expected: 0 actual : 1 Test: TestCopyFileCopyDest Messages: 1 objects not found fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:1035 Error: Should be true Test: TestCopyFileCopyDest Messages: listing wrong, want BackupDir/one (3), CopyDest/one (5), CopyDest/two (3), dst/one (5), dst/two (3) got BackupDir/one (3), CopyDest/one (5), CopyDest/two (3), dst/two (3) fstest.go:194: Not found "dst/one" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:1035 Error: Not equal: expected: 0 actual : 1 Test: TestCopyFileCopyDest Messages: 1 objects not found fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:1041 Error: Should be true Test: TestCopyFileCopyDest Messages: listing wrong, want BackupDir/one (3), CopyDest/one (5), CopyDest/two (3), dst/one (5), dst/two (3) got BackupDir/one (3), CopyDest/one (5), CopyDest/two (3), dst/two (3) fstest.go:194: Not found "dst/one" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:1041 Error: Not equal: expected: 0 actual : 1 Test: TestCopyFileCopyDest Messages: 1 objects not found fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:1046 Error: Should be true Test: TestCopyFileCopyDest Messages: listing wrong, want BackupDir/one (3), CopyDest/one (5), CopyDest/three (5), CopyDest/two (3), dst/one (5), dst/two (3) got BackupDir/one (3), CopyDest/one (5), CopyDest/three (5), CopyDest/two (3), dst/two (3) fstest.go:194: Not found "dst/one" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:1046 Error: Not equal: expected: 0 actual : 1 Test: TestCopyFileCopyDest Messages: 1 objects not found fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 operations_test.go:1055 Error: Should be true Test: TestCopyFileCopyDest Messages: listing wrong, want BackupDir/one (3), CopyDest/one (5), CopyDest/three (5), CopyDest/two (3), dst/one (5), dst/three (7), dst/two (3) got BackupDir/one (3), CopyDest/one (5), CopyDest/three (5), CopyDest/two (3), dst/three (7), dst/two (3) fstest.go:194: Not found "dst/one" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 operations_test.go:1055 Error: Not equal: expected: 0 actual : 1 Test: TestCopyFileCopyDest Messages: 1 objects not found === RUN TestSameConfig --- PASS: TestSameConfig (0.00s) === RUN TestSame --- PASS: TestSame (0.00s) === RUN TestOverlapping --- PASS: TestOverlapping (0.00s) === RUN TestCheckEqualReaders --- PASS: TestCheckEqualReaders (0.00s) === RUN TestListFormat --- PASS: TestListFormat (0.00s) === RUN TestDirMove 2020/04/15 05:16:37 DEBUG : A1/B2: Making directory 2020/04/15 05:16:37 DEBUG : A1/B1/C3: Making directory 2020/04/15 05:16:38 DEBUG : A1/B1/C1/four: SHA-1 = 9f8f7eec5dea5ac43738721939c120318cbff1df OK 2020/04/15 05:16:38 INFO : A1/B1/C1/four: Copied (server side copy) 2020/04/15 05:16:38 DEBUG : A1/B1/three: SHA-1 = b802f384302cb24fbab0a44997e820bf2e8507bb OK 2020/04/15 05:16:38 INFO : A1/B1/three: Copied (server side copy) 2020/04/15 05:16:38 DEBUG : A1/one: SHA-1 = fe05bcdcdc4928012781a5f1a2a77cbb5398e106 OK 2020/04/15 05:16:38 INFO : A1/one: Copied (server side copy) 2020/04/15 05:16:38 INFO : A1/one: Deleted 2020/04/15 05:16:39 INFO : A1/B1/C1/four: Deleted 2020/04/15 05:16:39 INFO : A1/B1/three: Deleted 2020/04/15 05:16:39 DEBUG : A1/two: SHA-1 = ad782ecdac770fc6eb9a62e44f90873fb97fb26b OK 2020/04/15 05:16:39 INFO : A1/two: Copied (server side copy) 2020/04/15 05:16:39 DEBUG : A1/B1/C2/five: SHA-1 = 4db2c1df4610cd6c0da6b9197b066bfb4e9b9d00 OK 2020/04/15 05:16:39 INFO : A1/B1/C2/five: Copied (server side copy) 2020/04/15 05:16:39 INFO : A1/two: Deleted 2020/04/15 05:16:40 INFO : A1/B1/C2/five: Deleted 2020/04/15 05:16:41 DEBUG : A2/one: SHA-1 = fe05bcdcdc4928012781a5f1a2a77cbb5398e106 OK 2020/04/15 05:16:41 INFO : A2/one: Copied (server side copy) 2020/04/15 05:16:41 INFO : A2/one: Deleted 2020/04/15 05:16:41 DEBUG : A2/B1/C1/four: SHA-1 = 9f8f7eec5dea5ac43738721939c120318cbff1df OK 2020/04/15 05:16:41 INFO : A2/B1/C1/four: Copied (server side copy) 2020/04/15 05:16:41 DEBUG : A2/B1/three: SHA-1 = b802f384302cb24fbab0a44997e820bf2e8507bb OK 2020/04/15 05:16:41 INFO : A2/B1/three: Copied (server side copy) 2020/04/15 05:16:42 DEBUG : A2/two: SHA-1 = ad782ecdac770fc6eb9a62e44f90873fb97fb26b OK 2020/04/15 05:16:42 INFO : A2/two: Copied (server side copy) 2020/04/15 05:16:42 INFO : A2/B1/C1/four: Deleted 2020/04/15 05:16:42 INFO : A2/two: Deleted 2020/04/15 05:16:43 INFO : A2/B1/three: Deleted 2020/04/15 05:16:43 DEBUG : A2/B1/C2/five: SHA-1 = 4db2c1df4610cd6c0da6b9197b066bfb4e9b9d00 OK 2020/04/15 05:16:43 INFO : A2/B1/C2/five: Copied (server side copy) 2020/04/15 05:16:43 INFO : A2/B1/C2/five: Deleted --- PASS: TestDirMove (13.41s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" fstest.go:241: Filtering empty directory "A1/B2" fstest.go:241: Filtering empty directory "A1/B1/C3" fstest.go:241: Filtering empty directory "A2/B2" fstest.go:241: Filtering empty directory "A2/B1/C3" fstest.go:241: Filtering empty directory "A3/B2" fstest.go:241: Filtering empty directory "A3/B1/C3" === RUN TestGetFsInfo --- PASS: TestGetFsInfo (0.30s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestRcat === RUN TestRcat/withChecksum=false,ignoreChecksum=false 2020/04/15 05:16:48 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: File to upload is small (34 bytes), uploading instead of streaming 2020/04/15 05:16:52 DEBUG : no_checksum_small_file_from_pipe: SHA-1 = 4c3452689ee5e2b950454c46181b8b5e7bcfeca9 OK 2020/04/15 05:16:52 INFO : no_checksum_small_file_from_pipe: Copied (new) 2020/04/15 05:16:52 DEBUG : no_checksum_big_file_from_pipe: File has 102401 bytes, which makes only one chunk. Using direct upload. 2020/04/15 05:16:52 DEBUG : no_checksum_big_file_from_pipe: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) === RUN TestRcat/withChecksum=true,ignoreChecksum=false 2020/04/15 05:16:54 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: File to upload is small (34 bytes), uploading instead of streaming 2020/04/15 05:16:54 DEBUG : with_checksum_small_file_from_pipe: SHA-1 = 4c3452689ee5e2b950454c46181b8b5e7bcfeca9 OK 2020/04/15 05:16:54 INFO : with_checksum_small_file_from_pipe: Copied (new) 2020/04/15 05:16:54 DEBUG : with_checksum_big_file_from_pipe: File has 102401 bytes, which makes only one chunk. Using direct upload. 2020/04/15 05:16:55 DEBUG : with_checksum_big_file_from_pipe: SHA-1 = d0080f73aa8b494570ad63df1beb25c01ea9eea2 OK 2020/04/15 05:16:55 DEBUG : with_checksum_big_file_from_pipe: Size and SHA-1 of src and dst objects identical === RUN TestRcat/withChecksum=false,ignoreChecksum=true 2020/04/15 05:16:57 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: File to upload is small (34 bytes), uploading instead of streaming 2020/04/15 05:16:57 INFO : ignore_checksum_small_file_from_pipe: Copied (new) 2020/04/15 05:16:57 DEBUG : ignore_checksum_big_file_from_pipe: File has 102401 bytes, which makes only one chunk. Using direct upload. 2020/04/15 05:16:58 DEBUG : ignore_checksum_big_file_from_pipe: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) === RUN TestRcat/withChecksum=true,ignoreChecksum=true 2020/04/15 05:17:01 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: File to upload is small (34 bytes), uploading instead of streaming 2020/04/15 05:17:01 INFO : ignore_checksum_small_file_from_pipe: Copied (new) 2020/04/15 05:17:02 DEBUG : ignore_checksum_big_file_from_pipe: File has 102401 bytes, which makes only one chunk. Using direct upload. 2020/04/15 05:17:02 NOTICE: B2 bucket rclone-test-fefesij9cerohub7negihiy0: --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2020/04/15 05:17:02 DEBUG : ignore_checksum_big_file_from_pipe: Size of src and dst objects identical --- PASS: TestRcat (16.85s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" --- PASS: TestRcat/withChecksum=false,ignoreChecksum=false (5.94s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" --- PASS: TestRcat/withChecksum=true,ignoreChecksum=false (3.05s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" --- PASS: TestRcat/withChecksum=false,ignoreChecksum=true (3.99s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" --- PASS: TestRcat/withChecksum=true,ignoreChecksum=true (3.87s) === RUN TestRcatSize 2020/04/15 05:17:06 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: File to upload is small (60 bytes), uploading instead of streaming 2020/04/15 05:17:06 DEBUG : potato2: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK 2020/04/15 05:17:06 INFO : potato2: Copied (new) --- PASS: TestRcatSize (4.36s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestCopyFileMaxTransfer 2020/04/15 05:17:09 DEBUG : file1: Need to transfer - File not found at Destination 2020/04/15 05:17:10 DEBUG : file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/04/15 05:17:10 INFO : file1: Copied (new) 2020/04/15 05:17:10 DEBUG : file2: Need to transfer - File not found at Destination 2020/04/15 05:17:10 ERROR : file2: Failed to copy: Post https://pod-000-1029-05.backblaze.com/b2api/v1/b2_upload_file/af827d63308d7bcb7f180e1b/c001_v0001029_t0038: Max transfer limit reached as set by --max-transfer 2020/04/15 05:17:10 DEBUG : file2: Need to transfer - File not found at Destination 2020/04/15 05:17:11 DEBUG : file2: Need to transfer - File not found at Destination 2020/04/15 05:17:11 DEBUG : file2: SHA-1 = c64a85fa1583e88ff15ef2f123a1977695b2a303 OK 2020/04/15 05:17:11 INFO : file2: Copied (new) --- PASS: TestCopyFileMaxTransfer (4.99s) run.go:176: Remote "B2 bucket rclone-test-fefesij9cerohub7negihiy0", Local "Local file system at /tmp/rclone268803179", Modify Window "1ms" === RUN TestRcAbout --- SKIP: TestRcAbout (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcCleanup --- SKIP: TestRcCleanup (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcCopyfile --- SKIP: TestRcCopyfile (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcCopyurl --- SKIP: TestRcCopyurl (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcDelete --- SKIP: TestRcDelete (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcDeletefile --- SKIP: TestRcDeletefile (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcList --- SKIP: TestRcList (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcMkdir --- SKIP: TestRcMkdir (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcMovefile --- SKIP: TestRcMovefile (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcPurge --- SKIP: TestRcPurge (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcRmdir --- SKIP: TestRcRmdir (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcRmdirs --- SKIP: TestRcRmdirs (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcSize --- SKIP: TestRcSize (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcPublicLink --- SKIP: TestRcPublicLink (0.00s) rc_test.go:21: Skipping test on non local remote === RUN TestRcFsInfo --- SKIP: TestRcFsInfo (0.00s) rc_test.go:21: Skipping test on non local remote FAIL 2020/04/15 05:17:14 DEBUG : B2 bucket rclone-test-fefesij9cerohub7negihiy0: Purge remote 2020/04/15 05:17:14 DEBUG : A1/B1/C1/four: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11540b77d4e553cd_d20200415_m051638_c001_v0001134_t0022") 2020/04/15 05:17:14 DEBUG : A1/B1/C1/four: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f53_d20200415_m051636_c001_v0001029_t0038") 2020/04/15 05:17:14 DEBUG : A1/B1/C1/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f107533549ba1b82a_d20200415_m050833_c001_v0001134_t0048") 2020/04/15 05:17:14 DEBUG : A1/B1/C1/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e30_d20200415_m050828_c001_v0001029_t0038") 2020/04/15 05:17:14 DEBUG : A1/B1/C2/five: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1035e9f2000598b7_d20200415_m051639_c001_v0001136_t0044") 2020/04/15 05:17:14 DEBUG : A1/B1/C2/five: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f54_d20200415_m051636_c001_v0001029_t0038") 2020/04/15 05:17:14 DEBUG : A1/B1/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f105331380637acc0_d20200415_m051638_c001_v0001136_t0040") 2020/04/15 05:17:14 DEBUG : A1/B1/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f52_d20200415_m051635_c001_v0001029_t0038") 2020/04/15 05:17:14 DEBUG : A1/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f110d8917b560057b_d20200415_m051638_c001_v0001011_t0019") 2020/04/15 05:17:14 DEBUG : A1/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f4f_d20200415_m051634_c001_v0001029_t0038") 2020/04/15 05:17:15 DEBUG : A1/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11439b6f38c2d8c5_d20200415_m051639_c001_v0001032_t0047") 2020/04/15 05:17:15 DEBUG : A1/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f50_d20200415_m051635_c001_v0001029_t0038") 2020/04/15 05:17:15 DEBUG : A1/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f102ac54b0aa4a6bd_d20200415_m050834_c001_v0001134_t0020") 2020/04/15 05:17:15 DEBUG : A1/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e34_d20200415_m050832_c001_v0001029_t0038") 2020/04/15 05:17:15 DEBUG : A2/B1/C1/four: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11143d3679d2735f_d20200415_m051641_c001_v0001130_t0001") 2020/04/15 05:17:15 DEBUG : A2/B1/C1/four: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1172e4bc44c944b7_d20200415_m051638_c001_v0001011_t0005") 2020/04/15 05:17:15 DEBUG : A2/B1/C2/five: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1096ec698a636d7c_d20200415_m051643_c001_v0001134_t0003") 2020/04/15 05:17:15 DEBUG : A2/B1/C2/five: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f111301984f745b4e_d20200415_m051639_c001_v0001131_t0058") 2020/04/15 05:17:15 DEBUG : A2/B1/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f113aef48b97e6207_d20200415_m051642_c001_v0001136_t0006") 2020/04/15 05:17:15 DEBUG : A2/B1/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1032f703a79ee0db_d20200415_m051638_c001_v0001131_t0012") 2020/04/15 05:17:15 DEBUG : A2/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f113a4d79c9f479d8_d20200415_m051641_c001_v0001134_t0049") 2020/04/15 05:17:15 DEBUG : A2/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f109f5e8569880d53_d20200415_m051638_c001_v0001003_t0044") 2020/04/15 05:17:15 DEBUG : A2/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f119ca6ee5865a6ea_d20200415_m051642_c001_v0001031_t0017") 2020/04/15 05:17:15 DEBUG : A2/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1037be8f4f480ac9_d20200415_m051638_c001_v0001039_t0021") 2020/04/15 05:17:15 DEBUG : A3/B1/C1/four: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11118694d1573323_d20200415_m051644_c001_v0001009_t0043") 2020/04/15 05:17:15 DEBUG : A3/B1/C1/four: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10986999504552d1_d20200415_m051640_c001_v0001136_t0049") 2020/04/15 05:17:16 DEBUG : A3/B1/C2/five: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10698c161402316f_d20200415_m051644_c001_v0001136_t0056") 2020/04/15 05:17:16 DEBUG : A3/B1/C2/five: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f5a_d20200415_m051642_c001_v0001029_t0042") 2020/04/15 05:17:16 DEBUG : A3/B1/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f110ef9e3ba274b50_d20200415_m051645_c001_v0001039_t0041") 2020/04/15 05:17:16 DEBUG : A3/B1/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f118336df13ca8b80_d20200415_m051641_c001_v0001136_t0015") 2020/04/15 05:17:16 DEBUG : A3/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f114360bfdebd228d_d20200415_m051646_c001_v0001128_t0050") 2020/04/15 05:17:16 DEBUG : A3/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f112ce8533d111eeb_d20200415_m051640_c001_v0001134_t0016") 2020/04/15 05:17:16 DEBUG : A3/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1107e0e362ee95c0_d20200415_m051646_c001_v0001134_t0011") 2020/04/15 05:17:16 DEBUG : A3/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1152c6f67c409462_d20200415_m051641_c001_v0001012_t0028") 2020/04/15 05:17:16 DEBUG : BackupDir/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1197d9802787a416_d20200415_m051628_c001_v0001128_t0001") 2020/04/15 05:17:16 DEBUG : BackupDir/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f114cd598d37534c9_d20200415_m050947_c001_v0001136_t0038") 2020/04/15 05:17:16 DEBUG : CompareDest/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1149744e00326284_d20200415_m050937_c001_v0001030_t0011") 2020/04/15 05:17:16 DEBUG : CompareDest/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e5b_d20200415_m050932_c001_v0001029_t0038") 2020/04/15 05:17:16 DEBUG : CompareDest/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10983463a92464a1_d20200415_m050938_c001_v0001113_t0010") 2020/04/15 05:17:16 DEBUG : CompareDest/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e5c_d20200415_m050933_c001_v0001029_t0038") 2020/04/15 05:17:16 DEBUG : CopyDest/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1116fba09b26bae6_d20200415_m051629_c001_v0001093_t0004") 2020/04/15 05:17:16 DEBUG : CopyDest/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e63_d20200415_m050945_c001_v0001029_t0038") 2020/04/15 05:17:16 DEBUG : CopyDest/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f100cce7b52e90851_d20200415_m051629_c001_v0001136_t0025") 2020/04/15 05:17:16 DEBUG : CopyDest/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028efa_d20200415_m051415_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : CopyDest/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1163808166d986b3_d20200415_m051631_c001_v0001136_t0021") 2020/04/15 05:17:17 DEBUG : CopyDest/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e89_d20200415_m051056_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : a.txt: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10856b1439ef65cd_d20200415_m050359_c001_v0001120_t0022") 2020/04/15 05:17:17 DEBUG : a.txt: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19276_d20200415_m050346_c001_v0001136_t0026") 2020/04/15 05:17:17 DEBUG : backup/dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1197d98027879a68_d20200415_m050924_c001_v0001128_t0016") 2020/04/15 05:17:17 DEBUG : backup/dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11835d34429c82b4_d20200415_m050922_c001_v0001128_t0012") 2020/04/15 05:17:17 DEBUG : backup/dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f118183ba8e46519c_d20200415_m050858_c001_v0001090_t0042") 2020/04/15 05:17:17 DEBUG : backup/dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1053159f63449199_d20200415_m050856_c001_v0001090_t0007") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1078d3bb9352644d_d20200415_m050925_c001_v0001136_t0047") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e55_d20200415_m050923_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10187c546109a8d5_d20200415_m050923_c001_v0001136_t0052") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e53_d20200415_m050920_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1194ccd7df168368_d20200415_m050916_c001_v0001136_t0025") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e46_d20200415_m050858_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f110774f2420d6bc3_d20200415_m050856_c001_v0001136_t0049") 2020/04/15 05:17:17 DEBUG : dst/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e44_d20200415_m050853_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10970beb77e862e2_d20200415_m050949_c001_v0001130_t0040") 2020/04/15 05:17:17 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10425bf4e1652c46_d20200415_m050949_c001_v0001136_t0032") 2020/04/15 05:17:17 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e62_d20200415_m050945_c001_v0001029_t0038") 2020/04/15 05:17:17 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f115f0a0be8938690_d20200415_m050944_c001_v0001131_t0021") 2020/04/15 05:17:17 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f115f0a0be893868f_d20200415_m050943_c001_v0001131_t0021") 2020/04/15 05:17:18 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10187c546109a996_d20200415_m050939_c001_v0001136_t0022") 2020/04/15 05:17:18 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e5a_d20200415_m050932_c001_v0001029_t0038") 2020/04/15 05:17:18 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10187c546109a92a_d20200415_m050930_c001_v0001136_t0038") 2020/04/15 05:17:18 DEBUG : dst/one: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10187c546109a913_d20200415_m050928_c001_v0001136_t0038") 2020/04/15 05:17:18 DEBUG : dst/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f114e17a09e1ab756_d20200415_m051631_c001_v0001120_t0035") 2020/04/15 05:17:18 DEBUG : dst/three: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f115f0a0be8938961_d20200415_m051522_c001_v0001131_t0021") 2020/04/15 05:17:18 DEBUG : dst/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f108616c3ea2a10e4_d20200415_m051633_c001_v0001012_t0040") 2020/04/15 05:17:18 DEBUG : dst/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10187c546109b049_d20200415_m051202_c001_v0001136_t0045") 2020/04/15 05:17:18 DEBUG : dst/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1007c9b298dc92f5_d20200415_m050940_c001_v0001041_t0019") 2020/04/15 05:17:18 DEBUG : dst/two: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10187c546109a96d_d20200415_m050935_c001_v0001136_t0038") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1126f656c0716b1c_d20200415_m050806_c001_v0001015_t0020") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e1e_d20200415_m050801_c001_v0001029_t0038") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1074a1bdb5aa9115_d20200415_m050745_c001_v0001120_t0033") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1162d95a39eb8fd0_d20200415_m050657_c001_v0001039_t0048") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10594d626643df11_d20200415_m050635_c001_v0001036_t0022") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19949_d20200415_m050619_c001_v0001136_t0026") 2020/04/15 05:17:18 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10698c16140210ae_d20200415_m050558_c001_v0001136_t0054") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19834_d20200415_m050556_c001_v0001136_t0026") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f104c07076de8f2c3_d20200415_m050541_c001_v0001004_t0038") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19770_d20200415_m050539_c001_v0001136_t0026") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1078d3bb93525b64_d20200415_m050535_c001_v0001136_t0016") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19725_d20200415_m050533_c001_v0001136_t0026") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f103dc668d86f2a57_d20200415_m050531_c001_v0001113_t0005") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e1941d_d20200415_m050421_c001_v0001136_t0026") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1128ea3be314e570_d20200415_m050417_c001_v0001130_t0014") 2020/04/15 05:17:19 DEBUG : empty space: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e193ce_d20200415_m050415_c001_v0001136_t0026") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f113aef48b97e4c98_d20200415_m050848_c001_v0001136_t0024") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e36_d20200415_m050836_c001_v0001029_t0038") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1135452926d7afac_d20200415_m050816_c001_v0001128_t0052") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e26_d20200415_m050812_c001_v0001029_t0038") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1114287e1f097c91_d20200415_m050341_c001_v0001134_t0022") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19218_d20200415_m050339_c001_v0001136_t0026") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f118336df13ca660b_d20200415_m050332_c001_v0001136_t0007") 2020/04/15 05:17:19 DEBUG : file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f118336df13ca65da_d20200415_m050328_c001_v0001136_t0007") 2020/04/15 05:17:19 DEBUG : file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11984afd1d8ee67c_d20200415_m050850_c001_v0001131_t0010") 2020/04/15 05:17:19 DEBUG : file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e40_d20200415_m050847_c001_v0001029_t0038") 2020/04/15 05:17:19 DEBUG : file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11175932e3b9a055_d20200415_m050817_c001_v0001044_t0006") 2020/04/15 05:17:20 DEBUG : file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e28_d20200415_m050813_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : filename.txt: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11984afd1d8ee67d_d20200415_m050850_c001_v0001131_t0000") 2020/04/15 05:17:20 DEBUG : filename.txt: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e37_d20200415_m050837_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : ignore_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f105331380637ae05_d20200415_m051703_c001_v0001136_t0029") 2020/04/15 05:17:20 DEBUG : ignore_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f70_d20200415_m051702_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : ignore_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f118336df13ca8c4d_d20200415_m051659_c001_v0001136_t0040") 2020/04/15 05:17:20 DEBUG : ignore_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f6b_d20200415_m051657_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : ignore_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1054518b334fdc87_d20200415_m051704_c001_v0001134_t0058") 2020/04/15 05:17:20 DEBUG : ignore_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f6e_d20200415_m051701_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : ignore_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1134f8e8fd54701c_d20200415_m051700_c001_v0001033_t0017") 2020/04/15 05:17:20 DEBUG : ignore_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f69_d20200415_m051657_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : large: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f107533549ba1b4a3_d20200415_m050617_c001_v0001134_t0024") 2020/04/15 05:17:20 DEBUG : large: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e198c5_d20200415_m050609_c001_v0001136_t0026") 2020/04/15 05:17:20 DEBUG : medium: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f102d87395bb752be_d20200415_m050611_c001_v0001006_t0025") 2020/04/15 05:17:20 DEBUG : medium: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e198bb_d20200415_m050608_c001_v0001136_t0026") 2020/04/15 05:17:20 DEBUG : no_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1102799615aad026_d20200415_m051653_c001_v0001042_t0034") 2020/04/15 05:17:20 DEBUG : no_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f63_d20200415_m051652_c001_v0001029_t0038") 2020/04/15 05:17:20 DEBUG : no_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f108813e080126ff6_d20200415_m051653_c001_v0001039_t0040") 2020/04/15 05:17:21 DEBUG : no_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f60_d20200415_m051648_c001_v0001029_t0038") 2020/04/15 05:17:21 DEBUG : potato1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1151ecb206771ca6_d20200415_m051707_c001_v0001136_t0057") 2020/04/15 05:17:21 DEBUG : potato1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f74_d20200415_m051705_c001_v0001029_t0038") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f110ef9e3ba274b5a_d20200415_m051708_c001_v0001039_t0029") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f75_d20200415_m051706_c001_v0001029_t0038") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1149b8e003e4cf48_d20200415_m050808_c001_v0001005_t0003") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e1f_d20200415_m050804_c001_v0001029_t0038") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f100cce7b52e8ef53_d20200415_m050745_c001_v0001136_t0041") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1162d95a39eb8fdb_d20200415_m050704_c001_v0001039_t0048") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1174bb3724f64e91_d20200415_m050643_c001_v0001044_t0014") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e1995a_d20200415_m050621_c001_v0001136_t0026") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11207ed7b4feb1bb_d20200415_m050604_c001_v0001001_t0026") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19821_d20200415_m050554_c001_v0001136_t0026") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10809b2c795c14ad_d20200415_m050551_c001_v0001136_t0007") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19761_d20200415_m050538_c001_v0001136_t0026") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1035e9f200057c5b_d20200415_m050536_c001_v0001136_t0050") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19716_d20200415_m050533_c001_v0001136_t0026") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1184c8e4c285b38e_d20200415_m050418_c001_v0001120_t0059") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e193f9_d20200415_m050418_c001_v0001136_t0026") 2020/04/15 05:17:21 DEBUG : potato2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e193ab_d20200415_m050412_c001_v0001136_t0026") 2020/04/15 05:17:21 DEBUG : remotepotato: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f114fd23b7c82d391_d20200415_m050810_c001_v0001001_t0009") 2020/04/15 05:17:22 DEBUG : remotepotato: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e20_d20200415_m050805_c001_v0001029_t0038") 2020/04/15 05:17:22 DEBUG : remotepotato: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f100f273f4c288622_d20200415_m050747_c001_v0001033_t0019") 2020/04/15 05:17:22 DEBUG : remotepotato: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11175932e3b9a029_d20200415_m050726_c001_v0001044_t0015") 2020/04/15 05:17:22 DEBUG : remotepotato: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f100cce7b52e8ecbc_d20200415_m050650_c001_v0001136_t0053") 2020/04/15 05:17:22 DEBUG : remotepotato: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1162d95a39eb8fb8_d20200415_m050626_c001_v0001039_t0048") 2020/04/15 05:17:22 DEBUG : rutabaga: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f100c0891724565e1_d20200415_m050810_c001_v0001120_t0056") 2020/04/15 05:17:22 DEBUG : rutabaga: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e1b_d20200415_m050759_c001_v0001029_t0038") 2020/04/15 05:17:22 DEBUG : rutabaga: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1184c8e4c285b717_d20200415_m050754_c001_v0001120_t0010") 2020/04/15 05:17:22 DEBUG : rutabaga: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1162d95a39eb8fcd_d20200415_m050653_c001_v0001039_t0048") 2020/04/15 05:17:22 DEBUG : rutabaga: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1138c219af34a34b_d20200415_m050651_c001_v0001000_t0039") 2020/04/15 05:17:22 DEBUG : rutabaga: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19932_d20200415_m050618_c001_v0001136_t0026") 2020/04/15 05:17:22 DEBUG : small: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f100c0891724563f9_d20200415_m050611_c001_v0001120_t0038") 2020/04/15 05:17:22 DEBUG : small: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e1989d_d20200415_m050606_c001_v0001136_t0026") 2020/04/15 05:17:22 DEBUG : sub dir/hello world: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1167504d90d62e4f_d20200415_m050411_c001_v0001128_t0010") 2020/04/15 05:17:22 DEBUG : sub dir/hello world: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19388_d20200415_m050408_c001_v0001136_t0026") 2020/04/15 05:17:22 DEBUG : sub dir/hello world: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f105b1d3798378c7f_d20200415_m050359_c001_v0001120_t0029") 2020/04/15 05:17:22 DEBUG : sub dir/hello world: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19299_d20200415_m050349_c001_v0001136_t0026") 2020/04/15 05:17:22 DEBUG : sub dir/hello world2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1128ea3be314e52e_d20200415_m050400_c001_v0001130_t0044") 2020/04/15 05:17:22 DEBUG : sub dir/hello world2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e192ab_d20200415_m050350_c001_v0001136_t0026") 2020/04/15 05:17:22 DEBUG : sub dir/ignore dir/.ignore: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10698c1614020af6_d20200415_m050400_c001_v0001136_t0051") 2020/04/15 05:17:23 DEBUG : sub dir/ignore dir/.ignore: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e192bc_d20200415_m050351_c001_v0001136_t0026") 2020/04/15 05:17:23 DEBUG : sub dir/ignore dir/should be ignored: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11984afd1d8ee347_d20200415_m050402_c001_v0001131_t0041") 2020/04/15 05:17:23 DEBUG : sub dir/ignore dir/should be ignored: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e192d3_d20200415_m050353_c001_v0001136_t0026") 2020/04/15 05:17:23 DEBUG : sub dir/potato3: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f114c89327ae037f6_d20200415_m050604_c001_v0001029_t0025") 2020/04/15 05:17:23 DEBUG : sub dir/potato3: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e19846_d20200415_m050557_c001_v0001136_t0026") 2020/04/15 05:17:23 DEBUG : sub dir/sub sub dir/hello world3: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f111f33a707684d37_d20200415_m050403_c001_v0001136_t0017") 2020/04/15 05:17:23 DEBUG : sub dir/sub sub dir/hello world3: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e192fb_d20200415_m050355_c001_v0001136_t0026") 2020/04/15 05:17:23 DEBUG : sub/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f117ed7d67ecf4389_d20200415_m051712_c001_v0001041_t0007") 2020/04/15 05:17:23 DEBUG : sub/file1: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f78_d20200415_m051709_c001_v0001029_t0038") 2020/04/15 05:17:23 DEBUG : sub/file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1048747450ab2c57_d20200415_m050919_c001_v0001113_t0036") 2020/04/15 05:17:23 DEBUG : sub/file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e50_d20200415_m050918_c001_v0001029_t0038") 2020/04/15 05:17:23 DEBUG : sub/file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f118336df13ca758f_d20200415_m050852_c001_v0001136_t0057") 2020/04/15 05:17:23 DEBUG : sub/file2: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028e42_d20200415_m050851_c001_v0001029_t0038") 2020/04/15 05:17:23 DEBUG : sub/file2c: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1144856feb91667f_d20200415_m051713_c001_v0001130_t0029") 2020/04/15 05:17:23 DEBUG : sub/file2c: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f7c_d20200415_m051711_c001_v0001029_t0038") 2020/04/15 05:17:23 DEBUG : with_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f114cd598d3754494_d20200415_m051655_c001_v0001136_t0007") 2020/04/15 05:17:23 DEBUG : with_checksum_big_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f66_d20200415_m051654_c001_v0001029_t0038") 2020/04/15 05:17:24 DEBUG : with_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f11363ee52ef1f2c8_d20200415_m051656_c001_v0001120_t0001") 2020/04/15 05:17:24 DEBUG : with_checksum_small_file_from_pipe: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f10591404d5028f65_d20200415_m051654_c001_v0001029_t0038") 2020/04/15 05:17:24 DEBUG : zend.txt: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f112d5c348f3747b6_d20200415_m050405_c001_v0001120_t0031") 2020/04/15 05:17:24 DEBUG : zend.txt: Deleting (id "4_zaf827d63308d7bcb7f180e1b_f1127a5ad39e1928c_d20200415_m050348_c001_v0001136_t0026") "./operations.test -test.v -test.timeout 30m0s -remote TestB2: -verbose -fast-list" - Finished ERROR in 13m59.072932044s (try 1/5): exit status 1: Failed [TestLsWithFilesFrom TestCopyFileCopyDest]