aiohttp client get request - exception without error message #5239

esundberg · 2020-11-15T09:43:38Z

🐞 Describe the bug
I have been having problems with a section of my code that uses aiohttp client to request phone number information from a API. The API Server has been tested to well over 600 queries per second and it's two servers behind a load balancer.

The program goes like this. We query a FastAPI Endpoint, the FastAPI Endpoint runs a function that queries another API using aiohttp client, processes the data, and then returns the result. We were noticing under some some load that aiohttp would create an exception without any errors. I have narrowed it down to the following section of code where the issues is and removed FastAPI from the mix.

I created a infinite loop that creates an asyncio task that calls the same function that does the aiohttp client request over and over again, sleeping for .01 seconds per per loop cycle. I see 51 aiohttp requests go out and receive good responses, then from session 52 onwards we get a aiohttp exception with no errors.

I am also getting different results on different environments.

Digital Ocean Server (shared 8vCPU, 16G RAM or dedicated 16 CPU, 65G RAM) - Ubuntu 20.04 python 3.8.5, aiohttp - 3.7.2, yarl, 1.6.3, multidict 5.0.2 - Issue Happens
-Side note CPU only gets to 6-7%

Digital Ocean Server (shared 4vCPU, 8G RAM) - Ubuntu 18.04, python 3.8.6, aiohttp -3.7.2, yarl 1.6.3, multidict 5.0.2 - No Issue

My PC - Windows 10, Python 3.8.2, aiohttp - 3.6.3, yarl, 1.5.1, multidict 4.7.6 - No Issue

VMWare Server- Ubuntu 18.05 (4 vCPU, 8G RAM) - Python 3.8.6, aiohttp 3.7.2, yarl 1.6.2, multidict, 5.0.0 - No Issue

VMWare Server - Ubuntu 20.04 (4 vCPU, 16G RAM) - Python 3.8.5 aiohttp 3.7.2, yarl 1.6.2, multidict 5.0.0 - No Issue

import aiohttp
import asyncio
import config as cfg

async def main():
    x = 0
    while True:
        x += 1
        asyncio.create_task(carrier_lookup(x, '3127100000'))
        await asyncio.sleep(.01)

async def carrier_lookup(id, number):
    status = False
    message = None
    response = None

    # Build URL Params
    params = {
        "apikey": cfg.api["apikey"],
        "number": number
    }

    try: 
        async with aiohttp.ClientSession() as session:
            async with session.get(cfg.api["url"], params=params, timeout=3) as resp:
                status = resp.status
                response = await resp.json()
    except Exception as e:
        print(f'AIOHTTP Session Exception:')
        print(e)

    print(f'{id} | Status: ({status}) | {response}')
    return response

if __name__ == '__main__':
    asyncio.run(main())

Output

1 | Status: (200) | {'query': '3127100000', 'number': '3127100000', 'source': 'LRN', 'record': '3127100', 'carrier': 'AT&T Wireline (Ameritech)', 'type': 'landline', 'timestamp': '2020-11-15T08:51:20.116907', 'load_time': '0.001271'}
2 | Status: (200) | {'query': '3127100000', 'number': '3127100000', 'source': 'LRN', 'record': '3127100', 'carrier': 'AT&T Wireline (Ameritech)', 'type': 'landline', 'timestamp': '2020-11-15T08:51:20.124436', 'load_time': '0.001247'}
~~~~snip~~~~
50 | Status: (200) | {'query': '3127100000', 'number': '3127100000', 'source': 'LRN', 'record': '3127100', 'carrier': 'AT&T Wireline (Ameritech)', 'type': 'landline', 'timestamp': '2020-11-15T08:51:20.639200', 'load_time': '0.001341'}
51 | Status: (200) | {'query': '3127100000', 'number': '3127100000', 'source': 'LRN', 'record': '3127100', 'carrier': 'AT&T Wireline (Ameritech)', 'type': 'landline', 'timestamp': '2020-11-15T08:51:20.648929', 'load_time': '0.001200'}
AIOHTTP Session Exception:

52 | Status: (False) | None
AIOHTTP Session Exception:

53 | Status: (False) | None
AIOHTTP Session Exception:

54 | Status: (False) | None
AIOHTTP Session Exception:

55 | Status: (False) | None
AIOHTTP Session Exception:

💡 To Reproduce
Run the code above

Running on Digitial Ocean Server

Ubuntu 20.04.1
Python 3.8.5
aiohttp==3.7.2

💡 Expected behavior
AIOHTTP requests should not stop

📋 Logs/tracebacks

📋 Your version of the Python

$ python --version
Python 3.8.5

📋 Your version of the aiohttp/yarl/multidict distributions

$ python -m pip show aiohttp
Name: aiohttp
Version: 3.7.2
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author: Nikolay Kim
Author-email: fafhrd91@gmail.com
License: Apache 2
Location: /opt/lrg-rvm-api/venv/lib/python3.8/site-packages
Requires: typing-extensions, yarl, async-timeout, chardet, multidict, attrs
Required-by:

$ python -m pip show multidict
Name: multidict
Version: 5.0.2
Summary: multidict implementation
Home-page: https://github.com/aio-libs/multidict
Author: Andrew Svetlov
Author-email: andrew.svetlov@gmail.com
License: Apache 2
Location: /opt/lrg-rvm-api/venv/lib/python3.8/site-packages
Requires: 
Required-by: yarl, aiohttp

$ python -m pip show yarl
Name: yarl
Version: 1.6.3
Summary: Yet another URL library
Home-page: https://github.com/aio-libs/yarl/
Author: Andrew Svetlov
Author-email: andrew.svetlov@gmail.com
License: Apache 2
Location: /opt/lrg-rvm-api/venv/lib/python3.8/site-packages
Requires: idna, multidict
Required-by: aiohttp

📋 Additional context
This is a pretty big bug for us. Any help would be greatly appreacited.

The text was updated successfully, but these errors were encountered:

derlih · 2020-11-15T09:58:53Z

@esundberg
can run you script with traceback.print_exc inside the except block?
https://docs.python.org/3/library/traceback.html#traceback.print_exc

esundberg · 2020-11-15T10:03:36Z

I get a asyncio.TimeoutError

I didn't include lines 1-48 from the output

49 | Status: (200) | {'query': '3127100000', 'number': '3127100000', 'source': 'LRN', 'record': '3127100', 'carrier': 'AT&T Wireline (Ameritech)', 'type': 'landline', 'timestamp': '2020-11-15T10:01:16.437983', 'load_time': '0.001248'}
50 | Status: (200) | {'query': '3127100000', 'number': '3127100000', 'source': 'LRN', 'record': '3127100', 'carrier': 'AT&T Wireline (Ameritech)', 'type': 'landline', 'timestamp': '2020-11-15T10:01:16.448345', 'load_time': '0.001210'}
AIOHTTP Session Exception:

Traceback (most recent call last):
  File "test.py", line 28, in carrier_lookup
    async with session.get(cfg.api["url"], params=params, timeout=3) as resp:
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 1124, in __aenter__
    self._resp = await self._coro
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 626, in _request
    break
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/helpers.py", line 656, in __exit__
    raise asyncio.TimeoutError from None
asyncio.exceptions.TimeoutError
51 | Status: (False) | None
AIOHTTP Session Exception:

Traceback (most recent call last):
  File "test.py", line 28, in carrier_lookup
    async with session.get(cfg.api["url"], params=params, timeout=3) as resp:
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 1124, in __aenter__
    self._resp = await self._coro
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 626, in _request
    break
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/helpers.py", line 656, in __exit__
    raise asyncio.TimeoutError from None
asyncio.exceptions.TimeoutError
52 | Status: (False) | None

esundberg · 2020-11-15T10:04:36Z

If needed. I can spin up a server for this issue for troubleshooting if you can't reproduce it in your environment. It's just a very odd issue.

Also Ubuntu 20.04 has not release a update to python 3.8.6. So, I am kind of stuck at 3.8.5. The deadsnake ppa will not let you update any 3.8 train when your on Ubuntu 20.04

I tried Python 3.9.0+and I am having the same issue.
Digital Ocean Server (shared 8vCPU, 16G RAM) - Ubuntu 20.04 python 3.9.0+, aiohttp - 3.7.2, yarl, 1.6.3, multidict 5.0.2 - Issue Happens

derlih · 2020-11-15T10:43:11Z

It looks like you hit the timeout of 3 seconds.
Can you measure the duration between session.get call and except block?

esundberg · 2020-11-15T17:24:05Z

I updated the code like this.

So this is even weirder. Yes it time's out a 3 second.

This is weird... It not goes in block of ~50 get asnwered in ~< second, next 50 get answered in 4 seconds, the next 50 in 8-9 seconds, the next 50 in 13 seconds, then the next 50 in 17 seconds, then timeout errors.

    start = time.monotonic()
    try: 
        async with aiohttp.ClientSession() as session:
            async with session.get(cfg.api["url"], params=params, timeout=5) as resp:
                status = resp.status
                response = await resp.json()
    except Exception as e:
        print(f'AIOHTTP Session Exception:')
        print(e)
        traceback.print_exc()
    end = time.monotonic()
    duration = end - start
    print(f'{id} | {duration} |Status: ({status}) | {response}')

Output

python test.py 
1 | 0.015050112997414544 | Status: (200)
2 | 0.008854095009155571 | Status: (200)
3 | 0.0077458409941755235 | Status: (200)
4 | 0.0077576850017067045 | Status: (200)
5 | 0.008234989014454186 | Status: (200)
6 | 0.007681662013055757 | Status: (200)
7 | 0.007963101990753785 | Status: (200)
8 | 0.007257168996147811 | Status: (200)
9 | 0.00810213602380827 | Status: (200)
10 | 0.0073463690059725195 | Status: (200)
11 | 0.008830986014800146 | Status: (200)
12 | 0.007833384996047243 | Status: (200)
13 | 0.008015371015062556 | Status: (200)
14 | 0.007408609002595767 | Status: (200)
15 | 0.00839541302411817 | Status: (200)
16 | 0.007865810010116547 | Status: (200)
17 | 0.00790692400187254 | Status: (200)
18 | 0.008009645011043176 | Status: (200)
19 | 0.007889543019700795 | Status: (200)
20 | 0.007086886995239183 | Status: (200)
21 | 0.007762866996927187 | Status: (200)
22 | 0.007301127974642441 | Status: (200)
23 | 0.008010810008272529 | Status: (200)
24 | 0.007314313988899812 | Status: (200)
25 | 0.008248906000517309 | Status: (200)
26 | 0.007292570022400469 | Status: (200)
27 | 0.008148882014211267 | Status: (200)
28 | 0.007672323990846053 | Status: (200)
29 | 0.00820953500806354 | Status: (200)
30 | 0.007499191997339949 | Status: (200)
31 | 0.008004095987416804 | Status: (200)
32 | 0.008108176989480853 | Status: (200)
33 | 0.007954236993100494 | Status: (200)
34 | 0.009653212007833645 | Status: (200)
35 | 0.008796563983196393 | Status: (200)
36 | 0.00853561400435865 | Status: (200)
37 | 0.008885268995072693 | Status: (200)
38 | 0.008047545998124406 | Status: (200)
39 | 0.009581441001500934 | Status: (200)
40 | 0.009264555992558599 | Status: (200)
41 | 0.00833637299365364 | Status: (200)
42 | 0.00789247700595297 | Status: (200)
43 | 0.008551623992389068 | Status: (200)
44 | 0.00791204598499462 | Status: (200)
45 | 0.008700061996933073 | Status: (200)
46 | 0.00875812498270534 | Status: (200)
47 | 0.009461426001507789 | Status: (200)
48 | 0.008741632977034897 | Status: (200)
49 | 0.009505714988335967 | Status: (200)
50 | 0.007524282991653308 | Status: (200)
51 | 0.007752734003588557 | Status: (200)
60 | 4.946505967993289 | Status: (200)
62 | 4.924067368992837 | Status: (200)
55 | 5.0035357140004635 | Status: (200)
57 | 4.980992931989022 | Status: (200)
58 | 4.9697598409838974 | Status: (200)
65 | 4.891956617007963 | Status: (200)
54 | 5.016686502000084 | Status: (200)
63 | 4.915065244014841 | Status: (200)
52 | 5.039551711990498 | Status: (200)
64 | 4.903783885005396 | Status: (200)
53 | 5.029411249997793 | Status: (200)
59 | 4.961382590001449 | Status: (200)
72 | 4.816740880982252 | Status: (200)
61 | 4.939254163007718 | Status: (200)
56 | 4.996079775999533 | Status: (200)
70 | 4.839424579986371 | Status: (200)
67 | 4.8724520149989985 | Status: (200)
69 | 4.850674457004061 | Status: (200)
71 | 4.829221089021303 | Status: (200)
66 | 4.8841583259927575 | Status: (200)
81 | 4.718837823020294 | Status: (200)
94 | 4.575747436989332 | Status: (200)
79 | 4.741344508976908 | Status: (200)
82 | 4.708477347012376 | Status: (200)
89 | 4.6317375719954725 | Status: (200)
105 | 4.455130168003961 | Status: (200)
95 | 4.566515629005153 | Status: (200)
84 | 4.687764207978034 | Status: (200)
106 | 4.4455968140100595 | Status: (200)
73 | 4.810510016977787 | Status: (200)
78 | 4.75464811900747 | Status: (200)
75 | 4.790799479989801 | Status: (200)
68 | 4.867694308981299 | Status: (200)
90 | 4.624876185989706 | Status: (200)
76 | 4.780005425011041 | Status: (200)
83 | 4.70208340100362 | Status: (200)
101 | 4.503206363006029 | Status: (200)
96 | 4.558960102003766 | Status: (200)
77 | 4.769299487990793 | Status: (200)
85 | 4.680304164008703 | Status: (200)
86 | 4.6693719849863555 | Status: (200)
107 | 4.438577708002413 | Status: (200)
87 | 4.659509405988501 | Status: (200)
74 | 4.80354787199758 | Status: (200)
111 | 4.394867987983162 | Status: (200)
113 | 4.373115861992119 | Status: (200)
112 | 4.385435041011078 | Status: (200)
92 | 4.606153180997353 | Status: (200)
114 | 4.363819196005352 | Status: (200)
97 | 4.550852151995059 | Status: (200)
104 | 4.473421942006098 | Status: (200)
115 | 4.352876568998909 | Status: (200)
88 | 4.650400362006621 | Status: (200)
91 | 4.6174686389858834 | Status: (200)
102 | 4.495591431012144 | Status: (200)
109 | 4.418824635999044 | Status: (200)
80 | 4.739981305989204 | Status: (200)
110 | 4.409286373003852 | Status: (200)
99 | 4.530314729985548 | Status: (200)
117 | 4.332685903995298 | Status: (200)
93 | 4.597057438018965 | Status: (200)
98 | 4.542111654998735 | Status: (200)
100 | 4.52013035301934 | Status: (200)
103 | 4.486957591987448 | Status: (200)
108 | 4.432171283988282 | Status: (200)
128 | 9.207754989009118 | Status: (200)
118 | 9.31795521499589 | Status: (200)
121 | 9.288324927008944 | Status: (200)
120 | 9.307504355005221 | Status: (200)
122 | 9.285663287999341 | Status: (200)
127 | 9.23063902600552 | Status: (200)
132 | 9.175772162998328 | Status: (200)
126 | 9.241921851993538 | Status: (200)
134 | 9.15272439000546 | Status: (200)
119 | 9.320930999994744 | Status: (200)
123 | 9.277107664995128 | Status: (200)
116 | 9.354050798981916 | Status: (200)
124 | 9.266273929009913 | Status: (200)
135 | 9.14401413698215 | Status: (200)
130 | 9.200163442990743 | Status: (200)
136 | 9.13304546099971 | Status: (200)
141 | 9.077704252005788 | Status: (200)
131 | 9.19111821000115 | Status: (200)
139 | 9.101666180999018 | Status: (200)
133 | 9.169346088980092 | Status: (200)
129 | 9.213319047994446 | Status: (200)
125 | 9.257479308987968 | Status: (200)
149 | 8.99215189597453 | Status: (200)
148 | 9.003170951997163 | Status: (200)
145 | 9.03805829299381 | Status: (200)
146 | 9.027309129014611 | Status: (200)
151 | 8.972600523993606 | Status: (200)
137 | 9.12662774999626 | Status: (200)
150 | 8.983699467004044 | Status: (200)
161 | 8.862961207982153 | Status: (200)
144 | 9.04953940300038 | Status: (200)
169 | 8.775055275997147 | Status: (200)
173 | 8.731079696008237 | Status: (200)
160 | 8.876660929992795 | Status: (200)
181 | 8.644993909983896 | Status: (200)
153 | 8.953576314001111 | Status: (200)
168 | 8.788864119007485 | Status: (200)
154 | 8.942716674006078 | Status: (200)
164 | 8.833074788999511 | Status: (200)
170 | 8.767095774994232 | Status: (200)
165 | 8.824306599010015 | Status: (200)
163 | 8.84631592000369 | Status: (200)
158 | 8.90129626300768 | Status: (200)
159 | 8.890386068000225 | Status: (200)
140 | 9.098899445001734 | Status: (200)
172 | 8.747440842998913 | Status: (200)
182 | 8.636916341987671 | Status: (200)
152 | 8.967467121983645 | Status: (200)
166 | 8.81378568900982 | Status: (200)
147 | 9.024862543999916 | Status: (200)
155 | 8.937080039991997 | Status: (200)
157 | 8.915257439017296 | Status: (200)
180 | 8.661691909015644 | Status: (200)
175 | 8.717385916010244 | Status: (200)
142 | 9.079961267998442 | Status: (200)
143 | 9.069032411993248 | Status: (200)
138 | 9.124289896979462 | Status: (200)
156 | 8.926544779009419 | Status: (200)
162 | 8.860617229016498 | Status: (200)
167 | 8.805791793973185 | Status: (200)
171 | 8.7618851599982 | Status: (200)
174 | 8.728860694973264 | Status: (200)
176 | 13.68446048500482 | Status: (200)
185 | 13.585190573008731 | Status: (200)
188 | 13.55430634698132 | Status: (200)
189 | 13.544970061979257 | Status: (200)
179 | 13.655705666024005 | Status: (200)
187 | 13.56719788099872 | Status: (200)
192 | 13.511014691001037 | Status: (200)
177 | 13.678125984995859 | Status: (200)
186 | 13.58036184599041 | Status: (200)
178 | 13.66899112900137 | Status: (200)
183 | 13.613596520997817 | Status: (200)
190 | 13.536232184007531 | Status: (200)
191 | 13.524059849994956 | Status: (200)
193 | 13.503420169989113 | Status: (200)
184 | 13.608313709992217 | Status: (200)
197 | 13.465290818014182 | Status: (200)
194 | 13.498995076020947 | Status: (200)
195 | 13.48797909298446 | Status: (200)
200 | 13.433831865986576 | Status: (200)
198 | 13.455933182995068 | Status: (200)
203 | 13.400907454983098 | Status: (200)
196 | 13.478234729991527 | Status: (200)
206 | 13.36794540900155 | Status: (200)
199 | 13.445124976016814 | Status: (200)
201 | 13.423090956988744 | Status: (200)
204 | 13.390109429019503 | Status: (200)
205 | 13.379410462017404 | Status: (200)
202 | 13.412613650987623 | Status: (200)
207 | 13.357796464988496 | Status: (200)
213 | 13.291937050991692 | Status: (200)
214 | 13.281139263999648 | Status: (200)
209 | 13.33677988301497 | Status: (200)
215 | 13.270762867003214 | Status: (200)
218 | 13.237821214977885 | Status: (200)
208 | 13.348228051007027 | Status: (200)
211 | 13.31573597897659 | Status: (200)
225 | 13.161451334017329 | Status: (200)
210 | 13.32687015098054 | Status: (200)
224 | 13.172869992995402 | Status: (200)
221 | 13.206654049019562 | Status: (200)
217 | 13.25057151299552 | Status: (200)
216 | 13.261581992002903 | Status: (200)
227 | 13.140641565987607 | Status: (200)
219 | 13.229155173001345 | Status: (200)
223 | 13.185249597998336 | Status: (200)
222 | 13.196383584989235 | Status: (200)
220 | 13.218614970013732 | Status: (200)
231 | 13.098043976002373 | Status: (200)
212 | 13.30729373099166 | Status: (200)
229 | 13.1204627029947 | Status: (200)
230 | 13.10959576498135 | Status: (200)
234 | 13.065548293991014 | Status: (200)
226 | 13.15373448599712 | Status: (200)
239 | 18.008187890984118 | Status: (200)
233 | 18.075488518021302 | Status: (200)
232 | 18.08684559300309 | Status: (200)
243 | 17.965738224011147 | Status: (200)
228 | 18.13293553100084 | Status: (200)
236 | 18.04519534300198 | Status: (200)
237 | 18.034237742016558 | Status: (200)
235 | 18.056243055994855 | Status: (200)
244 | 17.959149967005942 | Status: (200)
238 | 18.028972543979762 | Status: (200)
248 | 17.920066644001054 | Status: (200)
245 | 17.952269839996006 | Status: (200)
250 | 17.89802041501389 | Status: (200)
240 | 18.007394486980047 | Status: (200)
249 | 17.909152715990786 | Status: (200)
241 | 17.996459071000572 | Status: (200)
247 | 17.93349235400092 | Status: (200)
242 | 17.987716235016705 | Status: (200)
246 | 17.943914703995688 | Status: (200)
256 | 17.835408477985766 | Status: (200)
251 | 17.890954681992298 | Status: (200)
258 | 17.81470642099157 | Status: (200)
264 | 17.74994074399001 | Status: (200)
252 | 17.881930844014278 | Status: (200)
261 | 17.78285606999998 | Status: (200)
263 | 17.761019999015843 | Status: (200)
257 | 17.827393254003255 | Status: (200)
262 | 17.773964621999767 | Status: (200)
253 | 17.872924610011978 | Status: (200)
255 | 17.85089306399459 | Status: (200)
260 | 17.79612857400207 | Status: (200)
268 | 17.708538122999016 | Status: (200)
254 | 17.861996474995976 | Status: (200)
259 | 17.807200755021768 | Status: (200)
270 | 17.6869571779971 | Status: (200)
267 | 17.72020996498759 | Status: (200)
274 | 17.644800537003903 | Status: (200)
266 | 17.732629526988603 | Status: (200)
276 | 17.62406048498815 | Status: (200)
271 | 17.678949152992573 | Status: (200)
278 | 17.6023192749999 | Status: (200)
283 | 17.547120041999733 | Status: (200)
269 | 17.70173880099901 | Status: (200)
272 | 17.670155938976677 | Status: (200)
273 | 17.65930122300051 | Status: (200)
287 | 17.50374974301667 | Status: (200)
265 | 17.74718880202272 | Status: (200)
280 | 17.58240473200567 | Status: (200)
281 | 17.571448578994023 | Status: (200)
286 | 17.514828427985776 | Status: (200)
275 | 17.637490043998696 | Status: (200)
277 | 17.61565888300538 | Status: (200)
284 | 17.537650154001312 | Status: (200)
279 | 17.593831355014117 | Status: (200)
282 | 17.560534538002685 | Status: (200)
291 | 17.460820147010963 | Status: (200)
288 | 17.494125629978953 | Status: (200)
294 | 17.42778845599969 | Status: (200)
285 | 17.527354282996384 | Status: (200)
290 | 17.47228595300112 | Status: (200)
289 | 17.483466983016115 | Status: (200)
AIOHTTP Session Exception:

Traceback (most recent call last):
  File "test.py", line 30, in carrier_lookup
    async with session.get(cfg.api["url"], params=params, timeout=20) as resp:
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 1124, in __aenter__
    self._resp = await self._coro
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 626, in _request
    break
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/helpers.py", line 656, in __exit__
    raise asyncio.TimeoutError from None
asyncio.exceptions.TimeoutError
300 | 20.656390437012305 | Status: (False)
AIOHTTP Session Exception:

Traceback (most recent call last):
  File "test.py", line 30, in carrier_lookup
    async with session.get(cfg.api["url"], params=params, timeout=20) as resp:
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 1124, in __aenter__
    self._resp = await self._coro
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 626, in _request
    break
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/helpers.py", line 656, in __exit__
    raise asyncio.TimeoutError from None
asyncio.exceptions.TimeoutError
303 | 20.62213652097853 | Status: (False)
AIOHTTP Session Exception:

Traceback (most recent call last):
  File "test.py", line 30, in carrier_lookup
    async with session.get(cfg.api["url"], params=params, timeout=20) as resp:
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 1124, in __aenter__
    self._resp = await self._coro
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/client.py", line 626, in _request
    break
  File "/opt/lrg-rvm-api/venv/lib/python3.8/site-packages/aiohttp/helpers.py", line 656, in __exit__
    raise asyncio.TimeoutError from None

esundberg · 2020-11-15T17:29:24Z

I put a timer's in for each step of the loop. Looks like it's the get statement that is not completing. Seeing a lot of missing Step3 messages.

Also I tried this on my PC and it works fine, the duration for the request is constantly under .01 seconds

    start = time.monotonic()
    try: 
        print(f'{id} | Step1: {time.monotonic()}')
        async with aiohttp.ClientSession() as session:
            print(f'{id} | Step2: {time.monotonic()}')
            async with session.get(cfg.api["url"], params=params, timeout=20) as resp:
                print(f'{id} | Step3: {time.monotonic()}')
                status = resp.status
                response = await resp.json()
    except Exception as e:
        print(f'{id} | Step4: {time.monotonic()}')
        print(f'AIOHTTP Session Exception:')
        print(e)
        traceback.print_exc()
    print(f'{id} | Step5: {time.monotonic()}')
    end = time.monotonic()
    duration = end - start

    print(f'{id} | {duration} | Status: ({status})')

Output

46 | Step1: 208006.098866524
46 | Step2: 208006.098998251
46 | Step3: 208006.106477804
46 | Step5: 208006.106758266
46 | 0.007922396005596966 | Status: (200)
47 | Step1: 208006.110013794
47 | Step2: 208006.110155689
47 | Step3: 208006.117388824
47 | Step5: 208006.117626537
47 | 0.007638009003130719 | Status: (200)
48 | Step1: 208006.120861899
48 | Step2: 208006.120975356
48 | Step3: 208006.128383611
48 | Step5: 208006.128677054
48 | 0.007852971990359947 | Status: (200)
49 | Step1: 208006.131963342
49 | Step2: 208006.132086511
49 | Step3: 208006.139497562
49 | Step5: 208006.139856716
49 | 0.007922147982753813 | Status: (200)
50 | Step1: 208006.143146149
50 | Step2: 208006.143292875
50 | Step3: 208006.150619955
50 | Step5: 208006.150872085
50 | 0.007752548990538344 | Status: (200)
51 | Step1: 208006.154141796
51 | Step2: 208006.154272661
51 | Step3: 208006.161141993
51 | Step5: 208006.161378779
51 | 0.007261635997565463 | Status: (200)
52 | Step1: 208006.164653772
52 | Step2: 208006.164780957
53 | Step1: 208006.17550927
53 | Step2: 208006.175682734
54 | Step1: 208006.186896208
54 | Step2: 208006.187067763
55 | Step1: 208006.198426158
55 | Step2: 208006.198599857
56 | Step1: 208006.209813752
56 | Step2: 208006.210001821
57 | Step1: 208006.221230345
57 | Step2: 208006.221424288
58 | Step1: 208006.232624649
58 | Step2: 208006.232791059
59 | Step1: 208006.244009859
59 | Step2: 208006.244211955
60 | Step1: 208006.255417323
60 | Step2: 208006.255605445
61 | Step1: 208006.266784924

derlih · 2020-11-15T19:05:18Z

Those steps look like it hits some barriers.
Also 289 | 17.483466983016115 | Status: (200) Shows that request itself executed in 5 seconds (due to timeout) and then the continuation of your function was resumed after quite long time.

@asvetlov from your experience, does these steps look like that there is too many coroutines are scheduled on the loop?

@esundberg you can also try to run your script with uvloop. May be it will increase the number of requests that will not hit the timeout.

derlih · 2020-11-15T19:28:03Z

@earlbread
Also you can take a look onto this thread.
Using asyncio.Semaphore you can limit the number of executing download tasks.

esundberg · 2020-11-15T19:28:36Z

Those steps look like it hits some barriers.

Also 289 | 17.483466983016115 | Status: (200) Shows that request itself executed in 5 seconds (due to timeout) and then the continuation of your function was resumed after quite long time.

@asvetlov from your experience, does these steps look like that there is too many coroutines are scheduled on the loop?

@esundberg you can also try to run your script with uvloop. May be it will increase the number of requests that will not hit the timeout.

Ok i will try uvloop. It might be a bit of a learning curve because I have never used uvloop before.

esundberg · 2020-11-15T20:57:37Z

Kind of the same results with uvloop, but no timeout error. Except the code runs the ~50 task, then pauses, then completes the next 50 tasks in 4 seconds, followed by the next 50 tasks in 9 seconds. Also if I try a ctrl+c it takes a 2-3 minutes to cause python to exit.

Here is a video of it https://youtu.be/RZPnD4ZgGsw Baby dinosaur sounds in the background, my baby is playing next to me in the pack in play :)

esundberg · 2020-11-15T21:41:16Z

So this is going to be DNS related. It appears that the DNS server is sending a dns response and the socket used for the DNS lookup is not open, so the ubuntu server is sending back a ICMP Destination unreachable(Port Unreachable)

If I re run the script and use a IP Address for the url instead of a FQDN, it run just fine with no delays or errors.

Is there away to have aiohttp use a cached dns record instead of preforming a DNS lookup each time aiohttp client needs to send a query?

esundberg · 2020-11-15T22:21:30Z

I installed aiohttp[speedups] and the same thing is happening. Is there any thing special that I need to do to make sure aiodns is used?

esundberg · 2020-11-15T22:48:12Z

So I did the following and it seams to fix the issue.

This Works using 8.8.8.8 and 8.8.4.4 as the dns server. All responses are in order.

from aiohttp.resolver import AsyncResolver


        resolver = AsyncResolver(nameservers=["8.8.8.8", "8.8.4.4"])
        conn = aiohttp.TCPConnector(resolver=resolver)
        async with aiohttp.ClientSession(connector=conn) as session:
            async with session.get(cfg.api["url"], params=params, timeout=20) as resp:
                status = resp.status
                response = await resp.json()

Same code but using Digital Ocean DNS Servers of 67.207.67.3 and 67.207.67.2. I get some really weird delays in responses. Wondering if they have a rate limiter on there DNS servers?

70 | 0.007095023000147194 | Status: (200)
71 | 0.006469905987614766 | Status: (200)
72 | 0.0069583620061166584 | Status: (200)
73 | 0.006232422980247065 | Status: (200)
74 | 0.006745412014424801 | Status: (200)
75 | 0.0062044050137046725 | Status: (200)
76 | 0.006920018000528216 | Status: (200)
77 | 0.006298836000496522 | Status: (200)
78 | 0.006390694994479418 | Status: (200)
85 | 0.007023805985227227 | Status: (200)
93 | 0.007998454006155953 | Status: (200)
102 | 0.007630085019627586 | Status: (200)
111 | 0.007274115981999785 | Status: (200)
119 | 0.007039437012281269 | Status: (200)
127 | 0.010199895012192428 | Status: (200)
135 | 0.007669365004403517 | Status: (200)
142 | 0.00849951701820828 | Status: (200)
149 | 0.007551632996182889 | Status: (200)
157 | 0.009238906000973657 | Status: (200)
164 | 0.007726176001597196 | Status: (200)
128 | 0.5087432510044891 | Status: (200)
180 | 0.008824740012641996 | Status: (200)
189 | 0.008491701009916142 | Status: (200)
197 | 0.007330658991122618 | Status: (200)
206 | 0.008737191004911438 | Status: (200)
214 | 0.00770023200311698 | Status: (200)
222 | 0.007829958980437368 | Status: (200)
230 | 0.006796139001380652 | Status: (200)
237 | 0.007780551997711882 | Status: (200)
246 | 0.007286532985744998 | Status: (200)
260 | 0.007541108992882073 | Status: (200)
269 | 0.007159119006246328 | Status: (200)
278 | 0.0070987830113153905 | Status: (200)
294 | 0.0073966580093838274 | Status: (200)
305 | 0.008312589023262262 | Status: (200)
313 | 0.007333171000937 | Status: (200)
328 | 0.007867536012781784 | Status: (200)
336 | 0.007164070993894711 | Status: (200)
347 | 0.007760843000141904 | Status: (200)
360 | 0.007452313991962001 | Status: (200)
369 | 0.008478286006720737 | Status: (200)
380 | 0.007484535017283633 | Status: (200)
396 | 0.007647730002645403 | Status: (200)
405 | 0.007341627991991118 | Status: (200)
417 | 0.008267575001809746 | Status: (200)
426 | 0.008297344000311568 | Status: (200)
434 | 0.010120083985384554 | Status: (200)
437 | 0.008429149980656803 | Status: (200)
440 | 0.029436629003612325 | Status: (200)
451 | 0.007205383008113131 | Status: (200)
459 | 0.00788264098810032 | Status: (200)
469 | 0.007267314998898655 | Status: (200)
484 | 0.007794466975610703 | Status: (200)
494 | 0.00713224001810886 | Status: (200)
505 | 0.011658781993901357 | Status: (200)
508 | 0.006886675982968882 | Status: (200)
517 | 0.007680827984586358 | Status: (200)
528 | 0.007595510018290952 | Status: (200)
79 | 5.017722521995893 | Status: (200)
80 | 5.009508768009255 | Status: (200)
81 | 5.011346354993293 | Status: (200)
82 | 5.010442745988257 | Status: (200)
83 | 5.0121102390112355 | Status: (200)
84 | 5.00922656498733 | Status: (200)

derlih · 2020-11-16T07:22:14Z

If you hit to the DNS rate limit, you can install a local caching DNS on your machine and use it for resolving.
Looks like this problem is not on the aiohttp side.

esundberg · 2020-11-16T08:34:30Z

I have a lot of servers running aiohttp so I just setup two local bind servers to handle the dns requests.

Thanks for the help, it was really weird symptoms for a DNS issue with no errors pointing towards DNS.

esundberg added the bug label Nov 15, 2020

esundberg closed this as completed Nov 18, 2020

mdellweg mentioned this issue Jan 28, 2022

Users running into timeouts with error messages that are unhelpful pulp/pulpcore#2169

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

aiohttp client get request - exception without error message #5239

aiohttp client get request - exception without error message #5239

esundberg commented Nov 15, 2020 •

edited

Loading

derlih commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

derlih commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

derlih commented Nov 15, 2020

derlih commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020 •

edited

Loading

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

derlih commented Nov 16, 2020

esundberg commented Nov 16, 2020

aiohttp client get request - exception without error message #5239

aiohttp client get request - exception without error message #5239

Comments

esundberg commented Nov 15, 2020 • edited Loading

derlih commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

derlih commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

derlih commented Nov 15, 2020

derlih commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020 • edited Loading

esundberg commented Nov 15, 2020

esundberg commented Nov 15, 2020

derlih commented Nov 16, 2020

esundberg commented Nov 16, 2020

esundberg commented Nov 15, 2020 •

edited

Loading

esundberg commented Nov 15, 2020 •

edited

Loading