I use asyncpg with sanic. Before server start, a connection pool is made and attached to the app. In every route, the handler acquire a connection if pg access is needed. The problem is, if the pool is silent for too long, new acquired connection is not usable.
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
After one-time exception. The next acquisition is normal again. No exception with queries. Which is really weird for me.
I've tried to twist max_inactive_connection_lifetime parameter, got no luck. Actually I don't quite understand this parameter. Why would I need this parameter?
Any help is welcomed.
max_inactive_connection_lifetime is used to automatically close __unused__ connections in the pool after a period of inactivity. Please provide an example of the code that triggers this.
Thank you for your response. I use Sanic as I've said. Here's the code.
DB_CONFIG = {
'host': '127.0.0.1',
'user': 'postgres',
'password': 'pwabc',
'port': 5432,
'database': 'foo'
}
@app.listener('before_server_start')
async def init(app, loop):
app.pool = await create_pool(
**DB_CONFIG, loop=loop,
max_size=10, max_inactive_connection_lifetime=100
)
@bp.route('/info', methods=['GET'])
async def info(request):
async with request.app.pool.acquire() as conn:
d = await conn.fetchrow('''SELECT * FROM info''')
return json(dict(d))
I know this is not the solution, but I altered the max_inactive_connection_lifetime to a radical 3 seconds, and the problem seems to gone now.
Please post a complete traceback for the error you're getting. Had it been the culprit, max_inactive_connection_lifetime set to 3 would make this error occur _more_ frequently, not less.
Here the full trackback.
[2018-06-14 13:45:36 +0800] [37430] [ERROR] ConnectionResetError: [Errno 104] Connection reset by peer
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/sanic/app.py", line 556, in handle_request
response = await response
File "/usr/lib/python3.6/asyncio/coroutines.py", line 110, in __next__
return self.gen.send(None)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/sanic_jwt/decorators.py", line 35, in decorated_function
response = await response
File "/usr/lib/python3.6/asyncio/coroutines.py", line 110, in __next__
return self.gen.send(None)
File "/home/user/Projects/dfdc/app/routes/commit.py", line 407, in commit_detail
tts = await asyncio.gather(*[gather_person_tracks(p) for p in persons])
File "/usr/lib/python3.6/asyncio/coroutines.py", line 126, in send
return self.gen.send(value)
File "/home/user/Projects/dfdc/app/routes/commit.py", line 331, in gather_person_tracks
person['id'])
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 359, in fetch
return await self._execute(query, args, 0, timeout)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1303, in _execute
query, args, limit, timeout, return_status=return_status)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1311, in __execute
return await self._do_execute(query, executor, timeout)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1323, in _do_execute
stmt = await self._get_statement(query, None)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 288, in _get_statement
statement = await self._protocol.prepare(stmt_name, query, timeout)
File "asyncpg/protocol/protocol.pyx", line 171, in prepare
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
[2018-06-14 13:45:36 +0800] [37430] [ERROR] Exception occurred while handling uri: "http://192.168.1.29:7230/person/commit/90?order=id&page=1&src=&state=&step=5"
ConnectionResetError: [Errno 104] Connection reset by peer
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/sanic/app.py", line 556, in handle_request
response = await response
File "/usr/lib/python3.6/asyncio/coroutines.py", line 110, in __next__
return self.gen.send(None)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/sanic_jwt/decorators.py", line 35, in decorated_function
response = await response
File "/usr/lib/python3.6/asyncio/coroutines.py", line 110, in __next__
return self.gen.send(None)
File "/home/user/Projects/dfdc/app/routes/commit.py", line 407, in commit_detail
tts = await asyncio.gather(*[gather_person_tracks(p) for p in persons])
File "/usr/lib/python3.6/asyncio/coroutines.py", line 126, in send
return self.gen.send(value)
File "/home/user/Projects/dfdc/app/routes/commit.py", line 331, in gather_person_tracks
person['id'])
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 359, in fetch
return await self._execute(query, args, 0, timeout)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1303, in _execute
query, args, limit, timeout, return_status=return_status)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1311, in __execute
return await self._do_execute(query, executor, timeout)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1323, in _do_execute
stmt = await self._get_statement(query, None)
File "/usr/lib/python3.6/asyncio/coroutines.py", line 129, in throw
return self.gen.throw(type, value, traceback)
File "/home/user/Projects/dfdc/env/lib/python3.6/site-packages/asyncpg/connection.py", line 288, in _get_statement
statement = await self._protocol.prepare(stmt_name, query, timeout)
File "asyncpg/protocol/protocol.pyx", line 171, in prepare
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
It looks like your server is dropping the connections for some reason:
ConnectionResetError: [Errno 104] Connection reset by peer
Your setting max_inactive_connection_lifetime to a very low value "fixes" that because it makes the pool recycle the connections all the time. It would be interesting to look at the relevant portion of PostgreSQL log.
Sorry it took so long.
2018-05-31 09:30:24.272 UTC [1985] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.273 UTC [1979] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.274 UTC [1986] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.274 UTC [1991] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.276 UTC [1980] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.277 UTC [1987] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.277 UTC [1990] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.278 UTC [1982] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.279 UTC [1989] LOG: could not receive data from client: Connection reset by peer
2018-05-31 09:30:24.279 UTC [1984] LOG: could not receive data from client: Connection reset by peer
2018-05-31 10:39:13.025 UTC [2114] LOG: could not receive data from client: Connection reset by peer
2018-06-01 11:05:16.170 UTC [4073] FATAL: sorry, too many clients already
2018-06-01 11:05:16.170 UTC [4068] FATAL: sorry, too many clients already
2018-06-01 11:05:16.170 UTC [4074] FATAL: sorry, too many clients already
2018-06-01 11:05:16.170 UTC [4071] FATAL: sorry, too many clients already
2018-06-01 11:05:16.170 UTC [4063] FATAL: sorry, too many clients already
2018-06-01 11:05:16.170 UTC [4069] FATAL: sorry, too many clients already
This max_inactive_connection_lifetime work around has cost me something, seems like.
I have a similar problem:
asyncpg version: 0.16.0
PostgreSQL version: 9.6
local PostgreSQL:
Python version: 3.6.4
Platform: Freebsd 11.1
Do you use pgbouncer?: no
Did you install asyncpg with pip?: yes
File "/usr/local/lib/python3.6/runpy.py", line 193, in _run_module_as_main
"__main__", mod_spec)
File "/usr/local/lib/python3.6/runpy.py", line 85, in _run_code
exec(code, run_globals)
File "/usr/home/admin/bot/app/__main__.py", line 5, in <module>
web_app()
File "/usr/home/admin/bot/aiohttp_boilerplate/bootstrap/__init__.py", line 40, in web_app
loop=loop,
File "uvloop/loop.pyx", line 1448, in uvloop.loop.Loop.run_until_complete
File "/usr/home/admin/bot/aiohttp_boilerplate/dbpool/pg.py", line 51, in create_pool
setup=setup_connection
File "/usr/home/admin/bot/env/lib/python3.6/site-packages/asyncpg/pool.py", line 403, in _async__init__
await first_ch.connect()
File "/usr/home/admin/bot/env/lib/python3.6/site-packages/asyncpg/pool.py", line 125, in connect
self._con = await self._pool._get_new_connection()
File "/usr/home/admin/bot/env/lib/python3.6/site-packages/asyncpg/pool.py", line 452, in _get_new_connection
**self._connect_kwargs)
File "/usr/home/admin/bot/env/lib/python3.6/site-packages/asyncpg/connection.py", line 1577, in connect
max_cacheable_statement_size=max_cacheable_statement_size)
File "/usr/home/admin/bot/env/lib/python3.6/site-packages/asyncpg/connect_utils.py", line 426, in _connect
connection_class=connection_class)
File "/usr/home/admin/bot/env/lib/python3.6/site-packages/asyncpg/connect_utils.py", line 402, in _connect_addr
await asyncio.wait_for(connected, loop=loop, timeout=timeout)
File "/usr/local/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
return fut.result()
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
On the postgresql side:
LOG: invalid length of startup packet
Not sure why its happening and where should I dig too ...
Thank you for so quick reflection!
@Jeffwhen we had the same problem when deploying with docker-swarm.
In our case, the root cause was that ipvs, used by swarm to route packets, have default expiration time for idle connections set to 900 seconds. So if connection had no activity for more than 15 minutes, ipvs broke it.
900 seconds is significantly less than default linux tcp keepalive setting (7200 seconds) used by most of the services that can send keepalive tcp packets to keep connections from going idle.
The same problem is described here https://github.com/moby/moby/issues/31208
To fix this we had to set the following in postgresql.conf:
tcp_keepalives_idle = 600 # TCP_KEEPIDLE, in seconds;
# 0 selects the system default
tcp_keepalives_interval = 30 # TCP_KEEPINTVL, in seconds;
# 0 selects the system default
tcp_keepalives_count = 10 # TCP_KEEPCNT;
# 0 selects the system default
These settings are forcing PostgreSQL to keep connections from going idle by sending keepalive packets more often than ipvs default setting (that we can't change in docker-swarm, sadly).
I guess the same could be achieved by changing corresponding linux settings (net.ipv4.tcp_keepalive_time and the like), 'cause PostgreSQL uses them by default, but in our case changing these was a bit more cumbersome.
@q210 Yes I'm deploying postsql with docker-swarm. I've tried it out, your solution absolutely works.
Since #313 is closed, I am reporting the error here as well.
Test code:
(env) freebsd11% cat test.py
import asyncio
import asyncpg
import uvloop
async def run():
conn = await asyncpg.connect(database='testdb')
values = await conn.fetch('select * from test')
await conn.close()
asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())
loop = asyncio.get_event_loop()
loop.run_until_complete(run())
Python log:
Traceback (most recent call last):
File "./test.py", line 14, in <module>
loop.run_until_complete(run())
File "uvloop/loop.pyx", line 1446, in uvloop.loop.Loop.run_until_complete
File "./test.py", line 7, in run
conn = await asyncpg.connect(database='testdb')
File "/usr/home/dev/env/lib/python3.6/site-packages/asyncpg-0.19.0.dev0+43a7b21-py3.6-freebsd-11.2-RELEASE-amd64.egg/asyncpg/connection.py", line 1688, in connect
max_cacheable_statement_size=max_cacheable_statement_size)
File "/usr/home/dev/env/lib/python3.6/site-packages/asyncpg-0.19.0.dev0+43a7b21-py3.6-freebsd-11.2-RELEASE-amd64.egg/asyncpg/connect_utils.py", line 543, in _connect
connection_class=connection_class)
File "/usr/home/dev/env/lib/python3.6/site-packages/asyncpg-0.19.0.dev0+43a7b21-py3.6-freebsd-11.2-RELEASE-amd64.egg/asyncpg/connect_utils.py", line 519, in _connect_addr
await asyncio.wait_for(connected, loop=loop, timeout=timeout)
File "/usr/local/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
return fut.result()
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
Here is the postgres log
DEBUG: 00000: forked new backend, pid=4606 socket=9
LOCATION: BackendStartup, postmaster.c:4038
LOG: 00000: connection received: host=[local]
LOCATION: BackendInitialize, postmaster.c:4192
LOG: 08P01: invalid length of startup packet
LOCATION: ProcessStartupPacket, postmaster.c:1942
DEBUG: 00000: shmem_exit(0): 0 before_shmem_exit callbacks to make
LOCATION: shmem_exit, ipc.c:226
DEBUG: 00000: shmem_exit(0): 0 on_shmem_exit callbacks to make
LOCATION: shmem_exit, ipc.c:259
DEBUG: 00000: proc_exit(0): 1 callbacks to make
LOCATION: proc_exit_prepare, ipc.c:188
DEBUG: 00000: exit(0)
LOCATION: proc_exit, ipc.c:141
DEBUG: 00000: shmem_exit(-1): 0 before_shmem_exit callbacks to make
LOCATION: shmem_exit, ipc.c:226
DEBUG: 00000: shmem_exit(-1): 0 on_shmem_exit callbacks to make
LOCATION: shmem_exit, ipc.c:259
DEBUG: 00000: proc_exit(-1): 0 callbacks to make
LOCATION: proc_exit_prepare, ipc.c:188
DEBUG: 00000: reaping dead processes
LOCATION: reaper, postmaster.c:2779
DEBUG: 00000: server process (PID 4606) exited with exit code 0
LOCATION: LogChildExit, postmaster.c:3552
Happens with the latest released version as well as with master compiled locally.
I can confirm something broke the FreeBSD support between 0.17.0 and 0.18.0
Hi all! I can confirm @q210 's solution works for our swarm setup. For everyone coming from the search (and using docker swarm), here is a simple modification that fixes the problem:
In your postgresql server docker compose file:
services:
pg:
image: postgres
command:
- postgres
# the following lines tell pg server to adjust the TCP keepalive settings explicitly
# instead of reading from the container default, which is likely idle=7200 (seconds).
# The default value in the container is usually much larger than docker-swarm's IPVS default,
# which is 900. (And this is the culprit of the connection will be closed after ~15mins)
- -c
- 'tcp_keepalives_idle=600'
- -c
- 'tcp_keepalives_interval=30'
- -c
- 'tcp_keepalives_count=10'
Hey, having same issue, but i'm not using docker-swram, i'm using FastApi on k8s
i made some changes to add following settings: max_inactive_connection_lifetime=900, min_size=5, max_size=10), but still seeing this issue, wondering if there is a way to add pool_use_lifo=True, pool_pre_ping=True as per sqlalchemy https://docs.sqlalchemy.org/en/13/core/pooling.html, so closed connection we have in the pool are replaced with a "healthy one".
this issue happens randomly during the day.
these are packages version i'm using.
this is the full error stack
==================================== start ======================
uncaught exception: ConnectionResetError: [Errno 104] Connection reset by peer
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
......
rows = await self.engine.fetch_all(sql)
File "/root/anaconda/lib/python3.7/site-packages/databases/core.py", line 140, in fetch_all
return await connection.fetch_all(query, values)
File "/root/anaconda/lib/python3.7/site-packages/databases/core.py", line 237, in fetch_all
return await self._connection.fetch_all(built_query)
File "/root/anaconda/lib/python3.7/site-packages/databases/backends/postgres.py", line 147, in fetch_all
rows = await self._connection.fetch(query, *args)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 443, in fetch
return await self._execute(query, args, 0, timeout)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 1446, in _execute
query, args, limit, timeout, return_status=return_status)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 1454, in __execute
return await self._do_execute(query, executor, timeout)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 1466, in _do_execute
stmt = await self._get_statement(query, None)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 351, in _get_statement
statement = await self._protocol.prepare(stmt_name, query, timeout)
File "asyncpg/protocol/protocol.pyx", line 163, in prepare
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
100.64.128.99:31620 - "POST /invocations HTTP/1.0" 500
[2020-10-29 17:35:53 +0000] [8] [ERROR] Exception in ASGI application
Traceback (most recent call last):
File "/root/anaconda/lib/python3.7/site-packages/uvicorn/protocols/http/httptools_impl.py", line 390, in run_asgi
result = await app(self.scope, self.receive, self.send)
File "/root/anaconda/lib/python3.7/site-packages/uvicorn/middleware/proxy_headers.py", line 45, in __call__
return await self.app(scope, receive, send)
File "/root/anaconda/lib/python3.7/site-packages/fastapi/applications.py", line 179, in __call__
await super().__call__(scope, receive, send)
File "/root/anaconda/lib/python3.7/site-packages/starlette/applications.py", line 111, in __call__
await self.middleware_stack(scope, receive, send)
File "/root/anaconda/lib/python3.7/site-packages/starlette/middleware/errors.py", line 181, in __call__
raise exc from None
File "/root/anaconda/lib/python3.7/site-packages/starlette/middleware/errors.py", line 159, in __call__
await self.app(scope, receive, _send)
File "/root/anaconda/lib/python3.7/site-packages/starlette/exceptions.py", line 82, in __call__
raise exc from None
File "/root/anaconda/lib/python3.7/site-packages/starlette/exceptions.py", line 71, in __call__
await self.app(scope, receive, sender)
File "/root/anaconda/lib/python3.7/site-packages/starlette/routing.py", line 566, in __call__
await route.handle(scope, receive, send)
File "/root/anaconda/lib/python3.7/site-packages/starlette/routing.py", line 227, in handle
await self.app(scope, receive, send)
File "/root/anaconda/lib/python3.7/site-packages/starlette/routing.py", line 41, in app
response = await func(request)
File "/root/anaconda/lib/python3.7/site-packages/fastapi/routing.py", line 183, in app
dependant=dependant, values=values, is_coroutine=is_coroutine
File "/root/anaconda/lib/python3.7/site-packages/fastapi/routing.py", line 133, in run_endpoint_function
return await dependant.call(*values)
File "/root/anaconda/lib/python3.7/site-packages/newrelic/common/async_proxy.py", line 124, in throw
return self.__wrapped__.throw(args, *kwargs)
File "/app/api/main.py", line 79, in invocations
response = await service.predict(request)
File "/app/api/personas_classification_service.py", line 159, in predict
userBehaviorPredictions, currentPrediction = await asyncio.gather([t1, t2])
File "/app/api/personas_classification_service.py", line 96, in __computeCurrentPrediction
mcmid_data = await self.__query_raw_visitor_data(mcmid)
File "/app/api/personas_classification_service.py", line 90, in __query_raw_visitor_data
return await self.mlpredictionsRepository.query_raw_visitor_data(mcmid, days_for_predictions)
File "/app/api/mlpredictions_repository.py", line 18, in query_raw_visitor_data
rows = await self.engine.fetch_all(sql)
File "/root/anaconda/lib/python3.7/site-packages/databases/core.py", line 140, in fetch_all
return await connection.fetch_all(query, values)
File "/root/anaconda/lib/python3.7/site-packages/databases/core.py", line 237, in fetch_all
return await self._connection.fetch_all(built_query)
File "/root/anaconda/lib/python3.7/site-packages/databases/backends/postgres.py", line 147, in fetch_all
rows = await self._connection.fetch(query, *args)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 443, in fetch
return await self._execute(query, args, 0, timeout)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 1446, in _execute
query, args, limit, timeout, return_status=return_status)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 1454, in __execute
return await self._do_execute(query, executor, timeout)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 1466, in _do_execute
stmt = await self._get_statement(query, None)
File "/root/anaconda/lib/python3.7/site-packages/asyncpg/connection.py", line 351, in _get_statement
statement = await self._protocol.prepare(stmt_name, query, timeout)
File "asyncpg/protocol/protocol.pyx", line 163, in prepare
asyncpg.exceptions.ConnectionDoesNotExistError: connection was closed in the middle of operation
Most helpful comment
@Jeffwhen we had the same problem when deploying with docker-swarm.
In our case, the root cause was that ipvs, used by swarm to route packets, have default expiration time for idle connections set to 900 seconds. So if connection had no activity for more than 15 minutes, ipvs broke it.
900 seconds is significantly less than default linux tcp keepalive setting (7200 seconds) used by most of the services that can send keepalive tcp packets to keep connections from going idle.
The same problem is described here https://github.com/moby/moby/issues/31208
To fix this we had to set the following in
postgresql.conf:These settings are forcing PostgreSQL to keep connections from going idle by sending keepalive packets more often than ipvs default setting (that we can't change in docker-swarm, sadly).
I guess the same could be achieved by changing corresponding linux settings (
net.ipv4.tcp_keepalive_timeand the like), 'cause PostgreSQL uses them by default, but in our case changing these was a bit more cumbersome.