transaction() logs a failed flush's SQL parameters and DETAIL row values at WARNING (flush_before_commit=True by default) #57

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

When the pre-commit flush in transaction() fails, the unit of work logs str(e) at WARNING before re-raising (uow/sqlalchemy.py:336-343: logger.warning("Database flush failed", extra={"error": str(e)})). For a constraint violation, that string contains the row's values twice: once in PostgreSQL's DETAIL: Key (email)=(...) line, and once in SQLAlchemy's [parameters: (...)]. A JSON or structured formatter that emits extra fields therefore writes customer data into the logs at WARNING. This happens on the default path, because flush_before_commit defaults to True (uow/sqlalchemy.py:242). create_async_engine(hide_parameters=True) removes only the parameters, not the DETAIL. The exception itself still reaches the caller, so the same failure is reported twice.

Reproduction

import asyncio
import logging

from sqlalchemy.exc import IntegrityError
from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine
from sqlalchemy.orm import DeclarativeBase, Mapped, mapped_column
from sqlalchemy_foundation_kit import AsyncSQLAlchemyUnitOfWork, AsyncSQLAlchemyUowTransaction
from testcontainers.postgres import PostgresContainer


class Base(DeclarativeBase):
    pass


class Subscriber(Base):
    __tablename__ = "subscribers"
    id: Mapped[int] = mapped_column(primary_key=True)
    email: Mapped[str] = mapped_column(unique=True)


class Recorder(logging.Handler):
    def emit(self, record: logging.LogRecord) -> None:
        print(f"   log: {record.levelname} {record.name}: {record.getMessage()}")
        print(f"        extra error = {getattr(record, 'error', None)!r}")


async def main(url: str) -> None:
    logging.getLogger("sqlalchemy_foundation_kit").addHandler(Recorder())
    for hide_parameters, flush_before_commit in ((False, True), (True, True), (False, False)):
        print(f"hide_parameters={hide_parameters}, flush_before_commit={flush_before_commit}")
        engine = create_async_engine(url, hide_parameters=hide_parameters)
        uow = AsyncSQLAlchemyUnitOfWork(async_sessionmaker(engine), AsyncSQLAlchemyUowTransaction)
        async with engine.begin() as conn:
            await conn.run_sync(Base.metadata.drop_all)
            await conn.run_sync(Base.metadata.create_all)
        async with uow.transaction() as tx:
            tx.session.add(Subscriber(email="jane.doe@example.org"))
        try:
            async with uow.transaction(flush_before_commit=flush_before_commit) as tx:
                tx.session.add(Subscriber(email="jane.doe@example.org"))
        except IntegrityError as exc:
            print(f"   raised to the caller: {type(exc).__name__} (SQLSTATE {exc.orig.sqlstate})")
        await engine.dispose()


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

Actual

hide_parameters=False, flush_before_commit=True
   log: WARNING sqlalchemy_foundation_kit.uow.sqlalchemy: Database flush failed
        extra error = '(sqlalchemy.dialects.postgresql.asyncpg.IntegrityError) <class \'asyncpg.exceptions.UniqueViolationError\'>: duplicate key value violates unique constraint "subscribers_email_key"\nDETAIL:  Key (email)=(jane.doe@example.org) already exists.\n[SQL: INSERT INTO subscribers (email) VALUES ($1::VARCHAR) RETURNING subscribers.id]\n[parameters: (\'jane.doe@example.org\',)]\n(Background on this error at: https://sqlalche.me/e/20/gkpj)'
   raised to the caller: IntegrityError (SQLSTATE 23505)
hide_parameters=True, flush_before_commit=True
   log: WARNING sqlalchemy_foundation_kit.uow.sqlalchemy: Database flush failed
        extra error = '(sqlalchemy.dialects.postgresql.asyncpg.IntegrityError) <class \'asyncpg.exceptions.UniqueViolationError\'>: duplicate key value violates unique constraint "subscribers_email_key"\nDETAIL:  Key (email)=(jane.doe@example.org) already exists.\n[SQL: INSERT INTO subscribers (email) VALUES ($1::VARCHAR) RETURNING subscribers.id]\n[SQL parameters hidden due to hide_parameters=True]\n(Background on this error at: https://sqlalche.me/e/20/gkpj)'
   raised to the caller: IntegrityError (SQLSTATE 23505)
hide_parameters=False, flush_before_commit=False
   raised to the caller: IntegrityError (SQLSTATE 23505)

With flush_before_commit=False, the caller gets the same IntegrityError and nothing is logged.

Why

• str() of a SQLAlchemy StatementError contains the statement and its parameters. asyncpg's message for a constraint violation contains PostgreSQL's DETAIL line with the conflicting key values.
• The explicit flush does not change what the caller sees. It runs after yield uow (uow/sqlalchemy.py:335-340), which means when the async with block is exiting, not inside it. _owned_transaction then rolls back and re-raises (uow/sqlalchemy.py:128-136). Without the flush, session.commit() flushes first in the same transaction and raises the same exception through the same rollback (uow/sqlalchemy.py:132-136). The only observable difference is the WARNING. docs/agents.md:230-232 says the flush makes "an integrity error surface inside the block rather than at exit", but it runs at exit either way.

Proposal

• Remove the logger.warning and let the exception speak for itself. If a log line is wanted, write it at DEBUG with only non-identifying fields, e.g. type(e).__name__, getattr(e.orig, "sqlstate", None), and the constraint name from the asyncpg exception (getattr(e.orig.__cause__, "constraint_name", None)).
• Fix the docs/agents.md:230-232 sentence. If the flush really has no other purpose, consider deprecating flush_before_commit.