connection was closed in the middle of operation

[Jeffwhen]

• asyncpg version: 0.15.0
• PostgreSQL version: 10.3
• local PostgreSQL:
• Python version: 3.6.5
• Platform: Ubuntu 14.04.5
• Do you use pgbouncer?: no
• Did you install asyncpg with pip?: yes

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.

[elprans]

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.

[Jeffwhen]

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.

[elprans]

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.

[Jeffwhen]

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

[elprans]

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.

[Jeffwhen]

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.

[vladyslav2]

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 ...

[vladyslav2]

#313 helped
Thank you for so quick reflection!

[q210]

@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 moby/moby#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.

[Jeffwhen]

@q210 Yes I'm deploying postsql with docker-swarm. I've tried it out, your solution absolutely works.

[fpierfed]

Since #313 is closed, I am reporting the error here as well.

• asyncpg version: 0.18.2 and master
• PostgreSQL version: 9.6.10 and 10.6
• Do you use a PostgreSQL SaaS? NO
• Python version: 3.6.6
• Platform: FreeBSD 11.2
• Do you use pgbouncer?: NO
• Did you install asyncpg with pip?: YES (used setup.py for master)
• If you built asyncpg locally, which version of Cython did you use?: 0.29
• Can the issue be reproduced under both asyncio and uvloop?: YES

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.

[burmanm]

I can confirm something broke the FreeBSD support between 0.17.0 and 0.18.0

[bcho]

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'

ref: moby/moby#31208