Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 5 additions & 2 deletions docs/agents.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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`,
Expand Down
25 changes: 25 additions & 0 deletions docs/guide/advanced.md
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down
23 changes: 9 additions & 14 deletions sqlalchemy_foundation_kit/uow/sqlalchemy.py
Original file line number Diff line number Diff line change
Expand Up @@ -3,21 +3,17 @@
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
from ..session.locks import try_advisory_xact_lock
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)

Expand Down Expand Up @@ -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.
Expand All @@ -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(
Expand Down
36 changes: 36 additions & 0 deletions tests/integration/test_uow_integration.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@

from __future__ import annotations

import logging

import pytest
from sqlalchemy import func, select, text
from sqlalchemy.exc import DBAPIError, IntegrityError
Expand Down Expand Up @@ -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")] == []
14 changes: 8 additions & 6 deletions tests/unit/uow/test_sqlalchemy.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

from __future__ import annotations

import logging
from unittest.mock import AsyncMock, Mock, patch

import pytest
Expand Down Expand Up @@ -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)
Expand All @@ -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
Expand Down
Loading