"./sync.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -fast-list -test.run '^(TestCopyCheckFirst|TestSyncAfterAddingAFile|TestSyncAfterChangingContentsOnly|TestSyncAfterChangingModtimeOnly|TestSyncAfterRemovingAFileAndAddingAFile|TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors|TestSyncDeleteDuring|TestSyncDoesntUpdateModtime|TestSyncIgnoreExisting)$'" - Starting (try 2/5) === RUN TestCopyCheckFirst 2020/07/24 10:00:21 INFO : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Running all checks before starting transfers 2020/07/24 10:00:21 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:21 INFO : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Checks finished, now starting transfers 2020/07/24 10:00:21 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:23 DEBUG : sub dir/hello world: SHA-1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK 2020/07/24 10:00:23 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopyCheckFirst (2.57s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" === RUN TestSyncIgnoreExisting 2020/07/24 10:00:23 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:23 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:24 DEBUG : existing: SHA-1 = 3e2e95f5ad970eadfa7e17eaf73da97024aa5359 OK 2020/07/24 10:00:24 INFO : existing: Copied (new) 2020/07/24 10:00:24 DEBUG : Waiting for deletions to finish 2020/07/24 10:00:24 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:24 DEBUG : existing: Destination exists, skipping 2020/07/24 10:00:24 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:24 DEBUG : Waiting for deletions to finish 2020/07/24 10:00:24 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (1.54s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" === RUN TestSyncAfterChangingModtimeOnly 2020/07/24 10:00:25 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:25 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2020/07/24 10:00:25 DEBUG : empty space: SHA-1 = 3bc15c8aae3e4124dd409035f32ea2fd6835efc9 OK 2020/07/24 10:00:25 NOTICE: empty space: Skipped update modification time as --dry-run is set 2020/07/24 10:00:25 DEBUG : empty space: Unchanged skipping 2020/07/24 10:00:25 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:25 DEBUG : Waiting for deletions to finish 2020/07/24 10:00:25 INFO : There was nothing to transfer 2020/07/24 10:00:26 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:26 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2020/07/24 10:00:26 DEBUG : empty space: SHA-1 = 3bc15c8aae3e4124dd409035f32ea2fd6835efc9 OK 2020/07/24 10:00:26 INFO : empty space: Updated modification time in destination 2020/07/24 10:00:26 DEBUG : empty space: Unchanged skipping 2020/07/24 10:00:26 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:26 DEBUG : Waiting for deletions to finish 2020/07/24 10:00:26 INFO : There was nothing to transfer --- PASS: TestSyncAfterChangingModtimeOnly (2.25s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" === RUN TestSyncDoesntUpdateModtime 2020/07/24 10:00:28 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:28 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2020/07/24 10:00:28 DEBUG : foo: SHA-1 = 0beec7b5ea3f0fdbc95d0dd47f3c5bc275da8a33 (Local file system at /tmp/rclone735139551) 2020/07/24 10:00:28 DEBUG : foo: SHA-1 = 62cdb7020ff920e5aa642c3d4066950dd1f01f4d (B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2) 2020/07/24 10:00:28 DEBUG : foo: SHA-1 differ 2020/07/24 10:00:28 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:28 DEBUG : foo: SHA-1 = 0beec7b5ea3f0fdbc95d0dd47f3c5bc275da8a33 OK 2020/07/24 10:00:28 INFO : foo: Copied (replaced existing) 2020/07/24 10:00:28 DEBUG : Waiting for deletions to finish --- FAIL: TestSyncDoesntUpdateModtime (8.81s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Error Trace: fstest.go:302 fstest.go:335 run.go:169 run.go:339 sync_test.go:621 Error: Should be true Test: TestSyncDoesntUpdateModtime Messages: listing wrong, want got foo (3) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 run.go:169 run.go:339 sync_test.go:621 Error: Should be true Test: TestSyncDoesntUpdateModtime Messages: Unexpected file "foo" === RUN TestSyncAfterAddingAFile 2020/07/24 10:00:44 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/07/24 10:00:44 DEBUG : empty space: Unchanged skipping 2020/07/24 10:00:44 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:44 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:45 DEBUG : potato: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK 2020/07/24 10:00:45 INFO : potato: Copied (new) 2020/07/24 10:00:45 DEBUG : Waiting for deletions to finish 2020/07/24 10:00:45 INFO : foo: Deleted --- FAIL: TestSyncAfterAddingAFile (10.77s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Error Trace: fstest.go:302 fstest.go:335 fstest.go:347 sync_test.go:630 Error: Should be true Test: TestSyncAfterAddingAFile Messages: listing wrong, want empty space (1) got empty space (1), foo (3) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 fstest.go:347 sync_test.go:630 Error: Should be true Test: TestSyncAfterAddingAFile Messages: Unexpected file "foo" === RUN TestSyncAfterChangingContentsOnly 2020/07/24 10:00:47 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2020/07/24 10:00:47 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:47 DEBUG : potato: SHA-1 = 1ca5094b3b73f587249eabe179c40a3eec839b1f (Local file system at /tmp/rclone735139551) 2020/07/24 10:00:47 DEBUG : potato: SHA-1 = 0fd321a1023ac4e1e1054fcc0236b9d0755f722f (B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2) 2020/07/24 10:00:47 DEBUG : potato: SHA-1 differ 2020/07/24 10:00:47 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:48 DEBUG : potato: SHA-1 = 1ca5094b3b73f587249eabe179c40a3eec839b1f OK 2020/07/24 10:00:48 INFO : potato: Copied (replaced existing) 2020/07/24 10:00:48 DEBUG : Waiting for deletions to finish --- FAIL: TestSyncAfterChangingContentsOnly (1.87s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" fstest.go:140: Error Trace: fstest.go:140 fstest.go:146 fstest.go:192 fstest.go:305 fstest.go:335 fstest.go:347 sync_test.go:674 Error: Should be true Test: TestSyncAfterChangingContentsOnly Messages: B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2/potato: SHA-1 hash incorrect - expecting "1ca5094b3b73f587249eabe179c40a3eec839b1f" got "0fd321a1023ac4e1e1054fcc0236b9d0755f722f" fstest.go:124: Error Trace: fstest.go:124 fstest.go:129 fstest.go:148 fstest.go:192 fstest.go:305 fstest.go:335 fstest.go:347 sync_test.go:674 Error: Should be true Test: TestSyncAfterChangingContentsOnly Messages: potato: Modification time difference too big |-119h59m59.876543211s| > 1ms (want 2011-12-25 12:59:59.123456789 +0000 UTC vs got 2011-12-30 12:59:59 +0000 UTC) (precision 1ms) === RUN TestSyncAfterRemovingAFileAndAddingAFile 2020/07/24 10:00:49 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/07/24 10:00:49 DEBUG : empty space: Unchanged skipping 2020/07/24 10:00:49 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:49 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:50 DEBUG : potato2: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK 2020/07/24 10:00:50 INFO : potato2: Copied (new) 2020/07/24 10:00:50 DEBUG : Waiting for deletions to finish 2020/07/24 10:00:51 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (4.97s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors 2020/07/24 10:00:54 DEBUG : d: Making directory 2020/07/24 10:00:54 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:00:54 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/07/24 10:00:54 DEBUG : c/non empty space: Unchanged skipping 2020/07/24 10:00:54 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:00:55 DEBUG : a/potato2: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK 2020/07/24 10:00:55 INFO : a/potato2: Copied (new) 2020/07/24 10:00:55 ERROR : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: not deleting files as there were IO errors 2020/07/24 10:00:55 ERROR : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: not deleting directories as there were IO errors --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (5.59s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" fstest.go:247: Filtering empty directory "d" fstest.go:247: Filtering empty directory "d" === RUN TestSyncDeleteDuring 2020/07/24 10:01:00 DEBUG : Waiting for deletions to finish 2020/07/24 10:01:00 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2020/07/24 10:01:00 DEBUG : empty space: Unchanged skipping 2020/07/24 10:01:00 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for checks to finish 2020/07/24 10:01:00 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Waiting for transfers to finish 2020/07/24 10:01:00 DEBUG : potato2: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK 2020/07/24 10:01:00 INFO : potato2: Copied (new) 2020/07/24 10:01:00 INFO : potato: Deleted --- PASS: TestSyncDeleteDuring (4.39s) run.go:176: Remote "B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2", Local "Local file system at /tmp/rclone735139551", Modify Window "1ms" FAIL 2020/07/24 10:01:03 DEBUG : B2 bucket rclone-test-kuzubom9hadiqam8bijuqay2: Purge remote 2020/07/24 10:01:04 DEBUG : a/potato2: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f106271d1a12fe85a_d20200724_m100055_c001_v0001136_t0049") 2020/07/24 10:01:04 DEBUG : a/potato2: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f708_d20200724_m100054_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : b/potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1091505ddbe93ceb_d20200724_m100055_c001_v0001113_t0005") 2020/07/24 10:01:04 DEBUG : b/potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f703_d20200724_m100054_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : c/non empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f10278d76fc5efe9f_d20200724_m100056_c001_v0001040_t0001") 2020/07/24 10:01:04 DEBUG : c/non empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f705_d20200724_m100054_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f10818954e50d3820_d20200724_m100101_c001_v0001093_t0015") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f71b_d20200724_m100059_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f10517c294685c878_d20200724_m100051_c001_v0001120_t0010") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6ea_d20200724_m100049_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f10510c2f4e2f2d81_d20200724_m100046_c001_v0001136_t0036") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6b6_d20200724_m100036_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f101052749ff3342f_d20200724_m100027_c001_v0001137_t0035") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1094ac3957c478ff_d20200724_m100026_c001_v0001137_t0031") 2020/07/24 10:01:04 DEBUG : empty space: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f691_d20200724_m100025_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : existing: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f107013e83ed02617_d20200724_m100024_c001_v0001092_t0032") 2020/07/24 10:01:04 DEBUG : existing: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f689_d20200724_m100023_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : foo: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1043d7b57dc693d6_d20200724_m100045_c001_v0001130_t0059") 2020/07/24 10:01:04 DEBUG : foo: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f69c_d20200724_m100028_c001_v0001128_t0013") 2020/07/24 10:01:04 DEBUG : foo: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f117b48a9efca8315_d20200724_m100028_c001_v0001136_t0029") 2020/07/24 10:01:05 DEBUG : foo: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f698_d20200724_m100027_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f104d7c689047dd63_d20200724_m100100_c001_v0001091_t0023") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f719_d20200724_m100059_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f109b377c8475d096_d20200724_m100050_c001_v0001000_t0015") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6e6_d20200724_m100049_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f103450f34dfda422_d20200724_m100048_c001_v0001134_t0033") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6d8_d20200724_m100047_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6de_d20200724_m100047_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1109fb7de908ba1b_d20200724_m100046_c001_v0001136_t0016") 2020/07/24 10:01:05 DEBUG : potato: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6d5_d20200724_m100045_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato2: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1016abd5c1526f67_d20200724_m100103_c001_v0001136_t0009") 2020/07/24 10:01:05 DEBUG : potato2: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f721_d20200724_m100100_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : potato2: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1158e917a6d34945_d20200724_m100052_c001_v0001093_t0054") 2020/07/24 10:01:05 DEBUG : potato2: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f6ee_d20200724_m100049_c001_v0001128_t0013") 2020/07/24 10:01:05 DEBUG : sub dir/hello world: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f115aa36b71411027_d20200724_m100023_c001_v0001134_t0046") 2020/07/24 10:01:05 DEBUG : sub dir/hello world: Deleting (id "4_z9f023da3404d8b0b7f380e1b_f1040edc502c0f680_d20200724_m100022_c001_v0001128_t0013") "./sync.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -fast-list -test.run '^(TestCopyCheckFirst|TestSyncAfterAddingAFile|TestSyncAfterChangingContentsOnly|TestSyncAfterChangingModtimeOnly|TestSyncAfterRemovingAFileAndAddingAFile|TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors|TestSyncDeleteDuring|TestSyncDoesntUpdateModtime|TestSyncIgnoreExisting)$'" - Finished ERROR in 45.962237078s (try 2/5): exit status 1: Failed [TestSyncDoesntUpdateModtime TestSyncAfterAddingAFile TestSyncAfterChangingContentsOnly]