From 05d525b5b3a95a8a16733d73fbe214de2ed641fc Mon Sep 17 00:00:00 2001 From: Alexey Shalaev <75322386+AlexeyShalaev@users.noreply.github.com> Date: Fri, 16 Oct 2026 18:52:00 +0400 Subject: [PATCH] fix: stop logging a failed flush's parameters and row values --- docs/agents.md | 7 ++-- docs/guide/advanced.md | 25 ++++++++++++++ sqlalchemy_foundation_kit/uow/sqlalchemy.py | 23 ++++++------- tests/integration/test_uow_integration.py | 36 +++++++++++++++++++++ tests/unit/uow/test_sqlalchemy.py | 14 ++++---- 5 files changed, 83 insertions(+), 22 deletions(-) diff --git a/docs/agents.md b/docs/agents.md index 88101a3..ab18448 100644 --- a/docs/agents.md +++ b/docs/agents.md @@ -240,8 +240,10 @@ a wait histogram that never moves. `open_session` is the documented extension point: override it in a subclass to set a GUC, an RLS context or a statement timeout on every session, calling `super().open_session(...)` inside. `flush_before_commit=None` on `transaction()` falls back to the constructor value -(`True`), which flushes before the commit so an integrity error surfaces inside the block -rather than at exit. An `isolation_level` argument takes an `IsolationLevel` or a string +(`True`), which flushes explicitly before the commit. The commit flushes too, so either way +an integrity error raises as the block exits, through the same rollback, and reaches the +caller unchanged; the library does not log it, because its message carries parameters and +PostgreSQL's `DETAIL` row values. An `isolation_level` argument takes an `IsolationLevel` or a string in either spelling, and is set on the connection the block checks out, so it covers this transaction and leaves the engine alone. Setting it has to happen before the transaction starts, so it opens the transaction as the block is entered — `query()` included. @@ -473,6 +475,7 @@ is what to do on the version the row names. | `postgres_db_connection_timeouts_total` (0.3.0 and earlier) | stayed at zero through every pool checkout timeout. The counter was fed only from the engine's `handle_error` listener, and a pool `TimeoutError` is raised by `pool.connect()` before any DBAPI call, so it never reaches that listener — the one timeout a pool actually produces under load was the one the counter did not count | count `sqlalchemy.exc.TimeoutError` around your own session calls | | `postgres_db_pool_overflow`, `postgres_db_pool_checked_out` (0.4.0 and earlier) | sampled from the `checkout` / `checkin` events: `overflow` exported `QueuePool.overflow()`, which starts at `-pool_size` (`-9` with one connection open of 10), and since `checkin` fires before the connection is back, an idle pool kept reporting its last burst as checked out | read `pool.checkedout()` and `max(pool.overflow(), 0)` yourself | | `postgres_db_connection_timeouts_total` (0.4.0) | counted asyncpg statement timeouts — a slow query, on a healthy connection — and missed connect timeouts, which never reach `handle_error`. A database refusing connections moved no series at all | alert on `connection_errors_total{error_type="TimeoutError"}` for slow statements, and on the checkout wait for connections | +| `uow.transaction()` with a failing flush (0.4.0 and earlier, `flush_before_commit=True`, the default) | logged `str(exc)` at WARNING as `extra={"error": ...}` before re-raising: the statement's parameters and PostgreSQL's `DETAIL: Key (...)=(...)` row values went to the logs, and `hide_parameters=True` removed only the parameters | `flush_before_commit=False`; the same exception still reaches the caller | | `postgres_db_connection_checkout_duration_seconds` (0.3.0 and earlier) | the only checkout histogram there was, and it measures the time between the `checkout` and `checkin` events — how long a connection was *held*, which is query duration seen from the pool. The time a caller waited for a connection, which is what the name suggests and what predicts a pool outage, was not exposed at all | none; the wait was not measurable from outside the pool | `IsolationLevel` itself was always fine — `READ_UNCOMMITTED`, `READ_COMMITTED`, diff --git a/docs/guide/advanced.md b/docs/guide/advanced.md index 3c4e738..e6f8c36 100644 --- a/docs/guide/advanced.md +++ b/docs/guide/advanced.md @@ -52,6 +52,31 @@ async with uow.transaction() as tx: # Auto-rollback on exception ``` +**A failed commit is the caller's to log.** When the flush or the commit fails, the +transaction is rolled back and the exception reaches the caller unchanged. The library +does not log it: the message of an `IntegrityError` holds the statement's parameters and +PostgreSQL's `DETAIL: Key (email)=(...)` line, which are row values. Log what you need +where you handle it, at a level you choose: + +```python +from sqlalchemy.exc import IntegrityError + +try: + async with uow.transaction() as tx: + await tx.users.create(email=email) +except IntegrityError as exc: + cause = exc.orig.__cause__ # the asyncpg exception + logger.warning( + "user insert rejected", + extra={"sqlstate": exc.orig.sqlstate, "constraint": getattr(cause, "constraint_name", None)}, + ) + raise +``` + +`str(exc)` has the full text, DETAIL and parameters included, when you are debugging +locally. `create_async_engine(..., hide_parameters=True)` removes the parameters from it, +not the DETAIL line. + ### Isolation Levels Control transaction isolation for consistency vs. performance tradeoffs: diff --git a/sqlalchemy_foundation_kit/uow/sqlalchemy.py b/sqlalchemy_foundation_kit/uow/sqlalchemy.py index 0d16718..06957c8 100644 --- a/sqlalchemy_foundation_kit/uow/sqlalchemy.py +++ b/sqlalchemy_foundation_kit/uow/sqlalchemy.py @@ -3,12 +3,10 @@ from __future__ import annotations import asyncio -import logging from collections.abc import AsyncIterator, Callable from contextlib import asynccontextmanager from typing import Generic -from sqlalchemy.exc import SQLAlchemyError from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker from .._typing import T @@ -16,8 +14,6 @@ from .enums import IsolationLevel from .protocols import AsyncUnitOfWork, AsyncUowTransaction -logger = logging.getLogger(__name__) - # Cache valid isolation levels for performance (avoid recreating set on each call) _VALID_ISOLATION_LEVELS: frozenset[str] = frozenset(item.value for item in IsolationLevel) @@ -314,9 +310,11 @@ async def transaction( isolation_level: Optional transaction isolation level. Can be an IsolationLevel enum member or a string value. Supported values: "READ_COMMITTED", "REPEATABLE_READ", "SERIALIZABLE", "READ_UNCOMMITTED". - flush_before_commit: If True, flush the session before commit to surface - constraint violations while still inside the transaction. If ``None`` (default), - falls back to the value passed to the constructor (``True`` unless overridden). + flush_before_commit: If True, flush the session explicitly before the commit. + The commit flushes as well, so a constraint violation raises the same + exception through the same rollback either way, as the block exits. If + ``None`` (default), falls back to the value passed to the constructor + (``True`` unless overridden). Raises: ValueError: If isolation_level is not supported. @@ -334,13 +332,10 @@ async def transaction( uow = self._transaction_factory(session) yield uow if flush_before_commit: - # Flush changes before commit to catch constraint violations early - # while still inside the transaction context. - try: - await session.flush() - except SQLAlchemyError as e: - logger.warning("Database flush failed", extra={"error": str(e)}) - raise + # A failure propagates to the caller as is, and is not logged here: its + # message carries the statement's parameters and PostgreSQL's DETAIL line, + # which holds the conflicting row's values. + await session.flush() @asynccontextmanager async def managed_session( diff --git a/tests/integration/test_uow_integration.py b/tests/integration/test_uow_integration.py index abbfe6c..d06f7f1 100644 --- a/tests/integration/test_uow_integration.py +++ b/tests/integration/test_uow_integration.py @@ -2,6 +2,8 @@ from __future__ import annotations +import logging + import pytest from sqlalchemy import func, select, text from sqlalchemy.exc import DBAPIError, IntegrityError @@ -386,3 +388,37 @@ async def test__managed_session__search_path__reapplied_after_the_caller_commits assert before == SEARCH_PATH_SCHEMA assert after == SEARCH_PATH_SCHEMA assert count == 1 + + +# ============================================================================ +# Failed Flush Logging Tests (issue #57 scenario) +# ============================================================================ + + +@pytest.mark.integration +@pytest.mark.asyncio +@pytest.mark.parametrize("flush_before_commit", [True, False]) +async def test__transaction__failed_flush__row_values_reach_the_caller_and_no_log( + async_session_factory: async_sessionmaker[AsyncSession], + caplog: pytest.LogCaptureFixture, + flush_before_commit: bool, +) -> None: + # Arrange: the reporter's duplicate email, on the default flush_before_commit=True path too + uow = AsyncSQLAlchemyUnitOfWork(async_session_factory, transaction_factory=AsyncSQLAlchemyUowTransaction) + email = "jane.doe@example.org" + async with uow.transaction() as tx: + tx.session.add(TestUser(name="Jane", email=email, age=30)) + + # Act + with caplog.at_level(logging.DEBUG, logger="sqlalchemy_foundation_kit"): + with pytest.raises(IntegrityError) as raised: + async with uow.transaction(flush_before_commit=flush_before_commit) as tx: + tx.session.add(TestUser(name="Jane again", email=email, age=31)) + + # Assert: the caller has everything needed to debug it... + assert raised.value.orig is not None + assert getattr(raised.value.orig, "sqlstate", None) == "23505" + assert getattr(raised.value.orig.__cause__, "constraint_name", None) == "test_users_email_key" + assert email in str(raised.value) + # ...and the library wrote none of it to the logs, at any level + assert [r for r in caplog.records if r.name.startswith("sqlalchemy_foundation_kit")] == [] diff --git a/tests/unit/uow/test_sqlalchemy.py b/tests/unit/uow/test_sqlalchemy.py index 9feba1d..d75870b 100644 --- a/tests/unit/uow/test_sqlalchemy.py +++ b/tests/unit/uow/test_sqlalchemy.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging from unittest.mock import AsyncMock, Mock, patch import pytest @@ -520,14 +521,14 @@ async def test__transaction__flush_override__overrides_default() -> None: @pytest.mark.asyncio -async def test__transaction__flush_error__logs_warning_and_raises() -> None: - # Arrange +async def test__transaction__flush_error__raises_without_logging(caplog: pytest.LogCaptureFixture) -> None: + # Arrange: a flush error's message carries parameters and PostgreSQL's DETAIL row values mock_session = AsyncMock(spec=AsyncSession) mock_session.__aenter__ = AsyncMock(return_value=mock_session) mock_session.__aexit__ = AsyncMock(return_value=None) mock_session.begin = AsyncMock() mock_session.in_transaction = Mock(return_value=False) - mock_session.flush = AsyncMock(side_effect=SQLAlchemyError("Flush error")) + mock_session.flush = AsyncMock(side_effect=SQLAlchemyError("Key (email)=(jane.doe@example.org) already exists")) mock_transaction = Mock() mock_session_maker = Mock(return_value=mock_session) @@ -536,12 +537,13 @@ async def test__transaction__flush_error__logs_warning_and_raises() -> None: uow = AsyncSQLAlchemyUnitOfWork(mock_session_maker, mock_factory) # Act & Assert - with patch("sqlalchemy_foundation_kit.uow.sqlalchemy.logger") as mock_logger: - with pytest.raises(SQLAlchemyError): + with caplog.at_level(logging.DEBUG, logger="sqlalchemy_foundation_kit"): + with pytest.raises(SQLAlchemyError, match=r"jane\.doe@example\.org"): async with uow.transaction(): pass - mock_logger.warning.assert_called_once() + assert caplog.records == [] + mock_session.rollback.assert_awaited_once() @pytest.mark.asyncio