"./bisync.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose" - Starting (try 1/5) 2025/12/17 02:47:42 DEBUG : Creating backend with remote "TestBox:rclone-test-roziyuv9yujo" 2025/12/17 02:47:42 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/12/17 02:48:09 DEBUG : box root 'rclone-test-roziyuv9yujo': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 02:48:15 DEBUG : Creating backend with remote "/tmp/rclone3930481424" === RUN TestBisyncRemoteLocal 2025/12/17 02:48:15 DEBUG : Creating backend with remote "TestBox:rclone-test-sekexen6roqe" 2025/12/17 02:48:27 DEBUG : box root 'rclone-test-sekexen6roqe': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 02:48:28 NOTICE: remote: TestBox:rclone-test-sekexen6roqe === RUN TestBisyncRemoteLocal/all_changed 2025/12/17 02:48:28 DEBUG : Creating backend with remote "TestBox:rclone-test-sekexen6roqe/024828pu" 2025/12/17 02:48:37 DEBUG : box root 'rclone-test-sekexen6roqe/024828pu': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 02:49:08 DEBUG : box root 'rclone-test-sekexen6roqe': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 02:49:08 INFO : path1: Making directory 2025/12/17 02:49:08 DEBUG : box root 'rclone-test-sekexen6roqe/024828pu': Ignoring "Shared folder — ForNick" - unknown type "web_link" 2025/12/17 02:49:35 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:49:35 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:49:45 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:49:47 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:50:13 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:50:13 DEBUG : Creating backend with remote "TestBox:rclone-test-sekexen6roqe/024828pu/all_changed/path1" 2025/12/17 02:50:18 DEBUG : Creating backend with remote "/tmp/024828pu" 2025/12/17 02:50:18 DEBUG : Creating backend with remote "/tmp/024828pu/all_changed/path2" 2025/12/17 02:50:18 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_all_changed/initial" 2025/12/17 02:50:18 DEBUG : Creating backend with remote "/tmp/024828pu/initdir/test_all_changed-duluyax9" 2025/12/17 02:50:18 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : subdir: Making directory with metadata 2025/12/17 02:50:18 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2025/12/17 02:50:18 DEBUG : Added delayed dir = "subdir", newDst=subdir 2025/12/17 02:50:18 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:18 DEBUG : file1.copy1.txt.21b8fa2b.partial: size = 0 OK 2025/12/17 02:50:18 DEBUG : file1.copy2.txt.455881d5.partial: size = 0 OK 2025/12/17 02:50:18 DEBUG : file1.copy2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : file1.copy1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : file1.copy2.txt.455881d5.partial: renamed to: file1.copy2.txt 2025/12/17 02:50:18 INFO : file1.copy2.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : file1.copy1.txt.21b8fa2b.partial: renamed to: file1.copy1.txt 2025/12/17 02:50:18 INFO : file1.copy1.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : file1.copy3.txt.d0285540.partial: size = 0 OK 2025/12/17 02:50:18 DEBUG : file1.copy3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : file1.copy3.txt.d0285540.partial: renamed to: file1.copy3.txt 2025/12/17 02:50:18 INFO : file1.copy3.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : file1.copy5.txt.19e8a2bc.partial: size = 0 OK 2025/12/17 02:50:18 DEBUG : file1.copy5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : file1.copy4.txt.8c987629.partial: size = 0 OK 2025/12/17 02:50:18 DEBUG : file1.copy5.txt.19e8a2bc.partial: renamed to: file1.copy5.txt 2025/12/17 02:50:18 INFO : file1.copy5.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : file1.copy4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : file1.copy4.txt.8c987629.partial: renamed to: file1.copy4.txt 2025/12/17 02:50:18 DEBUG : file1.txt.56d0d699.partial: size = 0 OK 2025/12/17 02:50:18 INFO : file1.copy4.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : Local file system at /tmp/024828pu/initdir/test_all_changed-duluyax9: Waiting for checks to finish 2025/12/17 02:50:18 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt 2025/12/17 02:50:18 DEBUG : Local file system at /tmp/024828pu/initdir/test_all_changed-duluyax9: Waiting for transfers to finish 2025/12/17 02:50:18 INFO : file1.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK 2025/12/17 02:50:18 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/12/17 02:50:18 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt 2025/12/17 02:50:18 INFO : subdir/file20.txt: Copied (new) 2025/12/17 02:50:18 DEBUG : RCLONE_TEST.abb09051.partial: size = 109 OK 2025/12/17 02:50:18 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/12/17 02:50:18 DEBUG : RCLONE_TEST.abb09051.partial: renamed to: RCLONE_TEST 2025/12/17 02:50:18 INFO : RCLONE_TEST: Copied (new) 2025/12/17 02:50:18 INFO : subdir: Set directory modification time (using SetModTime) 2025/12/17 02:50:19 DEBUG : Waiting for deletions to finish 2025/12/17 02:50:19 ERROR : error listing: directory not found 2025/12/17 02:50:19 ERROR : Local file system at /tmp/024828pu/all_changed/path2: Failed to list "": directory not found 2025/12/17 02:50:19 DEBUG : removing 1 level 0 directories 2025/12/17 02:50:19 INFO : Local file system at /tmp/024828pu/all_changed/path2: Removing directory 2025/12/17 02:50:19 ERROR : Failed to rmdir: stat /tmp/024828pu/all_changed/path2: no such file or directory 2025/12/17 02:50:19 ERROR : error listing: directory not found 2025/12/17 02:50:19 ERROR : error listing: directory not found 2025/12/17 02:50:19 NOTICE: checking initFs Local file system at /tmp/024828pu/initdir/test_all_changed-duluyax9 2025/12/17 02:50:20 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:20 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:20 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:20 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:20 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:20 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/12/17 02:50:20 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/12/17 02:50:20 INFO : subdir: Making directory 2025/12/17 02:50:43 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:50:43 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:50:51 DEBUG : pacer: low level retry 2/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:50:51 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 02:50:52 DEBUG : pacer: Reducing sleep to 30ms 2025/12/17 02:50:53 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 02:51:11 DEBUG : pacer: low level retry 1/10 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:51:11 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/12/17 02:51:13 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 02:51:14 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 02:51:32 DEBUG : pacer: Reducing sleep to 18.984375ms 2025/12/17 02:51:32 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/12/17 02:51:32 DEBUG : box root 'rclone-test-sekexen6roqe/024828pu/all_changed/path1': Waiting for checks to finish 2025/12/17 02:51:32 DEBUG : box root 'rclone-test-sekexen6roqe/024828pu/all_changed/path1': Waiting for transfers to finish 2025/12/17 02:51:32 DEBUG : pacer: Reducing sleep to 14.238281ms 2025/12/17 02:51:34 DEBUG : pacer: Reducing sleep to 10.67871ms 2025/12/17 02:51:35 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:51:42 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:51:42 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:51:42 DEBUG : file1.copy4.txt: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 0/10 2025/12/17 02:51:43 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:51:43 DEBUG : file1.copy2.txt: size = 0 OK 2025/12/17 02:51:43 DEBUG : file1.copy2.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:51:43 INFO : file1.copy2.txt: Copied (new) 2025/12/17 02:51:44 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:51:49 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:51:52 DEBUG : file1.copy3.txt: size = 0 OK 2025/12/17 02:51:52 DEBUG : file1.copy3.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:51:52 INFO : file1.copy3.txt: Copied (new) 2025/12/17 02:51:54 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:51:54 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:51:54 DEBUG : file1.txt: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 0/10 2025/12/17 02:51:55 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:51:55 DEBUG : file1.copy1.txt: size = 0 OK 2025/12/17 02:51:55 DEBUG : file1.copy1.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:51:55 INFO : file1.copy1.txt: Copied (new) 2025/12/17 02:51:55 DEBUG : pacer: Reducing sleep to 11.25ms 2025/12/17 02:51:55 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 02:51:59 DEBUG : file1.copy4.txt: size = 0 OK 2025/12/17 02:51:59 DEBUG : file1.copy4.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:51:59 INFO : file1.copy4.txt: Copied (new) 2025/12/17 02:52:05 DEBUG : file1.copy5.txt: size = 0 OK 2025/12/17 02:52:05 DEBUG : file1.copy5.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:52:05 INFO : file1.copy5.txt: Copied (new) 2025/12/17 02:52: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:52:06 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 02:52:06 DEBUG : subdir/file20.txt: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 0/10 2025/12/17 02:52:10 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 02:52: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:52:11 DEBUG : pacer: Rate limited, increasing sleep to 30ms 2025/12/17 02:52:11 DEBUG : subdir/file20.txt: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 1/10 2025/12/17 02:52:14 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 02:52:20 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:52:20 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/12/17 02:52:20 DEBUG : subdir/file20.txt: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 2/10 2025/12/17 02:52:22 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 02:52:22 DEBUG : file1.txt: size = 0 OK 2025/12/17 02:52:22 DEBUG : file1.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:52:22 INFO : file1.txt: Copied (new) 2025/12/17 02:52:23 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 02:52: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:52:24 DEBUG : pacer: Rate limited, increasing sleep to 50.625ms 2025/12/17 02:52:24 DEBUG : RCLONE_TEST: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 0/10 2025/12/17 02:52:26 DEBUG : pacer: Reducing sleep to 37.96875ms 2025/12/17 02:52:26 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:52:26 DEBUG : pacer: Rate limited, increasing sleep to 75.9375ms 2025/12/17 02:52:26 DEBUG : RCLONE_TEST: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 1/10 2025/12/17 02:52:34 DEBUG : pacer: Reducing sleep to 56.953125ms 2025/12/17 02:52:50 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:52:50 DEBUG : pacer: Rate limited, increasing sleep to 113.90625ms 2025/12/17 02:52:50 DEBUG : RCLONE_TEST: Received error: Error "rate_limit_exceeded" (429): Request rate limit exceeded, please try again later - low level retry 2/10 2025/12/17 02:53:03 DEBUG : pacer: Reducing sleep to 85.429687ms 2025/12/17 02:53:03 DEBUG : subdir/file20.txt: size = 0 OK 2025/12/17 02:53:03 DEBUG : subdir/file20.txt: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2025/12/17 02:53:03 INFO : subdir/file20.txt: Copied (new) 2025/12/17 02:53:17 DEBUG : pacer: Reducing sleep to 64.072265ms 2025/12/17 02:55:15 DEBUG : pacer: low level retry 1/1 (error Error "unavailable" (503): Service is temporarily unavailable) 2025/12/17 02:55:15 DEBUG : pacer: Rate limited, increasing sleep to 128.14453ms 2025/12/17 02:55:15 DEBUG : RCLONE_TEST: Received error: Error "unavailable" (503): Service is temporarily unavailable - low level retry 3/10 2025/12/17 02:55:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:55:17 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:55:17 DEBUG : pacer: Rate limited, increasing sleep to 256.28906ms 2025/12/17 02:55:17 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:55:17 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:55:17 DEBUG : pacer: Rate limited, increasing sleep to 512.57812ms 2025/12/17 02:55:19 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:55:19 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:55:19 DEBUG : pacer: Rate limited, increasing sleep to 1.02515624s 2025/12/17 02:55:20 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:55:20 DEBUG : pacer: low level retry 4/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:55:20 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/17 02:56:06 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:56:06 DEBUG : pacer: low level retry 5/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:56:08 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:56:08 DEBUG : pacer: low level retry 6/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:56:10 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:56:10 DEBUG : pacer: low level retry 7/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:56:57 DEBUG : pacer: Reducing sleep to 1.5s 2025/12/17 02:58:35 DEBUG : pacer: Reducing sleep to 1.125s 2025/12/17 02:58:35 ERROR : RCLONE_TEST: Failed to copy: Error "item_name_in_use" (409): Item with the same name already exists ({"conflicts":{"type":"file","id":"2077334989839","file_version":{"type":"file_version","id":"2295126054639","sha1":"c799ac3b0eacf2b6fc3e741a7bea196aa129aab2"},"sequence_id":"0","etag":"0","sha1":"c799ac3b0eacf2b6fc3e741a7bea196aa129aab2","name":"RCLONE_TEST"}}) bisync_test.go:2013: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:2013 /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:506 /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:405 Error: Received unexpected error: Error "item_name_in_use" (409): Item with the same name already exists ({"conflicts":{"type":"file","id":"2077334989839","file_version":{"type":"file_version","id":"2295126054639","sha1":"c799ac3b0eacf2b6fc3e741a7bea196aa129aab2"},"sequence_id":"0","etag":"0","sha1":"c799ac3b0eacf2b6fc3e741a7bea196aa129aab2","name":"RCLONE_TEST"}}) Test: TestBisyncRemoteLocal/all_changed Messages: setting up path1 2025/12/17 02:58:35 NOTICE: checking Path1 box root 'rclone-test-sekexen6roqe/024828pu/all_changed/path1' 2025/12/17 02:58:37 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:37 DEBUG : pacer: low level retry 1/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:37 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/17 02:58:39 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:39 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:41 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:41 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:42 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:42 DEBUG : pacer: low level retry 4/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:46 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:46 DEBUG : pacer: low level retry 5/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:47 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:47 DEBUG : pacer: low level retry 6/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:49 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:49 DEBUG : pacer: low level retry 7/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 02:58:51 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 02:58:51 DEBUG : pacer: low level retry 8/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:14:31 DEBUG : pacer: low level retry 9/10 (error Get "https://api.box.com/2.0/folders/356314993289/items?fields=type%2Cid%2Csequence_id%2Cetag%2Csha1%2Cname%2Csize%2Ccreated_at%2Cmodified_at%2Ccontent_created_at%2Ccontent_modified_at%2Citem_status%2Cshared_link%2Cowned_by&limit=1000&usemarker=true": http2: timeout awaiting response headers) 2025/12/17 03:14:42 DEBUG : pacer: low level retry 10/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:14:42 ERROR : error listing: couldn't list files: Error "internal_server_error" (500): Internal Server Error fstest.go:282: Error listing: couldn't list files: Error "internal_server_error" (500): Internal Server Error === RUN TestBisyncRemoteLocal/backupdir 2025/12/17 03:14:42 DEBUG : Creating backend with remote "TestBox:rclone-test-sekexen6roqe/024828pu" 2025/12/17 03:14:42 DEBUG : Config file has changed externally - reloading 2025/12/17 03:14:52 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:14:52 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 03:15:03 DEBUG : pacer: low level retry 2/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:15:03 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 03:15:03 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:15:03 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:15:03 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/12/17 03:15:14 DEBUG : pacer: low level retry 4/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:15:14 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/12/17 03:15:14 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:15:14 DEBUG : pacer: low level retry 5/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:15:14 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/12/17 03:15:15 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:15:15 DEBUG : pacer: low level retry 6/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:15:15 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/12/17 03:15:25 DEBUG : pacer: low level retry 7/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:15:25 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/12/17 03:15:26 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:15:26 DEBUG : pacer: low level retry 8/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:15:26 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/17 03:16:30 DEBUG : pacer: Reducing sleep to 1.5s 2025/12/17 03:16:41 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:16:41 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/17 03:16:51 DEBUG : pacer: low level retry 2/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:16:51 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:16:51 DEBUG : pacer: low level retry 3/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:17:03 DEBUG : pacer: low level retry 4/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:17:04 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:17:04 DEBUG : pacer: low level retry 5/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:17:06 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:17:06 DEBUG : pacer: low level retry 6/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:17:07 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:17:07 DEBUG : pacer: low level retry 7/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:17:19 DEBUG : pacer: low level retry 8/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:17:21 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:17:21 DEBUG : pacer: low level retry 9/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:17:31 DEBUG : pacer: low level retry 10/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:17:41 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:17:52 DEBUG : pacer: low level retry 2/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:18:59 DEBUG : pacer: Reducing sleep to 1.5s 2025/12/17 03:19:09 DEBUG : pacer: low level retry 1/10 (error Error "internal_server_error" (500): Internal Server Error) 2025/12/17 03:19:09 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/17 03:19:10 DEBUG : Couldn't decode error response: invalid character 'u' looking for beginning of value 2025/12/17 03:19:10 DEBUG : pacer: low level retry 2/10 (error Error "503 Service Unavailable" (503)) 2025/12/17 03:20:31 DEBUG : pacer: Reducing sleep to 1.5s bisync_test.go:2013: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:2013 /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:638 /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:432 /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:405 Error: Received unexpected error: is a directory not a file Test: TestBisyncRemoteLocal/backupdir Messages: parsing remote TestBox:rclone-test-sekexen6roqe/024828pu 2025/12/17 03:20:31 INFO : path1: Making directory --- FAIL: TestBisyncRemoteLocal (1936.06s) --- FAIL: TestBisyncRemoteLocal/all_changed (1573.84s) --- FAIL: TestBisyncRemoteLocal/backupdir (349.65s) panic: runtime error: invalid memory address or nil pointer dereference [recovered] panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0xa9f9ea] goroutine 700 [running]: testing.tRunner.func1.2({0x23f7700, 0x422b600}) /usr/local/go/src/testing/testing.go:1734 +0x21c testing.tRunner.func1() /usr/local/go/src/testing/testing.go:1737 +0x35e panic({0x23f7700?, 0x422b600?}) /usr/local/go/src/runtime/panic.go:792 +0x132 github.com/rclone/rclone/fs/operations.Mkdir({0x2dcfd78, 0xc000114690}, {0x0, 0x0}, {0x28c4301, 0x5}) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1058 +0xea github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).makeTempRemote(0xc00077c8c0, {0x2dcfd78, 0xc000114690}, {0xc00081dc80, 0x20}, {0x28c4301, 0x5}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:639 +0x466 github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).runTestCase(0xc00077c8c0, {0x2dcfd78, 0xc000114690}, 0xc0009d9340, {0xc0003d30e5, 0x9}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:432 +0x149 github.com/rclone/rclone/cmd/bisync_test.testBisync.func4(0xc0009d9340) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:405 +0x234 testing.tRunner(0xc0009d9340, 0xc000692e40) /usr/local/go/src/testing/testing.go:1792 +0xf4 created by testing.(*T).Run in goroutine 29 /usr/local/go/src/testing/testing.go:1851 +0x413 "./bisync.test -test.v -test.timeout 1h0m0s -remote TestBox: -verbose" - Finished ERROR in 32m49.306148505s (try 1/5): exit status 2: Failed [TestBisyncRemoteLocal/all_changed TestBisyncRemoteLocal/backupdir]