"./sync.test -test.v -test.timeout 1h0m0s -remote TestPikPak: -verbose -test.run '^(TestCopyRedownload|TestSyncBackupDirWithSuffix)$'" - Starting (try 2/5)
2024/04/26 03:57:49 DEBUG : Creating backend with remote "TestPikPak:rclone-test-tohixaf2juwamir0mudegaf3"
2024/04/26 03:57:49 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2024/04/26 03:57:52 DEBUG : Creating backend with remote "/tmp/rclone538343486"
=== RUN   TestCopyRedownload
    run.go:180: Remote "PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3'", Local "Local file system at /tmp/rclone538343486", Modify Window "876000h0m0s"
2024/04/26 03:57:57 DEBUG : sub dir: Making directory with metadata
2024/04/26 03:57:57 INFO  : sub dir: Made directory with metadata (mtime=2024-04-26T11:57:54.549+08:00)
2024/04/26 03:57:57 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2024/04/26 03:57:58 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2024/04/26 03:57:58 DEBUG : Local file system at /tmp/rclone538343486: Waiting for checks to finish
2024/04/26 03:57:58 DEBUG : Local file system at /tmp/rclone538343486: Waiting for transfers to finish
2024/04/26 03:58:00 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check
2024/04/26 03:58:00 DEBUG : sub dir/hello world.lipahew9.partial: renamed to: sub dir/hello world
2024/04/26 03:58:00 INFO  : sub dir/hello world: Copied (new)
2024/04/26 03:58:00 INFO  : sub dir: Set directory modification time (using SetModTime)
    run.go:180: Remote "PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3'", Local "Local file system at /tmp/rclone538343486", Modify Window "876000h0m0s"
2024/04/26 03:58:01 DEBUG : sub dir: Rmdir: contains file: "hello world"
    run.go:125: removing dir "sub dir" failed - try 1/3: directory not empty
2024/04/26 03:58:02 DEBUG : sub dir: Rmdir: contains trashed file: "hello world"
    fstest.go:292: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:295: Flushing the directory cache
    fstest.go:286: Sleeping for 6s just to make sure
--- PASS: TestCopyRedownload (20.23s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:180: Remote "PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3'", Local "Local file system at /tmp/rclone538343486", Modify Window "876000h0m0s"
2024/04/26 03:58:17 DEBUG : pacer: low level retry 1/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:17 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2024/04/26 03:58:17 DEBUG : pacer: low level retry 2/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:17 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2024/04/26 03:58:18 DEBUG : pacer: low level retry 3/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:18 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2024/04/26 03:58:18 DEBUG : pacer: low level retry 4/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:18 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2024/04/26 03:58:18 DEBUG : pacer: low level retry 5/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:18 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2024/04/26 03:58:18 DEBUG : pacer: low level retry 6/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:18 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2024/04/26 03:58:19 DEBUG : pacer: low level retry 7/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:19 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2024/04/26 03:58:19 DEBUG : pacer: low level retry 8/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:19 DEBUG : pacer: Rate limited, increasing sleep to 2s
2024/04/26 03:58:21 DEBUG : pacer: low level retry 9/10 (error not PHASE_TYPE_COMPLETE)
2024/04/26 03:58:23 DEBUG : pacer: Reducing sleep to 1.5s
2024/04/26 03:58:25 DEBUG : pacer: Reducing sleep to 1.125s
2024/04/26 03:58:26 DEBUG : pacer: Reducing sleep to 843.75ms
2024/04/26 03:58:26 DEBUG : Creating backend with remote "TestPikPak:rclone-test-tohixaf2juwamir0mudegaf3/dst"
2024/04/26 03:58:27 DEBUG : Creating backend with remote "TestPikPak:rclone-test-tohixaf2juwamir0mudegaf3/backup"
2024/04/26 03:58:29 DEBUG : one: Sizes differ (src 4 vs dst 3)
2024/04/26 03:58:29 DEBUG : two: Sizes identical
2024/04/26 03:58:29 DEBUG : two: Unchanged skipping
2024/04/26 03:58:29 DEBUG : PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3/dst': Waiting for checks to finish
2024/04/26 03:58:30 INFO  : one: Moved (server-side) to: one.bak
2024/04/26 03:58:30 DEBUG : PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3/dst': Waiting for transfers to finish
2024/04/26 03:58:32 DEBUG : one: Dst hash empty - aborting Src hash check
2024/04/26 03:58:32 INFO  : one: Copied (new)
2024/04/26 03:58:32 DEBUG : Waiting for deletions to finish
2024/04/26 03:58:33 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2024/04/26 03:58:33 INFO  : three.txt: Moved into backup dir
2024/04/26 03:58:33 DEBUG : pacer: Reducing sleep to 632.8125ms
2024/04/26 03:58:34 DEBUG : pacer: Reducing sleep to 474.609375ms
2024/04/26 03:58:35 DEBUG : pacer: Reducing sleep to 355.957031ms
2024/04/26 03:58:35 DEBUG : pacer: Reducing sleep to 266.967773ms
2024/04/26 03:58:36 DEBUG : pacer: Reducing sleep to 200.225829ms
2024/04/26 03:58:36 DEBUG : pacer: Reducing sleep to 150.169371ms
2024/04/26 03:58:36 DEBUG : pacer: Reducing sleep to 112.627028ms
2024/04/26 03:58:37 DEBUG : pacer: Reducing sleep to 84.470271ms
2024/04/26 03:58:37 DEBUG : pacer: Reducing sleep to 63.352703ms
2024/04/26 03:58:37 DEBUG : pacer: Reducing sleep to 47.514527ms
2024/04/26 03:58:37 DEBUG : one: Sizes differ (src 5 vs dst 4)
2024/04/26 03:58:37 DEBUG : PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3/dst': Waiting for checks to finish
2024/04/26 03:58:37 DEBUG : two: Sizes identical
2024/04/26 03:58:37 DEBUG : two: Unchanged skipping
2024/04/26 03:58:38 INFO  : one.bak: Deleted
2024/04/26 03:58:38 INFO  : one: Moved (server-side) to: one.bak
2024/04/26 03:58:38 DEBUG : PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3/dst': Waiting for transfers to finish
2024/04/26 03:58:39 DEBUG : one: Dst hash empty - aborting Src hash check
2024/04/26 03:58:39 INFO  : one: Copied (new)
2024/04/26 03:58:39 DEBUG : Waiting for deletions to finish
2024/04/26 03:58:40 INFO  : three.txt.bak: Deleted
2024/04/26 03:58:40 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2024/04/26 03:58:40 INFO  : three.txt: Moved into backup dir
2024/04/26 03:58:40 DEBUG : pacer: Reducing sleep to 35.635895ms
2024/04/26 03:58:41 DEBUG : pacer: Reducing sleep to 26.726921ms
2024/04/26 03:58:41 DEBUG : pacer: Reducing sleep to 20.04519ms
2024/04/26 03:58:42 DEBUG : pacer: Reducing sleep to 15.033892ms
2024/04/26 03:58:42 DEBUG : pacer: Reducing sleep to 11.275419ms
2024/04/26 03:58:42 DEBUG : pacer: Reducing sleep to 10ms
2024/04/26 03:58:43 DEBUG : dst: Rmdir: contains trashed file: "one"
2024/04/26 03:58:43 DEBUG : dst: Rmdir: contains trashed file: "two"
2024/04/26 03:58:44 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak"
2024/04/26 03:58:44 DEBUG : backup: Rmdir: contains trashed file: "one.bak"
2024/04/26 03:58:44 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak"
2024/04/26 03:58:44 DEBUG : backup: Rmdir: contains trashed file: "one.bak"
--- PASS: TestSyncBackupDirWithSuffix (32.26s)
PASS
2024/04/26 03:58:44 DEBUG : PikPak root 'rclone-test-tohixaf2juwamir0mudegaf3': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestPikPak: -verbose -test.run '^(TestCopyRedownload|TestSyncBackupDirWithSuffix)$'" - Finished OK in 55.561367817s (try 2/5)