"./sync.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose -test.run '^(TestSyncEmptyDirectories|TestSyncNoEmptyDirectories)$'" - Starting (try 2/5)
2025/12/17 02:30:15 DEBUG : Creating backend with remote "TestBox:rclone-test-pimaceg6jasu"
2025/12/17 02:30:15 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/12/17 02:30:25 DEBUG : box root 'rclone-test-pimaceg6jasu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/12/17 02:30:32 DEBUG : Creating backend with remote "/tmp/rclone1606348020"
=== RUN   TestSyncEmptyDirectories
    run.go:185: Remote "box root 'rclone-test-pimaceg6jasu'", Local "Local file system at /tmp/rclone1606348020", Modify Window "1s"
2025/12/17 02:30:32 DEBUG : sub dir2: Making directory with metadata
2025/12/17 02:30:32 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/12/17 02:30:32 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/12/17 02:30:45 DEBUG : box root 'rclone-test-pimaceg6jasu': Ignoring "Shared folder — ForNick" - unknown type "web_link"
2025/12/17 02:31:07 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/12/17 02:31:07 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/12/17 02:31:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/12/17 02:31:17 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/12/17 02:31:17 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/12/17 02:31:24 DEBUG : pacer: Reducing sleep to 30ms
2025/12/17 02:31:31 DEBUG : pacer: Reducing sleep to 22.5ms
2025/12/17 02:31:31 INFO  : sub dir2: Making directory
2025/12/17 02:31:31 DEBUG : pacer: Reducing sleep to 16.875ms
2025/12/17 02:31:35 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/12/17 02:31:35 INFO  : sub dir: Making directory
2025/12/17 02:31:48 DEBUG : pacer: Reducing sleep to 10ms
2025/12/17 02:32:04 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/12/17 02:32:04 DEBUG : box root 'rclone-test-pimaceg6jasu': Waiting for checks to finish
2025/12/17 02:32:04 DEBUG : box root 'rclone-test-pimaceg6jasu': Waiting for transfers to finish
2025/12/17 02:32:28 DEBUG : sub dir/hello world: size = 11 OK
2025/12/17 02:32:28 DEBUG : sub dir/hello world: sha1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK
2025/12/17 02:32:28 INFO  : sub dir/hello world: Copied (new)
2025/12/17 02:32:28 DEBUG : Waiting for deletions to finish
2025/12/17 02:32:30 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/12/17 02:32:30 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503))
2025/12/17 02:32:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/12/17 02:32:34 DEBUG : pacer: Reducing sleep to 15ms
2025/12/17 02:32:41 DEBUG : pacer: Reducing sleep to 11.25ms
2025/12/17 02:32:41 DEBUG : box root 'rclone-test-pimaceg6jasu': Skipping modtime test as remote does not support DirSetModTime or MkdirMetadata
2025/12/17 02:32:54 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncEmptyDirectories (209.66s)
=== RUN   TestSyncNoEmptyDirectories
    run.go:185: Remote "box root 'rclone-test-pimaceg6jasu'", Local "Local file system at /tmp/rclone1606348020", Modify Window "1s"
2025/12/17 02:34:02 INFO  : sub dir2: Making directory
2025/12/17 02:34:10 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/12/17 02:34:10 DEBUG : box root 'rclone-test-pimaceg6jasu': Waiting for checks to finish
2025/12/17 02:34:10 DEBUG : box root 'rclone-test-pimaceg6jasu': Waiting for transfers to finish
2025/12/17 02:34:24 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later)
2025/12/17 02:34:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/12/17 02:34:24 DEBUG : sub dir/hello world: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 0/10
2025/12/17 02:34:30 DEBUG : pacer: Reducing sleep to 15ms
2025/12/17 02:34:32 DEBUG : pacer: Reducing sleep to 11.25ms
2025/12/17 02:34:32 DEBUG : sub dir/hello world: size = 11 OK
2025/12/17 02:34:32 DEBUG : sub dir/hello world: sha1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK
2025/12/17 02:34:32 INFO  : sub dir/hello world: Copied (new)
2025/12/17 02:34:32 DEBUG : Waiting for deletions to finish
2025/12/17 02:34:33 DEBUG : pacer: Reducing sleep to 10ms
2025/12/17 02:35:14 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/12/17 02:35:14 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/12/17 02:35:58 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value
2025/12/17 02:35:58 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503))
2025/12/17 02:35:58 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/12/17 02:36:27 DEBUG : pacer: low level retry 3/10 (error Error "unavailable" (503): Service is temporarily unavailable)
2025/12/17 02:36:27 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/12/17 02:36:54 DEBUG : pacer: Reducing sleep to 60ms
2025/12/17 02:37:09 DEBUG : pacer: Reducing sleep to 45ms
2025/12/17 02:37:16 DEBUG : pacer: Reducing sleep to 33.75ms
--- PASS: TestSyncNoEmptyDirectories (194.21s)
PASS
2025/12/17 02:37:16 DEBUG : box root 'rclone-test-pimaceg6jasu': Purge remote
2025/12/17 02:37:51 DEBUG : pacer: Reducing sleep to 25.3125ms
"./sync.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose -test.run '^(TestSyncEmptyDirectories|TestSyncNoEmptyDirectories)$'" - Finished OK in 7m36.300873885s (try 2/5)