Hi,
VERY intermittently, our Box rclone copy (upload) will hit an error and then cease to make progress from that point onwards...
We've seen this with 1.54.1 as well as 1.52.0, running on a 64-bit CentOs 7.
Once we hit the "Couldn't decode error response" errors, the upload will just stall and never complete or progress even many hours later. I'm not sure what is causing the initial error, but it seems that we should eventually retry altogether.
Config file contains...
[Box_Remote]
type = box
token = {"access_token":"rwuA12bXXXXiaj1aOcdoad","token_type":"bearer","refresh_token":"vPg1oLFtaVaiYJYSHsiXmzXXXXXXNTdTmy2m3Kj","expiry":"2021-03-18T09:28:04.534158205-07:00"}
rclone copy -L --retries 40 -vvv /tmp/Yq8ugxWqnm/ Box_Remote:nightly_clone/Dev/2021/2021-03/2021-03-18/017185/
03:39:28 2021/03/18 03:39:28 DEBUG : rclone: Version "v1.54.1" starting with parameters ["rclone" "copy" "-L" "--retries" "40" "-vvv" "/tmp/Yq8ugxWqnm/" "Box_Remote:nightly_clone/Dev/2021/2021-03/2021-03-18/017185/"]
03:39:28 2021/03/18 03:39:28 DEBUG : Creating backend with remote "/tmp/Yq8ugxWqnm/"
03:39:28 2021/03/18 03:39:28 DEBUG : Using config file from "/home/XXXXX/.config/rclone/rclone.conf"
03:39:28 2021/03/18 03:39:28 DEBUG : Creating backend with remote "Box_XXX/2021/2021-03/2021-03-18/017185/"
03:39:33 2021/03/18 03:39:33 DEBUG : fs cache: renaming cache item "Box_XXXX/2021/2021-03/2021-03-18/017185/" to be canonical "Box_XXX/2021/2021-03/2021-03-18/017185"
03:39:33 2021/03/18 03:39:33 DEBUG : box root 'XXXX/2021/2021-03/2021-03-18/017185': Waiting for checks to finish
03:39:33 2021/03/18 03:39:33 DEBUG : box root 'XXXX/2021/2021-03/2021-03-18/017185': Waiting for transfers to finish
skipping a long run of normal stuff...
Last checkpoint...
03:40:33 Transferred: 257.530M / 312.645 MBytes, 82%, 4.307 MBytes/s, ETA 12s
03:40:33 Transferred: 12 / 25, 48%
03:40:33 Elapsed time: 1m5.1s
03:40:33 Transferring:
...
03:39:50 2021/03/18 03:39:50 INFO : nand_fs_image_256_ubi.w: Copied (new)
03:39:50 2021/03/18 03:39:50 DEBUG : uboot_linux.itb: SHA-1 = c5122ad2cefee7c78cb5e6f161e679506db9a9c4 OK
03:39:50 2021/03/18 03:39:50 INFO : uboot_linux.itb: Copied (new)
03:39:53 2021/03/18 03:39:53 DEBUG : bootstrap_image_128.bin: SHA-1 = cefc3ce2b59ff5df34c4013138a5b7c0f5919e44 OK
03:39:53 2021/03/18 03:39:53 INFO : bootstrap_image_128.bin: Copied (new)
03:39:55 2021/03/18 03:39:55 DEBUG : bootstrap_image_256.bin: SHA-1 = a903fef874c0667d895dbc44032acbb00f3101b2 OK
03:39:55 2021/03/18 03:39:55 INFO : bootstrap_image_256.bin: Copied (new)
03:39:57 2021/03/18 03:39:57 DEBUG : bootstrap_image_emmc_boot_part.bin.gz: SHA-1 = 3a0045dd674c7d36b3262a4f494ccc641eea1fd9 OK
03:39:57 2021/03/18 03:39:57 INFO : bootstrap_image_emmc_boot_part.bin.gz: Copied (new)
03:40:33 2021/03/18 03:40:33 INFO :
03:40:33 Transferred: 257.530M / 312.645 MBytes, 82%, 4.307 MBytes/s, ETA 12s
03:40:33 Transferred: 12 / 25, 48%
03:40:33 Elapsed time: 1m5.1s
03:40:33 Transferring:
03:40:33 * nand_cferom_fs_image_256_ubi.w: 83% /37.250M, 160.082k/s, 40s
03:40:33 * uboot_boo���c_userdata_part.bin.gz:100% /621.788k, 5.604k/s, 0s
03:40:33 * uboot_rootfs_256.ubifs:100% /29.789M, 333.765k/s, 0s
03:40:33 * bootstrap_image_emmc_userdata_part.bin.gz:100% /621.770k, 11.398k/s, 0s
03:40:33
03:40:38 2021/03/18 03:40:38 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
03:40:38 2021/03/18 03:40:38 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway" (502))
03:40:38 2021/03/18 03:40:38 DEBUG : pacer: Rate limited, increasing sleep to 20ms
03:40:47 2021/03/18 03:40:47 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
03:40:47 2021/03/18 03:40:47 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway" (502))
03:40:47 2021/03/18 03:40:47 DEBUG : pacer: Rate limited, increasing sleep to 40ms
03:40:47 2021/03/18 03:40:47 DEBUG : uboot_bootstrap_image_emmc_userdata_part.bin.gz: Received error: Error "502 Bad Gateway" (502) - low level retry 1/10
03:40:47 2021/03/18 03:40:47 DEBUG : pacer: Reducing sleep to 30ms
03:40:49 2021/03/18 03:40:49 DEBUG : pacer: Reducing sleep to 22.5ms
03:40:49 2021/03/18 03:40:49 DEBUG : uboot_bootstrap_image_emmc_userdata_part.bin.gz: SHA-1 = ff54863e468c46ab85fc8e8b8b305d726358ff55 OK
03:40:49 2021/03/18 03:40:49 INFO : uboot_bootstrap_image_emmc_userdata_part.bin.gz: Copied (new)
03:40:49 2021/03/18 03:40:49 DEBUG : pacer: Reducing sleep to 16.875ms
03:40:50 2021/03/18 03:40:50 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
03:40:50 2021/03/18 03:40:50 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway" (502))
03:40:50 2021/03/18 03:40:50 DEBUG : pacer: Rate limited, increasing sleep to 33.75ms
03:40:50 2021/03/18 03:40:50 DEBUG : uboot_rootfs_256.ubifs: Received error: Error "502 Bad Gateway" (502) - low level retry 1/10
03:40:51 2021/03/18 03:40:51 DEBUG : pacer: Reducing sleep to 25.3125ms
03:40:52 2021/03/18 03:40:52 DEBUG : pacer: Reducing sleep to 18.984375ms
03:40:52 2021/03/18 03:40:52 DEBUG : brcm_full_linux.itb: SHA-1 = c5122ad2cefee7c78cb5e6f161e679506db9a9c4 OK
03:40:52 2021/03/18 03:40:52 INFO : brcm_full_linux.itb: Copied (new)
03:40:53 2021/03/18 03:40:53 DEBUG : pacer: Reducing sleep to 14.238281ms
03:40:54 2021/03/18 03:40:54 DEBUG : pacer: Reducing sleep to 10.67871ms
03:40:54 2021/03/18 03:40:54 DEBUG : brcm_simple.dup.itb: SHA-1 = 6339190b67f267f2695800e4450c7bca9870ab60 OK
03:40:54 2021/03/18 03:40:54 INFO : brcm_simple.dup.itb: Copied (new)
03:40:55 2021/03/18 03:40:55 DEBUG : pacer: Reducing sleep to 10ms
03:40:55 2021/03/18 03:40:55 DEBUG : uboot_rootfs_256.ubifs: SHA-1 = 6bcd3ea12a7c14cd45ef662a0752869ea1afdd18 OK
03:40:55 2021/03/18 03:40:55 INFO : uboot_rootfs_256.ubifs: Copied (new)
03:40:57 2021/03/18 03:40:57 DEBUG : brcm_simple.itb: SHA-1 = 49fad279f5871e3adbf8fe431138e44465e4573c OK
03:40:57 2021/03/18 03:40:57 INFO : brcm_simple.itb: Copied (new)
03:40:57 2021/03/18 03:40:57 DEBUG : build_id.txt: SHA-1 = 6549abf0d3713a41579afde4e8ee1b955648195d OK
03:40:57 2021/03/18 03:40:57 INFO : build_id.txt: Copied (new)
03:40:58 2021/03/18 03:40:58 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
03:40:58 2021/03/18 03:40:58 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway" (502))
03:40:58 2021/03/18 03:40:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms
03:40:58 2021/03/18 03:40:58 DEBUG : bootstrap_image_emmc_userdata_part.bin.gz: Received error: Error "502 Bad Gateway" (502) - low level retry 1/10
03:40:58 2021/03/18 03:40:58 DEBUG : pacer: Reducing sleep to 15ms
03:40:58 2021/03/18 03:40:58 DEBUG : culprits.txt: SHA-1 = da3ddb9dad90e0f96d2a5032acf518e4314329e6 OK
03:40:58 2021/03/18 03:40:58 INFO : culprits.txt: Copied (new)
03:40:58 2021/03/18 03:40:58 DEBUG : pacer: Reducing sleep to 11.25ms
03:40:58 2021/03/18 03:40:58 DEBUG : pacer: Reducing sleep to 10ms
03:40:59 2021/03/18 03:40:59 DEBUG : JENKINS_CHANGELIST.txt: SHA-1 = 3e32f440828b75aa0a04cce4a838c176d2c8b4ad OK
03:40:59 2021/03/18 03:40:59 INFO : JENKINS_CHANGELIST.txt: Copied (new)
03:41:00 2021/03/18 03:41:00 DEBUG : bootstrap_image_emmc_userdata_part.bin.gz: SHA-1 = cb1e219e04ae41419252ea1a2398fee88aa475e4 OK
03:41:00 2021/03/18 03:41:00 INFO : bootstrap_image_emmc_userdata_part.bin.gz: Copied (new)
03:41:01 2021/03/18 03:41:01 DEBUG : tmp_brcm_simple.itb: SHA-1 = e9fee4f36f34be30fe2a19d89b29923ac4ee98ef OK
03:41:01 2021/03/18 03:41:01 INFO : tmp_brcm_simple.itb: Copied (new)
03:41:03 2021/03/18 03:41:03 DEBUG : tmp_fit.itb: SHA-1 = 0f8c2e760d155aeca8537c1bcddfcdcaf39b6a9d OK
03:41:03 2021/03/18 03:41:03 INFO : tmp_fit.itb: Copied (new)
03:41:04 2021/03/18 03:41:04 DEBUG : rootfs_256.ubifs: SHA-1 = 6bcd3ea12a7c14cd45ef662a0752869ea1afdd18 OK
03:41:04 2021/03/18 03:41:04 INFO : rootfs_256.ubifs: Copied (new)
03:41:33 2021/03/18 03:41:33 INFO :
03:41:33 Transferred: 337.395M / 343.649 MBytes, 98%, 2.816 MBytes/s, ETA 2s
03:41:33 Transferred: 24 / 25, 96%
03:41:33 Elapsed time: 2m5.1s
03:41:33 Transferring:
03:41:33 * nand_cferom_fs_image_256_ubi.w: 83% /37.250M, 3.331k/s, 32m2s
03:41:33
03:42:33 2021/03/18 03:42:33 INFO :
03:42:33 Transferred: 337.395M / 343.649 MBytes, 98%, 1.877 MBytes/s, ETA 3s
03:42:33 Transferred: 24 / 25, 96%
03:42:33 Elapsed time: 3m5.1s
03:42:33 Transferring:
03:42:33 * nand_cferom_fs_image_256_ubi.w: 83% /37.250M, 70/s, 25h39m35s
03:42:33
03:43:33 2021/03/18 03:43:33 INFO :
03:43:33 Transferred: 337.395M / 343.649 MBytes, 98%, 1.407 MBytes/s, ETA 4s
03:43:33 Transferred: 24 / 25, 96%
03:43:33 Elapsed time: 4m5.1s
03:43:33 Transferring:
03:43:33 * nand_cferom_fs_image_256_ubi.w: 83% /37.250M, 1/s, 1233h2m6s
03:43:33
03:44:33 2021/03/18 03:44:33 INFO :
03:44:33 Transferred: 337.395M / 343.649 MBytes, 98%, 1.125 MBytes/s, ETA 5s
03:44:33 Transferred: 24 / 25, 96%
03:44:33 Elapsed time: 5m5.1s
03:44:33 Transferring:
03:44:33 * nand_cferom_fs_image_256_ubi.w: 83% /37.250M, 0/s, 59251h26m4s
03:44:33
03:45:33 2021/03/18 03:45:33 INFO :
03:45:33 Transferred: 337.395M / 343.649 MBytes, 98%, 960.240 kBytes/s, ETA 6s
03:45:33 Transferred: 24 / 25, 96%
03:45:33 Elapsed time: 6m5.1s
03:45:33 Transferring:
03:45:33 * nand_cferom_fs_image_256_ubi.w: 83% /37.250M, 0/s, 0s