asyncpg.exceptions.InvalidSQLStatementNameError: prepared statement "__asyncpg_stmt_37__" does not exist

[kxepal]

• asyncpg version: 0.9.0, 0.10.1
• PostgreSQL version: 9.6
• Python version: 3.6
• Platform: FreeBSD 10.2
• Do you use pgbouncer?: no yes
• Did you install asyncpg with pip?: yes
• If you built asyncpg locally, which version of Cython did you use?: yes
• Can the issue be reproduced under both asyncio and
  uvloop?: yes

Hi!

We notice a problem that issue name describes pretty well. How did we get it?

We have a small aiohttp service which runs a static query to PostgreSQL database on every handled request. Like SELECT foo, bar FROM table ORDER BY baz. No parameters, nothing all. That's the only query we executre to database. We're using connection pool sized from 1 to 4 connections as well, the rest parameters are default (except connection one of course).

Everything works fine until eventually we starting get the InvalidSQLStatementNameError exception on connection.fetch call. It doesn't happens instantly, it occurs after few hours of service uptime. Sometimes every .fetch call ends with that exception. Sometimes every even only. The number of __asyncpg_stmt_ token is always different, but stable until restart when error occurs.

We tried to disable statements cache at all, set it to zero. This didn't happened. We thought that 0.10 release will fix that problem. Suddenly, it doesn't. We played around the cache size, connection pool size, connection life time, but all ended with the same issue. Difference may be in dozen of minutes, but all ends similar.

It's quite hard for me to provide any example to reproduce the problem because everything just works for a quite long time. Except that particular service, which isn't quite different, doesn't uses any hacks, globals, pretty trivial. Just no idea what to try next.

The last bits of the traceback are here:

      File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 340, in fetch
        return await self._execute(query, args, 0, timeout)
      File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 651, in _execute
        return await self._do_execute(query, executor, timeout)
      File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 672, in _do_execute
        result = await executor(stmt, None)
      File "asyncpg/protocol/protocol.pyx", line 170, in bind_execute (asyncpg/protocol/protocol.c:57679)
    asyncpg.exceptions.InvalidSQLStatementNameError: prepared statement "__asyncpg_stmt_37__" does not exist

Any ideas how to debug this issue? Or workaround it? Would be grateful for any help.

[elprans]

Setting statement_cache_size to 0 in 0.10.0 or later will stop asyncpg from using the named prepared statements. Are you certain that you still see the error with the cache disabled?

[elprans]

Start by printing stmt here https://github.com/MagicStack/asyncpg/blob/master/asyncpg/connection.py#L513. We have to see if the statement gets deallocated erroneously.

[elprans]

Also, you're not using threads in any way, are you?

[kxepal]

@elprans

Setting statement_cache_size to 0 in 0.10.0 or later will stop asyncpg from using the named prepared statements. Are you certain that you still see the error with the cache disabled?

Yes, I do. That was my first attempt to workaround issue and without any luck.

Also, you're not using threads in any way, are you?

No, I don't. At least explicitly, but don't recall if aiohttp used them as well.

Start by printing stmt here https://github.com/MagicStack/asyncpg/blob/master/asyncpg/connection.py#L513. We have to see if the statement gets deallocated erroneously.

Thanks for the suggestion! Will try this today.

[elprans]

Ideally, we'd like to see the code on which this can be reproduced.

[kxepal]

I understand. It would be quite complicated however since to make sure that error occurs there need to wait for several hours. As I said, everything works fine since very start till some random moment. I'll try to setup some simple toy script in hopes to reproduce the problem, that just could take some time.

I have added prints you asked for. Also I add the one for statement when query execution fails. Btw, I noticed that sometimes error becomes different:

      File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 340, in fetch
        return await self._execute(query, args, 0, timeout)
      File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 651, in _execute
        return await self._do_execute(query, executor, timeout)
      File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 672, in _do_execute
        result = await executor(stmt, None)
      File "asyncpg/protocol/protocol.pyx", line 170, in bind_execute (asyncpg/protocol/protocol.c:57679)
    asyncpg.exceptions.InvalidSQLStatementNameError: unnamed prepared statement does not exist

We do have cache disabled now, but we observe both named and unnamed prepared statements miss.

Here are the prints log. I just realized that there would be nice to see timestamps, but that's for a second iterations if you'll be interested in that part of information:

_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80bbabcc8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca447c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca897c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca527c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca59368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca8f368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca86c28>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca70368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca97368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca66368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85368>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca91408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7ac28>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca8dc28>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7dc28>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caaac28>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca99368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7e368>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca8dc28>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a188>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca80408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca59408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca85b88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca6a4a8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab7b88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca76408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca8b4a8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca5dae8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca75408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caa8b88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7b408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca67b88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca59408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca74408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol .PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca54408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca8d408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caacb88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca43408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab2b88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caacb88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80bbabcc8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7db88>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab5408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca5d408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca43408>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca687c8>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca927c8>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca927c8>
... skip 469 similar records ...
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca927c8>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca927c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca927c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caa7688>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab47c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca4f7c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca7a7c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caaa7c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca4f7c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab37c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca657c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80ca5e7c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab47c8>
_cleanup_stmts <asyncpg.protocol.protocol.PreparedStatementState object at 0x80cab5908>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caad908>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caad908>
... skip 25 similar records ...
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caad908>
_do_execute SELECT url, lda FROM content ORDER BY updated_at <asyncpg.protocol.protocol.PreparedStatementState object at 0x80caad908>
... here we did restart ...

[kxepal]

I noticed that for some ids, statement was cleared before it get executed again. That's probably the part of the problem we're investigating, right?

[elprans]

I don't actually see any states cleared before use in your log. They do get cleared after. Timestamps would be useful, yes.

[kxepal]

Hm...true. I misread few ids. Ok, waiting for the next round. This will take some time.

[elprans]

Also, please indicate in the log the first occurrence of the error.

[kxepal]

Ok. But first occurrence of _do_execute message is about that.

[kxepal]

Duplicates: #149
Fixed in 0.13 release.

[elprans]

Ha, interesting! If this was indeed fixed, then it's most likely an effect of either 50edd8c or 57c9ffd.

[1st1]

Ha, interesting! If this was indeed fixed, then it's most likely an effect of either 50edd8c or 57c9ffd.

Still can't imagine a scenario how either of those could have fixed something that could cause a bug like that. @kxepal would it be possible for you to test asyncpg with one of those commits reverted to see if a problem reoccurs? We really need to understand what happened here.

[kxepal]

Actually, I'm confused: I don't understand origins of this bug. It was in our production (though we had dirty-patched it), upgrade to 0.13 get rid it completely so far - it happens almost instantly. But now I managed to reproduce it with 0.13.

import asyncio
import asyncpg
import random
import uuid


async def main(host='...',
               port=...,
               username='...',
               password='...',
               database='...'):
    pool = await asyncpg.create_pool(
        host=host,
        port=port,
        user=username,
        password=password,
        database=database,
    )
    async with pool.acquire() as connection:  # type: asyncpg.Connection
        await connection.execute(
            'CREATE TABLE IF NOT EXISTS bug_121 (key varchar, value int)'
        )
        await connection.execute('TRUNCATE bug_121')

    while True:
        done, _ = await asyncio.wait([
            all_reader(pool),
            specific_reader(pool),
            writer(pool)
        ], return_when=asyncio.FIRST_EXCEPTION)
        for task in done:
            if task.exception():
                raise task.exception()


async def all_reader(pool):
    while True:
        async with pool.acquire() as connection:  # type: asyncpg.Connection
            await connection.fetch('SELECT * FROM bug_121')
            await asyncio.sleep(0.1)


async def specific_reader(pool):
    while True:
        async with pool.acquire() as connection:  # type: asyncpg.Connection
            await connection.fetch('SELECT * FROM bug_121 WHERE value > $1',
                                   random.randint(1, 10))
            await asyncio.sleep(1)


async def writer(pool):
    while True:
        async with pool.acquire() as connection:  # type: asyncpg.Connection
            await connection.execute('INSERT INTO bug_121 VALUES ($1, $2)',
                                     uuid.uuid4().hex, random.randint(0, 15))
            await asyncio.sleep(1)

asyncio.get_event_loop().run_until_complete(main())

Run it as simple Python script. It fails like:

Traceback (most recent call last):
  File "../asyncpg-test.py", line 59, in <module>
    asyncio.get_event_loop().run_until_complete(main())
  File "/usr/local/lib/python3.6/asyncio/base_events.py", line 466, in run_until_complete
    return future.result()
  File "../asyncpg-test.py", line 33, in main
    raise task.exception()
  File "../asyncpg-test.py", line 55, in writer
    uuid.uuid4().hex, random.randint(0, 15))
  File "/usr/home/ashorin/asyncpg/asyncpg/connection.py", line 240, in execute
    _, status, _ = await self._execute(query, args, 0, timeout, True)
  File "/usr/home/ashorin/asyncpg/asyncpg/connection.py", line 1195, in _execute
    query, args, limit, timeout, return_status=return_status)
  File "/usr/home/ashorin/asyncpg/asyncpg/connection.py", line 1203, in __execute
    return await self._do_execute(query, executor, timeout)
  File "/usr/home/ashorin/asyncpg/asyncpg/connection.py", line 1215, in _do_execute
    stmt = await self._get_statement(query, None)
  File "/usr/home/ashorin/asyncpg/asyncpg/connection.py", line 286, in _get_statement
    statement = await self._protocol.prepare(stmt_name, query, timeout)
  File "asyncpg/protocol/protocol.pyx", line 168, in prepare (asyncpg/protocol/protocol.c:67248)
    return await waiter
asyncpg.exceptions.DuplicatePreparedStatementError: prepared statement "__asyncpg_stmt_1__" already exists

But! I can't reproduce it in 0.13 release with the following script:

import asyncio
import asyncpg
import random

async def main(host='...',
               port=...,
               username='...',
               password='...',
               database='...'):
    pool = await asyncpg.create_pool(
        host=host,
        port=port,
        user=username,
        password=password,
        database=database,
    )
    for _ in range(10000):
        async with pool.acquire() as connection:
            await connection.fetch('SELECT 1')
            await connection.fetch('SELECT %s' % random.randint(1, 10000))
            await connection.fetch('SELECT 3 WHERE 1 = $1', 1)
            await connection.fetch('SELECT 4 WHERE 1 = $1', random.randint(1, 10000))

asyncio.get_event_loop().run_until_complete(main())

While it triggers the bug in 0.11 and 0.12 releases and for commit 57c9ffd, but not for 50edd8c.

P.S. FYI 0.13 release also fixed issue with false positive asyncpg.exceptions.ProtocolViolationError: Auth failed exception on pool creation - credentials are fine, but auth randomly fails. Script to reproduce:

import asyncio

import aiohttp.web
import asyncpg
import uvloop


LOOP_FACTORIES = [asyncio.new_event_loop, uvloop.new_event_loop]


def create_app(loop: asyncio.AbstractEventLoop) -> \
        aiohttp.web.Application:
    app = aiohttp.web.Application(loop=loop)
    app.on_startup.append(on_startup)
    app.on_shutdown.append(on_shutdown)
    return app


async def on_startup(app: aiohttp.web.Application):
    app['pool'] = await pool()


async def on_shutdown(app: aiohttp.web.Application):
    await app['pool'].close()



async def pool(max_size=20, **kwargs):
    host, port = ..., ...
    database = '...'
    username = '...'
    password = '...'
    pool = await asyncpg.create_pool(
        max_size=max_size,
        host=host,
        port=port,
        user=username,
        database=database,
        password=password,
        **kwargs
    )
    return pool

async def test1(test_client, loop):
    app = create_app(loop=loop)
    client = await test_client(app)

async def test2(test_client, loop):
    app = create_app(loop=loop)
    client = await test_client(app)

async def test3(test_client, loop):
    app = create_app(loop=loop)
    client = await test_client(app)

async def test4(test_client, loop):
    app = create_app(loop=loop)
    client = await test_client(app)

Run it with py.test. And it fails like:

_________________________________________________________________________________________________________ test4[pyloop] _________________________________________________________________________________________________________

test_client = <function test_client.<locals>.go at 0x80978bf28>, loop = <_UnixSelectorEventLoop running=False closed=False debug=False>

    async def test4(test_client, loop):
        app = create_app(loop=loop)
>       client = await test_client(app)

test.py:57: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
venv/lib/python3.6/site-packages/aiohttp/pytest_plugin.py:244: in go
    yield from client.start_server()
venv/lib/python3.6/site-packages/aiohttp/test_utils.py:217: in start_server
    yield from self._server.start_server(loop=self._loop)
venv/lib/python3.6/site-packages/aiohttp/test_utils.py:73: in start_server
    handler = yield from self._make_factory(**kwargs)
venv/lib/python3.6/site-packages/aiohttp/test_utils.py:152: in _make_factory
    yield from self.app.startup()
venv/lib/python3.6/site-packages/aiohttp/web.py:256: in startup
    yield from self.on_startup.send(self)
venv/lib/python3.6/site-packages/aiohttp/signals.py:50: in send
    yield from self._send(*args, **kwargs)
venv/lib/python3.6/site-packages/aiohttp/signals.py:16: in _send
    yield from res
test.py:20: in on_startup
    app['pool'] = await pool()
test.py:40: in pool
    **kwargs
asyncpg/asyncpg/pool.py:344: in _async__init__
    await asyncio.gather(*connect_tasks, loop=self._loop)
asyncpg/asyncpg/pool.py:133: in connect
    connection_class=self._pool._connection_class)
asyncpg/asyncpg/connect_utils.py:274: in _connect_addr
    await asyncio.wait_for(connected, loop=loop, timeout=timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

fut = <Future finished exception=ProtocolViolationError('Auth failed',)>, timeout = 59.984085963107646

    @coroutine
    def wait_for(fut, timeout, *, loop=None):
        """Wait for the single Future or coroutine to complete, with timeout.
    
        Coroutine will be wrapped in Task.
    
        Returns result of the Future or coroutine.  When a timeout occurs,
        it cancels the task and raises TimeoutError.  To avoid the task
        cancellation, wrap it in shield().
    
        If the wait is cancelled, the task is also cancelled.
    
        This function is a coroutine.
        """
        if loop is None:
            loop = events.get_event_loop()
    
        if timeout is None:
            return (yield from fut)
    
        waiter = loop.create_future()
        timeout_handle = loop.call_later(timeout, _release_waiter, waiter)
        cb = functools.partial(_release_waiter, waiter)
    
        fut = ensure_future(fut, loop=loop)
        fut.add_done_callback(cb)
    
        try:
            # wait until the future completes or the timeout
            try:
                yield from waiter
            except futures.CancelledError:
                fut.remove_done_callback(cb)
                fut.cancel()
                raise
    
            if fut.done():
>               return fut.result()
E               asyncpg.exceptions.ProtocolViolationError: Auth failed

/usr/local/lib/python3.6/asyncio/tasks.py:352: ProtocolViolationError

Suddenly, I'm failed to reproduce it with something simpler.

[kxepal]

@elprans @1st1
Let me know if any else information would be useful to fix it. BTW, it seems that our dirty hack which I mentioned above helps here again:

diff --git a/asyncpg/connection.py b/asyncpg/connection.py
index ce346fb..afbef9f 100644
--- a/asyncpg/connection.py
+++ b/asyncpg/connection.py
@@ -283,7 +283,11 @@ class Connection(metaclass=ConnectionMeta):
         else:
             stmt_name = ''
 
-        statement = await self._protocol.prepare(stmt_name, query, timeout)
+        try:
+            statement = await self._protocol.prepare(stmt_name, query, timeout)
+        except exceptions.DuplicatePreparedStatementError:
+            statement = await self._protocol.prepare('', query, timeout)
+
         ready = statement._init_types()
         if ready is not True:
             types, intro_stmt = await self.__execute(
@@ -1230,7 +1234,7 @@ class Connection(metaclass=ConnectionMeta):
                     after = time.monotonic()
                     timeout -= after - before
 
-        except exceptions.InvalidCachedStatementError:
+        except (exceptions.InvalidCachedStatementError, exceptions.InvalidSQLStatementNameError):
             # PostgreSQL will raise an exception when it detects
             # that the result type of the query has changed from
             # when the statement was prepared.  This may happen,

This is definitely not how it should be fixed, but it eventually helps to avoid bug in all the asyncpg versions. Hope it helps.

[elprans]

Hm, there's a bug in your repro script. asyncio.wait is a coroutine, so it should be await-ed. What you are doing is "unpacking" the coroutine object, which iterates it (incorrectly). Your script actually crashes for me with:

Traceback (most recent call last):
  File ".local/test_bug121.py", line 68, in <module>
    asyncio.get_event_loop().run_until_complete(main())
  File "/home/elvis/dev/venvs/asyncpg/lib64/python3.6/asyncio/base_events.py", line 467, in run_until_complete
    return future.result()
  File "/home/elvis/dev/venvs/asyncpg/lib64/python3.6/asyncio/futures.py", line 245, in result
    raise self._exception
  File "/home/elvis/dev/venvs/asyncpg/lib64/python3.6/asyncio/tasks.py", line 180, in _step
    result = coro.send(None)
  File ".local/test_bug121.py", line 21, in main
    ], return_when=asyncio.FIRST_EXCEPTION)
  File "/home/elvis/dev/venvs/asyncpg/lib64/python3.6/asyncio/tasks.py", line 314, in wait
    return (yield from _wait(fs, timeout, return_when, loop))
  File "/home/elvis/dev/venvs/asyncpg/lib64/python3.6/asyncio/tasks.py", line 397, in _wait
    yield from waiter
  File "/home/elvis/dev/venvs/asyncpg/lib64/python3.6/asyncio/futures.py", line 333, in __iter__
    assert self.done(), "yield from wasn't used with future"
AssertionError: yield from wasn't used with future

When doing the right thing (await-ing on asyncio.wait), I could not reproduce the issue. How long should it run?

[elprans]

I can't reproduce with your 0.12 repro script on 0.12 either. I'm beginning to think that there is something in your environment that triggers this. Maybe it's a platform issue. Are you able to reproduce this on a Linux host? On a local Postgres instance?

[kxepal]

@elprans
Yeah, I copy-pasted wrong version. There should be await asyncio.wait certainly. Fixed. Sorry for that!

I could not reproduce the issue. How long should it run?

It took about three-five minutes for me to trigger it for v0.13 and almost 5-10 seconds for the rest ones.

I'm beginning to think that there is something in your environment that triggers this. Maybe it's a platform issue.

I tend to think so as well. I'd updates the top post about pgbounces presence - we actually has it. There is a bit problem with whole setup since I don't control PostgreSQL service - it provided as SaaS. Do you know what questions I could ask service admins to gain useful information for debug process?

However, there are no any issues with our setup with aiopg or psycopg2.

Are you able to reproduce this on a Linux host?

Yes. And it takes a few moments to catch that issue. On FreeBSD it takes awhile.

On a local Postgres instance?

Definitelly not reproduced.

[elprans]

FWIW, I could not reproduce this in a FreeBSD 10.4-STABLE VM with either script. (stock python3.6 and postgresql96-server).

[elprans]

Which SaaS are you using? Are you able to provide access to a test database instance? If so, please send the details to elvis@magic.io

[elprans]

Also, if there is indeed pgbouncer involved, you cannot use the statement cache at all, since pgbouncer does not support prepared statements. Disable it by passing statement_cache_size=0 to connect() and create_pool().

[elprans]

Also, see https://pgbouncer.github.io/faq.html#how-to-use-prepared-statements-with-session-pooling

[kxepal]

Which SaaS are you using? Are you able to provide access to a test database instance?

It's not public, but internal service. It's administrated by different team and provided for the rest company as SaaS. Sorry, I should be more specific on this SaaS term. From docs it should be like this one:

PostgreSQL - 9.6
pgBouncer - 1.7.2

Providing access much likely will be not possible or be extremely complicated task.

Disable it by passing statement_cache_size=0 to connect() and create_pool().

We followed that advice from #76 issue, but it has limited effect on this issue so I threw it away. I rerun first script with disabled cache and it failed with different error now:

Traceback (most recent call last):
  File "asyncpg-test.py", line 60, in <module>
    asyncio.get_event_loop().run_until_complete(main())
  File "/usr/lib64/python3.6/asyncio/base_events.py", line 466, in run_until_complete
    return future.result()
  File "asyncpg-test.py", line 34, in main
    raise task.exception()
  File "asyncpg-test.py", line 56, in writer
    uuid.uuid4().hex, random.randint(0, 15))
  File "/home/a.shorin/tmp/asyncpg/asyncpg/connection.py", line 240, in execute
    _, status, _ = await self._execute(query, args, 0, timeout, True)
  File "/home/a.shorin/tmp/asyncpg/asyncpg/connection.py", line 1195, in _execute
    query, args, limit, timeout, return_status=return_status)
  File "/home/a.shorin/tmp/asyncpg/asyncpg/connection.py", line 1203, in __execute
    return await self._do_execute(query, executor, timeout)
  File "/home/a.shorin/tmp/asyncpg/asyncpg/connection.py", line 1225, in _do_execute
    result = await executor(stmt, None)
  File "asyncpg/protocol/protocol.pyx", line 200, in bind_execute
    return await waiter
asyncpg.exceptions.InvalidSQLStatementNameError: unnamed prepared statement does not exist

[kxepal]

Also, see https://pgbouncer.github.io/faq.html#how-to-use-prepared-statements-with-session-pooling

Thanks! I modified create pool in following way:

async def reset_prepared_statements(conn):
    await conn.execute('DISCARD ALL')


async def main(host='...',
               port=...,
               username='...',
               password='...',
               database='...'):
    pool = await asyncpg.create_pool(
        host=host,
        port=port,
        user=username,
        password=password,
        database=database,
        statement_cache_size=0,
        setup=reset_prepared_statements
    )

But seems it doesn't helps no matter if it discard or deallocate. That was naive attempt in hope that it may help.

I also noticed that sometimes it takes dozen minutes to catch the failure while sometimes, rarely, it fails instantly for few times. What could provocate such behaviour? Server-side misconfiguration?

[elprans]

Right, the statement_cache_size workaround is actually incorrect, since any "Extended Query" flow, which is any query with parameters will break. Disabling the statement cache simply has asyncpg using anonymous prepared statements.

I stand firm in my opinion that pgbouncer in "transaction" or "statement" pool_mode is broken. Your options at this point is either switch pgbouncer pool_mode to session, or keep using your hack.

I will add a relevant advice to the docs and the FAQ.

[kxepal]

The pool_mode is transaction indeed. So, it seems there is nothing to do from user side?

[elprans]

I'm not aware of a clean way to handle this, unfortunately. You should continue to roll your hack for now. Also, you probably need to patch Connection._get_unique_id() to use a counter that is globally unique to avoid the risk of pgbouncer switching you to the session that has a completely different statement under that id.

[elprans]

I would also open a pgbouncer bug. Basically, pgbouncer must make a session "sticky" as soon as it sees a Prepare message (or anything else that is session-specific).

[1st1]

Also, you probably need to patch Connection._get_unique_id() to use a counter that is globally unique to avoid the risk of pgbouncer switching you to the session that has a completely different statement under that id.

We actually should do this regardless of this bug. I'll make a PR.

[elprans]

Incidentally: pgbouncer/pgbouncer#242

[kxepal]

We changed pool_mode to session and the issue is solved for us. No more hacks! Thanks a lot @elprans for help!

[elprans]

Great! Closing.