TimeoutError while using PostgreSQL 12+

还没有人认领这个 Issue。

* **asyncpg version**: 0.25
* **PostgreSQL version**: 12+
* **Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
the issue with a local PostgreSQL install?**: I use postgres service in CI: https://docs.gitlab.com/ee/ci/services/. I can't reproduce it local (docker)
* **Python version**: 3.9.5
* **Platform**: CI
* **Do you use pgbouncer?**: no
* **Did you install asyncpg with pip?**: Yes, but no - poetry
* **If you built asyncpg locally, which version of Cython did you use?**:
* **Can the issue be reproduced under both asyncio and
[uvloop](https://github.com/magicstack/uvloop)?**: I have not tried running tests without uvloop

Hello. When I run my tests in CI on the kubernetes runner I get an `asyncio.exceptions.TimeoutError`.

Traceback

```python
Traceback (most recent call last):
File "/service/src/app/system/middlewares.py", line 109, in _errors_middleware
return await handler(request)
File "/service/src/app/system/middlewares.py", line 53, in decorator
return await metrics_func(request, handler)
File "/service/src/app/system/middlewares.py", line 145, in _tracing_middleware
return await handler(request)
File "/service/src/app/system/middlewares.py", line 40, in decorator
return await metrics_func(request, handler)
File "/service/src/app/system/middlewares.py", line 162, in _context_middleware
return await handler(request)
File "/service/src/app/system/middlewares.py", line 40, in decorator
return await metrics_func(request, handler)
File "/service/src/app/system/middlewares.py", line 170, in _not_found_middleware
return await handler(request)
File "/service/src/app/system/middlewares.py", line 40, in decorator
return await metrics_func(request, handler)
File "/usr/local/lib/python3.9/site-packages/aiohttp_jwt/middleware.py", line 43, in jwt_middleware
return await handler(request)
File "/service/src/app/api/blacklist/handler.py", line 52, in post
await insert_document(
File "/service/src/app/external/postgres/bad_documents.py", line 34, in insert_document
return await db.pool.fetch(
File "/usr/local/lib/python3.9/site-packages/asyncpg/pool.py", line 554, in fetch
return await con.fetch(query, *args, timeout=timeout)
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 583, in fetch
return await self._execute(
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 1625, in _execute
result, _ = await self.__execute(
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 1650, in __execute
return await self._do_execute(
File "/usr/local/lib/python3.9/site-packages/mdw_asyncpg/engine.py", line 110, in _do_execute
return await self._traced_query(
File "/usr/local/lib/python3.9/site-packages/mdw_asyncpg/engine.py", line 97, in _traced_query
return await func(query, *args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 1685, in _do_execute
stmt = await self._get_statement(
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 390, in _get_statement
types, intro_stmt = await self._introspect_types(
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 436, in _introspect_types
return await self.__execute(
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 1650, in __execute
return await self._do_execute(
File "/usr/local/lib/python3.9/site-packages/mdw_asyncpg/engine.py", line 110, in _do_execute
return await self._traced_query(
File "/usr/local/lib/python3.9/site-packages/mdw_asyncpg/engine.py", line 97, in _traced_query
return await func(query, *args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/asyncpg/connection.py", line 1700, in _do_execute
result = await executor(stmt, timeout)
File "asyncpg/protocol/protocol.pyx", line 199, in bind_execute
asyncio.exceptions.TimeoutError
```

Method for inserting a document into the black list:
```python
async def insert_document(
db: PostgresEngine,
number: str,
serial: str,
reason: str,
comment: str = '',
operator_id: str = '',
timeout=2,
) -> List[Record]:
"""Add document to blacklist."""
sql_template = """
INSERT INTO blacklist.documents
("number", "serial", "reason", "comment", "operator_id")
VALUES ($1, $2, $3, $4, $5)
ON CONFLICT DO NOTHING
RETURNING "number", "serial", "created_time"
"""
return await db.pool.fetch(
sql_template,
number,
prepare_serial(serial),
reason.name,
comment,
operator_id,
timeout=timeout,
)
```

Kubernetes runner log

```markdown
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".

Data page checksums are disabled.

fixing permissions on existing directory /var/lib/postgresql/data ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Etc/UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
syncing data to disk ... ok
initdb: warning: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.

Success. You can now start the database server using:

pg_ctl -D /var/lib/postgresql/data -l logfile start

waiting for server to start....2022-04-27 02:35:37.408 UTC [50] LOG: starting PostgreSQL 12.9 (Debian 12.9-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-04-27 02:35:37.409 UTC [50] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-04-27 02:35:37.424 UTC [51] LOG: database system was shut down at 2022-04-27 02:35:37 UTC
2022-04-27 02:35:37.428 UTC [50] LOG: database system is ready to accept connections
done
server started
CREATE DATABASE

/usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*

2022-04-27 02:35:37.841 UTC [50] LOG: received fast shutdown request
waiting for server to shut down....2022-04-27 02:35:37.842 UTC [50] LOG: aborting any active transactions
2022-04-27 02:35:37.893 UTC [50] LOG: background worker "logical replication launcher" (PID 57) exited with exit code 1
2022-04-27 02:35:37.893 UTC [52] LOG: shutting down
2022-04-27 02:35:37.935 UTC [50] LOG: database system is shut down
done
server stopped

PostgreSQL init process complete; ready for start up.

2022-04-27 02:35:37.962 UTC [1] LOG: starting PostgreSQL 12.9 (Debian 12.9-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-04-27 02:35:37.962 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
2022-04-27 02:35:37.962 UTC [1] LOG: listening on IPv6 address "::", port 5432
2022-04-27 02:35:37.966 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-04-27 02:35:37.983 UTC [78] LOG: database system was shut down at 2022-04-27 02:35:37 UTC
2022-04-27 02:35:37.989 UTC [1] LOG: database system is ready to accept connections
2022-04-27 02:36:14.734 UTC [91] ERROR: canceling statement due to user request
2022-04-27 02:36:14.734 UTC [91] STATEMENT: WITH RECURSIVE typeinfo_tree(
oid, ns, name, kind, basetype, elemtype, elemdelim,
range_subtype, attrtypoids, attrnames, depth)
AS (
SELECT
ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
ti.elemtype, ti.elemdelim, ti.range_subtype,
ti.attrtypoids, ti.attrnames, 0
FROM
(
SELECT
t.oid AS oid,
ns.nspname AS ns,
t.typname AS name,
t.typtype AS kind,
(CASE WHEN t.typtype = 'd' THEN
(WITH RECURSIVE typebases(oid, depth) AS (
SELECT
t2.typbasetype AS oid,
0 AS depth
FROM
pg_type t2
WHERE
t2.oid = t.oid

UNION ALL

SELECT
t2.typbasetype AS oid,
tb.depth + 1 AS depth
FROM
pg_type t2,
typebases tb
WHERE
tb.oid = t2.oid
AND t2.typbasetype != 0
) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)

ELSE NULL
END) AS basetype,
t.typelem AS elemtype,
elem_t.typdelim AS elemdelim,
range_t.rngsubtype AS range_subtype,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.atttypid ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)

ELSE NULL
END) AS attrtypoids,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.attname::text ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)

ELSE NULL
END) AS attrnames
FROM
pg_catalog.pg_type AS t
INNER JOIN pg_catalog.pg_namespace ns ON (
ns.oid = t.typnamespace)
LEFT JOIN pg_type elem_t ON (
t.typlen = -1 AND
t.typelem != 0 AND
t.typelem = elem_t.oid
)
LEFT JOIN pg_range range_t ON (
t.oid = range_t.rngtypid
)
)
AS ti
WHERE
ti.oid = any($1::oid[])

UNION ALL

SELECT
ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
ti.elemtype, ti.elemdelim, ti.range_subtype,
ti.attrtypoids, ti.attrnames, tt.depth + 1
FROM
(
SELECT
t.oid AS oid,
ns.nspname AS ns,
t.typname AS name,
t.typtype AS kind,
(CASE WHEN t.typtype = 'd' THEN
(WITH RECURSIVE typebases(oid, depth) AS (
SELECT
t2.typbasetype AS oid,
0 AS depth
FROM
pg_type t2
WHERE
t2.oid = t.oid

UNION ALL

SELECT
t2.typbasetype AS oid,
tb.depth + 1 AS depth
FROM
pg_type t2,
typebases tb
WHERE
tb.oid = t2.oid
AND t2.typbasetype != 0
) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)

ELSE NULL
END) AS basetype,
t.typelem AS elemtype,
elem_t.typdelim AS elemdelim,
range_t.rngsubtype AS range_subtype,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.atttypid ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)

ELSE NULL
END) AS attrtypoids,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.attname::text ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)

ELSE NULL
END) AS attrnames
FROM
pg_catalog.pg_type AS t
INNER JOIN pg_catalog.pg_namespace ns ON (
ns.oid = t.typnamespace)
LEFT JOIN pg_type elem_t ON (
t.typlen = -1 AND
t.typelem != 0 AND
t.typelem = elem_t.oid
)
LEFT JOIN pg_range range_t ON (
t.oid = range_t.rngtypid
)
)
ti,
typeinfo_tree tt
WHERE
(tt.elemtype IS NOT NULL AND ti.oid = tt.elemtype)
OR (tt.attrtypoids IS NOT NULL AND ti.oid = any(tt.attrtypoids))
OR (tt.range_subtype IS NOT NULL AND ti.oid = tt.range_subtype)
)

SELECT DISTINCT
*,
basetype::regtype::text AS basetype_name,
elemtype::regtype::text AS elemtype_name,
range_subtype::regtype::text AS range_subtype_name
FROM
typeinfo_tree
ORDER BY
depth DESC

2022-04-27 02:36:19.394 UTC [1] LOG: received fast shutdown request
2022-04-27 02:36:19.398 UTC [1] LOG: aborting any active transactions
2022-04-27 02:36:19.400 UTC [1] LOG: background worker "logical replication launcher" (PID 84) exited with exit code 1
2022-04-27 02:36:19.401 UTC [79] LOG: shutting down
2022-04-27 02:36:19.430 UTC [1] LOG: database system is shut down
```

P.s. before tests, alembic migrations pass without errors:
```
INFO [alembic.runtime.migration] Context impl PostgresqlImpl.
INFO [alembic.runtime.migration] Will assume transactional DDL.
INFO [alembic.runtime.migration] Running upgrade -> 42b521e36eb2, base
INFO [alembic.runtime.migration] Running upgrade 42b521e36eb2 -> 49205dfbd4c8, create logs schema
INFO [alembic.runtime.migration] Running upgrade 49205dfbd4c8 -> a8fc015effac, create metric_type enum
INFO [alembic.runtime.migration] Running upgrade a8fc015effac -> 9a0dd4c02bcf, create logs.plain table
..................
```

首先，在所报告的 GitLab CI Kubernetes 设置中使用 PostgreSQL 12+、Python 3.9.5 和 asyncpg 0.25 重现超时。以提供的 insert_document 调用作为测试用例，跟踪从 asyncpg/connection.py 经由 _introspect_types 和 protocol.pyx bind_execute 的路径。完成的标准是确定一个可重现的原因，并记录或测试一个已确认的修复；该报告目前没有提供 repository 测试文件。

由索引模型根据 Issue 内容生成。