is my timeout not being honored for some reason?

[sickmint79]

in my
class testUser(FastHttpUser):

i have

        max_retries = 1
        retry_count = 0
        response = None

        while retry_count < max_retries:
            try:
                response = self.client.post(
                    self.path,
                    json=data,
                    headers=self.headers,
                    timeout=0.05  # 50 milliseconds
                )
                response.raise_for_status()  # Raises an HTTPError for bad responses
                break  # Exit loop if request is successful
            except (requests.exceptions.Timeout, requests.exceptions.RequestException) as e:
                logging.error(f"Request failed: {e}. Retrying {retry_count + 1}/{max_retries}...")
                retry_count += 1
                if retry_count >= max_retries:
                    logging.error("Max retries reached. Exiting the request.")
                    return  # Exit the function if max retries reached

however my responses exceed 50ms, and i am collecting metadata in my responses (like how long it took to read an underlying table) and i have found this includes results with 500ms reads. so it feels like my timeout is not being honored, however the code seems correct? i am quite confused.

as a total aside, i'm wondering if this works for giving my users a random seed:

    def on_start(self):
        user_id = self.environment.runner.user_count
        np.random.seed(user_id)

[cyberw]

If you check the docs closely https://requests.readthedocs.io/en/latest/user/advanced/#timeouts

it says ”Specifically, it’s the number of seconds that the client will wait between bytes sent from the server. In 99.9% of cases, this is the time before the server sends the first byte”.

its kind of weird but could explain what happened..

[cyberw]

I think fasthttpuser/geventhttpclients logic might be different.

[sickmint79]

tried moving this out to fasthttpuser;

class testUser(FastHttpUser):
        
    # number of tasks this user will try to send/limit to per second
    wait_time = constant_throughput(4)
    # timeout at 50ms
    network_timeout = 0.05

still retrying:

        retries = 2
        for attempt in range(retries):
            try:
                response = self.client.post(
                    self.path,
                    json = data,
                    headers = self.headers)

                # Check for successful response
                if response.status_code == 200:
                    break  # Exit on success
            except Exception as e:
                logging.info(f"Retrying attempt {e}")
                if attempt == retries - 1:  # Last attempt
                    # Log failure or handle it accordingly
                    logging.info(f"Request failed after {retries} attempts: {e}")

this appears to work, as any successful request has metadata logged indicating server time spent was under 50ms.

the problem is when things go wrong, it goes haywire. it could be later in a ramp, this one i just did had it earlier; once it starts it seems to catastrophically fail with tons of these.

[2024-10-24 22:33:50,978] ip-172-31-8-35/INFO/root: Retrying attempt A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Thu, 24 Oct 2024 22:33:50 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>.
[2024-10-24 22:33:50,978] ip-172-31-8-35/INFO/root: Retrying attempt A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Thu, 24 Oct 2024 22:33:50 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>.

i don't think i understand the details well enough to understand what is going on here. it did fail, if it is the result of a timeout fail do i get his message though? or is this a second attempt and it is made the first one was timed out?

[sickmint79]

attempted changes

class testUser(FastHttpUser):

    # number of tasks this user will try to send/limit to per second
    wait_time = constant_throughput(4)
    # timeout at 50ms
    network_timeout = 0.05
    pool_size = 1000
    max_retries = 2

and

        retries = self.max_retries
        
        for attempt in range(retries):
            try:
                response = self.client.post(
                    self.path,
                    json=data,
                    headers=self.headers
                )
                
                if response.status_code == 200:
                    break
                    
                # Any non-200 response should trigger a retry
                if attempt == retries - 1:
                    logging.info(f"Request failed after {retries} retries. Last error: {response.text}")
                    return
                logging.info(f"Retrying after non-200 response: {response.text}")
                continue
                        
            except Exception as e:
                if attempt == retries - 1:
                    logging.info(f"Request failed after {retries} attempts: {str(e)}")
                    return
                logging.info(f"Retrying after exception: {str(e)}")
                continue

result in:

[2024-10-24 23:38:51,416] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: {"error":"unexpected EOF", "code":3, "message":"unexpected EOF"}
[2024-10-24 23:38:51,417] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: {"error":"unexpected EOF", "code":3, "message":"unexpected EOF"}
[2024-10-24 23:38:51,417] ip-172-31-8-35/INFO/root: Retrying after exception: A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Thu, 24 Oct 2024 23:38:51 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>.
[2024-10-24 23:38:51,429] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: {"error":"unexpected EOF", "code":3, "message":"unexpected EOF"}
[2024-10-24 23:38:51,456] ip-172-31-8-35/INFO/root: Retrying after non-200 response: {"error":"unexpected EOF", "code":3, "message":"unexpected EOF"}
[2024-10-24 23:38:51,457] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: <html>
<head><title>400 Bad Request</title></head>
<body>
<center><h1>400 Bad Request</h1></center>```

[sickmint79]

`
        retries = self.max_retries
        
        for attempt in range(retries):
            try:
                response = self.client.post(
                    self.path,
                    json=data,
                    headers=self.headers
                )
                
                if response.status_code == 200:
                    break
                    
                # Any non-200 response should trigger a retry
                if attempt == retries - 1:
                    logging.info(f"Request failed after {retries} retries. Last error: {response.status_code} - {response.text} and payload was: {data}")
                    return
                logging.info(f"Retrying after non-200 response: {response.status_code} - {response.text} and payload was: {data}")
                continue
                        
            except Exception as e:
                if attempt == retries - 1:
                    logging.info(f"Request failed with exception after {retries} attempts: {str(e)} and payload was: {data}")
                    return
                logging.info(f"Retrying after exception: {str(e)}")
                continue

# occurrences      Error                                                                                               
------------------|---------------------------------------------------------------------------------------------------------------------------------------------
4                  POST api/v1/feature-service/get-features: BadStatusCode('https://demo.ai/api/v1/get-features', code=429)
327                POST api/v1/feature-service/get-features: RetriesExceeded('https://demo.ai/api/v1/get-features', 2, original=The read operation timed out)
1878               POST api/v1/feature-service/get-features: BadStatusCode('https://demo.ai/api/v1/get-features', code=400)
------------------|---------------------------------------------------------------------------------------------------------------------------------------------

the 429s were handled fine.
it seems once the timeouts start, the 400s blow up. it doesn't seem to handle the timeout gracefully, but explode into 400s.

[2024-10-25 00:06:45,221] ip-172-31-8-35/INFO/root: Retrying after non-200 response: 400 - <html>
<head><title>400 Bad Request</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx</center>
</body>
</html>
 and payload was: 
[2024-10-25 00:06:45,233] ip-172-31-8-35/INFO/root: Retrying after exception: A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Fri, 25 Oct 2024 00:06:45 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>.
[2024-10-25 00:06:45,245] ip-172-31-8-35/INFO/root: Request failed with exception after 2 attempts: A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Fri, 25 Oct 2024 00:06:45 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>. and payload was: 
[2024-10-25 00:06:45,269] ip-172-31-8-35/INFO/root: Retrying after non-200 response: 0 - None and payload was: 
[2024-10-25 00:06:45,334] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: 0 - None and payload was: 
[2024-10-25 00:06:45,346] ip-172-31-8-35/INFO/root: Retrying after exception: A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Fri, 25 Oct 2024 00:06:45 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>.
[2024-10-25 00:06:45,359] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: 400 - {"error":"unexpected EOF", "code":3, "message":"unexpected EOF"} and payload was: 

i think the error pattern is:
2024-10-25 00:06:44,182] ip-172-31-8-35/INFO/root: Retrying after non-200 response: 400 - {"error":"unexpected EOF", "code":3, "message":"unexpected EOF"}

[2024-10-25 00:06:44,182] ip-172-31-8-35/INFO/root: Request failed after 2 retries. Last error: 400 - <html>
<head><title>400 Bad Request</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx</center>
</body>
</html>

and sometimes
[2024-10-25 00:06:44,293] ip-172-31-8-35/INFO/root: Request failed with exception after 2 attempts: A new response began before end of <HTTPSocketPoolResponse status=400 headers={'Date': 'Fri, 25 Oct 2024 00:06:44 GMT', 'Content-Type': 'application/json', 'Content-Length': '64', 'Connection': 'keep-alive', 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'}>.

this also seems to be some kind of connection pooling and usage problem that i don't quite understand?