"./vfs.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose" - Starting (try 1/5) 2025/12/17 01:32:51 DEBUG : Creating backend with remote "TestBox:rclone-test-tugafuz4vepe" 2025/12/17 01:32:51 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/12/17 01:32:57 DEBUG : box root 'rclone-test-tugafuz4vepe': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 01:32:59 DEBUG : Creating backend with remote "/tmp/rclone2953525156" === RUN TestDirHandleMethods run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 01:33:05 DEBUG : box root 'rclone-test-tugafuz4vepe': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 01:33:09 DEBUG : pacer: low level retry 1/10 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:33:09 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:33:23 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:33:25 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:33:25 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:34:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063419927309") 2025/12/17 01:34:00 DEBUG : box root 'rclone-test-tugafuz4vepe': ["rclone-test-tugafuz4vepe"(0)|folder|ITEM_CREATE|356308871618|3582914fa75cf97c3cc05efdb1f9a9b0ba14b205] new parent not found 2025/12/17 01:34:00 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356310452471|56f3fc351d0218e4baa420df9d6a19bacb8352e9] added new path ("dir") for notify 2025/12/17 01:34:00 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:34:00 DEBUG : >changeNotify: 2025/12/17 01:34:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 1 paths and 1 notifications 2025/12/17 01:34:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063419987588") 2025/12/17 01:34:51 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:34:51 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:35:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063419988412") 2025/12/17 01:35:00 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:35:00 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077311352123|26abc27f74c4a765922481b9644c9d4690cab29b] new parent not found 2025/12/17 01:35:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 01:35:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420047595") 2025/12/17 01:35:01 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:35:07 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:35:08 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:35:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:35:20 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:35:37 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:35:37 DEBUG : pacer: Rate limited, increasing sleep to 30ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 3/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:35:39 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 01:35:51 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:35:51 DEBUG : pacer: Rate limited, increasing sleep to 45ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 4/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:36:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420048395") 2025/12/17 01:36:00 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 01:36:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 01:36:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420107594") 2025/12/17 01:36:01 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 01:36:02 DEBUG : pacer: Reducing sleep to 18.984375ms 2025/12/17 01:36:09 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:36:09 DEBUG : pacer: Rate limited, increasing sleep to 37.96875ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 5/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:36:12 DEBUG : pacer: Reducing sleep to 28.476562ms 2025/12/17 01:36:55 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:36:55 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 6/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:37:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420107881") 2025/12/17 01:37:00 DEBUG : pacer: Reducing sleep to 42.714843ms 2025/12/17 01:37:00 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356310609516|8dc7f4de2a98b6c075847d461084c2d287ee8a48] new parent not found 2025/12/17 01:37:00 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077311590380|f6b76b26b89b4af4ecbb7d1418248bb68b16068c] new parent not found 2025/12/17 01:37:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 0 paths and 0 notifications 2025/12/17 01:37:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420167597") 2025/12/17 01:37:01 DEBUG : pacer: Reducing sleep to 32.036132ms 2025/12/17 01:37:02 DEBUG : pacer: Reducing sleep to 24.027099ms 2025/12/17 01:37:49 DEBUG : pacer: Reducing sleep to 18.020324ms 2025/12/17 01:37:56 DEBUG : pacer: Reducing sleep to 13.515243ms 2025/12/17 01:38:00 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420167878") 2025/12/17 01:38:00 DEBUG : pacer: Reducing sleep to 10.136432ms 2025/12/17 01:38:03 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:38:03 DEBUG : WaitForWriters: timeout=30s 2025/12/17 01:38:03 DEBUG : dir: Looking for writers 2025/12/17 01:38:03 DEBUG : Looking for writers 2025/12/17 01:38:03 DEBUG : dir: reading active writers 2025/12/17 01:38:03 DEBUG : >WaitForWriters: 2025/12/17 01:38:20 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:38:20 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:38:48 DEBUG : pacer: low level retry 2/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:38:48 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 01:38:57 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 01:39:05 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 01:39:10 DEBUG : pacer: Reducing sleep to 16.875ms --- PASS: TestDirHandleMethods (371.16s) === RUN TestDirHandleReaddir run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 01:39:11 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/12/17 01:39:14 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:39:49 DEBUG : box root 'rclone-test-tugafuz4vepe': Background refresher detected expired token but no uploads in progress - doing nothing 2025/12/17 01:39:50 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:39:50 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:39:50 DEBUG : TestBox: Token expired 2025/12/17 01:39:50 DEBUG : TestBox: No updated token found in the config file 2025/12/17 01:39:56 DEBUG : TestBox: Token refresh failed try 1/5: oauth2: "temporarily_unavailable" "The server is currently unable to handle the request due to a temporary overloading of the server" 2025/12/17 01:39:57 DEBUG : TestBox: No updated token found in the config file 2025/12/17 01:40:08 DEBUG : TestBox: Token refresh failed try 2/5: oauth2: "temporarily_unavailable" "The server is currently unable to handle the request due to a temporary overloading of the server" 2025/12/17 01:40:09 DEBUG : TestBox: No updated token found in the config file 2025/12/17 01:40:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420297962") 2025/12/17 01:40:13 DEBUG : TestBox: Token refresh failed try 3/5: oauth2: "temporarily_unavailable" "The server is currently unable to handle the request due to a temporary overloading of the server" 2025/12/17 01:40:14 DEBUG : Config file has changed externally - reloading 2025/12/17 01:40:14 DEBUG : TestBox: Loaded fresh token from config file 2025/12/17 01:40:14 DEBUG : TestBox: Loaded new refresh token from config file 2025/12/17 01:40:14 DEBUG : TestBox: Token refresh successful 2025/12/17 01:40:14 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356310452471|b3e86f9a23eb7e6017c5aa13e03c2c0b36ed5087] added old path ("dir") for notify 2025/12/17 01:40:14 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:40:14 DEBUG : >changeNotify: 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 1 paths and 1 notifications 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420361086") 2025/12/17 01:40:14 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356310637774|af15bd6cbb50753067e065478c3c3a01381405de] new parent not found 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420361363") 2025/12/17 01:40:14 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:40:14 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356310637774|af15bd6cbb50753067e065478c3c3a01381405de] ignored due to duplicate EventID 2025/12/17 01:40:25 DEBUG : pacer: low level retry 2/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:40:25 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:40:46 DEBUG : pacer: low level retry 3/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:40:46 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 01:41:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420361630") 2025/12/17 01:41:11 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 01:41:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356310637774|af15bd6cbb50753067e065478c3c3a01381405de] ignored due to duplicate EventID 2025/12/17 01:41:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077302544654|62aad99d47c92016fcb85be1228c51be9571c7ee] new parent not found 2025/12/17 01:41:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 0 paths and 0 notifications 2025/12/17 01:41:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420418239") 2025/12/17 01:41:11 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 01:41:20 DEBUG : pacer: low level retry 4/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 01:41:20 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/12/17 01:41:28 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 01:41:32 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 01:41:40 DEBUG : pacer: Reducing sleep to 18.984375ms 2025/12/17 01:41:41 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:41:41 DEBUG : pacer: Rate limited, increasing sleep to 37.96875ms run.go:286: Retry Put of "dir/file2" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:41:45 DEBUG : pacer: Reducing sleep to 28.476562ms 2025/12/17 01:41:46 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:41:46 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms run.go:286: Retry Put of "dir/file2" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:41:48 DEBUG : pacer: Reducing sleep to 42.714843ms 2025/12/17 01:41:49 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:41:49 DEBUG : pacer: Rate limited, increasing sleep to 85.429686ms run.go:286: Retry Put of "dir/file2" to box root 'rclone-test-tugafuz4vepe': 3/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:41:59 DEBUG : pacer: Reducing sleep to 64.072264ms 2025/12/17 01:42:00 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:42:00 DEBUG : pacer: Rate limited, increasing sleep to 128.144528ms run.go:286: Retry Put of "dir/file2" to box root 'rclone-test-tugafuz4vepe': 4/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:42:04 DEBUG : pacer: Reducing sleep to 96.108396ms 2025/12/17 01:42:08 DEBUG : pacer: Reducing sleep to 72.081297ms 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420418521") 2025/12/17 01:42:11 DEBUG : pacer: Reducing sleep to 54.060972ms 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356310527943|edcbba36b04416f9d01b543a4835218c8775894b] added new path ("dir") for notify 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file1"(0)|file|ITEM_UPLOAD|2077306389322|35fdb79c9eaaa233859aaac906f36886cad6601a] added new path ("dir/file1") for notify 2025/12/17 01:42:11 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:42:11 DEBUG : >changeNotify: 2025/12/17 01:42:11 DEBUG : changeNotify: relativePath="dir/file1", type=1 2025/12/17 01:42:11 DEBUG : >changeNotify: 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 2 paths and 2 notifications 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420478235") 2025/12/17 01:42:11 DEBUG : pacer: Reducing sleep to 40.545729ms 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file2"(0)|file|ITEM_UPLOAD|2077312460883|c93c9ea78eab6aac0b5d32d1054326323197fdf6] added new path ("dir/file2") for notify 2025/12/17 01:42:11 DEBUG : changeNotify: relativePath="dir/file2", type=1 2025/12/17 01:42:11 DEBUG : >changeNotify: 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 1 paths and 1 notifications 2025/12/17 01:42:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420478518") 2025/12/17 01:42:12 DEBUG : pacer: Reducing sleep to 30.409296ms 2025/12/17 01:42:12 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file2"(0)|file|ITEM_UPLOAD|2077312460883|c93c9ea78eab6aac0b5d32d1054326323197fdf6] ignored due to duplicate EventID 2025/12/17 01:42:13 DEBUG : pacer: Reducing sleep to 22.806972ms 2025/12/17 01:42:18 DEBUG : pacer: Reducing sleep to 17.105229ms 2025/12/17 01:42:26 DEBUG : pacer: Reducing sleep to 12.828921ms 2025/12/17 01:43:02 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:43:02 DEBUG : pacer: Rate limited, increasing sleep to 25.657842ms run.go:286: Retry Put of "dir/subdir/file3" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:43:06 DEBUG : pacer: Reducing sleep to 19.243381ms 2025/12/17 01:43:07 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:43:07 DEBUG : pacer: Rate limited, increasing sleep to 38.486762ms run.go:286: Retry Put of "dir/subdir/file3" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:43:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420478822") 2025/12/17 01:43:11 DEBUG : pacer: Reducing sleep to 28.865071ms 2025/12/17 01:43:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file2"(0)|file|ITEM_UPLOAD|2077312460883|c93c9ea78eab6aac0b5d32d1054326323197fdf6] ignored due to duplicate EventID 2025/12/17 01:43:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["subdir"(0)|folder|ITEM_CREATE|356310597316|88439ac9d32fcb91a697eb23ece31d0b7586d12e] added new path ("dir/subdir") for notify 2025/12/17 01:43:11 DEBUG : changeNotify: relativePath="dir/subdir", type=0 2025/12/17 01:43:11 DEBUG : >changeNotify: 2025/12/17 01:43:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 4 events, resulting in 1 paths and 1 notifications 2025/12/17 01:43:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420538240") 2025/12/17 01:43:11 DEBUG : pacer: Reducing sleep to 21.648803ms 2025/12/17 01:43:16 DEBUG : pacer: Reducing sleep to 16.236602ms 2025/12/17 01:43:28 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:43:28 DEBUG : pacer: Rate limited, increasing sleep to 32.473204ms run.go:286: Retry Put of "dir/subdir/file3" to box root 'rclone-test-tugafuz4vepe': 3/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:43:38 DEBUG : pacer: Reducing sleep to 24.354903ms 2025/12/17 01:44:04 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:44:04 DEBUG : pacer: Rate limited, increasing sleep to 48.709806ms run.go:286: Retry Put of "dir/subdir/file3" to box root 'rclone-test-tugafuz4vepe': 4/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:44:08 DEBUG : pacer: Reducing sleep to 36.532354ms 2025/12/17 01:44:09 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:44:09 DEBUG : pacer: Rate limited, increasing sleep to 73.064708ms run.go:286: Retry Put of "dir/subdir/file3" to box root 'rclone-test-tugafuz4vepe': 5/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:44:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420538515") 2025/12/17 01:44:11 DEBUG : pacer: Reducing sleep to 54.798531ms 2025/12/17 01:44:11 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356307995463|cb2a641fa9fe5b93dd847ad3ce911bc387e1f483] new parent not found 2025/12/17 01:44:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 01:44:11 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420598256") 2025/12/17 01:44:11 DEBUG : pacer: Reducing sleep to 41.098898ms 2025/12/17 01:44:17 DEBUG : pacer: Reducing sleep to 30.824173ms 2025/12/17 01:44:40 DEBUG : pacer: Reducing sleep to 23.118129ms 2025/12/17 01:44:46 DEBUG : pacer: Reducing sleep to 17.338596ms 2025/12/17 01:44:46 DEBUG : pacer: Reducing sleep to 13.003947ms 2025/12/17 01:44:51 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:45:06 DEBUG : WaitForWriters: timeout=30s 2025/12/17 01:45:06 DEBUG : dir/subdir: Looking for writers 2025/12/17 01:45:06 DEBUG : dir: Looking for writers 2025/12/17 01:45:06 DEBUG : file2: reading active writers 2025/12/17 01:45:06 DEBUG : subdir: reading active writers 2025/12/17 01:45:06 DEBUG : file1: reading active writers 2025/12/17 01:45:06 DEBUG : Looking for writers 2025/12/17 01:45:06 DEBUG : dir: reading active writers 2025/12/17 01:45:06 DEBUG : >WaitForWriters: 2025/12/17 01:45:58 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:45:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:46:09 DEBUG : pacer: low level retry 2/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:46:09 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 01:46:21 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 01:46:24 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 01:46:31 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 01:46:31 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 01:46:31 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/12/17 01:46:44 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 01:46:58 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 01:47:19 DEBUG : pacer: Reducing sleep to 18.984375ms 2025/12/17 01:47:29 DEBUG : pacer: Reducing sleep to 14.238281ms --- PASS: TestDirHandleReaddir (498.07s) === RUN TestDirHandleReaddirnames run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 01:47:29 DEBUG : pacer: Reducing sleep to 10.67871ms 2025/12/17 01:47:34 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:48:03 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:48:03 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:48:03 DEBUG : forgetting directory cache 2025/12/17 01:48:03 DEBUG : dir: forgetting directory cache 2025/12/17 01:48:03 DEBUG : dir: forgetting directory cache 2025/12/17 01:48:10 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:48:29 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420796041") 2025/12/17 01:48:29 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:48:29 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356310527943|db64dc2381287905bf981713e7b122f457f5338f] added old path ("dir") for notify 2025/12/17 01:48:29 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356310354983|f1e56a5f644da5a03ffe6e442446c301528a6097] added new path ("dir") for notify 2025/12/17 01:48:29 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:48:29 DEBUG : >changeNotify: 2025/12/17 01:48:29 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 2 paths and 1 notifications 2025/12/17 01:48:29 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420856325") 2025/12/17 01:48:29 DEBUG : pacer: Reducing sleep to 10ms run.go:290: Failed to put "dir/file1" to "box root 'rclone-test-tugafuz4vepe'": Error "item_name_in_use" (409): Item with the same name already exists ({"conflicts":{"type":"file","id":"2077300396674","file_version":{"type":"file_version","id":"2295079528674","sha1":"a379624177abc4679cafafa8eae1d73e1478aaa6"},"sequence_id":"0","etag":"0","sha1":"a379624177abc4679cafafa8eae1d73e1478aaa6","name":"file1"}}) 2025/12/17 01:49:00 DEBUG : WaitForWriters: timeout=30s 2025/12/17 01:49:00 DEBUG : Looking for writers 2025/12/17 01:49:00 DEBUG : >WaitForWriters: --- FAIL: TestDirHandleReaddirnames (152.31s) === RUN TestDirMethods run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 01:50:16 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:50:16 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:50:29 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:51:01 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063420948326") 2025/12/17 01:51:01 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:51:01 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356310354983|0965487a416ac684a7e5781934aaf09a7f2c29dc] added old path ("dir") for notify 2025/12/17 01:51:01 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356309329679|80e2700e302d95537d08e0535abdf0d0ad26ae04] added new path ("dir") for notify 2025/12/17 01:51:01 DEBUG : box root 'rclone-test-tugafuz4vepe': ["potato2"(0)|file|ITEM_UPLOAD|2077299222271|0a3fbaaae7100081e72abbc1d2e7ce77b7376be0] new parent not found 2025/12/17 01:51:01 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:51:01 DEBUG : >changeNotify: 2025/12/17 01:51:01 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 2 paths and 1 notifications 2025/12/17 01:51:01 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421008552") 2025/12/17 01:51:02 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:51:35 DEBUG : WaitForWriters: timeout=30s 2025/12/17 01:51:35 DEBUG : dir: Looking for writers 2025/12/17 01:51:35 DEBUG : Looking for writers 2025/12/17 01:51:35 DEBUG : dir: reading active writers 2025/12/17 01:51:35 DEBUG : >WaitForWriters: 2025/12/17 01:51:58 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:51:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:52:11 DEBUG : pacer: low level retry 2/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:52:11 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 01:52:39 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 01:52:41 DEBUG : pacer: Reducing sleep to 22.5ms --- PASS: TestDirMethods (159.74s) === RUN TestDirForgetAll run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 01:52:41 DEBUG : pacer: Reducing sleep to 16.875ms 2025/12/17 01:52:47 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/12/17 01:52:50 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:53:10 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:53:10 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:53:31 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:53:40 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:53:40 DEBUG : pacer: Rate limited, increasing sleep to 30ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:53:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421108049") 2025/12/17 01:53:41 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 01:53:41 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356309329679|4617bab3b09147bec370bc3875a2d7bc76bae2a7] added old path ("dir") for notify 2025/12/17 01:53:41 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356309098980|d447357cf0aaceb966185727878b84fdc7edbff3] added new path ("dir") for notify 2025/12/17 01:53:41 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:53:41 DEBUG : >changeNotify: 2025/12/17 01:53:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 2 paths and 1 notifications 2025/12/17 01:53:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421168287") 2025/12/17 01:53:41 DEBUG : pacer: Reducing sleep to 16.875ms 2025/12/17 01:53:42 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/12/17 01:53:45 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:53:51 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:53:51 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:07 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:54:08 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:08 DEBUG : pacer: Rate limited, increasing sleep to 30ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 3/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:13 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 01:54:13 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:13 DEBUG : pacer: Rate limited, increasing sleep to 45ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 4/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:23 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 01:54:25 DEBUG : pacer: low level retry 1/1 (error Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:25 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 5/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 01:54:30 DEBUG : pacer: Reducing sleep to 50.625ms 2025/12/17 01:54:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421168521") 2025/12/17 01:54:41 DEBUG : pacer: Reducing sleep to 37.96875ms 2025/12/17 01:54:41 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077306434963|410252482b11b8c78a9d378b7b4f3cedb71328a9] new parent not found 2025/12/17 01:54:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 01:54:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421228273") 2025/12/17 01:54:41 DEBUG : pacer: Reducing sleep to 28.476562ms 2025/12/17 01:54:41 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077306434963|410252482b11b8c78a9d378b7b4f3cedb71328a9] ignored due to duplicate EventID 2025/12/17 01:54:55 DEBUG : forgetting directory cache 2025/12/17 01:54:55 DEBUG : dir: forgetting directory cache 2025/12/17 01:54:55 DEBUG : dir/subdir: forgetting directory cache 2025/12/17 01:55:31 DEBUG : pacer: low level retry 1/1 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:55:31 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 6/10 (Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:55:35 DEBUG : pacer: Reducing sleep to 42.714843ms 2025/12/17 01:55:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421228516") 2025/12/17 01:55:41 DEBUG : pacer: Reducing sleep to 32.036132ms 2025/12/17 01:55:41 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077306434963|410252482b11b8c78a9d378b7b4f3cedb71328a9] ignored due to duplicate EventID 2025/12/17 01:55:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 0 paths and 0 notifications 2025/12/17 01:55:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421288281") 2025/12/17 01:55:41 DEBUG : pacer: Reducing sleep to 24.027099ms 2025/12/17 01:56:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421288516") 2025/12/17 01:56:41 DEBUG : pacer: Reducing sleep to 18.020324ms 2025/12/17 01:56:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 0 paths and 0 notifications 2025/12/17 01:56:41 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421348271") 2025/12/17 01:56:41 DEBUG : pacer: Reducing sleep to 13.515243ms 2025/12/17 01:56:44 DEBUG : pacer: low level retry 1/1 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 01:56:44 DEBUG : pacer: Rate limited, increasing sleep to 27.030486ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 7/10 (Error "internal_server_error" (500): Internal Server Error) 2025/12/17 01:56:46 DEBUG : pacer: Reducing sleep to 20.272864ms 2025/12/17 01:56:51 DEBUG : pacer: Reducing sleep to 15.204648ms 2025/12/17 01:56:55 DEBUG : pacer: Reducing sleep to 11.403486ms 2025/12/17 01:57:01 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:57:05 DEBUG : dir: forgetting directory cache 2025/12/17 01:57:05 DEBUG : forgetting directory cache 2025/12/17 01:57:05 DEBUG : dir: forgetting directory cache 2025/12/17 01:57:05 DEBUG : WaitForWriters: timeout=30s 2025/12/17 01:57:05 DEBUG : Looking for writers 2025/12/17 01:57:05 DEBUG : >WaitForWriters: 2025/12/17 01:57:24 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 01:57:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:57:29 DEBUG : forgetting directory cache 2025/12/17 01:57:45 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:58:06 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:58:07 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestDirForgetAll (326.24s) === RUN TestDirForgetPath run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 01:58:31 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 01:58:31 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 01:58:40 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 01:59:07 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421434287") 2025/12/17 01:59:07 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 01:59:07 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356309098980|5081b143075d37e4a255b85fac09d7b216434c83] added old path ("dir") for notify 2025/12/17 01:59:07 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077302368649|e35539de537cf266daf2b03e60bb2ce72cb16d04] new parent not found 2025/12/17 01:59:07 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356311290362|ec3532614837032ef34f893c416fafeeca1556f7] added new path ("dir") for notify 2025/12/17 01:59:07 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 01:59:07 DEBUG : >changeNotify: 2025/12/17 01:59:07 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 2 paths and 1 notifications 2025/12/17 01:59:07 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421494527") 2025/12/17 01:59:08 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 01:59:26 DEBUG : ForgetPath: relativePath="dir/notfound", type=1 2025/12/17 01:59:26 DEBUG : dir: invalidating directory cache 2025/12/17 01:59:26 DEBUG : >ForgetPath: 2025/12/17 01:59:26 DEBUG : ForgetPath: relativePath="dir", type=0 2025/12/17 01:59:26 DEBUG : invalidating directory cache 2025/12/17 01:59:26 DEBUG : dir: forgetting directory cache 2025/12/17 01:59:26 DEBUG : >ForgetPath: 2025/12/17 01:59:26 DEBUG : ForgetPath: relativePath="not/in/cache", type=0 2025/12/17 01:59:26 DEBUG : >ForgetPath: 2025/12/17 01:59:26 DEBUG : WaitForWriters: timeout=30s 2025/12/17 01:59:26 DEBUG : dir: Looking for writers 2025/12/17 01:59:26 DEBUG : Looking for writers 2025/12/17 01:59:26 DEBUG : dir: reading active writers 2025/12/17 01:59:26 DEBUG : >WaitForWriters: --- PASS: TestDirForgetPath (88.35s) === RUN TestDirWalk run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 02:00:35 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421522642") 2025/12/17 02:00:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file1"(1)|file|ITEM_TRASH|2077319118623|330a5bc3b51b2d34d90684221a64e822fa126e32] old parent not cached 2025/12/17 02:00:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356311290362|d1dfdd214d223197537ec198a105b8868097a1a8] added old path ("dir") for notify 2025/12/17 02:00:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356311359739|164ac83af46dd28e6fb3abdda6846351d4f7953a] ignored due to old SequenceID ('\x00') 2025/12/17 02:00:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file1"(0)|file|ITEM_UPLOAD|2077313826508|9fea8d8e6d3a92453c63471b7368b0a87cccfd3d] ignored due to old SequenceID ('\x00') 2025/12/17 02:00:36 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 02:00:36 DEBUG : invalidating directory cache 2025/12/17 02:00:36 DEBUG : >changeNotify: 2025/12/17 02:00:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 6 events, resulting in 1 paths and 1 notifications 2025/12/17 02:00:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421582862") 2025/12/17 02:01:19 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:01:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:01:30 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:01:35 DEBUG : dir: forgetting directory cache 2025/12/17 02:01:35 DEBUG : forgetting directory cache 2025/12/17 02:01:35 DEBUG : dir: forgetting directory cache 2025/12/17 02:01:35 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421583101") 2025/12/17 02:01:36 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:01:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir2"(0)|folder|ITEM_CREATE|356311191627|bc686f4b551f794dc196a235b75740e5249bbc56] new parent not found 2025/12/17 02:01:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 02:01:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421642885") 2025/12/17 02:01:36 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:02:04 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:02:04 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "fil/a/b/c" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:02:10 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:02:11 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:02:11 DEBUG : pacer: Rate limited, increasing sleep to 30ms run.go:286: Retry Put of "fil/a/b/c" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:02:13 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:02:13 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:02:13 DEBUG : pacer: Rate limited, increasing sleep to 60ms 2025/12/17 02:02:15 DEBUG : pacer: Reducing sleep to 45ms 2025/12/17 02:02:35 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421643107") 2025/12/17 02:02:36 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 02:02:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["fil"(0)|folder|ITEM_CREATE|356310006963|d63f405fe25eb5427f86abc8a5c418032875a911] added new path ("fil") for notify 2025/12/17 02:02:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["a"(0)|folder|ITEM_CREATE|356309630028|c50d37e5e3a9187c30f80fb475d9d80a85fe3eec] added new path ("fil/a") for notify 2025/12/17 02:02:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["b"(0)|folder|ITEM_CREATE|356310501020|26a14daf281228b58e462c68a7bff7a1224ffda9] added new path ("fil/a/b") for notify 2025/12/17 02:02:36 DEBUG : changeNotify: relativePath="fil", type=0 2025/12/17 02:02:36 DEBUG : >changeNotify: 2025/12/17 02:02:36 DEBUG : changeNotify: relativePath="fil/a", type=0 2025/12/17 02:02:36 DEBUG : >changeNotify: 2025/12/17 02:02:36 DEBUG : changeNotify: relativePath="fil/a/b", type=0 2025/12/17 02:02:36 DEBUG : >changeNotify: 2025/12/17 02:02:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 3 paths and 3 notifications 2025/12/17 02:02:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421702867") 2025/12/17 02:02:36 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 02:02:53 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:02:53 DEBUG : pacer: Rate limited, increasing sleep to 50.625ms run.go:286: Retry Put of "fil/a/b/c" to box root 'rclone-test-tugafuz4vepe': 3/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:03:11 DEBUG : pacer: Reducing sleep to 37.96875ms 2025/12/17 02:03:18 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:03:18 DEBUG : pacer: Rate limited, increasing sleep to 75.9375ms run.go:286: Retry Put of "fil/a/b/c" to box root 'rclone-test-tugafuz4vepe': 4/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:03:22 DEBUG : pacer: Reducing sleep to 56.953125ms 2025/12/17 02:03:23 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:03:23 DEBUG : pacer: Rate limited, increasing sleep to 113.90625ms run.go:286: Retry Put of "fil/a/b/c" to box root 'rclone-test-tugafuz4vepe': 5/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:03:26 DEBUG : pacer: Reducing sleep to 85.429687ms 2025/12/17 02:03:27 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:03:27 DEBUG : pacer: Rate limited, increasing sleep to 170.859374ms run.go:286: Retry Put of "fil/a/b/c" to box root 'rclone-test-tugafuz4vepe': 6/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:03:29 DEBUG : pacer: Reducing sleep to 128.14453ms 2025/12/17 02:03:30 DEBUG : pacer: Reducing sleep to 96.108397ms 2025/12/17 02:03:31 DEBUG : pacer: Reducing sleep to 72.081297ms 2025/12/17 02:03:32 DEBUG : pacer: Reducing sleep to 54.060972ms 2025/12/17 02:03:35 DEBUG : pacer: Reducing sleep to 40.545729ms 2025/12/17 02:03:35 DEBUG : pacer: Reducing sleep to 30.409296ms 2025/12/17 02:03:35 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421703100") 2025/12/17 02:03:36 DEBUG : pacer: Reducing sleep to 22.806972ms 2025/12/17 02:03:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356310714264|b681050e7886e60d003aea099feee8af67327c85] new parent not found 2025/12/17 02:03:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077301684484|c56d0a8048301919c4d5529e32f5d376bb1eefd9] new parent not found 2025/12/17 02:03:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["c"(0)|file|ITEM_UPLOAD|2077307723050|1930a7f39f0ba09528ba9765733c77e84ddbdf40] added new path ("fil/a/b/c") for notify 2025/12/17 02:03:36 DEBUG : changeNotify: relativePath="fil/a/b/c", type=1 2025/12/17 02:03:36 DEBUG : >changeNotify: 2025/12/17 02:03:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 4 events, resulting in 1 paths and 1 notifications 2025/12/17 02:03:36 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421762878") 2025/12/17 02:03:36 DEBUG : pacer: Reducing sleep to 17.105229ms 2025/12/17 02:03:36 DEBUG : box root 'rclone-test-tugafuz4vepe': ["c"(0)|file|ITEM_UPLOAD|2077307723050|1930a7f39f0ba09528ba9765733c77e84ddbdf40] ignored due to duplicate EventID 2025/12/17 02:03:40 DEBUG : pacer: Reducing sleep to 12.828921ms 2025/12/17 02:03:40 DEBUG : forgetting directory cache 2025/12/17 02:03:40 DEBUG : dir: forgetting directory cache 2025/12/17 02:03:47 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:03:48 DEBUG : WaitForWriters: timeout=30s 2025/12/17 02:03:48 DEBUG : fil/a/b: Looking for writers 2025/12/17 02:03:48 DEBUG : fil/a: Looking for writers 2025/12/17 02:03:48 DEBUG : b: reading active writers 2025/12/17 02:03:48 DEBUG : fil: Looking for writers 2025/12/17 02:03:48 DEBUG : a: reading active writers 2025/12/17 02:03:48 DEBUG : dir: Looking for writers 2025/12/17 02:03:48 DEBUG : Looking for writers 2025/12/17 02:03:48 DEBUG : dir: reading active writers 2025/12/17 02:03:48 DEBUG : fil: reading active writers 2025/12/17 02:03:48 DEBUG : >WaitForWriters: 2025/12/17 02:04:08 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:04:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:04:10 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:04:49 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:04:58 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:06:11 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:06:11 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:06:29 DEBUG : pacer: low level retry 2/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 02:06:29 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 02:06:51 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 02:07:05 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 02:07:29 DEBUG : pacer: Reducing sleep to 16.875ms 2025/12/17 02:07:30 DEBUG : pacer: Reducing sleep to 12.65625ms --- PASS: TestDirWalk (474.86s) === RUN TestDirSetModTime run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 02:07:30 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063421997492") 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356311359739|3f6dc814cb0e1921971ff3d1e09dc9d705e20bca] added old path ("dir") for notify 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356311043342|6d5ea28a21c62d300563153c1e24331a853162da] new parent not found 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077312611981|ec502a112d9f3bfb1563cb9f06b8f19fa073cc50] new parent not found 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356311453530|d637fbf57cfda9c9f6c7bdf1a26956a062941e0c] added new path ("dir") for notify 2025/12/17 02:08:59 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 02:08:59 DEBUG : >changeNotify: 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 4 events, resulting in 2 paths and 1 notifications 2025/12/17 02:08:59 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422086278") 2025/12/17 02:09:26 DEBUG : forgetting directory cache 2025/12/17 02:09:26 DEBUG : dir: forgetting directory cache 2025/12/17 02:09:30 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422086510") 2025/12/17 02:09:45 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:09:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:09:51 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:10:11 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:10:12 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:10:12 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:10:30 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422117726") 2025/12/17 02:10:30 DEBUG : pacer: Reducing sleep to 16.875ms 2025/12/17 02:10:30 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 02:10:30 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422177731") 2025/12/17 02:10:31 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/12/17 02:10:37 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:11:22 DEBUG : WaitForWriters: timeout=30s 2025/12/17 02:11:22 DEBUG : dir: Looking for writers 2025/12/17 02:11:22 DEBUG : Looking for writers 2025/12/17 02:11:22 DEBUG : dir: reading active writers 2025/12/17 02:11:22 DEBUG : >WaitForWriters: 2025/12/17 02:11:49 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:11:49 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:12:04 DEBUG : pacer: low level retry 2/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:12:04 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 02:12:39 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 02:12:45 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 02:12:50 DEBUG : pacer: Reducing sleep to 16.875ms --- PASS: TestDirSetModTime (320.24s) === RUN TestDirStat run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 02:12:51 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/12/17 02:12:53 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:13:25 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 02:13:25 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:13:33 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:13:47 DEBUG : forgetting directory cache 2025/12/17 02:13:47 DEBUG : dir: forgetting directory cache 2025/12/17 02:13:47 DEBUG : fil: forgetting directory cache 2025/12/17 02:13:47 DEBUG : fil/a: forgetting directory cache 2025/12/17 02:13:47 DEBUG : fil/a/b: forgetting directory cache 2025/12/17 02:13:47 DEBUG : dir: forgetting directory cache 2025/12/17 02:13:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422317799") 2025/12/17 02:13:51 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:13:51 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356311453530|dcd3791a561618c8d7a98f249c33d13ad5eaa9d3] added old path ("dir") for notify 2025/12/17 02:13:51 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356311307573|2c3cb4213028c73f01519dd02fd0c2503d7d7037] added new path ("dir") for notify 2025/12/17 02:13:51 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 02:13:51 DEBUG : >changeNotify: 2025/12/17 02:13:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 4 events, resulting in 2 paths and 1 notifications 2025/12/17 02:13:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422378030") 2025/12/17 02:13:51 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:14:21 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:14:21 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:14:26 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:14:40 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:14:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422378260") 2025/12/17 02:14:51 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:14:51 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356309925012|4b12b923db582e11ec35b772ff4ddb26e155ec0c] new parent not found 2025/12/17 02:14:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 02:14:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422438060") 2025/12/17 02:15:06 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:15:06 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 2/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:15:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422438279") 2025/12/17 02:15:51 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:15:51 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077311066562|fcf0365c5dc6192c03d4d3f81bb58be101af1ca1] new parent not found 2025/12/17 02:15:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 02:15:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422498046") 2025/12/17 02:15:51 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:15:51 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:16:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422498338") 2025/12/17 02:16:51 DEBUG : box root 'rclone-test-tugafuz4vepe': ["rclone-test-tocunog1fuba"(0)|folder|ITEM_CREATE|356312106365|d7ba9f52f8786881763f6cd68a0ac8c507df20dc] new parent not found 2025/12/17 02:16:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 1 events, resulting in 0 paths and 0 notifications 2025/12/17 02:16:51 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422558043") 2025/12/17 02:16:56 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:16:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file1" to box root 'rclone-test-tugafuz4vepe': 3/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:17:01 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:17:12 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:17:13 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:17:16 DEBUG : WaitForWriters: timeout=30s 2025/12/17 02:17:16 DEBUG : dir: Looking for writers 2025/12/17 02:17:16 DEBUG : file1: reading active writers 2025/12/17 02:17:16 DEBUG : Looking for writers 2025/12/17 02:17:16 DEBUG : dir: reading active writers 2025/12/17 02:17:16 DEBUG : >WaitForWriters: --- PASS: TestDirStat (341.14s) === RUN TestDirReadDirAll run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 02:19:00 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:19:00 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:19:09 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:19:09 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:19:09 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 02:19:21 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 02:19:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422658876") 2025/12/17 02:19:32 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 02:19:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356311307573|862596921785001c8a3f9b47829f184515076604] added old path ("dir") for notify 2025/12/17 02:19:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356312065538|d7184f5914fcafab8bfa60844f45690ec2c8c46d] added new path ("dir") for notify 2025/12/17 02:19:32 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 02:19:32 DEBUG : >changeNotify: 2025/12/17 02:19:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 5 events, resulting in 2 paths and 1 notifications 2025/12/17 02:19:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422719099") 2025/12/17 02:19:32 DEBUG : pacer: Reducing sleep to 16.875ms 2025/12/17 02:19:47 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/12/17 02:19:54 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:20: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:20:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/file2" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:20:31 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:20:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422719330") 2025/12/17 02:20:32 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:20:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file1"(0)|file|ITEM_UPLOAD|2077310821847|b93a29158cc366385cf3f787f31ed88e7a8fb39d] added new path ("dir/file1") for notify 2025/12/17 02:20:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356309872460|69a2542cf224460b08bdb98849de0c3ef4e1c1b0] new parent not found 2025/12/17 02:20:32 DEBUG : changeNotify: relativePath="dir/file1", type=1 2025/12/17 02:20:32 DEBUG : >changeNotify: 2025/12/17 02:20:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 4 events, resulting in 1 paths and 1 notifications 2025/12/17 02:20:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422779105") 2025/12/17 02:20:32 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:20:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356309872460|69a2542cf224460b08bdb98849de0c3ef4e1c1b0] ignored due to duplicate EventID 2025/12/17 02:21:05 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:21:05 DEBUG : pacer: Rate limited, increasing sleep to 20ms run.go:286: Retry Put of "dir/subdir/file3" to box root 'rclone-test-tugafuz4vepe': 1/10 (Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later) 2025/12/17 02:21:13 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:21:18 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:21:22 DEBUG : forgetting directory cache 2025/12/17 02:21:22 DEBUG : dir: forgetting directory cache 2025/12/17 02:21:24 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422779340") 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356309872460|69a2542cf224460b08bdb98849de0c3ef4e1c1b0] ignored due to duplicate EventID 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file2"(0)|file|ITEM_UPLOAD|2077302889956|b102089a1e3dbace70c6f3f865847dbc77d59a49] ignored due to old SequenceID ('\x00') 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077312492481|86e6353f73f219951962feab2965d0d3b652a967] new parent not found 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["subdir"(0)|folder|ITEM_CREATE|356311700730|de2eeb82527b8eeb5d4eeac5448945ea1fb334ac] ignored due to old SequenceID ('\x00') 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(1)|file|ITEM_UPLOAD|2077312492481|9032807bb67a3eb744bf2bb4eb0632d7ddcfb814] new parent not found 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 5 events, resulting in 0 paths and 0 notifications 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422839107") 2025/12/17 02:21:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(1)|file|ITEM_UPLOAD|2077312492481|9032807bb67a3eb744bf2bb4eb0632d7ddcfb814] ignored due to duplicate EventID === RUN TestDirReadDirAll/Virtual 2025/12/17 02:22:00 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile" 2025/12/17 02:22:00 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir" 2025/12/17 02:22:00 DEBUG : dir: Added virtual directory entry vDel: "file2" 2025/12/17 02:22:00 DEBUG : dir: Added virtual directory entry vDel: "subdir" 2025/12/17 02:22:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422839354") 2025/12/17 02:22:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(1)|file|ITEM_UPLOAD|2077312492481|9032807bb67a3eb744bf2bb4eb0632d7ddcfb814] ignored due to duplicate EventID 2025/12/17 02:22:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file3"(0)|file|ITEM_UPLOAD|2077313404250|b2c11ee7a3c3df72b1f23be6c6dc76c89844cd7c] ignored due to old SequenceID ('\x00') 2025/12/17 02:22:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 0 paths and 0 notifications 2025/12/17 02:22:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422899108") 2025/12/17 02:23:10 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:23:10 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:23:27 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:23:27 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:23:27 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 02:23:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422899336") 2025/12/17 02:23:32 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 02:23:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["virtualFile"(0)|file|ITEM_UPLOAD|2077318792681|d64c415ad65b74b5da2160c0a215b3d81bb64184] added new path ("dir/virtualFile") for notify 2025/12/17 02:23:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356312144762|b08f2b59d792992661f5040a1ae207c7d4be8b95] new parent not found 2025/12/17 02:23:32 DEBUG : changeNotify: relativePath="dir/virtualFile", type=1 2025/12/17 02:23:32 DEBUG : dir: invalidating directory cache 2025/12/17 02:23:32 DEBUG : >changeNotify: 2025/12/17 02:23:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 4 events, resulting in 1 paths and 1 notifications 2025/12/17 02:23:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422959099") 2025/12/17 02:23:32 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 02:23:33 DEBUG : pacer: low level retry 3/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:23:33 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/12/17 02:23:58 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:23:58 DEBUG : pacer: low level retry 4/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:23:58 DEBUG : pacer: Rate limited, increasing sleep to 90ms 2025/12/17 02:24:09 DEBUG : pacer: Reducing sleep to 67.5ms 2025/12/17 02:24:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063422959334") 2025/12/17 02:24:32 DEBUG : pacer: Reducing sleep to 50.625ms 2025/12/17 02:24:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(0)|file|ITEM_UPLOAD|2077313446947|d979ea8ca4d9ae71171627ab1b3b06d8ead58646] new parent not found 2025/12/17 02:24:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["virtualDir"(0)|folder|ITEM_CREATE|356310112066|e3e5e5a247866a27892ceb35a0937a97135e1d11] added new path ("dir/virtualDir") for notify 2025/12/17 02:24:32 DEBUG : changeNotify: relativePath="dir/virtualDir", type=0 2025/12/17 02:24:32 DEBUG : >changeNotify: 2025/12/17 02:24:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 2 events, resulting in 1 paths and 1 notifications 2025/12/17 02:24:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423019127") 2025/12/17 02:24:32 DEBUG : pacer: Reducing sleep to 37.96875ms 2025/12/17 02:24:42 DEBUG : pacer: Reducing sleep to 28.476562ms 2025/12/17 02:24:44 DEBUG : pacer: Reducing sleep to 21.357421ms 2025/12/17 02:24:44 DEBUG : pacer: Reducing sleep to 16.018065ms 2025/12/17 02:25:07 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 02:25:07 DEBUG : pacer: Rate limited, increasing sleep to 32.03613ms 2025/12/17 02:25:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423019369") 2025/12/17 02:25:32 DEBUG : pacer: Reducing sleep to 24.027097ms 2025/12/17 02:25:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["rclone-test-hixovir5zeki"(0)|folder|ITEM_CREATE|356311480183|0c95f3265bb45f7de01d7105ee631956a52eba02] new parent not found 2025/12/17 02:25:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["testFile"(0)|file|ITEM_UPLOAD|2077320613952|2737b066d7148757b559d88f954b632887b4fd2c] added new path ("dir/virtualDir/testFile") for notify 2025/12/17 02:25:32 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356311094247|75195ce8017c811a974b2551a2ff73204dae7642] new parent not found 2025/12/17 02:25:32 DEBUG : changeNotify: relativePath="dir/virtualDir/testFile", type=1 2025/12/17 02:25:32 DEBUG : >changeNotify: 2025/12/17 02:25:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 1 paths and 1 notifications 2025/12/17 02:25:32 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423079111") 2025/12/17 02:25:32 DEBUG : pacer: Reducing sleep to 18.020322ms 2025/12/17 02:25:33 DEBUG : pacer: Reducing sleep to 13.515241ms 2025/12/17 02:26:12 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:26:12 DEBUG : pacer: Rate limited, increasing sleep to 27.030482ms 2025/12/17 02:26:15 DEBUG : pacer: Reducing sleep to 20.272861ms 2025/12/17 02:26:17 DEBUG : pacer: Reducing sleep to 15.204645ms 2025/12/17 02:26:17 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir" 2025/12/17 02:26:17 DEBUG : dir: Removed virtual directory entry vDel: "file2" 2025/12/17 02:26:17 DEBUG : dir: Removed virtual directory entry vDel: "subdir" 2025/12/17 02:26:17 DEBUG : dir/file1: Reset virtual modtime 2025/12/17 02:26:17 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile" 2025/12/17 02:26:17 DEBUG : dir/virtualFile: Reset virtual modtime 2025/12/17 02:26:17 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2" 2025/12/17 02:26:17 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2" 2025/12/17 02:26:17 DEBUG : dir: Added virtual directory entry vDel: "file1" 2025/12/17 02:26:17 DEBUG : dir: invalidating directory cache 2025/12/17 02:26:21 DEBUG : pacer: Reducing sleep to 11.403483ms 2025/12/17 02:26:21 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2" 2025/12/17 02:26:21 DEBUG : dir: Removed virtual directory entry vDel: "file1" 2025/12/17 02:26:21 DEBUG : dir/virtualFile: Reset virtual modtime 2025/12/17 02:26:21 DEBUG : forgetting directory cache 2025/12/17 02:26:21 DEBUG : dir: forgetting directory cache 2025/12/17 02:26:21 DEBUG : dir/virtualDir: forgetting directory cache 2025/12/17 02:26:21 DEBUG : WaitForWriters: timeout=30s 2025/12/17 02:26:21 DEBUG : dir/virtualDir: Looking for writers 2025/12/17 02:26:21 DEBUG : dir: Looking for writers 2025/12/17 02:26:21 DEBUG : virtualFile: reading active writers 2025/12/17 02:26:21 DEBUG : virtualDir: reading active writers 2025/12/17 02:26:21 DEBUG : file1: reading active writers 2025/12/17 02:26:21 DEBUG : virtualFile2: reading active writers 2025/12/17 02:26:21 DEBUG : Looking for writers 2025/12/17 02:26:21 DEBUG : dir: reading active writers 2025/12/17 02:26:21 DEBUG : >WaitForWriters: 2025/12/17 02:26:24 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:27:14 DEBUG : forgetting directory cache 2025/12/17 02:27:14 DEBUG : dir: forgetting directory cache 2025/12/17 02:27:35 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:27:35 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:27:35 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:27:36 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:27:38 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:28:16 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestDirReadDirAll (611.30s) --- PASS: TestDirReadDirAll/Virtual (260.44s) === RUN TestDirOpen run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 02:28:59 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:28:59 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:29:06 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:29:43 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423270190") 2025/12/17 02:29:43 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:29:43 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world-rclone-copy-fatohob1"(0)|file|ITEM_COPY|2077314930682|25cc58d4c4a454d3d6054ac6119e516eb6799b40] new parent not found 2025/12/17 02:29:43 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356312065538|f5a41c5b3052d47d9c6751bd366d5fff6255c589] added old path ("dir") for notify 2025/12/17 02:29:43 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356310438833|679d899cdf3c813e076e6ccdbdc65309da97d681] added new path ("dir") for notify 2025/12/17 02:29:43 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 02:29:43 DEBUG : >changeNotify: 2025/12/17 02:29:43 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 2 paths and 1 notifications 2025/12/17 02:29:43 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423330422") 2025/12/17 02:29:43 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:30:28 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:30:28 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:30:28 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:30:31 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:30:42 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:30:43 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423330642") 2025/12/17 02:30:43 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:30:43 DEBUG : box root 'rclone-test-tugafuz4vepe': ["hello world"(1)|file|ITEM_RENAME|2077314930682|5a183557f988ce201b0f2b47022a0066321d4839] new parent not found 2025/12/17 02:30:43 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file1"(0)|file|ITEM_UPLOAD|2077308409285|8aed26005be6246241ae354f77fab3a041a8b1d9] ignored due to old SequenceID ('\x00') 2025/12/17 02:30:43 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 3 events, resulting in 0 paths and 0 notifications 2025/12/17 02:30:43 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423390417") 2025/12/17 02:30:45 ERROR : dir/: Can only open directories read only 2025/12/17 02:30:45 DEBUG : WaitForWriters: timeout=30s 2025/12/17 02:30:45 DEBUG : dir: Looking for writers 2025/12/17 02:30:45 DEBUG : Looking for writers 2025/12/17 02:30:45 DEBUG : dir: reading active writers 2025/12/17 02:30:45 DEBUG : >WaitForWriters: --- PASS: TestDirOpen (163.64s) === RUN TestDirCreate run.go:185: Remote "box root 'rclone-test-tugafuz4vepe'", Local "Local file system at /tmp/rclone2953525156", Modify Window "1s" 2025/12/17 02:32:00 DEBUG : dir/subdir: forgetting directory cache 2025/12/17 02:32:26 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE 2025/12/17 02:32:26 DEBUG : dir: Added virtual directory entry vAddFile: "potato" 2025/12/17 02:32:26 DEBUG : dir/potato: >Open: fd=dir/potato (w), err= 2025/12/17 02:32:26 DEBUG : dir: Added virtual directory entry vAddFile: "potato" 2025/12/17 02:32:26 DEBUG : box root 'rclone-test-tugafuz4vepe': File to upload is small (5 bytes), uploading instead of streaming 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423433822") 2025/12/17 02:32:27 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:32:27 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:32:27 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:32:27 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': ["rclone-test-pimaceg6jasu"(0)|folder|ITEM_CREATE|356311374825|3d8787e59a4b183651dd13160f5f9d30980e8a64] new parent not found 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(1)|folder|ITEM_TRASH|356310438833|26cab1510a23e394683916e4cab83400c56e31ec] added old path ("dir") for notify 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir2"(0)|folder|ITEM_CREATE|356310909500|e717ea487b2110a073336565f8d5f142add78c3c] new parent not found 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': ["dir"(0)|folder|ITEM_CREATE|356311235494|43cec2d4797286012d647615079a6665ae8c798e] ignored due to old SequenceID ('\x00') 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': ["file1"(0)|file|ITEM_UPLOAD|2077321725535|9798ec2d7b4e6813c704b0576aeb4367964b3f8e] ignored due to old SequenceID ('\x00') 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': ["sub dir"(0)|folder|ITEM_CREATE|356313393147|36e81aca24995612d1014058315318b3c46b0095] new parent not found 2025/12/17 02:32:27 DEBUG : changeNotify: relativePath="dir", type=0 2025/12/17 02:32:27 DEBUG : invalidating directory cache 2025/12/17 02:32:27 DEBUG : dir: invalidating directory cache 2025/12/17 02:32:27 DEBUG : >changeNotify: 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': Received 6 events, resulting in 1 paths and 1 notifications 2025/12/17 02:32:27 DEBUG : box root 'rclone-test-tugafuz4vepe': Checking for changes on remote (next_stream_position: "30401063423494055") 2025/12/17 02:32:27 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:32:32 DEBUG : pacer: Reducing sleep to 10ms panic: test timed out after 1h0m0s running tests: TestDirCreate (1m33s) goroutine 1593 [running]: testing.(*M).startAlarm.func1() /usr/local/go/src/testing/testing.go:2484 +0x394 created by time.goFunc /usr/local/go/src/time/sleep.go:215 +0x2d goroutine 1 [chan receive]: testing.(*T).Run(0xc0000dcc40, {0x28d2a9f?, 0xc000069ad8?}, 0x2a25270) /usr/local/go/src/testing/testing.go:1859 +0x431 testing.runTests.func1(0xc0000dcc40) /usr/local/go/src/testing/testing.go:2279 +0x37 testing.tRunner(0xc0000dcc40, 0xc000069c18) /usr/local/go/src/testing/testing.go:1792 +0xf4 testing.runTests(0xc00043c558, {0x4297fe0, 0x59, 0x59}, {0xee0d3ff4b?, 0x42b4ec0?, 0x42b4ec0?}) /usr/local/go/src/testing/testing.go:2277 +0x4b4 testing.(*M).Run(0xc000698000) /usr/local/go/src/testing/testing.go:2142 +0x64a github.com/rclone/rclone/fstest.TestMain(0xc000698000) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:74 +0xa6 github.com/rclone/rclone/vfs.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:36 main.main() _testmain.go:225 +0xa9 goroutine 40 [chan receive, 60 minutes]: github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1() /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27 created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 1 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xa7 goroutine 39 [syscall, 60 minutes]: os/signal.signal_recv() /usr/local/go/src/runtime/sigqueue.go:152 +0x29 os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:23 +0x13 created by os/signal.Notify.func1.1 in goroutine 1 /usr/local/go/src/os/signal/signal.go:152 +0x1f goroutine 24 [select, 54 minutes]: github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc0005cd000) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:43 +0x86 created by github.com/rclone/rclone/lib/oauthutil.NewRenew in goroutine 1 /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:32 +0xe5 goroutine 1488 [chan receive]: github.com/rclone/rclone/vfs.(*WriteFileHandle).close(0xc000584360) /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:205 +0x105 github.com/rclone/rclone/vfs.(*WriteFileHandle).Close(0x2d929c0?) /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:220 +0x74 github.com/rclone/rclone/vfs.TestDirCreate(0xc0003fe000) /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:370 +0x229 testing.tRunner(0xc0003fe000, 0x2a25270) /usr/local/go/src/testing/testing.go:1792 +0xf4 created by testing.(*T).Run in goroutine 1 /usr/local/go/src/testing/testing.go:1851 +0x413 goroutine 12 [IO wait]: internal/poll.runtime_pollWait(0x7a46b70cb808, 0x72) /usr/local/go/src/runtime/netpoll.go:351 +0x85 internal/poll.(*pollDesc).wait(0xc000819700?, 0xc0004ef300?, 0x0) /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 internal/poll.(*FD).Read(0xc000819700, {0xc0004ef300, 0x1300, 0x1300}) /usr/local/go/src/internal/poll/fd_unix.go:165 +0x27a net.(*netFD).Read(0xc000819700, {0xc0004ef300?, 0x0?, 0x7a46b70cb838?}) /usr/local/go/src/net/fd_posix.go:55 +0x25 net.(*conn).Read(0xc000088008, {0xc0004ef300?, 0x3?, 0xc000309920?}) /usr/local/go/src/net/net.go:194 +0x45 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000680000, {0xc0004ef300?, 0x7a46b569a008?, 0x7a46ff3c0f30?}) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29 crypto/tls.(*atLeastReader).Read(0xc000402d80, {0xc0004ef300?, 0x0?, 0x0?}) /usr/local/go/src/crypto/tls/conn.go:809 +0x3b bytes.(*Buffer).ReadFrom(0xc00082a638, {0x2d95f80, 0xc000402d80}) /usr/local/go/src/bytes/buffer.go:211 +0x98 crypto/tls.(*Conn).readFromUntil(0xc00082a388, {0x7a46b45d6000, 0xc000680000}, 0x4426d4?) /usr/local/go/src/crypto/tls/conn.go:831 +0xde crypto/tls.(*Conn).readRecordOrCCS(0xc00082a388, 0x0) /usr/local/go/src/crypto/tls/conn.go:629 +0x3cf crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:591 crypto/tls.(*Conn).Read(0xc00082a388, {0xc000251000, 0x1000, 0x7?}) /usr/local/go/src/crypto/tls/conn.go:1385 +0x145 bufio.(*Reader).Read(0xc0000b9f20, {0xc0006d62e0, 0x9, 0x42bf360?}) /usr/local/go/src/bufio/bufio.go:245 +0x197 io.ReadAtLeast({0x2d92e80, 0xc0000b9f20}, {0xc0006d62e0, 0x9, 0x9}, 0x9) /usr/local/go/src/io/io.go:335 +0x91 io.ReadFull(...) /usr/local/go/src/io/io.go:354 net/http.http2readFrameHeader({0xc0006d62e0, 0x9, 0xc00065a240?}, {0x2d92e80?, 0xc0000b9f20?}) /usr/local/go/src/net/http/h2_bundle.go:1805 +0x65 net/http.(*http2Framer).ReadFrame(0xc0006d62a0) /usr/local/go/src/net/http/h2_bundle.go:2072 +0x7d net/http.(*http2clientConnReadLoop).run(0xc000309fa8) /usr/local/go/src/net/http/h2_bundle.go:9933 +0xda net/http.(*http2ClientConn).readLoop(0xc000369500) /usr/local/go/src/net/http/h2_bundle.go:9812 +0x79 created by net/http.(*http2Transport).newClientConn in goroutine 11 /usr/local/go/src/net/http/h2_bundle.go:8334 +0xde5 goroutine 146 [select]: github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0xc0002f1680, {0x2dbc9a0, 0xc0008802d0}) /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:352 +0x145 created by github.com/rclone/rclone/fs/accounting.(*StatsInfo)._startAverageLoop in goroutine 67 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:389 +0x11a goroutine 1568 [select]: net/http.(*http2ClientConn).roundTrip(0xc0003fe380, 0xc0007d4c80, 0x0) /usr/local/go/src/net/http/h2_bundle.go:8870 +0x4d3 net/http.(*http2ClientConn).RoundTrip(...) /usr/local/go/src/net/http/h2_bundle.go:8767 net/http.(*http2Transport).RoundTripOpt(0xc000698140, 0xc0007d4c80, {0x40?, 0x65?}) /usr/local/go/src/net/http/h2_bundle.go:8063 +0x1ec net/http.(*http2Transport).RoundTrip(...) /usr/local/go/src/net/http/h2_bundle.go:8014 net/http.http2noDialH2RoundTripper.RoundTrip({0xc0004bcea0?}, 0xc0007d4c80?) /usr/local/go/src/net/http/h2_bundle.go:10872 +0x1c net/http.(*Transport).roundTrip(0xc0004bcea0, 0xc0007d4b40) /usr/local/go/src/net/http/transport.go:615 +0x497 net/http.(*Transport).RoundTrip(...) /usr/local/go/src/net/http/roundtrip.go:30 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc0000b8540, 0xc0007d4b40) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:496 +0x345 golang.org/x/oauth2.(*Transport).RoundTrip(0xc0004c2fe0, 0xc0007d4a00) /home/rclone/go/pkg/mod/golang.org/x/oauth2@v0.33.0/transport.go:55 +0x15e net/http.send(0xc0007d4a00, {0x2d96e60, 0xc0004c2fe0}, {0x6fdc01?, 0xc000586548?, 0x0?}) /usr/local/go/src/net/http/client.go:259 +0x5e2 net/http.(*Client).send(0xc0003cf3e0, 0xc0007d4a00, {0x16?, 0x1?, 0x0?}) /usr/local/go/src/net/http/client.go:180 +0x91 net/http.(*Client).do(0xc0003cf3e0, 0xc0007d4a00) /usr/local/go/src/net/http/client.go:728 +0x989 net/http.(*Client).Do(...) /usr/local/go/src/net/http/client.go:587 github.com/rclone/rclone/lib/rest.(*Client).Call(0xc0001c2f00, {0x2dbc8f8, 0x42d8780}, 0xc000069268) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:353 +0xd67 github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc0001c2f00, {0x2dbc8f8, 0x42d8780}, 0xc0007d48c0?, {0x222c5a0?, 0xc0007a0410?}, {0x222c4e0, 0xc00078ae80}, 0x41373d?, 0x2a26c90, ...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:550 +0x3f2 github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:493 github.com/rclone/rclone/backend/box.(*Object).upload.func1() /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:1722 +0x91 github.com/rclone/rclone/fs.pacerInvoker(0x1, 0x1, 0xc0005ff5b4?) /home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:86 +0x32 github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0000b8600, 0xc0007a0460, 0x1) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0xd2 github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry(...) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:244 github.com/rclone/rclone/backend/box.(*Object).upload(0xc000050e70, {0x2dbc8f8, 0x42d8780}, {0x2d92e20, 0xc000889e60}, {0xc0005ff5b4, 0x6}, {0xc0005ffc50, 0xc}, {0xc248a36eb7143827, ...}, ...) /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:1721 +0x465 github.com/rclone/rclone/backend/box.(*Object).Update(0xc000050e70, {0x2dbc8f8, 0x42d8780}, {0x2d92e20, 0xc000889e60}, {0x2dc9310, 0xc00069c4d0}, {0xc000373a10, 0x1, 0x1}) /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:1757 +0x26c github.com/rclone/rclone/backend/box.(*Fs).PutUnchecked(0xc0001a8cc0, {0x2dbc8f8, 0x42d8780}, {0x2d92e20, 0xc000889e60}, {0x2dc9310, 0xc00069c4d0}, {0xc000373a10, 0x1, 0x1}) /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:910 +0x14c github.com/rclone/rclone/backend/box.(*Fs).Put(0xc0001a8cc0, {0x2dbc8f8, 0x42d8780}, {0x2d92e20, 0xc000889e60}, {0x2dc9310, 0xc00069c4d0}, {0xc000373a10, 0x1, 0x1}) /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:877 +0x333 github.com/rclone/rclone/fs/operations.rcatSrc.func4() /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1459 +0x19e github.com/rclone/rclone/fs/operations.Retry({0x2dbc8f8, 0x42d8780}, {0x2736920, 0xc00069c4d0}, 0xa, 0xc000069e68) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:742 +0xa5 github.com/rclone/rclone/fs/operations.rcatSrc({0x2dbc8f8, 0x42d8780}, {0x2dd3940, 0xc0001a8cc0}, {0xc0005ff5b0, 0xa}, {0x2da6bc0, 0xc000407ec0}, {0xc248a36eb7143827, 0x3408dd2eb30, ...}, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1454 +0xe05 github.com/rclone/rclone/fs/operations.Rcat(...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1355 github.com/rclone/rclone/vfs.(*WriteFileHandle).openPending.func1() /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:74 +0xac created by github.com/rclone/rclone/vfs.(*WriteFileHandle).openPending in goroutine 1488 /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:72 +0x165 goroutine 1569 [select]: github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xc00081e200) /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:221 +0xed created by github.com/rclone/rclone/fs/accounting.newAccountSizeName in goroutine 1568 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:119 +0x436 goroutine 1510 [select]: github.com/rclone/rclone/vfs.(*VFS).signalHandler(0xc000548000, {0x2dbc9a0, 0xc00041a0a0}) /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:290 +0xc5 created by github.com/rclone/rclone/vfs.New in goroutine 1488 /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:266 +0x7fe goroutine 1536 [IO wait]: internal/poll.runtime_pollWait(0x7a46b70cb5d8, 0x72) /usr/local/go/src/runtime/netpoll.go:351 +0x85 internal/poll.(*pollDesc).wait(0xc00052b180?, 0xc0004f1900?, 0x0) /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 internal/poll.(*FD).Read(0xc00052b180, {0xc0004f1900, 0x1300, 0x1300}) /usr/local/go/src/internal/poll/fd_unix.go:165 +0x27a net.(*netFD).Read(0xc00052b180, {0xc0004f1900?, 0x0?, 0x7a46b70cb608?}) /usr/local/go/src/net/fd_posix.go:55 +0x25 net.(*conn).Read(0xc0000880d8, {0xc0004f1900?, 0x6?, 0xc000666920?}) /usr/local/go/src/net/net.go:194 +0x45 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc00032e900, {0xc0004f1900?, 0x7a46b569a008?, 0x7a46ff3c0f30?}) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29 crypto/tls.(*atLeastReader).Read(0xc000402480, {0xc0004f1900?, 0x0?, 0x0?}) /usr/local/go/src/crypto/tls/conn.go:809 +0x3b bytes.(*Buffer).ReadFrom(0xc0006869b8, {0x2d95f80, 0xc000402480}) /usr/local/go/src/bytes/buffer.go:211 +0x98 crypto/tls.(*Conn).readFromUntil(0xc000686708, {0x7a46b45d6000, 0xc00032e900}, 0x4426d4?) /usr/local/go/src/crypto/tls/conn.go:831 +0xde crypto/tls.(*Conn).readRecordOrCCS(0xc000686708, 0x0) /usr/local/go/src/crypto/tls/conn.go:629 +0x3cf crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:591 crypto/tls.(*Conn).Read(0xc000686708, {0xc0003d9000, 0x1000, 0x7?}) /usr/local/go/src/crypto/tls/conn.go:1385 +0x145 bufio.(*Reader).Read(0xc000407e60, {0xc000786200, 0x9, 0x42be360?}) /usr/local/go/src/bufio/bufio.go:245 +0x197 io.ReadAtLeast({0x2d92e80, 0xc000407e60}, {0xc000786200, 0x9, 0x9}, 0x9) /usr/local/go/src/io/io.go:335 +0x91 io.ReadFull(...) /usr/local/go/src/io/io.go:354 net/http.http2readFrameHeader({0xc000786200, 0x9, 0xc00065a1b0?}, {0x2d92e80?, 0xc000407e60?}) /usr/local/go/src/net/http/h2_bundle.go:1805 +0x65 net/http.(*http2Framer).ReadFrame(0xc0007861c0) /usr/local/go/src/net/http/h2_bundle.go:2072 +0x7d net/http.(*http2clientConnReadLoop).run(0xc000666fa8) /usr/local/go/src/net/http/h2_bundle.go:9933 +0xda net/http.(*http2ClientConn).readLoop(0xc0003fe380) /usr/local/go/src/net/http/h2_bundle.go:9812 +0x79 created by net/http.(*http2Transport).newClientConn in goroutine 1535 /usr/local/go/src/net/http/h2_bundle.go:8334 +0xde5 goroutine 1592 [select]: net/http.(*http2clientStream).writeRequest(0xc000494f00, 0xc0007d4c80, 0x0) /usr/local/go/src/net/http/h2_bundle.go:9044 +0xc05 net/http.(*http2clientStream).doRequest(0xc000494f00, 0x7d5a25?, 0xc0003fe380?) /usr/local/go/src/net/http/h2_bundle.go:8901 +0x56 created by net/http.(*http2ClientConn).roundTrip in goroutine 1568 /usr/local/go/src/net/http/h2_bundle.go:8806 +0x419 goroutine 1489 [select]: github.com/rclone/rclone/backend/box.(*Fs).ChangeNotify.func1() /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:1299 +0x1d9 created by github.com/rclone/rclone/backend/box.(*Fs).ChangeNotify in goroutine 1488 /home/rclone/go/src/github.com/rclone/rclone/backend/box/box.go:1285 +0xa8 "./vfs.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose" - Finished ERROR in 1h0m8.657519795s (try 1/5): exit status 2: Failed [TestDirHandleReaddirnames]