Michal-Leszczynski
commented
1 month ago There might be race at some point as this test should return err context cancelled after 2 attempts, but it still returns the request err status code 999 even though this error should result in additional retry.
This test has been sporadically failing quite a few times. Below are the logs of a failed execution.
Logs
``` 2024-05-13T11:56:38.9658908Z 11:56:31.974 [34mINFO[0m rclone registered s3 provider [name=s3, disable_checksum=true, no_check_bucket=true, env_auth=true, chunk_size=50M, memory_pool_flush_time=5m, memory_pool_use_mmap=true, upload_concurrency=2] 2024-05-13T11:56:38.9660621Z 11:56:31.980 [35mDEBUG[0m HTTP {"host": "127.0.0.1:34577", "method": "POST", "uri": "/agent/rclone/operations/list", "duration": "3ms", "status": 200, "bytes": -1} 2024-05-13T11:56:38.9661843Z 11:56:32.077 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsList", "timeout": "200ms"} 2024-05-13T11:56:38.9663088Z 11:56:32.078 [34mINFO[0m HTTP retry backoff {"operation": "OperationsList", "wait": "191.206267ms", "error": "context deadline exceeded"} 2024-05-13T11:56:38.9664455Z 11:56:32.271 [35mDEBUG[0m HTTP {"host": "127.0.0.1:34577", "method": "POST", "uri": "/agent/rclone/operations/list", "duration": "0ms", "status": 200, "bytes": -1} 2024-05-13T11:56:38.9666152Z 11:56:32.424 [35mDEBUG[0m HTTP {"host": "127.0.0.1:34577", "method": "POST", "uri": "/agent/rclone/operations/list", "duration": "0ms", "status": 200, "bytes": -1} 2024-05-13T11:56:38.9668884Z 11:56:32.597 [34mINFO[0m HTTP {"host": "127.0.0.1:41247", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "1ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9674367Z 11:56:32.598 [34mINFO[0m HTTP {"host": "127.0.0.1:34863", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "1ms", "status": 400, "bytes": 15, "dump": "HTTP/1.1 400 Bad Request\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":400}\n"} 2024-05-13T11:56:38.9677183Z 11:56:32.598 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "41.994037ms", "error": "agent [HTTP 400] "} 2024-05-13T11:56:38.9680142Z 11:56:32.598 [34mINFO[0m HTTP {"host": "127.0.0.1:46175", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "1ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9682663Z 11:56:32.598 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "46.294825ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9685611Z 11:56:32.599 [34mINFO[0m HTTP {"host": "127.0.0.1:38997", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9688072Z 11:56:32.599 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "56.201615ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9689720Z 11:56:32.627 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "31ms"} 2024-05-13T11:56:38.9691190Z 11:56:32.628 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsPut", "timeout": "60ms"} 2024-05-13T11:56:38.9692709Z 11:56:32.628 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "47.623627ms", "error": "after 30ms: context deadline exceeded"} 2024-05-13T11:56:38.9696483Z 11:56:32.641 [34mINFO[0m HTTP {"host": "127.0.0.1:34863", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 400, "bytes": 15, "dump": "HTTP/1.1 400 Bad Request\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":400}\n"} 2024-05-13T11:56:38.9700000Z 11:56:32.641 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "104.847149ms", "error": "agent [HTTP 400] "} 2024-05-13T11:56:38.9703579Z 11:56:32.646 [34mINFO[0m HTTP {"host": "127.0.0.1:46175", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9708782Z 11:56:32.657 [34mINFO[0m HTTP {"host": "127.0.0.1:38997", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9712670Z 11:56:32.657 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "91.984078ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9715089Z 11:56:32.696 [35mDEBUG[0m HTTP {"host": "127.0.0.1:40441", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "50ms"} 2024-05-13T11:56:38.9717695Z 11:56:32.737 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "61ms"} 2024-05-13T11:56:38.9719963Z 11:56:32.737 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsPut", "timeout": "120ms"} 2024-05-13T11:56:38.9722423Z 11:56:32.737 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "108.545397ms", "error": "after 60ms: context deadline exceeded"} 2024-05-13T11:56:38.9726612Z 11:56:32.748 [34mINFO[0m HTTP {"host": "127.0.0.1:34863", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 400, "bytes": 15, "dump": "HTTP/1.1 400 Bad Request\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":400}\n"} 2024-05-13T11:56:38.9730406Z 11:56:32.748 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "164.442855ms", "error": "agent [HTTP 400] "} 2024-05-13T11:56:38.9734616Z 11:56:32.750 [34mINFO[0m HTTP {"host": "127.0.0.1:38997", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9738778Z 11:56:32.750 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "173.402644ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9742840Z 11:56:32.914 [34mINFO[0m HTTP {"host": "127.0.0.1:34863", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 400, "bytes": 15, "dump": "HTTP/1.1 400 Bad Request\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":400}\n"} 2024-05-13T11:56:38.9748414Z 11:56:32.916 [34mINFO[0m HTTP {"host": "127.0.0.1:38279", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9754116Z 11:56:32.917 [34mINFO[0m HTTP {"host": "127.0.0.1:43089", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9757836Z 11:56:32.917 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "47.928082ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9761955Z 11:56:32.925 [34mINFO[0m HTTP {"host": "127.0.0.1:38997", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9767656Z 11:56:32.927 [34mINFO[0m HTTP {"host": "127.0.0.1:41725", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9771420Z 11:56:32.927 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "50.091003ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9773937Z 11:56:32.966 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "120ms"} 2024-05-13T11:56:38.9776289Z 11:56:32.967 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsPut", "timeout": "240ms"} 2024-05-13T11:56:38.9778419Z 11:56:32.967 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "199.99031ms", "error": "after 120ms: context deadline exceeded"} 2024-05-13T11:56:38.9782920Z 11:56:32.967 [34mINFO[0m HTTP {"host": "127.0.0.1:43089", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 400, "bytes": 15, "dump": "HTTP/1.1 400 Bad Request\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":400}\n"} 2024-05-13T11:56:38.9788557Z 11:56:32.978 [34mINFO[0m HTTP {"host": "127.0.0.1:41725", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:32 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9792371Z 11:56:32.978 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "114.742647ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9796430Z 11:56:33.094 [34mINFO[0m HTTP {"host": "127.0.0.1:41725", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 999, "bytes": 15, "dump": "HTTP/1.1 999 status code 999\r\nContent-Length: 15\r\nContent-Type: text/plain; charset=utf-8\r\nDate: Mon, 13 May 2024 11:56:33 GMT\r\n\r\n{\"status\":999}\n"} 2024-05-13T11:56:38.9800415Z 11:56:33.094 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "199.303314ms", "error": "agent [HTTP 999] "} 2024-05-13T11:56:38.9803171Z 11:56:33.295 [35mDEBUG[0m HTTP {"host": "127.0.0.1:41725", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "0ms", "status": 200, "bytes": 0} 2024-05-13T11:56:38.9806169Z 11:56:33.369 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "201ms", "status": 200, "bytes": 0} 2024-05-13T11:56:38.9809080Z 11:56:33.399 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "30ms"} 2024-05-13T11:56:38.9811514Z 11:56:33.400 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "1s", "error": "after 30ms: context deadline exceeded"} 2024-05-13T11:56:38.9813964Z 11:56:34.431 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "30ms"} 2024-05-13T11:56:38.9816898Z 11:56:34.437 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "5ms"} 2024-05-13T11:56:38.9819023Z 11:56:34.437 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsPut", "timeout": "65ms"} 2024-05-13T11:56:38.9821140Z 11:56:34.437 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "49.385989ms", "error": "after 5ms: context deadline exceeded"} 2024-05-13T11:56:38.9823749Z 11:56:34.553 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "65ms"} 2024-05-13T11:56:38.9825887Z 11:56:34.553 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsPut", "timeout": "125ms"} 2024-05-13T11:56:38.9828107Z 11:56:34.553 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "82.627821ms", "error": "after 65ms: context deadline exceeded"} 2024-05-13T11:56:38.9830502Z 11:56:34.763 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "126ms"} 2024-05-13T11:56:38.9832645Z 11:56:34.763 [35mDEBUG[0m HTTP increasing timeout {"operation": "OperationsPut", "timeout": "245ms"} 2024-05-13T11:56:38.9834851Z 11:56:34.763 [34mINFO[0m HTTP retry backoff {"operation": "OperationsPut", "wait": "180.245027ms", "error": "after 125ms: context deadline exceeded"} 2024-05-13T11:56:38.9837935Z 11:56:35.145 [35mDEBUG[0m HTTP {"host": "127.0.0.1:46235", "method": "POST", "uri": "/agent/rclone/operations/put?fs=s3%3A&remote=%2Ffoo%2Fbar", "duration": "201ms", "status": 200, "bytes": 0} 2024-05-13T11:56:38.9840108Z --- FAIL: TestRetryRest (0.00s) 2024-05-13T11:56:38.9841647Z --- FAIL: TestRetryRest/TestRetryCancelContext (1.05s) 2024-05-13T11:56:38.9843070Z --- FAIL: TestRetryRest/TestRetryCancelContext/Repeat (0.05s) 2024-05-13T11:56:38.9844965Z retry_test.go:127: invokeClient() error giving up after 2 attempts: agent [HTTP 999] 2024-05-13T11:56:38.9847181Z retry_test.go:133: invokeClient() error=giving up after 2 attempts: agent [HTTP 999] , expected context.Canceled ```