connection_timeouts_total counts asyncpg statement timeouts and misses connect timeouts #55

Versions: sqlalchemy-foundation-kit 0.4.0 (same code on master, adcd645), SQLAlchemy 2.0.54, asyncpg 0.31.0, prometheus-client 0.26.0, Python 3.13.12, PostgreSQL 17

Follow-up to #26. That issue added the pool checkout timeout to postgres_db_connection_timeouts_total and left the handle_error path unchanged. As a result, the counter now mixes two kinds of events and leaves out a third that belongs in it:

• Counted, though it is not a connection timeout: asyncpg's command_timeout firing on a statement that is already running. on_error marks any TimeoutError that reaches handle_error as a timeout (session/manager.py:171-179), and record_error increments the counter (contrib/metrics/postgres.py:166-174).
• Not counted anywhere: a connect timeout while the pool opens a new connection. asyncpg raises a builtin TimeoutError from connect(). That is not a DBAPI error, so handle_error never sees it, and InstrumentedPool.connect catches only sqlalchemy.exc.TimeoutError (session/manager.py:93-110). This checkout records neither a timeout, nor an error, nor its wait.

The table rows document the first half: docs/guide/advanced.md:278 says "Pool checkout timeouts, and TimeoutErrors during execution", and docs/agents.md:345 agrees. Everything else that reads the counter treats it as pool exhaustion. The Prometheus HELP is "Number of connection checkout timeouts" (contrib/metrics/postgres.py:120). The PromQL panel is titled "Checkouts that gave up waiting" (docs/guide/advanced.md:343-344). docs/guide/configuration.md:563-566 and docs/agents.md:438-439 describe it as what the checkout wait turns into at pool_timeout. An alert built from those will fire on a slow query and stay silent while the database cannot be reached.

Reproduction

import asyncio

from prometheus_client import REGISTRY
from sqlalchemy import text
from sqlalchemy_foundation_kit import AsyncSessionManager
from sqlalchemy_foundation_kit.contrib.metrics import PostgresMetrics
from sqlalchemy_foundation_kit.contrib.settings import PoolSettings
from testcontainers.postgres import PostgresContainer


def report(prefix: str) -> None:
    def sample(name: str, **labels: str) -> float:
        return REGISTRY.get_sample_value(f"{prefix}_postgres_db_{name}", labels) or 0.0

    print(f"   connection_timeouts_total            = {sample('connection_timeouts_total')}")
    print(f"   connection_errors_total (all labels) = "
          f"{sum(s.value for m in REGISTRY.collect() if m.name == f'{prefix}_postgres_db_connection_errors' for s in m.samples if s.name.endswith('_total'))}")
    print(f"   connection_checkout_wait_seconds_count = {sample('connection_checkout_wait_seconds_count')}")


async def run(prefix: str, url: str, connect_args: dict, statement: str) -> None:
    manager = AsyncSessionManager(
        url,
        poolclass="async_adapted_queue",
        pool_settings=PoolSettings(size=2, max_overflow=0, timeout=5.0, pre_ping=False),
        connect_args=connect_args,
        metrics=PostgresMetrics(prefix=prefix),
    )
    try:  # one caller, a pool of two: the pool itself never times out here
        async with manager.get_session() as session:
            await session.execute(text(statement))
    except Exception as exc:
        print(f"   raised: {type(exc).__module__}.{type(exc).__name__}")
    report(prefix)
    await manager.aclose()


async def main(url: str) -> None:
    print("1. asyncpg command_timeout=0.1 hits a running statement (the connection was established fine)")
    await run("stmt", url, {"command_timeout": 0.1}, "SELECT pg_sleep(1)")
    print("2. asyncpg connect timeout=0.5 while the pool opens a connection (unroutable address)")
    await run("conn", "postgresql+asyncpg://u:p@10.255.255.1:5432/db", {"timeout": 0.5}, "SELECT 1")
    help_text = next(m for m in REGISTRY.collect() if m.name == "stmt_postgres_db_connection_timeouts").documentation
    print(f"HELP connection_timeouts_total: {help_text}")


with PostgresContainer("postgres:17-alpine", driver="asyncpg") as pg:
    asyncio.run(main(pg.get_connection_url()))

Actual

1. asyncpg command_timeout=0.1 hits a running statement (the connection was established fine)
   raised: builtins.TimeoutError
   connection_timeouts_total            = 1.0
   connection_errors_total (all labels) = 1.0
   connection_checkout_wait_seconds_count = 1.0
2. asyncpg connect timeout=0.5 while the pool opens a connection (unroutable address)
   raised: builtins.TimeoutError
   connection_timeouts_total            = 0.0
   connection_errors_total (all labels) = 0
   connection_checkout_wait_seconds_count = 0.0
HELP connection_timeouts_total: Number of connection checkout timeouts

In case 1 the connection was healthy and the pool never waited, yet the counter moved. In case 2 the caller waited 0.5 s for a connection that never arrived, and no series moved at all.

Why

• A handle_error listener sees only errors raised on an established connection. In case 1 it gets original_exception=TimeoutError, connection set and statement='SELECT pg_sleep(1)'. In case 2 it is never called: SQLAlchemy dispatches handle_error on connect only for dbapi.Error, and asyncpg's connect timeout is a builtin TimeoutError that the asyncpg dialect does not translate. A pool sqlalchemy.exc.TimeoutError never reaches it either (Pool metrics: the timeout counter never counts pool checkout timeouts, and the checkout histogram measures held time, not wait #26). So the is_timeout branch in on_error can only ever count statement timeouts.
• InstrumentedPool.connect (session/manager.py:96-105) records the wait only on success or on SATimeoutError. Any other exception from super().connect() skips record_checkout_wait, and that includes a connect timeout, which is a connection timeout by any reading.

Proposal

• Stop incrementing connection_timeouts_total from on_error. Statement timeouts are already counted in connection_errors_total{error_type="TimeoutError"}. If they deserve their own series, give it a name that says so, e.g. postgres_db_statement_timeouts_total.
• In InstrumentedPool.connect, treat a builtin TimeoutError like the pool timeout: record the wait with timed_out=True. For any other exception, record the wait and an error, e.g. record_error(error_type=type(exc).__name__), so that a database refusing connections shows up in connection_errors_total.
• Make the HELP text and the two docs table rows say "pool checkout timeouts and connect timeouts", which also makes the "Checkouts that gave up waiting" panel accurate.