"./sync.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -fast-list -test.run '^(TestCopyWithDepth|TestSyncAfterChangingModtimeOnly|TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors|TestSyncDeleteDuring|TestSyncIgnoreTimes|TestSyncNoTraverse|TestSyncSuffix)$'" - Starting (try 2/5)
=== RUN   TestSyncNoTraverse
2020/05/15 06:25:13 ERROR : Ignoring --no-traverse with sync
2020/05/15 06:25:13 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:13 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:15 DEBUG : sub dir/hello world: SHA-1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK
2020/05/15 06:25:15 INFO  : sub dir/hello world: Copied (new)
2020/05/15 06:25:15 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncNoTraverse (3.03s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", Modify Window "1ms"
=== RUN   TestCopyWithDepth
2020/05/15 06:25:16 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:16 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:17 DEBUG : hello world2: SHA-1 = c0bf117f9c93d02c894fe8ffd6e5cecf3545c209 OK
2020/05/15 06:25:17 INFO  : hello world2: Copied (new)
--- PASS: TestCopyWithDepth (1.61s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", Modify Window "1ms"
=== RUN   TestSyncIgnoreTimes
2020/05/15 06:25:19 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2020/05/15 06:25:19 DEBUG : existing: Unchanged skipping
2020/05/15 06:25:19 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:19 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:19 DEBUG : Waiting for deletions to finish
2020/05/15 06:25:19 INFO  : There was nothing to transfer
2020/05/15 06:25:19 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2020/05/15 06:25:19 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:19 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:20 DEBUG : existing: SHA-1 = 3e2e95f5ad970eadfa7e17eaf73da97024aa5359 OK
2020/05/15 06:25:20 INFO  : existing: Copied (replaced existing)
2020/05/15 06:25:20 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncIgnoreTimes (3.26s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", Modify Window "1ms"
=== RUN   TestSyncAfterChangingModtimeOnly
2020/05/15 06:25:22 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:22 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/05/15 06:25:22 DEBUG : empty space: SHA-1 = 3bc15c8aae3e4124dd409035f32ea2fd6835efc9 OK
2020/05/15 06:25:22 NOTICE: empty space: Not updating modification time as --dry-run
2020/05/15 06:25:22 DEBUG : empty space: Unchanged skipping
2020/05/15 06:25:22 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:22 DEBUG : Waiting for deletions to finish
2020/05/15 06:25:22 INFO  : There was nothing to transfer
2020/05/15 06:25:22 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/05/15 06:25:22 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:22 DEBUG : empty space: SHA-1 = 3bc15c8aae3e4124dd409035f32ea2fd6835efc9 OK
2020/05/15 06:25:23 INFO  : empty space: Updated modification time in destination
2020/05/15 06:25:23 DEBUG : empty space: Unchanged skipping
2020/05/15 06:25:23 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:23 DEBUG : Waiting for deletions to finish
2020/05/15 06:25:23 INFO  : There was nothing to transfer
--- FAIL: TestSyncAfterChangingModtimeOnly (10.36s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", 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:552
        	Error:      	Should be true
        	Test:       	TestSyncAfterChangingModtimeOnly
        	Messages:   	listing wrong, want
        	            	   got
        	            	  empty space (1)
    fstest.go:188: 
        	Error Trace:	fstest.go:188
        	            				fstest.go:305
        	            				fstest.go:335
        	            				run.go:169
        	            				run.go:339
        	            				sync_test.go:552
        	Error:      	Should be true
        	Test:       	TestSyncAfterChangingModtimeOnly
        	Messages:   	Unexpected file "empty space"
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
2020/05/15 06:25:33 DEBUG : d: Making directory
2020/05/15 06:25:41 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2020/05/15 06:25:41 DEBUG : c/non empty space: Unchanged skipping
2020/05/15 06:25:41 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:41 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:42 DEBUG : a/potato2: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK
2020/05/15 06:25:42 INFO  : a/potato2: Copied (new)
2020/05/15 06:25:42 ERROR : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: not deleting files as there were IO errors
2020/05/15 06:25:42 ERROR : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: not deleting directories as there were IO errors
--- FAIL: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (20.09s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", Modify Window "1ms"
    fstest.go:247: Filtering empty directory "d"
    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
        	            				sync_test.go:788
        	Error:      	Should be true
        	Test:       	TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
        	Messages:   	listing wrong, want
        	            	  b/potato (21), c/non empty space (5) got
        	            	  b/potato (21), c/non empty space (5), empty space (1)
    fstest.go:188: 
        	Error Trace:	fstest.go:188
        	            				fstest.go:305
        	            				fstest.go:335
        	            				sync_test.go:788
        	Error:      	Should be true
        	Test:       	TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
        	Messages:   	Unexpected file "empty space"
    fstest.go:247: Filtering empty directory "d"
    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
        	            				sync_test.go:821
        	Error:      	Should be true
        	Test:       	TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
        	Messages:   	listing wrong, want
        	            	  a/potato2 (60), b/potato (21), c/non empty space (5) got
        	            	  a/potato2 (60), b/potato (21), c/non empty space (5), empty space (1)
    fstest.go:188: 
        	Error Trace:	fstest.go:188
        	            				fstest.go:305
        	            				fstest.go:335
        	            				sync_test.go:821
        	Error:      	Should be true
        	Test:       	TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
        	Messages:   	Unexpected file "empty space"
=== RUN   TestSyncDeleteDuring
2020/05/15 06:25:54 DEBUG : Waiting for deletions to finish
2020/05/15 06:25:54 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2020/05/15 06:25:54 DEBUG : empty space: Unchanged skipping
2020/05/15 06:25:54 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for checks to finish
2020/05/15 06:25:54 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Waiting for transfers to finish
2020/05/15 06:25:54 INFO  : potato: Deleted
2020/05/15 06:25:55 DEBUG : potato2: SHA-1 = 9dc7f7d3279715991a22853f5981df582b7f9f6d OK
2020/05/15 06:25:55 INFO  : potato2: Copied (new)
--- PASS: TestSyncDeleteDuring (5.01s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", Modify Window "1ms"
=== RUN   TestSyncSuffix
2020/05/15 06:25:59 DEBUG : one: Sizes differ (src 4 vs dst 3)
2020/05/15 06:26:00 DEBUG : one: SHA-1 = fe05bcdcdc4928012781a5f1a2a77cbb5398e106 OK
2020/05/15 06:26:00 INFO  : one: Copied (server side copy)
2020/05/15 06:26:00 INFO  : one: Deleted
2020/05/15 06:26:01 DEBUG : one: SHA-1 = d63a9910ed57f038b76549c070df6196b2102f42 OK
2020/05/15 06:26:01 INFO  : one: Copied (new)
2020/05/15 06:26:01 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2020/05/15 06:26:01 DEBUG : two: Unchanged skipping
2020/05/15 06:26:01 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2020/05/15 06:26:02 DEBUG : three.txt: SHA-1 = b802f384302cb24fbab0a44997e820bf2e8507bb OK
2020/05/15 06:26:02 INFO  : three.txt: Copied (server side copy)
2020/05/15 06:26:03 INFO  : three.txt: Deleted
2020/05/15 06:26:04 DEBUG : three.txt: SHA-1 = 92e0258fe3c7456f15dff78d509f6e3c9166c254 OK
2020/05/15 06:26:04 INFO  : three.txt: Copied (new)
2020/05/15 06:26:05 DEBUG : one: Sizes differ (src 5 vs dst 4)
2020/05/15 06:26:07 DEBUG : one: SHA-1 = d63a9910ed57f038b76549c070df6196b2102f42 OK
2020/05/15 06:26:07 INFO  : one: Copied (server side copy)
2020/05/15 06:26:08 INFO  : one: Deleted
2020/05/15 06:26:09 DEBUG : one: SHA-1 = 88a8c2880f555638f990d1ec4c8359b25caa20c7 OK
2020/05/15 06:26:09 INFO  : one: Copied (new)
2020/05/15 06:26:09 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2020/05/15 06:26:09 DEBUG : two: Unchanged skipping
2020/05/15 06:26:09 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2020/05/15 06:26:13 DEBUG : three.txt: SHA-1 = 92e0258fe3c7456f15dff78d509f6e3c9166c254 OK
2020/05/15 06:26:13 INFO  : three.txt: Copied (server side copy)
2020/05/15 06:26:22 INFO  : three.txt: Deleted
2020/05/15 06:26:24 DEBUG : three.txt: SHA-1 = 476e1707cbd7f0497a7dc4d44f0b07b8566ffc30 OK
2020/05/15 06:26:24 INFO  : three.txt: Copied (new)
--- PASS: TestSyncSuffix (30.13s)
    run.go:176: Remote "B2 bucket rclone-test-daxuyoc9busegib5kuwizot3", Local "Local file system at /tmp/rclone127233858", Modify Window "1ms"
FAIL
2020/05/15 06:26:26 DEBUG : B2 bucket rclone-test-daxuyoc9busegib5kuwizot3: Purge remote
2020/05/15 06:26:26 DEBUG : a/potato2: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f103d0314a0d03aad_d20200515_m062549_c001_v0001137_t0055")
2020/05/15 06:26:26 DEBUG : a/potato2: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e0890ec_d20200515_m062541_c001_v0001137_t0056")
2020/05/15 06:26:26 DEBUG : b/potato: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f109d36d209ff9f11_d20200515_m062550_c001_v0001137_t0047")
2020/05/15 06:26:26 DEBUG : b/potato: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e08902c_d20200515_m062532_c001_v0001137_t0056")
2020/05/15 06:26:26 DEBUG : c/non empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f111c120e75134efe_d20200515_m062550_c001_v0001136_t0021")
2020/05/15 06:26:26 DEBUG : c/non empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e089040_d20200515_m062532_c001_v0001137_t0056")
2020/05/15 06:26:26 DEBUG : dst/one: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1141bc51f390adc1_d20200515_m062625_c001_v0001033_t0056")
2020/05/15 06:26:26 DEBUG : dst/one: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f101490251331054c_d20200515_m062608_c001_v0001113_t0053")
2020/05/15 06:26:26 DEBUG : dst/one: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f108c28cb9684e971_d20200515_m062607_c001_v0001091_t0054")
2020/05/15 06:26:27 DEBUG : dst/one: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1014902513310544_d20200515_m062601_c001_v0001113_t0053")
2020/05/15 06:26:27 DEBUG : dst/one: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f119844f30766b89e_d20200515_m062600_c001_v0001091_t0043")
2020/05/15 06:26:27 DEBUG : dst/one: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e08920d_d20200515_m062556_c001_v0001137_t0056")
2020/05/15 06:26:27 DEBUG : dst/one.bak: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1019a0a080624808_d20200515_m062625_c001_v0001090_t0040")
2020/05/15 06:26:27 DEBUG : dst/one.bak: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f111df2d1e9fbc9ff_d20200515_m062605_c001_v0001137_t0054")
2020/05/15 06:26:27 DEBUG : dst/one.bak: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f103d0314a0d03b64_d20200515_m062559_c001_v0001137_t0052")
2020/05/15 06:26:27 DEBUG : dst/three.txt: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f105ebcc7e97c809a_d20200515_m062625_c001_v0001137_t0011")
2020/05/15 06:26:27 DEBUG : dst/three.txt: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1014902513310556_d20200515_m062623_c001_v0001113_t0053")
2020/05/15 06:26:27 DEBUG : dst/three.txt: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1044d420667db8db_d20200515_m062613_c001_v0001036_t0037")
2020/05/15 06:26:27 DEBUG : dst/three.txt: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f101490251331054a_d20200515_m062603_c001_v0001113_t0053")
2020/05/15 06:26:27 DEBUG : dst/three.txt: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f11840c3dce86fb74_d20200515_m062602_c001_v0001137_t0037")
2020/05/15 06:26:27 DEBUG : dst/three.txt: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e089221_d20200515_m062557_c001_v0001137_t0056")
2020/05/15 06:26:27 DEBUG : dst/three.txt.bak: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f106e28d9b88b7d4d_d20200515_m062626_c001_v0001131_t0029")
2020/05/15 06:26:27 DEBUG : dst/three.txt.bak: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f109c1011ed8d4ea5_d20200515_m062610_c001_v0001042_t0019")
2020/05/15 06:26:28 DEBUG : dst/three.txt.bak: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f11141cf9af5dc9c8_d20200515_m062602_c001_v0001134_t0010")
2020/05/15 06:26:28 DEBUG : dst/two: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f103a96279fe7db57_d20200515_m062626_c001_v0001131_t0032")
2020/05/15 06:26:28 DEBUG : dst/two: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e089218_d20200515_m062557_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f110febbcec5ad687_d20200515_m062555_c001_v0001136_t0048")
2020/05/15 06:26:28 DEBUG : empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e0891d6_d20200515_m062553_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1133b5be7763931a_d20200515_m062551_c001_v0001029_t0020")
2020/05/15 06:26:28 DEBUG : empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1113941e6b39c0cd_d20200515_m062523_c001_v0001039_t0047")
2020/05/15 06:26:28 DEBUG : empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f10888b12a86140d2_d20200515_m062523_c001_v0001137_t0024")
2020/05/15 06:26:28 DEBUG : empty space: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e088f4b_d20200515_m062521_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : existing: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f115235bdbb2e368f_d20200515_m062520_c001_v0001134_t0026")
2020/05/15 06:26:28 DEBUG : existing: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e088f19_d20200515_m062519_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : existing: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e088f09_d20200515_m062518_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : hello world2: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f107d445bea6a447f_d20200515_m062517_c001_v0001137_t0037")
2020/05/15 06:26:28 DEBUG : hello world2: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e088eeb_d20200515_m062516_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : potato: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f1192345ec07aec7a_d20200515_m062554_c001_v0001137_t0031")
2020/05/15 06:26:28 DEBUG : potato: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e0891c0_d20200515_m062552_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : potato2: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f110febbcec5ad688_d20200515_m062556_c001_v0001136_t0033")
2020/05/15 06:26:28 DEBUG : potato2: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e0891e4_d20200515_m062554_c001_v0001137_t0056")
2020/05/15 06:26:28 DEBUG : sub dir/hello world: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f10408141a8df8d28_d20200515_m062515_c001_v0001137_t0023")
2020/05/15 06:26:28 DEBUG : sub dir/hello world: Deleting (id "4_zef521dc3002d1b7b7f280e1b_f114768723e088ecc_d20200515_m062514_c001_v0001137_t0056")
"./sync.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -fast-list -test.run '^(TestCopyWithDepth|TestSyncAfterChangingModtimeOnly|TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors|TestSyncDeleteDuring|TestSyncIgnoreTimes|TestSyncNoTraverse|TestSyncSuffix)$'" - Finished ERROR in 1m16.95704018s (try 2/5): exit status 1: Failed [TestSyncAfterChangingModtimeOnly TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors]