Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TestRetryRest/TestRetryCancelContext/Repeat is flaky #3848

Open
Michal-Leszczynski opened this issue May 13, 2024 · 1 comment
Open

TestRetryRest/TestRetryCancelContext/Repeat is flaky #3848

Michal-Leszczynski opened this issue May 13, 2024 · 1 comment
Labels
bug Something isn't working testing

Comments

@Michal-Leszczynski
Copy link
Collaborator

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
@Michal-Leszczynski Michal-Leszczynski added bug Something isn't working testing labels May 13, 2024
@Michal-Leszczynski
Copy link
Collaborator Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working testing
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@Michal-Leszczynski