AttributeError: 'NoneType' object has no attribute 'cancelled'

[danigosa]

• asyncpg version: 0.14.0
• PostgreSQL version: 9.6.6
• Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
  the issue with a local PostgreSQL install?: I can't reproduce
• Python version: 3.6.4
• Platform: Alpine Linux
• Do you use pgbouncer?: Yes
• Did you install asyncpg with pip?: Yes
• If you built asyncpg locally, which version of Cython did you use?: 0.27.3
• Can the issue be reproduced under both asyncio and
  uvloop?: No

Same query sometimes breaks with this, meaning the exact query other times works flawlessly, any ideas?

[06:06:23][ERROR] robbie.http.microservice.middleware.errors api.py:__call__:242 | ("Non SQL error happened: 'NoneType' object has no attribute 'cancelled'", AttributeError("'NoneType' object has no attribute 'cancelled'",))
Traceback (most recent call last):
  File "robbie/sql/postgresql/utils.py", line 119, in robbie.sql.postgresql.utils.sql_exceptions_handler.wrapper
  File "robbie/sql/postgresql/client.py", line 119, in fetch
  File "/usr/local/lib/python3.6/site-packages/asyncpg/pool.py", line 405, in fetch
    return await con.fetch(query, *args, timeout=timeout)
  File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 345, in fetch
    return await self._execute(query, args, 0, timeout)
  File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 1289, in _execute
    query, args, limit, timeout, return_status=return_status)
  File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 1297, in __execute
    return await self._do_execute(query, executor, timeout)
  File "/usr/local/lib/python3.6/site-packages/asyncpg/connection.py", line 1312, in _do_execute
    stmt = await self._get_statement(query, timeout)
  File "/usr/local/lib/python3.6/site-packages/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
  File "asyncpg/protocol/coreproto.pyx", line 122, in asyncpg.protocol.protocol.CoreProtocol._read_server_messages
  File "asyncpg/protocol/coreproto.pyx", line 625, in asyncpg.protocol.protocol.CoreProtocol._push_result
  File "asyncpg/protocol/protocol.pyx", line 818, in asyncpg.protocol.protocol.BaseProtocol._on_result
  File "asyncpg/protocol/protocol.pyx", line 745, in asyncpg.protocol.protocol.BaseProtocol._dispatch_result
AttributeError: 'NoneType' object has no attribute 'cancelled'

[elprans]

Seems like a race. My best guess would be that connection_lost is somehow called before the results of the last query are dispatched to the waiting query future.

[danigosa]

Hi @elprans again it occurs when HA clusters are deployed, meaning single-instance and/or non-proxied connections seems to be stable. This is then expected behavior? This is hurting us because we have special treatment of all connection related exceptions and issues, but obviously not for AttributeError which could mask our own development errors.

[elprans]

No, this is definitely a bug. Until we find a good way to reproduce, and if it really bothers you, you can try adding if waiter is None or to this check:

asyncpg/asyncpg/protocol/protocol.pyx

Line 745 in 8cec66f

if waiter.cancelled():

[hyzyla]

@elprans, I also have a similar issue

     await insert_products_mappings(conn, products_maps)
   File "/usr/local/lib/python3.7/site-packages/asyncpg/transaction.py", line 89, in __aexit__
     await self.__rollback()
   File "/usr/local/lib/python3.7/site-packages/asyncpg/transaction.py", line 198, in __rollback
     await self._connection.execute(query)
   File "/usr/local/lib/python3.7/site-packages/asyncpg/connection.py", line 273, in execute
     return await self._protocol.query(query, timeout)
   File "asyncpg/protocol/protocol.pyx", line 313, in query
   File "asyncpg/protocol/protocol.pyx", line 804, in asyncpg.protocol.protocol.BaseProtocol._dispatch_result
   File "asyncpg/protocol/protocol.pyx", line 727, in asyncpg.protocol.protocol.BaseProtocol._on_result__simple_query
 AttributeError: 'NoneType' object has no attribute 'decode'

One way how to reproduce is to insert a lot of values using loop

[prostomarkeloff]

Hav

@elprans, I also have a similar issue

     await insert_products_mappings(conn, products_maps)
   File "/usr/local/lib/python3.7/site-packages/asyncpg/transaction.py", line 89, in __aexit__
     await self.__rollback()
   File "/usr/local/lib/python3.7/site-packages/asyncpg/transaction.py", line 198, in __rollback
     await self._connection.execute(query)
   File "/usr/local/lib/python3.7/site-packages/asyncpg/connection.py", line 273, in execute
     return await self._protocol.query(query, timeout)
   File "asyncpg/protocol/protocol.pyx", line 313, in query
   File "asyncpg/protocol/protocol.pyx", line 804, in asyncpg.protocol.protocol.BaseProtocol._dispatch_result
   File "asyncpg/protocol/protocol.pyx", line 727, in asyncpg.protocol.protocol.BaseProtocol._on_result__simple_query
 AttributeError: 'NoneType' object has no attribute 'decode'

One way how to reproduce is to insert a lot of values using loop

Have same issue

[dddsnn]

This issue still exists in 0.22.0, and I think I know the cause. I can reproduce it pretty consistently with this:

async def writer(bs):
    print('writing')

async def main():
    async with asyncpg.create_pool(dsn) as pool, pool.acquire() as conn:
        await conn.copy_from_query(
            'SELECT generate_series(0,1000000)', output=writer)

if __name__ == '__main__':
    asyncio.run(main())

This works fine when connected to a local DB, but with a remote one it will print writing a couple of times and then fail with the exception in the OP. I've added some debugging print()s. With these, the last bit of the output is as follows:

...
received CopyData
waiting for sink
writing
sink done
received CopyData
waiting for sink
writing
sink done
received CopyData
received CopyData
waiting for sink
writing
sink done
Traceback (most recent call last):
...

What we expect to happen:

• the read loop of BaseProtocol.copy_out() sets self.waiter and awaits it for data
• we receive a CopyData message from the backend
• we eventually call _dispatch_result(), which takes self.waiter, puts the data into its result, and sets it back to None
• the read loop sends the data off to the sink and then creates a new self.waiter that will be used for the next chunk

But as you can see from the output, there are 2 messages received back to back, without the sink coroutine being executed. Consequently the read loop doesn't create a new waiter, hence the exception on the next call to _dispatch_result().

I think the problem is the assumption that, when we receive CopyData, there is a waiter on the object that was created by the read loop. That is probably based on the assumption that, after we've set the result of the waiter, the sink will be executed before the next data arrives. There's even a self.pause_reading() in _on_result__copy_out() that looks like it was made to ensure that, but obviously it doesn't always work.

I've created a pretty rough fix that makes data_received() await an event that indicates the read loop has created a new waiter if the protocol is in copy mode. That fixes the example above for me, although I haven't done any further testing.

[elprans]

Hi @dddsnn. Thanks for diagnosing the issue! I'm aware of it, as it recently popped up while testing on aarch64, and I've been looking into fixing this. This issue isn't specific to just Copy, I'm afraid, although it is easiest to get triggered by Copy. The real fix would have to be a bit more invasive.

[datafuz]

I've been getting this error recently as well.

[SantjagoCorkez]

Have stuck with the same bug (using Connection.copy_from_query()). Since I know there was no such a bug in our environment (the project just evolves in other parts that are not affecting asyncpg direct usage anyhow) I checked our appliances.

• 0.24.0 - bugged
• 0.23.0 - bugged
• 0.22.0 - bugged
• 0.20.1 - works

For those getting this bug on PGSQL COPY special methods downgrading to 0.20.x could be a workaround until this bug is fixed.

[thehesiod]

I just hit this w/ copy_from_query and it reminded me of #726 (which is an asyncio bug), so I tried w/ uvloop and that seems to fix the problem as well.

[yohanboniface]

FYI, I have the same issue (using copy_from_table) on a server running python 3.8, but not in local running python 3.9 or 3.10. And I confirm that using uvloop works around the issue.

[dada-engineer]

Any idea on this @elprans ? Occurs for me as well lately with asyncpg 0.29.0 and python 3.11.x. Also using uvloop does not fix this as suggested above.

Traceback (most recent call last):
  File "asyncpg/protocol/coreproto.pyx", line 122, in asyncpg.protocol.protocol.CoreProtocol._read_server_messages
  File "asyncpg/protocol/coreproto.pyx", line 729, in asyncpg.protocol.protocol.CoreProtocol._push_result
  File "asyncpg/protocol/protocol.pyx", line 927, in asyncpg.protocol.protocol.BaseProtocol._on_result
  File "asyncpg/protocol/protocol.pyx", line 849, in asyncpg.protocol.protocol.BaseProtocol._dispatch_result
AttributeError: 'NoneType' object has no attribute 'cancelled'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "uvloop/sslproto.pyx", line 711, in uvloop.loop.SSLProtocol._do_read
  File "uvloop/sslproto.pyx", line 791, in uvloop.loop.SSLProtocol._do_read__copied
  File "asyncpg/protocol/protocol.pyx", line 975, in asyncpg.protocol.protocol.BaseProtocol.data_received
  File "asyncpg/protocol/coreproto.pyx", line 143, in asyncpg.protocol.protocol.CoreProtocol._read_server_messages
  File "asyncpg/protocol/coreproto.pyx", line 729, in asyncpg.protocol.protocol.CoreProtocol._push_result
  File "asyncpg/protocol/protocol.pyx", line 927, in asyncpg.protocol.protocol.BaseProtocol._on_result
  File "asyncpg/protocol/protocol.pyx", line 849, in asyncpg.protocol.protocol.BaseProtocol._dispatch_result
AttributeError: 'NoneType' object has no attribute 'cancelled'

EDIT:
I am using SqlALchemy 2.0.29 and have set pool_pre_ping=True with a statement timeout configured (But running into this throws the expected Timeout error so I guess it is unrelated)