Infinite hang on leaving conn.transaction() block

[Piatachock]

Hi, I am experiencing hangs at aexit of Transaction context manager, with traceback as follows:

...
  File "/usr/local/lib/python3.7/dist-packages/asyncpg/transaction.py", line 89, in __aexit__
    await self.__rollback()
  File "/usr/local/lib/python3.7/dist-packages/asyncpg/transaction.py", line 198, in __rollback
    await self._connection.execute(query)
  File "/code/callmeback/detail/log_helpers/postgre_conn.py", line 53, in execute
    return await super(LoggingConn, self).execute(query, *args, timeout=timeout)
  File "/usr/local/lib/python3.7/dist-packages/asyncpg/connection.py", line 273, in execute
    return await self._protocol.query(query, timeout)

Default command timeout is set for connection:

>>> conn = frame.f_locals['self']
>>> conn._config
ConnectionConfiguration(command_timeout=10.0, statement_cache_size=100, max_cached_statement_lifetime=300, max_cacheable_statement_size=15360)
>>> conn._protocol._get_timeout(None)
10.0

So I expect self._protocol.query() to throw TimeoutError of some kind, but related coroutine hanged for three days with no progress.

I will happily provide you with any additional information, if I can. My app has aiomonitor onboard, so if any info reachable that way will help you - please let me know.

I tried to fiddle with conn._protocol, but almost nothing of its state is reachable from aioconsole since it's Cython.

My suspection is that exception that leads to rollback is coming from in-transaction query that somehow leads connection in such a state that rollback() cannot be processed normally. I will provide you with information about exception once that problem triggers next time.

• asyncpg version: 0.18.3
• PostgreSQL version: 10.7
• Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
  the issue with a local PostgreSQL install?:
• Python version: 3.7
• Platform: Ubuntu 16.04
• Do you use pgbouncer?: Yes (session-level pooling)
• Did you install asyncpg with pip?: Yes
• If you built asyncpg locally, which version of Cython did you use?: --
• Can the issue be reproduced under both asyncio and
  uvloop?: Yes, I am using uvloop

[Piatachock]

Update: original exception that forces conn.rollback() is concurrent.futures._base.TimeoutError with traceback like this:

  File "/usr/local/lib/python3.7/dist-packages/asyncpg/connection.py", line 421, in fetch
    return await self._execute(query, args, 0, timeout)
  File "/usr/local/lib/python3.7/dist-packages/asyncpg/connection.py", line 1414, in _execute
    query, args, limit, timeout, return_status=return_status)
  File "/usr/local/lib/python3.7/dist-packages/asyncpg/connection.py", line 1422, in __execute
    return await self._do_execute(query, executor, timeout)
  File "/usr/local/lib/python3.7/dist-packages/asyncpg/connection.py", line 1447, in _do_execute
    result = await executor(stmt, timeout)
  File "asyncpg/protocol/protocol.pyx", line 196, in bind_execute

While examining this stack, I've noticed that _do_execute() frame has negative timeout value, probably after _get_statement() call. So looks like successor self._protocol.bind_execute() call is raising TimeoutError right away in self._get_timeout_impl(timeout) because of negative timeout.

[elprans]

This is interesting. Does this trigger on a specific query, or randomly? I wonder why _get_statement would trigger a timeout, unless there's something seriously wrong with the connection.

[Piatachock]

This is happening in same place on same queries, yes. My app has very little amount of queries, tho, so I'm not sure if this is query-specific problem. Query itself is pretty light and planning + execution time is usually <1ms.
I can imagine some problems with connections since I sometimes see TimeoutError even without further hangs. I wans't able to dig on that problem yet, tho.

[Piatachock]

Besides _get_statement() timeout - please note that there actually was an stmt object in locals() of _do_execute() frame, altho I wasn't able to recognize if it was properly initiated or not. I looked on couple of it's method's return values like binded attribute oids and stuff like that - and there was reasonable values. But after - before was a bit bigger than timeout value

[Piatachock]

JFYI wrapping Connection object with this ugly code fixed problem for me:

    @asynccontextmanager
    async def transaction(self):
        tx = super(LoggingConn, self).transaction()
        try:
            await tx.start()
            yield tx
            await tx.commit()
        except TimeoutError as e:
            self.terminate()
            raise
        except:
            await tx.rollback()
            raise

But this code does not look good indeed, so if you will have a chance to find more stable solution, that would be wonderful.