Minimal example testing behaviour of tenacity.retry() with asyncio.Semaphore()

_tenacity_retry_with_asyncio_semaphore.py

import asyncio
import random
import logging

import httpx
import tenacity

logging.basicConfig(level=logging.INFO, format="%(relativeCreated)dms %(message)s")

N_SEMAPHORE = 2
N_PARALLEL = 4

semaphore = asyncio.Semaphore(N_SEMAPHORE)


@tenacity.retry(
    stop=tenacity.stop_after_attempt(10),
    wait=tenacity.wait_fixed(2),
    # before=tenacity.before_log(logging, logging.INFO),
    after=tenacity.after_log(logging, logging.INFO),
)
async def random_delay_request(n):
    delay = random.randint(0, 5)
    do_fail = random.choice([True, False])
    logging.info(f"[{n}] <begin> {semaphore.locked()=} {'FAIL' if do_fail else ''}")
    async with semaphore, httpx.AsyncClient() as client:
        logging.info(f"[{n}] <in> {semaphore.locked()=}")
        post = f"{delay}" if not do_fail else f"kekeke_{n}"
        response = await client.get(f'http://httpbin.org/delay/{post}')
        response.raise_for_status()
        logging.info(f"[{n}] <out> {semaphore.locked()=}")
    logging.info(f"[{n}] <finish> {semaphore.locked()=}")


if __name__ == '__main__':
    loop = asyncio.get_event_loop()
    jobs = [random_delay_request(n) for n in range(1, N_PARALLEL+1)]
    loop.run_until_complete(asyncio.gather(*jobs))

log1.txt

$ python try_tenacity_retry_with_asyncio_semaphore.py
100ms [1] <begin> semaphore.locked()=False FAIL
106ms [1] <in> semaphore.locked()=False
108ms [2] <begin> semaphore.locked()=False
112ms [2] <in> semaphore.locked()=True
112ms [3] <begin> semaphore.locked()=True
112ms [4] <begin> semaphore.locked()=True FAIL
342ms HTTP Request: GET http://httpbin.org/delay/kekeke_1 "HTTP/1.1 500 INTERNAL SERVER ERROR"
344ms Finished call to '__main__.random_delay_request' after 0.244(s), this was the 1st time calling it.
355ms [3] <in> semaphore.locked()=True
624ms HTTP Request: GET http://httpbin.org/delay/0 "HTTP/1.1 200 OK"
625ms [3] <out> semaphore.locked()=True
626ms [3] <finish> semaphore.locked()=True
634ms [4] <in> semaphore.locked()=True
--- note this part below:
1061ms HTTP Request: GET http://httpbin.org/delay/kekeke_4 "HTTP/1.1 500 INTERNAL SERVER ERROR"
1065ms Finished call to '__main__.random_delay_request' after 0.952(s), this was the 1st time calling it.
2346ms [1] <begin> semaphore.locked()=False
---
2359ms [1] <in> semaphore.locked()=True
2590ms HTTP Request: GET http://httpbin.org/delay/0 "HTTP/1.1 200 OK"
2592ms [1] <out> semaphore.locked()=True
2592ms [1] <finish> semaphore.locked()=False
3066ms [4] <begin> semaphore.locked()=False
3079ms [4] <in> semaphore.locked()=True
4312ms HTTP Request: GET http://httpbin.org/delay/1 "HTTP/1.1 200 OK"
4318ms [4] <out> semaphore.locked()=True
4319ms [4] <finish> semaphore.locked()=False
4341ms HTTP Request: GET http://httpbin.org/delay/4 "HTTP/1.1 200 OK"
4341ms [2] <out> semaphore.locked()=False
4341ms [2] <finish> semaphore.locked()=False

log2.txt

$ python try_tenacity_retry_with_asyncio_semaphore.py
102ms [1] <begin> semaphore.locked()=False FAIL
108ms [1] <in> semaphore.locked()=False
110ms [2] <begin> semaphore.locked()=False FAIL
113ms [2] <in> semaphore.locked()=True
113ms [3] <begin> semaphore.locked()=True
113ms [4] <begin> semaphore.locked()=True FAIL
--- note below, [1] and [2] fail and [3] and [4] immediately get the semaphore:
364ms HTTP Request: GET http://httpbin.org/delay/kekeke_2 "HTTP/1.1 500 INTERNAL SERVER ERROR"
367ms HTTP Request: GET http://httpbin.org/delay/kekeke_1 "HTTP/1.1 500 INTERNAL SERVER ERROR"
367ms Finished call to '__main__.random_delay_request' after 0.258(s), this was the 1st time calling it.
378ms [3] <in> semaphore.locked()=True
379ms Finished call to '__main__.random_delay_request' after 0.277(s), this was the 1st time calling it.
386ms [4] <in> semaphore.locked()=True
---
804ms HTTP Request: GET http://httpbin.org/delay/kekeke_4 "HTTP/1.1 500 INTERNAL SERVER ERROR"
805ms Finished call to '__main__.random_delay_request' after 0.692(s), this was the 1st time calling it.
2369ms [2] <begin> semaphore.locked()=False
2381ms [2] <in> semaphore.locked()=True
2389ms [1] <begin> semaphore.locked()=True FAIL
2807ms [4] <begin> semaphore.locked()=True FAIL
4678ms HTTP Request: GET http://httpbin.org/delay/4 "HTTP/1.1 200 OK"
4683ms [3] <out> semaphore.locked()=True
4683ms [3] <finish> semaphore.locked()=True
4694ms [1] <in> semaphore.locked()=True
4695ms HTTP Request: GET http://httpbin.org/delay/2 "HTTP/1.1 200 OK"
4695ms [2] <out> semaphore.locked()=True
4696ms [2] <finish> semaphore.locked()=True
4703ms [4] <in> semaphore.locked()=True
4928ms HTTP Request: GET http://httpbin.org/delay/kekeke_4 "HTTP/1.1 500 INTERNAL SERVER ERROR"
4929ms HTTP Request: GET http://httpbin.org/delay/kekeke_1 "HTTP/1.1 500 INTERNAL SERVER ERROR"
4931ms Finished call to '__main__.random_delay_request' after 4.818(s), this was the 2nd time calling it.
4931ms Finished call to '__main__.random_delay_request' after 4.829(s), this was the 2nd time calling it.
6933ms [4] <begin> semaphore.locked()=False
6945ms [4] <in> semaphore.locked()=False
6945ms [1] <begin> semaphore.locked()=False FAIL
6954ms [1] <in> semaphore.locked()=True
7614ms HTTP Request: GET http://httpbin.org/delay/kekeke_1 "HTTP/1.1 500 INTERNAL SERVER ERROR"
7617ms Finished call to '__main__.random_delay_request' after 7.514(s), this was the 3rd time calling it.
9618ms [1] <begin> semaphore.locked()=False
9631ms [1] <in> semaphore.locked()=True
11336ms HTTP Request: GET http://httpbin.org/delay/4 "HTTP/1.1 200 OK"
11340ms [4] <out> semaphore.locked()=True
11340ms [4] <finish> semaphore.locked()=False
13875ms HTTP Request: GET http://httpbin.org/delay/4 "HTTP/1.1 200 OK"
13878ms [1] <out> semaphore.locked()=False
13878ms [1] <finish> semaphore.locked()=False

log3.txt

$ python try_tenacity_retry_with_asyncio_semaphore.py
104ms [1] <begin> semaphore.locked()=False FAIL
110ms [1] <in> semaphore.locked()=False
112ms [2] <begin> semaphore.locked()=False FAIL
116ms [2] <in> semaphore.locked()=True
116ms [3] <begin> semaphore.locked()=True FAIL
116ms [4] <begin> semaphore.locked()=True FAIL
--- note below, [1] and [2] fail and [3] and [4] immediately get the semaphore:
382ms HTTP Request: GET http://httpbin.org/delay/kekeke_1 "HTTP/1.1 500 INTERNAL SERVER ERROR"
385ms HTTP Request: GET http://httpbin.org/delay/kekeke_2 "HTTP/1.1 500 INTERNAL SERVER ERROR"
385ms Finished call to '__main__.random_delay_request' after 0.281(s), this was the 1st time calling it.
396ms [3] <in> semaphore.locked()=True
397ms Finished call to '__main__.random_delay_request' after 0.285(s), this was the 1st time calling it.
405ms [4] <in> semaphore.locked()=True
---
762ms HTTP Request: GET http://httpbin.org/delay/kekeke_3 "HTTP/1.1 500 INTERNAL SERVER ERROR"
763ms Finished call to '__main__.random_delay_request' after 0.647(s), this was the 1st time calling it.
799ms HTTP Request: GET http://httpbin.org/delay/kekeke_4 "HTTP/1.1 500 INTERNAL SERVER ERROR"
800ms Finished call to '__main__.random_delay_request' after 0.684(s), this was the 1st time calling it.
2387ms [1] <begin> semaphore.locked()=False
2402ms [1] <in> semaphore.locked()=False
2403ms [2] <begin> semaphore.locked()=False
2408ms [2] <in> semaphore.locked()=True
2765ms [3] <begin> semaphore.locked()=True FAIL
2802ms [4] <begin> semaphore.locked()=True
3639ms HTTP Request: GET http://httpbin.org/delay/1 "HTTP/1.1 200 OK"
3643ms [1] <out> semaphore.locked()=True
3644ms [1] <finish> semaphore.locked()=True
3655ms [3] <in> semaphore.locked()=True
3882ms HTTP Request: GET http://httpbin.org/delay/kekeke_3 "HTTP/1.1 500 INTERNAL SERVER ERROR"
3885ms Finished call to '__main__.random_delay_request' after 3.769(s), this was the 2nd time calling it.
3898ms [4] <in> semaphore.locked()=True
5688ms HTTP Request: GET http://httpbin.org/delay/3 "HTTP/1.1 200 OK"
5693ms [2] <out> semaphore.locked()=True
5693ms [2] <finish> semaphore.locked()=False
5889ms [3] <begin> semaphore.locked()=False
5902ms [3] <in> semaphore.locked()=True
8155ms HTTP Request: GET http://httpbin.org/delay/4 "HTTP/1.1 200 OK"
8161ms [4] <out> semaphore.locked()=True
8161ms [4] <finish> semaphore.locked()=False
9415ms HTTP Request: GET http://httpbin.org/delay/3 "HTTP/1.1 200 OK"
9417ms [3] <out> semaphore.locked()=False
9417ms [3] <finish> semaphore.locked()=False