Случайные ошибки тайм-аута при использовании heroku + gunicorn + aiohttp
Я разработал сервис, который действует как шлюз для перенаправления запросов в разные микро-сервисы. Для этого я использовал aiohttp для обработки запросов на перенаправление, gunicorn (w/ aiohttp.worker.GunicornWebWorker) и Heroku в качестве хоста.
Работая локально, все работает отлично, 100% запросов возвращают ответ, и клиент всегда получает нужную информацию, НО, когда я развертываю в Heroku и перенаправляю некоторые запросы (5k в минуту), я вижу от 3 до 7 запросов со статусом HTTP 503 Timeout Error. Не о чем беспокоиться, потому что доля хорошо решенных запросов очень высока (99,9994), но я хочу знать, что происходит. Возникновение исключения перед тайм-аутами выглядит так:
[2017-02-10 17:03:48 +0000] [683] [INFO] Worker exiting (pid: 683)
ERROR:asyncio:Task was destroyed but it is pending!
[2017-02-10 17:03:48 +0000] [683] [INFO] Stopping server: 683, connections: 1
Exception ignored in: <generator object GunicornWebWorker._run at 0x7f18b1d2f518>
Traceback (most recent call last):
yield from self.close()
yield from self.wsgi.shutdown()
File "/app/.heroku/python/lib/python3.5/site-packages/aiohttp/web.py", line 199, in shutdown
yield from self.on_shutdown.send(self)
File "/app/.heroku/python/lib/python3.5/site-packages/aiohttp/signals.py", line 48, in send
yield from self._send(*args, **kwargs)
File "/app/.heroku/python/lib/python3.5/site-packages/aiohttp/signals.py", line 16, in _send
yield from res
File "/app/app/app.py", line 14, in close_redis
app.redis_pool.close()
File "/app/.heroku/python/lib/python3.5/site-packages/aioredis/pool.py", line 135, in close
self._close_state.set()
File "/app/.heroku/python/lib/python3.5/asyncio/locks.py", line 242, in set
fut.set_result(True)
File "/app/.heroku/python/lib/python3.5/asyncio/futures.py", line 332, in set_result
self._schedule_callbacks()
File "/app/.heroku/python/lib/python3.5/asyncio/futures.py", line 242, in _schedule_callbacks
self._loop.call_soon(callback, self)
File "/app/.heroku/python/lib/python3.5/asyncio/base_events.py", line 497, in call_soon
handle = self._call_soon(callback, args)
File "/app/.heroku/python/lib/python3.5/asyncio/base_events.py", line 506, in _call_soon
self._check_closed()
File "/app/.heroku/python/lib/python3.5/asyncio/base_events.py", line 334, in _check_closed
raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<ServerHttpProtocol.start() running at /app/.heroku/python/lib/python3.5/site-packages/aiohttp/server.py:261>>
[2017-02-10 17:03:48 +0000] [4] [CRITICAL] WORKER TIMEOUT (pid:683)
Тогда геройку / роутер выдает такую ошибку:
at=error code=H12 desc="Request timeout" method=GET path="/users/21324/posts/" host=superapp.herokuapp.com request_id=209bd839-baac-4e72-a04e-657d85348f45 fwd="84.78.56.97" dyno=web.2 connect=0ms service=30000ms status=503 bytes=0
Я запускаю приложение с:
gunicorn --pythonpath app app.app:aio_app --worker-class aiohttp.worker.GunicornWebWorker --workers 3
Основной код:
def init(asyncio_loop):
app = web.Application(loop=asyncio_loop, middlewares=[middlewares.auth_middleware,
middlewares.logging_middleware])
# INIT DBs
app.redis_pool = asyncio_loop.run_until_complete(
create_pool((settings.REDIS['host'], settings.REDIS['port']),
password=settings.REDIS['password']))
# Clean connections on stop
app.on_shutdown.append(close_redis)
# Add rollbar
rollbar.init(settings.ROLLBAR_TOKEN, 'production') # access_token, environment
# Bind routes
for r in routes:
app.router.add_route(r[0], r[1], r[2])
return app
# Create app
loop = asyncio.get_event_loop()
aio_app = init(loop)
И пример перенаправления:
async with aiohttp.ClientSession() as s:
try:
async with s.request(method=method,
url=new_url,
headers=new_headers,
data=body,
allow_redirects=False,
timeout=25) as response:
# Clean response
resp_headers = MSRepository.filter_response_headers(response.headers)
resp_body = (await response.read())
return ResponseDataEntity(resp_headers, response.status, resp_body)
except asyncio.TimeoutError:
raise MSConnectionError("Request timeout")
except Exception as e:
rollbar.report_message(str(e), extra_data={
"url": new_url,
"data": body,
"method": method,
"headers": new_headers
})
raise MSConnectionError(str(e))
Как вы можете видеть, время ожидания составляет 25 с, а исключение увеличивается с временем ожидания 30 с.
Кто-нибудь знает, что происходит?
(Примечание: когда я пишу перенаправление, я не имею в виду HTTP 302, я имею в виду обработку запроса, редактирование заголовков, проверку подлинности, выполнение асинхронного запроса к подходящей MS, обработку ответа и возврат этого ответа)
1 ответ
В конце проблема была в одном из обработчиков. Я на самом деле не знаю, что происходило, потому что тайм-ауты были абсолютно случайными для всех конечных точек, но после 6 часов работы с более чем 10 000 запросов в минуту я уверен, что проблема была в этом. Вот код до и после исправления:
async def bad_handler(request):
# Read body in ALL cases to not to block requests
if '/event-log/action/' == request.path:
if request.query_string != '':
action_type = request.query_string
else:
try:
request_body = await request.json()
action_type = request_body.get('type', '')
except:
action_type = ''
print("Action_type={}".format(action_type))
# Response to client
return aiohttp.web.json_response(data={}, status=200)
async def good_handler(request):
# Read body in ALL cases to not to block requests
try:
request_body = await request.json()
except:
request_body = None
if '/event-log/action/' == request.path:
if request.query_string != '':
action_type = request.query_string
else:
if request_body is not None:
action_type = request_body.get('type', '')
else:
action_type = ''
print("Action_type={}".format(action_type))
# Response to client
return aiohttp.web.json_response(data={}, status=200)
Как видите, единственная разница в том, что в одном случае мы ожидаем тела всегда, а в другом - нет.
Я оставлю вопрос открытым, просто прыгнув, кто-то ответит мне, почему он работает сейчас.:)