"./sync.test -test.v -test.timeout 30m0s -remote TestSharefile: -verbose" - Starting (try 1/5) === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.06s) === RUN TestRcCopy --- SKIP: TestRcCopy (0.00s) rc_test.go:16: Skipping test on non local remote === RUN TestRcMove --- SKIP: TestRcMove (0.00s) rc_test.go:16: Skipping test on non local remote === RUN TestRcSync --- SKIP: TestRcSync (0.00s) rc_test.go:16: Skipping test on non local remote === RUN TestCopyWithDryRun 2019/10/02 06:14:42 NOTICE: sub dir/hello world: Not copying as --dry-run 2019/10/02 06:14:42 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:14:42 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (9.77s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopy 2019/10/02 06:14:46 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:14:46 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:14:59 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:14:59 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopy (29.36s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyMissingDirectory 2019/10/02 06:15:16 ERROR : : error reading source directory: directory not found 2019/10/02 06:15:16 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:15:16 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (3.83s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyNoTraverse 2019/10/02 06:15:19 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:15:19 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:15:34 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:15:34 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopyNoTraverse (29.14s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncNoTraverse 2019/10/02 06:15:47 ERROR : Ignoring --no-traverse with sync 2019/10/02 06:15:50 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:15:50 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:16:04 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:16:04 INFO : sub dir/hello world: Copied (new) 2019/10/02 06:16:04 INFO : Waiting for deletions to finish --- PASS: TestSyncNoTraverse (30.13s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyWithDepth 2019/10/02 06:16:18 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:16:18 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:16:29 DEBUG : hello world2: MD5 = cc2c857f89648dbd139d7b2a6665957d OK 2019/10/02 06:16:29 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (18.43s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyWithFilesFrom 2019/10/02 06:16:36 DEBUG : hello world2: Excluded 2019/10/02 06:16:37 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:16:37 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:16:45 DEBUG : potato2: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:16:45 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (16.73s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyWithFilesFromAndNoTraverse 2019/10/02 06:16:54 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:16:54 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:17:05 DEBUG : potato2: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:17:05 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (19.71s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyEmptyDirectories 2019/10/02 06:17:12 DEBUG : sub dir2: Making directory 2019/10/02 06:17:14 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:17:14 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:17:27 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:17:27 INFO : sub dir/hello world: Copied (new) 2019/10/02 06:17:27 DEBUG : sub dir2: Making directory 2019/10/02 06:17:32 DEBUG : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': copied 1 directories --- PASS: TestCopyEmptyDirectories (38.48s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestMoveEmptyDirectories 2019/10/02 06:17:51 DEBUG : sub dir2: Making directory 2019/10/02 06:17:52 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:17:52 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:18:07 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:18:07 INFO : sub dir/hello world: Copied (new) 2019/10/02 06:18:07 INFO : sub dir/hello world: Deleted 2019/10/02 06:18:07 DEBUG : sub dir: Making directory 2019/10/02 06:18:07 DEBUG : sub dir2: Making directory 2019/10/02 06:18:12 DEBUG : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': copied 2 directories --- PASS: TestMoveEmptyDirectories (38.78s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncEmptyDirectories 2019/10/02 06:18:30 DEBUG : sub dir2: Making directory 2019/10/02 06:18:31 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:18:31 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:18:45 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:18:45 INFO : sub dir/hello world: Copied (new) 2019/10/02 06:18:45 DEBUG : sub dir2: Making directory 2019/10/02 06:18:50 DEBUG : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': copied 1 directories 2019/10/02 06:18:50 INFO : Waiting for deletions to finish --- PASS: TestSyncEmptyDirectories (40.54s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestServerSideCopy 2019/10/02 06:19:35 INFO : sharefile root 'rclone-test-bolexas4riquluh8juhicus3': Waiting for checks to finish 2019/10/02 06:19:35 INFO : sharefile root 'rclone-test-bolexas4riquluh8juhicus3': Waiting for transfers to finish 2019/10/02 06:19:54 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:19:54 INFO : sub dir/hello world: Copied (server side copy) 2019/10/02 06:19:58 DEBUG : sharefile root 'rclone-test-bolexas4riquluh8juhicus3': Purge remote --- PASS: TestServerSideCopy (63.32s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" sync_test.go:257: Server side copy (if possible) sharefile root 'rclone-test-xalezas8hotelid6vezanog4' -> sharefile root 'rclone-test-bolexas4riquluh8juhicus3' === RUN TestCopyAfterDelete 2019/10/02 06:20:29 ERROR : : error listing: directory not found 2019/10/02 06:20:31 DEBUG : Local file system at /tmp/rclone329954573: Making directory 2019/10/02 06:20:34 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:20:34 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish --- PASS: TestCopyAfterDelete (94.95s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyRedownload 2019/10/02 06:22:08 INFO : Local file system at /tmp/rclone329954573: Waiting for checks to finish 2019/10/02 06:22:08 INFO : Local file system at /tmp/rclone329954573: Waiting for transfers to finish 2019/10/02 06:22:11 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:22:11 INFO : sub dir/hello world: Copied (new) --- PASS: TestCopyRedownload (33.86s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncBasedOnCheckSum 2019/10/02 06:22:24 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:22:24 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:22:34 DEBUG : check sum: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/02 06:22:34 INFO : check sum: Copied (new) 2019/10/02 06:22:34 INFO : Waiting for deletions to finish 2019/10/02 06:22:37 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:22:37 DEBUG : check sum: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/02 06:22:37 DEBUG : check sum: Size and MD5 of src and dst objects identical 2019/10/02 06:22:37 DEBUG : check sum: Unchanged skipping 2019/10/02 06:22:37 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:22:37 INFO : Waiting for deletions to finish --- PASS: TestSyncBasedOnCheckSum (28.27s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncSizeOnly 2019/10/02 06:22:52 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:22:52 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:23:03 DEBUG : sizeonly: MD5 = 8ee2027983915ec78acc45027d874316 OK 2019/10/02 06:23:03 INFO : sizeonly: Copied (new) 2019/10/02 06:23:03 INFO : Waiting for deletions to finish 2019/10/02 06:23:06 DEBUG : sizeonly: Sizes identical 2019/10/02 06:23:06 DEBUG : sizeonly: Unchanged skipping 2019/10/02 06:23:06 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:23:06 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:23:06 INFO : Waiting for deletions to finish --- PASS: TestSyncSizeOnly (23.02s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncIgnoreSize 2019/10/02 06:23:15 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:23:15 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:23:24 DEBUG : ignore-size: MD5 = 98bf7d8c15784f0a3d63204441e1e2aa OK 2019/10/02 06:23:24 INFO : ignore-size: Copied (new) 2019/10/02 06:23:24 INFO : Waiting for deletions to finish 2019/10/02 06:23:27 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:23:27 DEBUG : ignore-size: Size and modification time the same (differ by 1ns, within tolerance 1s) 2019/10/02 06:23:27 DEBUG : ignore-size: Unchanged skipping 2019/10/02 06:23:27 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:23:27 INFO : Waiting for deletions to finish --- PASS: TestSyncIgnoreSize (20.35s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncIgnoreTimes 2019/10/02 06:24:47 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:24:47 DEBUG : existing: Size and modification time the same (differ by 1ns, within tolerance 1s) 2019/10/02 06:24:47 DEBUG : existing: Unchanged skipping 2019/10/02 06:24:47 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:24:47 INFO : Waiting for deletions to finish 2019/10/02 06:24:47 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:24:47 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2019/10/02 06:24:47 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:24:52 DEBUG : existing: MD5 = 8ee2027983915ec78acc45027d874316 OK 2019/10/02 06:24:52 INFO : existing: Copied (replaced existing) 2019/10/02 06:24:52 INFO : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (82.71s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncIgnoreExisting 2019/10/02 06:24:58 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:24:58 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:25:08 DEBUG : existing: MD5 = 8ee2027983915ec78acc45027d874316 OK 2019/10/02 06:25:08 INFO : existing: Copied (new) 2019/10/02 06:25:08 INFO : Waiting for deletions to finish 2019/10/02 06:25:10 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:25:10 DEBUG : existing: Destination exists, skipping 2019/10/02 06:25:10 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:25:10 INFO : Waiting for deletions to finish --- PASS: TestSyncIgnoreExisting (19.95s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncIgnoreErrors 2019/10/02 06:25:41 DEBUG : d: Making directory 2019/10/02 06:25:49 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:25:49 DEBUG : c/non empty space: Unchanged skipping 2019/10/02 06:25:49 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:25:49 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:25:59 DEBUG : a/potato2: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:25:59 INFO : a/potato2: Copied (new) 2019/10/02 06:25:59 INFO : Waiting for deletions to finish 2019/10/02 06:26:03 INFO : b/potato: Deleted 2019/10/02 06:26:03 DEBUG : d: Removing directory 2019/10/02 06:26:06 DEBUG : b: Removing directory 2019/10/02 06:26:09 DEBUG : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': deleted 2 directories --- PASS: TestSyncIgnoreErrors (70.10s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterChangingModtimeOnly 2019/10/02 06:26:41 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:26:41 DEBUG : empty space: Modification times differ by -95456h54m52.623456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.5 +0000 UTC 2019/10/02 06:26:41 DEBUG : empty space: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/02 06:26:41 NOTICE: empty space: Not updating modification time as --dry-run 2019/10/02 06:26:41 DEBUG : empty space: Unchanged skipping 2019/10/02 06:26:41 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:26:41 INFO : Waiting for deletions to finish 2019/10/02 06:26:44 DEBUG : empty space: Modification times differ by -95456h54m52.623456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.5 +0000 UTC 2019/10/02 06:26:44 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:26:44 DEBUG : empty space: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/02 06:26:46 INFO : empty space: Updated modification time in destination 2019/10/02 06:26:46 DEBUG : empty space: Unchanged skipping 2019/10/02 06:26:46 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:26:46 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (27.15s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime 2019/10/02 06:27:04 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:27:04 DEBUG : empty space: Modification times differ by -95456h54m52.623456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.5 +0000 UTC 2019/10/02 06:27:04 DEBUG : empty space: MD5 = 336d5ebc5436534e61d16e63ddfca327 OK 2019/10/02 06:27:04 DEBUG : empty space: Unchanged skipping 2019/10/02 06:27:04 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:27:04 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (19.21s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncDoesntUpdateModtime 2019/10/02 06:27:24 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:27:24 DEBUG : foo: Modification times differ by -95456h54m52.623456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.5 +0000 UTC 2019/10/02 06:27:24 DEBUG : foo: MD5 = acbd18db4cc2f85cedef654fccc4a4d8 (Local file system at /tmp/rclone329954573) 2019/10/02 06:27:24 DEBUG : foo: MD5 = 37b51d194a7513e45b56f6524f2d51f2 (sharefile root 'rclone-test-xalezas8hotelid6vezanog4') 2019/10/02 06:27:24 DEBUG : foo: MD5 differ 2019/10/02 06:27:24 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:27:33 DEBUG : foo: MD5 = acbd18db4cc2f85cedef654fccc4a4d8 OK 2019/10/02 06:27:33 INFO : foo: Copied (replaced existing) 2019/10/02 06:27:33 INFO : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (28.67s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterAddingAFile 2019/10/02 06:27:51 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:27:51 DEBUG : empty space: Unchanged skipping 2019/10/02 06:27:51 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:27:51 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:28:00 DEBUG : potato: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:28:00 INFO : potato: Copied (new) 2019/10/02 06:28:00 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (26.72s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterChangingFilesSizeOnly 2019/10/02 06:28:20 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2019/10/02 06:28:20 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:28:20 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:28:26 DEBUG : potato: MD5 = 100defcf18c42a1e0dc42a789b107cd2 OK 2019/10/02 06:28:26 INFO : potato: Copied (replaced existing) 2019/10/02 06:28:26 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (25.73s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterChangingContentsOnly 2019/10/02 06:28:46 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 2019/10/02 06:28:46 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:28:46 DEBUG : potato: MD5 = e4cb6955d9106df6263c45fcfc10f163 (Local file system at /tmp/rclone329954573) 2019/10/02 06:28:46 DEBUG : potato: MD5 = 100defcf18c42a1e0dc42a789b107cd2 (sharefile root 'rclone-test-xalezas8hotelid6vezanog4') 2019/10/02 06:28:46 DEBUG : potato: MD5 differ 2019/10/02 06:28:46 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:28:53 DEBUG : potato: MD5 = e4cb6955d9106df6263c45fcfc10f163 OK 2019/10/02 06:28:53 INFO : potato: Copied (replaced existing) 2019/10/02 06:28:53 INFO : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (28.32s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun 2019/10/02 06:29:20 NOTICE: potato2: Not copying as --dry-run 2019/10/02 06:29:20 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:29:20 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:29:20 DEBUG : empty space: Unchanged skipping 2019/10/02 06:29:20 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:29:20 INFO : Waiting for deletions to finish 2019/10/02 06:29:20 NOTICE: potato: Not deleting as --dry-run --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (30.00s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFile 2019/10/02 06:29:55 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:29:55 DEBUG : empty space: Unchanged skipping 2019/10/02 06:29:55 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:29:55 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:30:05 DEBUG : potato2: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:30:05 INFO : potato2: Copied (new) 2019/10/02 06:30:05 INFO : Waiting for deletions to finish 2019/10/02 06:30:09 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (46.47s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir 2019/10/02 06:30:45 DEBUG : d: Making directory 2019/10/02 06:30:49 DEBUG : d/e: Making directory 2019/10/02 06:31:03 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:31:03 DEBUG : c/non empty space: Unchanged skipping 2019/10/02 06:31:07 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:31:07 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:31:14 DEBUG : a/potato2: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:31:14 INFO : a/potato2: Copied (new) 2019/10/02 06:31:14 INFO : Waiting for deletions to finish 2019/10/02 06:31:16 INFO : b/potato: Deleted 2019/10/02 06:31:16 DEBUG : d/e: Removing directory 2019/10/02 06:31:20 DEBUG : d: Removing directory 2019/10/02 06:31:23 DEBUG : b: Removing directory 2019/10/02 06:31:26 DEBUG : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': deleted 3 directories --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (92.31s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors 2019/10/02 06:32:29 DEBUG : d: Making directory 2019/10/02 06:32:39 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:32:39 DEBUG : c/non empty space: Unchanged skipping 2019/10/02 06:32:39 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:32:39 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:32:51 DEBUG : a/potato2: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:32:51 INFO : a/potato2: Copied (new) 2019/10/02 06:32:51 ERROR : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': not deleting files as there were IO errors 2019/10/02 06:32:51 ERROR : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': not deleting directories as there were IO errors --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (91.21s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring 2019/10/02 06:33:47 INFO : Waiting for deletions to finish 2019/10/02 06:33:48 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:33:48 DEBUG : empty space: Unchanged skipping 2019/10/02 06:33:48 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:33:48 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:33:52 INFO : potato: Deleted 2019/10/02 06:34:01 DEBUG : potato2: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:34:01 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (55.11s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncDeleteBefore 2019/10/02 06:34:42 INFO : Waiting for deletions to finish 2019/10/02 06:34:43 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:34:43 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:34:46 INFO : potato: Deleted 2019/10/02 06:34:48 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:34:48 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:34:48 DEBUG : empty space: Unchanged skipping 2019/10/02 06:34:48 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:34:58 DEBUG : potato2: MD5 = d6548b156ea68a4e003e786df99eee76 OK 2019/10/02 06:34:58 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (51.24s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestCopyDeleteBefore 2019/10/02 06:35:23 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:35:23 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:36:13 DEBUG : potato2: MD5 = 9519bc2e940e1696ea7365b4b81adedc OK 2019/10/02 06:36:13 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (75.26s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncWithExclude 2019/10/02 06:36:50 DEBUG : potato2: Excluded 2019/10/02 06:36:50 DEBUG : enormous: Excluded 2019/10/02 06:36:52 DEBUG : potato2: Excluded 2019/10/02 06:36:52 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:36:52 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:36:52 DEBUG : empty space: Unchanged skipping 2019/10/02 06:36:52 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:36:52 INFO : Waiting for deletions to finish 2019/10/02 06:36:54 DEBUG : potato2: Excluded 2019/10/02 06:36:54 DEBUG : enormous: Excluded 2019/10/02 06:36:56 DEBUG : potato2: Excluded 2019/10/02 06:36:56 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1s) 2019/10/02 06:36:56 DEBUG : empty space: Unchanged skipping 2019/10/02 06:36:56 INFO : Local file system at /tmp/rclone329954573: Waiting for checks to finish 2019/10/02 06:36:56 INFO : Local file system at /tmp/rclone329954573: Waiting for transfers to finish 2019/10/02 06:36:56 INFO : Waiting for deletions to finish --- PASS: TestSyncWithExclude (41.00s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncWithExcludeAndDeleteExcluded 2019/10/02 06:37:42 DEBUG : potato2: Excluded 2019/10/02 06:37:42 DEBUG : enormous: Excluded 2019/10/02 06:37:44 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:37:44 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1s) 2019/10/02 06:37:44 DEBUG : empty space: Unchanged skipping 2019/10/02 06:37:44 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:37:44 INFO : Waiting for deletions to finish 2019/10/02 06:37:48 INFO : enormous: Deleted 2019/10/02 06:37:48 INFO : potato2: Deleted 2019/10/02 06:37:51 INFO : Local file system at /tmp/rclone329954573: Waiting for checks to finish 2019/10/02 06:37:51 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1s) 2019/10/02 06:37:51 DEBUG : empty space: Unchanged skipping 2019/10/02 06:37:51 INFO : Local file system at /tmp/rclone329954573: Waiting for transfers to finish 2019/10/02 06:37:51 INFO : Waiting for deletions to finish 2019/10/02 06:37:51 INFO : enormous: Deleted 2019/10/02 06:37:51 INFO : potato2: Deleted --- PASS: TestSyncWithExcludeAndDeleteExcluded (56.22s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncWithUpdateOlder 2019/10/02 06:38:47 DEBUG : four: Destination mod time is within 1s of source but sizes differ, transferring 2019/10/02 06:38:47 DEBUG : one: Destination is newer than source, skipping 2019/10/02 06:38:47 DEBUG : three: Destination mod time is within 1s of source and sizes identical, skipping 2019/10/02 06:38:47 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:38:47 DEBUG : two: Destination is older than source, transferring 2019/10/02 06:38:47 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:38:56 DEBUG : two: MD5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2019/10/02 06:38:56 INFO : two: Copied (replaced existing) 2019/10/02 06:38:56 DEBUG : four: MD5 = 8cbad96aced40b3838dd9f07f6ef5772 OK 2019/10/02 06:38:56 INFO : four: Copied (replaced existing) 2019/10/02 06:38:57 DEBUG : five: MD5 = 30056e1cab7a61d256fc8edd970d14f5 OK 2019/10/02 06:38:57 INFO : five: Copied (new) 2019/10/02 06:38:57 INFO : Waiting for deletions to finish --- PASS: TestSyncWithUpdateOlder (85.14s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestSyncWithTrackRenames 2019/10/02 06:39:28 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Making map for --track-renames 2019/10/02 06:39:28 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Finished making map for --track-renames 2019/10/02 06:39:28 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:39:28 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for renames to finish 2019/10/02 06:39:28 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:39:34 DEBUG : yam: MD5 = 48dc443644c4b89556dc06834b46451d OK 2019/10/02 06:39:34 INFO : yam: Copied (new) 2019/10/02 06:39:35 DEBUG : potato: MD5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2019/10/02 06:39:35 INFO : potato: Copied (new) 2019/10/02 06:39:35 INFO : Waiting for deletions to finish 2019/10/02 06:39:38 DEBUG : potato: Size and modification time the same (differ by 1ns, within tolerance 1s) 2019/10/02 06:39:38 DEBUG : potato: Unchanged skipping 2019/10/02 06:39:38 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Making map for --track-renames 2019/10/02 06:39:38 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Finished making map for --track-renames 2019/10/02 06:39:38 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:39:38 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for renames to finish 2019/10/02 06:39:44 INFO : yam: Moved (server side) 2019/10/02 06:39:44 INFO : yaml: Renamed from "yam" 2019/10/02 06:39:44 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:39:44 INFO : Waiting for deletions to finish --- PASS: TestSyncWithTrackRenames (26.99s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" sync_test.go:993: Can track renames: true === RUN TestMoveWithDeleteEmptySrcDirs 2019/10/02 06:39:55 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:39:55 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:40:11 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:40:11 INFO : sub dir/hello world: Copied (new) 2019/10/02 06:40:11 INFO : sub dir/hello world: Deleted 2019/10/02 06:40:22 DEBUG : nested/sub dir/file: MD5 = 83d3784ea62518eafc60e98d84f877ad OK 2019/10/02 06:40:22 INFO : nested/sub dir/file: Copied (new) 2019/10/02 06:40:22 INFO : nested/sub dir/file: Deleted 2019/10/02 06:40:22 DEBUG : sub dir: Removing directory 2019/10/02 06:40:22 DEBUG : nested/sub dir: Removing directory 2019/10/02 06:40:22 DEBUG : nested: Removing directory 2019/10/02 06:40:22 DEBUG : Local file system at /tmp/rclone329954573: deleted 3 directories --- PASS: TestMoveWithDeleteEmptySrcDirs (52.97s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestMoveWithoutDeleteEmptySrcDirs 2019/10/02 06:40:48 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for checks to finish 2019/10/02 06:40:48 INFO : sharefile root 'rclone-test-xalezas8hotelid6vezanog4': Waiting for transfers to finish 2019/10/02 06:41:05 DEBUG : sub dir/hello world: MD5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2019/10/02 06:41:05 INFO : sub dir/hello world: Copied (new) 2019/10/02 06:41:05 INFO : sub dir/hello world: Deleted 2019/10/02 06:41:17 DEBUG : nested/sub dir/file: MD5 = 83d3784ea62518eafc60e98d84f877ad OK 2019/10/02 06:41:17 INFO : nested/sub dir/file: Copied (new) 2019/10/02 06:41:17 INFO : nested/sub dir/file: Deleted --- PASS: TestMoveWithoutDeleteEmptySrcDirs (56.00s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" === RUN TestServerSideMove 2019/10/02 06:43:23 DEBUG : pacer: low level retry 1/10 (error A system error occurred.: InternalServerError: Unspecified) 2019/10/02 06:43:23 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2019/10/02 06:43:24 DEBUG : pacer: Reducing sleep to 15ms 2019/10/02 06:43:24 DEBUG : sharefile root 'rclone-test-gifugoc8rimuruh2homazar1': Purge remote 2019/10/02 06:43:25 DEBUG : pacer: Reducing sleep to 11.25ms 2019/10/02 06:43:27 DEBUG : pacer: Reducing sleep to 10ms --- FAIL: TestServerSideMove (114.49s) run.go:176: Remote "sharefile root 'rclone-test-xalezas8hotelid6vezanog4'", Local "Local file system at /tmp/rclone329954573", Modify Window "1s" sync_test.go:1098: Server side move (if possible) sharefile root 'rclone-test-xalezas8hotelid6vezanog4' -> sharefile root 'rclone-test-gifugoc8rimuruh2homazar1' run.go:234: Failed to mkdir "sharefile root 'rclone-test-gifugoc8rimuruh2homazar1'": failed to make directory: CreateDir: Conflict Item:A folder with this name already exists. Try again.: Conflict: Conflict === RUN TestServerSideMoveWithFilter 2019/10/02 06:44:32 DEBUG : empty space: Excluded 2019/10/02 06:44:33 DEBUG : empty space: Excluded 2019/10/02 06:44:33 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2019/10/02 06:44:33 INFO : sharefile root 'rclone-test-tuhokat2zilecad6jihifah6': Waiting for checks to finish 2019/10/02 06:44:33 INFO : sharefile root 'rclone-test-tuhokat2zilecad6jihifah6': Waiting for transfers to finish 2019/10/02 06:44:35 INFO : potato3: Deleted panic: test timed out after 30m0s goroutine 6126 [running]: testing.(*M).startAlarm.func1() /usr/local/go/src/testing/testing.go:1377 +0xdf created by time.goFunc /usr/local/go/src/time/sleep.go:168 +0x44 goroutine 1 [chan receive, 2 minutes]: testing.(*T).Run(0xc0005e2300, 0x14bc7fb, 0x1c, 0x1507460, 0x4c2c00) /usr/local/go/src/testing/testing.go:961 +0x377 testing.runTests.func1(0xc000118700) /usr/local/go/src/testing/testing.go:1202 +0x78 testing.tRunner(0xc000118700, 0xc000197d78) /usr/local/go/src/testing/testing.go:909 +0xc9 testing.runTests(0xc0005e04e0, 0x20d69c0, 0x3d, 0x3d, 0x798765) /usr/local/go/src/testing/testing.go:1200 +0x2a7 testing.(*M).Run(0xc00010b400, 0x0) /usr/local/go/src/testing/testing.go:1117 +0x176 github.com/rclone/rclone/fstest.TestMain(0xc00010b400) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:68 +0x92 github.com/rclone/rclone/fs/sync.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:35 main.main() _testmain.go:162 +0x136 goroutine 34 [syscall, 30 minutes]: os/signal.signal_recv(0x0) /usr/local/go/src/runtime/sigqueue.go:147 +0x9c os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:23 +0x22 created by os/signal.init.0 /usr/local/go/src/os/signal/signal_unix.go:29 +0x41 goroutine 21 [select]: github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.(*worker).start(0xc0000d8e10) /home/rclone/go/src/github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:154 +0x100 created by github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.init.0 /home/rclone/go/src/github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:32 +0x57 goroutine 22 [chan receive, 30 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0004943c0) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:39 +0x67 created by github.com/rclone/rclone/lib/oauthutil.NewRenew /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:28 +0x84 goroutine 6216 [select]: net/http.(*http2ClientConn).roundTrip(0xc0007e0000, 0xc00082ab00, 0x0, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:7573 +0x9a0 net/http.(*http2Transport).RoundTripOpt(0xc00038b920, 0xc00082ab00, 0xc0007de900, 0x740135, 0x0, 0xc0004926c0) /usr/local/go/src/net/http/h2_bundle.go:6936 +0x172 net/http.(*http2Transport).RoundTrip(...) /usr/local/go/src/net/http/h2_bundle.go:6897 net/http.http2noDialH2RoundTripper.RoundTrip(0xc00038b920, 0xc00082ab00, 0xc00011ab40, 0x5, 0xc000492748) /usr/local/go/src/net/http/h2_bundle.go:9032 +0x3e net/http.(*Transport).roundTrip(0xc000395a40, 0xc00082ab00, 0x14a2578, 0xa, 0xc00077a378) /usr/local/go/src/net/http/transport.go:485 +0xd0a net/http.(*Transport).RoundTrip(...) /usr/local/go/src/net/http/roundtrip.go:17 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc000494150, 0xc00082ab00, 0xc00082ab00, 0x0, 0x150) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:330 +0x1de github.com/rclone/rclone/vendor/golang.org/x/oauth2.(*Transport).RoundTrip(0xc0002f2c30, 0xc00082aa00, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/vendor/golang.org/x/oauth2/transport.go:56 +0x124 net/http.send(0xc00082aa00, 0x1723e20, 0xc0002f2c30, 0x0, 0x0, 0x0, 0xc0000ba598, 0x400, 0x1, 0x0) /usr/local/go/src/net/http/client.go:250 +0x43a net/http.(*Client).send(0xc0002f2c60, 0xc00082aa00, 0x0, 0x0, 0x0, 0xc0000ba598, 0x0, 0x1, 0x7f33c3c76638) /usr/local/go/src/net/http/client.go:174 +0xfa net/http.(*Client).do(0xc0002f2c60, 0xc00082aa00, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/client.go:641 +0x3ce net/http.(*Client).Do(...) /usr/local/go/src/net/http/client.go:509 github.com/rclone/rclone/lib/rest.(*Client).Call(0xc00013e140, 0x1745840, 0xc00007a0c0, 0xc0007df5a8, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:270 +0x78a github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc00013e140, 0x1745840, 0xc00007a0c0, 0xc0007df5a8, 0x11b4520, 0xc0000d94a0, 0x11a22e0, 0xc0000ba558, 0x15069d8, 0x15076e0, ...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:454 +0x206 github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:397 github.com/rclone/rclone/backend/sharefile.(*Fs).updateItem.func1(0xc0007df8b0, 0x8, 0x30) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:910 +0xc7 github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc0000d94f0, 0xc0000d94f0, 0x2, 0xc0007df990) /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1394 +0x3c github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00038aa80, 0xc0000d94f0, 0xa, 0x50, 0x13f9ea0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x8b github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc00038aa80, 0xc0000d94f0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a github.com/rclone/rclone/backend/sharefile.(*Fs).updateItem(0xc00061a0a0, 0x1745840, 0xc00007a0c0, 0xc000645830, 0x24, 0x0, 0x0, 0xc000644720, 0x24, 0x0, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:909 +0x686 github.com/rclone/rclone/backend/sharefile.(*Fs).move(0xc00061a0a0, 0x1745840, 0xc00007a0c0, 0xc0004be201, 0xc000645830, 0x24, 0xc0004be200, 0x7, 0xc0004be200, 0x7, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:948 +0x1d7 github.com/rclone/rclone/backend/sharefile.(*Fs).Move(0xc00061a0a0, 0x1745840, 0xc00007a0c0, 0x1758c80, 0xc0006f04e0, 0xc0004be200, 0x7, 0x0, 0x0, 0x0, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:994 +0x2ad github.com/rclone/rclone/fs/operations.Move(0x1745840, 0xc00007a0c0, 0x1758c00, 0xc00061a0a0, 0x1758c80, 0xc0006f0300, 0xc0004be200, 0x7, 0x1758c80, 0xc0006f04e0, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:467 +0x225 github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove(0xc00057e8c0, 0x1745840, 0xc00007a0c0, 0xc000189fc0, 0x1758c00, 0xc00061a0a0, 0xc00057e998) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:295 +0x189 created by github.com/rclone/rclone/fs/sync.(*syncCopyMove).startTransfers /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:322 +0xb1 goroutine 6173 [IO wait]: internal/poll.runtime_pollWait(0x7f33c3c68c10, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc00048b798, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc00048b780, 0xc000649000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc00048b780, 0xc000649000, 0xe62, 0xe62, 0x35ad8d8215de2210, 0x2539653726b25e0b, 0x10000004f7648d1) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc0001221a8, 0xc000649000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0004e9360, 0xc0005bb888, 0xc000649000, 0xe62, 0xe62, 0x203000, 0x0, 0xe55) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0004e9360, 0xc000649000, 0xe62, 0xe62, 0xc00064900d, 0xf5, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0002f8420, 0xc000649000, 0xe62, 0xe62, 0x112, 0x1722840, 0xc0005bb970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc000087058, 0x1722620, 0xc0002f8420, 0x40bfa5, 0x12b7a80, 0x13c6900) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000086e00, 0x7f33c3c0c008, 0xc0004e9360, 0x5, 0xc0004e9360, 0xf5) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000086e00, 0x0, 0x0, 0x7f33c3cc6218) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc000086e00, 0xc0006c5000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc00011d2c0, 0xc0005130d8, 0x9, 0x9, 0xc0005bbd10, 0x0, 0x732392) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1722460, 0xc00011d2c0, 0xc0005130d8, 0x9, 0x9, 0x9, 0xc00009e050, 0x0, 0x1722840) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc0005130d8, 0x9, 0x9, 0x1722460, 0xc00011d2c0, 0x0, 0x0, 0xc0000a0d20, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc0005130a0, 0xc0000a0d20, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc0005bbfb8, 0x70c2dd, 0xc00038b920) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc0007ea300) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 5950 [chan receive, 3 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000350930) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:39 +0x67 created by github.com/rclone/rclone/lib/oauthutil.NewRenew /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:28 +0x84 goroutine 6082 [semacquire]: sync.runtime_Semacquire(0xc00057e9a0) /usr/local/go/src/runtime/sema.go:56 +0x42 sync.(*WaitGroup).Wait(0xc00057e998) /usr/local/go/src/sync/waitgroup.go:130 +0x64 github.com/rclone/rclone/fs/sync.(*syncCopyMove).stopTransfers(0xc00057e8c0) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:330 +0x66 github.com/rclone/rclone/fs/sync.(*syncCopyMove).run(0xc00057e8c0, 0xc0000b6010, 0x1758c00) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:689 +0x303 github.com/rclone/rclone/fs/sync.runSyncCopyMove(0x1745880, 0xc0000b6010, 0x1758c00, 0xc00061a0a0, 0x1758c00, 0xc0003c8fa0, 0x100, 0x5b3b90, 0xc0005b3be8) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:889 +0x276 github.com/rclone/rclone/fs/sync.moveDir(...) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:904 github.com/rclone/rclone/fs/sync.MoveDir(0x1745880, 0xc0000b6010, 0x1758c00, 0xc00061a0a0, 0x1758c00, 0xc0003c8fa0, 0x0, 0x14e189f, 0x3c) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:936 +0x4ec github.com/rclone/rclone/fs/sync.testServerSideMove(0xc0005e2300, 0xc00038a240, 0xc000380001) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1107 +0x775 github.com/rclone/rclone/fs/sync.TestServerSideMoveWithFilter(0xc0005e2300) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1213 +0xeb testing.tRunner(0xc0005e2300, 0x1507460) /usr/local/go/src/testing/testing.go:909 +0xc9 created by testing.(*T).Run /usr/local/go/src/testing/testing.go:960 +0x350 goroutine 6228 [chan receive]: github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc00048ba00, 0xc0006f00c0, 0xc00028be30) /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:189 +0x4e created by github.com/rclone/rclone/fs/march.(*March).Run /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:187 +0x2ea goroutine 5045 [IO wait]: internal/poll.runtime_pollWait(0x7f33c3c68b40, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc00012ed18, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc00012ed00, 0xc0007a0000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc00012ed00, 0xc0007a0000, 0xe62, 0xe62, 0xe2dbe9a8134f2578, 0x852bd866816823df, 0x100000049ea18aa) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc0000ba078, 0xc0007a0000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0002c4860, 0xc00023f888, 0xc0007a0000, 0xe62, 0xe62, 0x203000, 0x0, 0xe55) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0002c4860, 0xc0007a0000, 0xe62, 0xe62, 0xc0007a000d, 0x1a, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc000578a60, 0xc0007a0000, 0xe62, 0xe62, 0x37, 0x1722840, 0xc00023f970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc0000873d8, 0x1722620, 0xc000578a60, 0x40bfa5, 0x12b7a80, 0x13c6900) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000087180, 0x7f33c3c0c008, 0xc0002c4860, 0x5, 0xc0002c4860, 0x1a) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000087180, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc000087180, 0xc0007e2000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc00080f320, 0xc0002730d8, 0x9, 0x9, 0xc00023fd93, 0x95d1fefc, 0x1) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1722460, 0xc00080f320, 0xc0002730d8, 0x9, 0x9, 0x9, 0x72e77d, 0xc0007e0050, 0xc0003130e0) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc0002730d8, 0x9, 0x9, 0x1722460, 0xc00080f320, 0x0, 0xc000000000, 0xc00023fdf0, 0x732b62) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc0002730a0, 0xc00027fd80, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc00023ffb8, 0x15093d8, 0xc0006585c0) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc0007e0000) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 6100 [IO wait, 2 minutes]: internal/poll.runtime_pollWait(0x7f33c3c689a0, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc00012ea98, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc00012ea80, 0xc0006da000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc00012ea80, 0xc0006da000, 0xe62, 0xe62, 0xe46ee5f556f568a1, 0xd8d4f0c831e75618, 0x1000000c6976dcd) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc00066c100, 0xc0006da000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc000578d20, 0xc0005b9888, 0xc0006da000, 0xe62, 0xe62, 0x203000, 0x0, 0xc6b) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000578d20, 0xc0006da000, 0xe62, 0xe62, 0xc0006da1f7, 0xf8, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0002c4fa0, 0xc0006da000, 0xe62, 0xe62, 0xc0005b99b8, 0x41027e, 0xc0005b9970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc000057758, 0x1722620, 0xc0002c4fa0, 0x40bfa5, 0x12b7a80, 0x13c6900) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000057500, 0x7f33c3c0c008, 0xc000578d20, 0x5, 0xc000578d20, 0xf8) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000057500, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc000057500, 0xc000708000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc000671a40, 0xc000272818, 0x9, 0x9, 0xc0005b9d10, 0x0, 0x732392) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1722460, 0xc000671a40, 0xc000272818, 0x9, 0x9, 0x9, 0xc00009e050, 0x0, 0x1722840) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc000272818, 0x9, 0x9, 0x1722460, 0xc000671a40, 0x0, 0x0, 0xc0005acb70, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc0002727e0, 0xc0005acb70, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc0005b9fb8, 0x70c2dd, 0xc00038b920) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc0007e0780) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 1237 [chan receive, 25 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000351830) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:39 +0x67 created by github.com/rclone/rclone/lib/oauthutil.NewRenew /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:28 +0x84 goroutine 6083 [chan receive, 2 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0002f2cf0) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:39 +0x67 created by github.com/rclone/rclone/lib/oauthutil.NewRenew /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:28 +0x84 goroutine 6119 [IO wait]: internal/poll.runtime_pollWait(0x7f33c3c68ce0, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc00012e318, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc00012e300, 0xc0004ae000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc00012e300, 0xc0004ae000, 0xe62, 0xe62, 0x53d65a549573833, 0x2f9d1e851a41be67, 0x100000043878e1f) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc0000ba060, 0xc0004ae000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0003341c0, 0xc0005ba888, 0xc0004ae000, 0xe62, 0xe62, 0x203000, 0x0, 0xe55) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0003341c0, 0xc0004ae000, 0xe62, 0xe62, 0xc0004ae00d, 0xf8, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0005785c0, 0xc0004ae000, 0xe62, 0xe62, 0x115, 0x1722840, 0xc0005ba970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc0001b0cd8, 0x1722620, 0xc0005785c0, 0x40bfa5, 0x12b7a80, 0x13c6900) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc0001b0a80, 0x7f33c3c0c008, 0xc0003341c0, 0x5, 0xc0003341c0, 0xf8) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc0001b0a80, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc0001b0a80, 0xc000653000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc000671b00, 0xc0002c8ab8, 0x9, 0x9, 0xc0005bad10, 0x0, 0x732392) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1722460, 0xc000671b00, 0xc0002c8ab8, 0x9, 0x9, 0x9, 0xc00009e050, 0x0, 0x1722840) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc0002c8ab8, 0x9, 0x9, 0x1722460, 0xc000671b00, 0x0, 0x0, 0xc0002f3260, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc0002c8a80, 0xc0002f3260, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc0005bafb8, 0x15093d8, 0xc000658040) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc00062e180) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 6166 [IO wait]: internal/poll.runtime_pollWait(0x7f33c3c68a70, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc00012e718, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc00012e700, 0xc0004c3000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc00012e700, 0xc0004c3000, 0xe62, 0xe62, 0x43598a4533ac30c9, 0xb110bd82708fff1, 0x10000006a192a6f) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc000122140, 0xc0004c3000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc000590d20, 0xc000063888, 0xc0004c3000, 0xe62, 0xe62, 0x203000, 0x0, 0xc6b) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000590d20, 0xc0004c3000, 0xe62, 0xe62, 0xc0004c31f7, 0xfa, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc0004e9200, 0xc0004c3000, 0xe62, 0xe62, 0x7f33c12f2f00, 0x7f33c14c0fff, 0xc000063970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc000086958, 0x1722620, 0xc0004e9200, 0x40bfa5, 0x12b7a80, 0x13c6900) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000086700, 0x7f33c3c0c008, 0xc000590d20, 0x5, 0xc000590d20, 0xfa) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000086700, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc000086700, 0xc000619000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc00080f7a0, 0xc000512b98, 0x9, 0x9, 0xc000063d10, 0x0, 0x732392) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1722460, 0xc00080f7a0, 0xc000512b98, 0x9, 0x9, 0x9, 0xc00009e050, 0x0, 0x1722840) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc000512b98, 0x9, 0x9, 0x1722460, 0xc00080f7a0, 0x0, 0x0, 0xc0005a83c0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc000512b60, 0xc0005a83c0, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc000063fb8, 0x70c2dd, 0xc00038b920) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc000089080) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 6081 [IO wait]: internal/poll.runtime_pollWait(0x7f33c3c68e80, 0x72, 0xffffffffffffffff) /usr/local/go/src/runtime/netpoll.go:184 +0x55 internal/poll.(*pollDesc).wait(0xc0006f3018, 0x72, 0xe00, 0xe62, 0xffffffffffffffff) /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc0006f3000, 0xc000788000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf net.(*netFD).Read(0xc0006f3000, 0xc000788000, 0xe62, 0xe62, 0x2339baa015525d14, 0x74e2ca05d8bcfa2b, 0x1000000a594df62) /usr/local/go/src/net/fd_unix.go:202 +0x4f net.(*conn).Read(0xc0000100a8, 0xc000788000, 0xe62, 0xe62, 0x0, 0x0, 0x0) /usr/local/go/src/net/net.go:184 +0x68 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0004f65c0, 0xc00023e888, 0xc000788000, 0xe62, 0xe62, 0x203000, 0x0, 0xc6b) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0004f65c0, 0xc000788000, 0xe62, 0xe62, 0xc0007881f7, 0xf8, 0x10) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a crypto/tls.(*atLeastReader).Read(0xc000334080, 0xc000788000, 0xe62, 0xe62, 0x400, 0x64020e7900, 0xc00023e970) /usr/local/go/src/crypto/tls/conn.go:780 +0x60 bytes.(*Buffer).ReadFrom(0xc000433058, 0x1722620, 0xc000334080, 0x40bfa5, 0x12b7a80, 0x13c6900) /usr/local/go/src/bytes/buffer.go:204 +0xb4 crypto/tls.(*Conn).readFromUntil(0xc000432e00, 0x7f33c3c0c008, 0xc0004f65c0, 0x5, 0xc0004f65c0, 0xf8) /usr/local/go/src/crypto/tls/conn.go:802 +0xec crypto/tls.(*Conn).readRecordOrCCS(0xc000432e00, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:609 +0x124 crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:577 crypto/tls.(*Conn).Read(0xc000432e00, 0xc0007ee000, 0x1000, 0x1000, 0x0, 0x0, 0x0) /usr/local/go/src/crypto/tls/conn.go:1255 +0x161 bufio.(*Reader).Read(0xc00011d980, 0xc000513298, 0x9, 0x9, 0xc00023ed10, 0x0, 0x732392) /usr/local/go/src/bufio/bufio.go:226 +0x26a io.ReadAtLeast(0x1722460, 0xc00011d980, 0xc000513298, 0x9, 0x9, 0x9, 0xc00009e050, 0x0, 0x1722840) /usr/local/go/src/io/io.go:310 +0x87 io.ReadFull(...) /usr/local/go/src/io/io.go:329 net/http.http2readFrameHeader(0xc000513298, 0x9, 0x9, 0x1722460, 0xc00011d980, 0x0, 0x0, 0xc0002f21e0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1477 +0x87 net/http.(*http2Framer).ReadFrame(0xc000513260, 0xc0002f21e0, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:1735 +0xa1 net/http.(*http2clientConnReadLoop).run(0xc00023efb8, 0x15093d8, 0xc000658bc0) /usr/local/go/src/net/http/h2_bundle.go:8175 +0x8e net/http.(*http2ClientConn).readLoop(0xc0007ea000) /usr/local/go/src/net/http/h2_bundle.go:8103 +0xa3 created by net/http.(*http2Transport).newClientConn /usr/local/go/src/net/http/h2_bundle.go:7162 +0x62f goroutine 6218 [select]: net/http.(*http2ClientConn).roundTrip(0xc0007e0000, 0xc00074e000, 0x0, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/h2_bundle.go:7573 +0x9a0 net/http.(*http2Transport).RoundTripOpt(0xc00038b920, 0xc00074e000, 0xc000522900, 0x740135, 0x0, 0xc0004926c0) /usr/local/go/src/net/http/h2_bundle.go:6936 +0x172 net/http.(*http2Transport).RoundTrip(...) /usr/local/go/src/net/http/h2_bundle.go:6897 net/http.http2noDialH2RoundTripper.RoundTrip(0xc00038b920, 0xc00074e000, 0xc0004973b0, 0x5, 0xc000492748) /usr/local/go/src/net/http/h2_bundle.go:9032 +0x3e net/http.(*Transport).roundTrip(0xc000395a40, 0xc00074e000, 0x14a2578, 0xa, 0xc0007e88f8) /usr/local/go/src/net/http/transport.go:485 +0xd0a net/http.(*Transport).RoundTrip(...) /usr/local/go/src/net/http/roundtrip.go:17 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc000494150, 0xc00074e000, 0xc00074e000, 0x0, 0x150) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:330 +0x1de github.com/rclone/rclone/vendor/golang.org/x/oauth2.(*Transport).RoundTrip(0xc0002f2c30, 0xc0005e3f00, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/vendor/golang.org/x/oauth2/transport.go:56 +0x124 net/http.send(0xc0005e3f00, 0x1723e20, 0xc0002f2c30, 0x0, 0x0, 0x0, 0xc000122268, 0x203000, 0x1, 0x0) /usr/local/go/src/net/http/client.go:250 +0x43a net/http.(*Client).send(0xc0002f2c60, 0xc0005e3f00, 0x0, 0x0, 0x0, 0xc000122268, 0x0, 0x1, 0x12ecb40) /usr/local/go/src/net/http/client.go:174 +0xfa net/http.(*Client).do(0xc0002f2c60, 0xc0005e3f00, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/client.go:641 +0x3ce net/http.(*Client).Do(...) /usr/local/go/src/net/http/client.go:509 github.com/rclone/rclone/lib/rest.(*Client).Call(0xc00013e140, 0x1745840, 0xc00007a0c0, 0xc00025f5a8, 0x0, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:270 +0x78a github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc00013e140, 0x1745840, 0xc00007a0c0, 0xc00025f5a8, 0x11b4520, 0xc0000d93b0, 0x11a22e0, 0xc0000ba3d0, 0x15069d8, 0x15076e0, ...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:454 +0x206 github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:397 github.com/rclone/rclone/backend/sharefile.(*Fs).updateItem.func1(0xc000235c80, 0xc000235d08, 0xc000671cd8) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:910 +0xc7 github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc0000d9400, 0xc0000d9400, 0x2, 0xc0005bf990) /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1394 +0x3c github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00038aa80, 0xc0000d9400, 0xa, 0x50, 0x13f9ea0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x8b github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc00038aa80, 0xc0000d9400, 0x0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a github.com/rclone/rclone/backend/sharefile.(*Fs).updateItem(0xc00061a0a0, 0x1745840, 0xc00007a0c0, 0xc000645800, 0x24, 0x0, 0x0, 0xc000644720, 0x24, 0x0, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:909 +0x686 github.com/rclone/rclone/backend/sharefile.(*Fs).move(0xc00061a0a0, 0x1745840, 0xc00007a0c0, 0xc0004be101, 0xc000645800, 0x24, 0xc0004be1f0, 0x7, 0xc0004be1f0, 0x7, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:948 +0x1d7 github.com/rclone/rclone/backend/sharefile.(*Fs).Move(0xc00061a0a0, 0x1745840, 0xc00007a0c0, 0x1758c80, 0xc0006f0480, 0xc0004be1f0, 0x7, 0xd, 0x1478001, 0xd, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/sharefile/sharefile.go:994 +0x2ad github.com/rclone/rclone/fs/operations.Move(0x1745840, 0xc00007a0c0, 0x1758c00, 0xc00061a0a0, 0x0, 0x0, 0xc0004be1f0, 0x7, 0x1758c80, 0xc0006f0480, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:467 +0x225 github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove(0xc00057e8c0, 0x1745840, 0xc00007a0c0, 0xc000189fc0, 0x1758c00, 0xc00061a0a0, 0xc00057e998) /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:295 +0x189 created by github.com/rclone/rclone/fs/sync.(*syncCopyMove).startTransfers /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:322 +0xb1 "./sync.test -test.v -test.timeout 30m0s -remote TestSharefile: -verbose" - Finished ERROR in 30m4.58275076s (try 1/5): exit status 2: Failed [TestServerSideMove]