diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 7cf8d6ad..97917f7f 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -63,7 +63,7 @@ jobs: - name: Install activerecord and testsuite run: | - pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/partition-maintenance" # NOSONAR + pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/logging-execution" # NOSONAR pip install "rhosocial-activerecord-testsuite @ git+https://github.com/rhosocial/python-activerecord-testsuite.git@release/v1.0.0.dev17" - name: Install dependencies @@ -278,7 +278,7 @@ jobs: - name: Install activerecord and testsuite run: | - pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/partition-maintenance" # NOSONAR + pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/logging-execution" # NOSONAR pip install "rhosocial-activerecord-testsuite @ git+https://github.com/rhosocial/python-activerecord-testsuite.git@release/v1.0.0.dev17" - name: Install dependencies @@ -385,7 +385,7 @@ jobs: - name: Install activerecord and testsuite run: | - pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/partition-maintenance" # NOSONAR + pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/logging-execution" # NOSONAR pip install "rhosocial-activerecord-testsuite @ git+https://github.com/rhosocial/python-activerecord-testsuite.git@release/v1.0.0.dev17" - name: Install dependencies @@ -441,16 +441,21 @@ jobs: export PYTHONPATH=src:tests python -m pytest tests/ --tb=short -n 8 --dist=loadgroup - - name: Run tests with coverage (only for postgres 18) - if: matrix.postgres-version == '18' + - name: Run tests with coverage (only for postgres 18 on Python 3.14) + if: matrix.postgres-version == '18' && matrix.python-version == '3.14' run: | export PYTHONPATH=src:tests pip install codecov - python -m pytest tests/ --tb=short -n 8 --dist=loadgroup --cov=src --cov-report=xml + python -m pytest tests/ --tb=short -n auto --dist=loadgroup --cov=src/rhosocial --cov-report=xml + + - name: Debug coverage report + if: matrix.postgres-version == '18' && matrix.python-version == '3.14' + run: | + python -m coverage report -m --include="src/rhosocial/activerecord/backend/impl/postgres/*" || true - name: Upload coverage to Codecov - if: matrix.postgres-version == '18' - uses: codecov/codecov-action@v4 + if: matrix.postgres-version == '18' && matrix.python-version == '3.14' + uses: codecov/codecov-action@v5 with: token: ${{ secrets.CODECOV_TOKEN }} files: ./coverage.xml @@ -488,7 +493,7 @@ jobs: - name: Install activerecord and testsuite run: | - pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/partition-maintenance" # NOSONAR + pip install "rhosocial-activerecord @ git+https://github.com/rhosocial/python-activerecord.git@feature/logging-execution" # NOSONAR pip install "rhosocial-activerecord-testsuite @ git+https://github.com/rhosocial/python-activerecord-testsuite.git@release/v1.0.0.dev17" - name: Install dependencies diff --git a/changelog.d/68.changed.md b/changelog.d/68.changed.md new file mode 100644 index 00000000..fb085a36 --- /dev/null +++ b/changelog.d/68.changed.md @@ -0,0 +1 @@ +Adapted this backend to the core execution logging contract: structured execution summaries, shared sync/async logger ownership, redacted SQL logging, and bridges for the shared relation/query/basic contracts. diff --git a/codecov.yml b/codecov.yml new file mode 100644 index 00000000..a132e071 --- /dev/null +++ b/codecov.yml @@ -0,0 +1,18 @@ +# Codecov status configuration. +# +# The CI uploads one report with the shared `unittests` flag plus the +# interpreter/backend flags. Status checks read the shared flag explicitly so +# they do not depend on whichever flag Codecov happens to pick as default. +coverage: + status: + project: + default: + target: auto + threshold: 0.2% + flags: + - unittests + patch: + default: + target: 75% + flags: + - unittests diff --git a/pyproject.toml b/pyproject.toml index 49b52aab..f48098c1 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -110,6 +110,7 @@ markers = [ [tool.coverage.run] source = ["rhosocial"] branch = true +relative_files = true [tool.coverage.report] exclude_lines = [ diff --git a/src/rhosocial/activerecord/backend/impl/postgres/backend/async_backend.py b/src/rhosocial/activerecord/backend/impl/postgres/backend/async_backend.py index 29819aab..829b811c 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/backend/async_backend.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/backend/async_backend.py @@ -39,6 +39,11 @@ ) from rhosocial.activerecord.backend.base import AsyncStorageBackend +from rhosocial.activerecord.backend.base.execution_logging import ( + log_batch_start, + log_batch_summary, + log_execution_error, +) from rhosocial.activerecord.backend.introspection.backend_mixin import IntrospectorBackendMixin from rhosocial.activerecord.backend.explain import AsyncExplainBackendMixin from rhosocial.activerecord.backend.errors import ( @@ -49,8 +54,9 @@ OperationalError, QueryError, ) -from rhosocial.activerecord.backend.options import ExecutionOptions +from rhosocial.activerecord.backend.options import ExecutionOptions, StatementType from rhosocial.activerecord.backend.result import QueryResult +from rhosocial.activerecord.logging.redaction import unwrap_sensitive from ..config import PostgresConnectionConfig from ..dialect import PostgresDialect from .base import PostgresBackendMixin, PostgresConcurrencyMixin @@ -176,7 +182,7 @@ def __init__(self, **kwargs: Any) -> None: # Initialize transaction manager (will use backend.execute()) self._transaction_manager = AsyncPostgresTransactionManager(self, self.logger) - self.log(logging.INFO, "AsyncPostgresBackend initialized") + self.log(logging.DEBUG, "AsyncPostgresBackend initialized") def _create_introspector(self) -> Any: """Create and return an AsyncPostgreSQLIntrospector with an async executor.""" @@ -267,7 +273,7 @@ async def connect(self) -> None: f"Connected to PostgreSQL database: {self.config.host}:{self.config.port}/{self.config.database}", ) except PsycopgError as e: - self.log(logging.ERROR, f"Failed to connect to PostgreSQL database: {str(e)}") + self.log(logging.DEBUG, f"Failed to connect to PostgreSQL database: {str(e)}") raise ConnectionError(f"Failed to connect to PostgreSQL: {str(e)}") from e async def disconnect(self) -> None: @@ -282,7 +288,7 @@ async def disconnect(self) -> None: self._connection = None self.log(logging.INFO, "Disconnected from PostgreSQL database") except PsycopgError as e: - self.log(logging.ERROR, f"Error during disconnection: {str(e)}") + self.log(logging.DEBUG, f"Error during disconnection: {str(e)}") raise OperationalError(f"Error during PostgreSQL disconnection: {str(e)}") from e async def _get_cursor(self) -> Any: @@ -394,22 +400,32 @@ async def copy_from( await self._try_rollback_transaction() raise - async def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: - """Execute the same SQL statement multiple times with different parameters asynchronously.""" + async def execute_many( + self, + sql: str, + params_list: List[Tuple], + *, + options: Optional[ExecutionOptions] = None, + ) -> QueryResult: + """Execute the same SQL statement multiple times with different parameters. + + The backend owns the canonical DEBUG batch record and INFO batch + summary; callers only pass the logging context through ``options``. + """ if not self._connection: await self.connect() + if options is None: + options = ExecutionOptions(stmt_type=StatementType.DML) + params_list = [unwrap_sensitive(params) for params in params_list] + log_batch_start(self, sql, params_list, options) + cursor = None start_time = datetime.datetime.now() try: cursor = await self._get_cursor() - # Log the batch operation if logging is enabled - if getattr(self.config, "log_queries", False): - self.log(logging.DEBUG, f"Executing batch operation: {sql}") - self.log(logging.DEBUG, f"With {len(params_list)} parameter sets") - # Execute multiple statements affected_rows = 0 for params in params_list: @@ -420,20 +436,17 @@ async def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: result = QueryResult(affected_rows=affected_rows, data=None, duration=duration) - self.log( - logging.INFO, - f"Batch operation completed, affected {affected_rows} rows, duration={duration:.3f}s", - ) + log_batch_summary(self, sql, params_list, affected_rows, duration, options) return result except PsycopgIntegrityError as e: - self.log(logging.ERROR, f"Integrity error in batch: {str(e)}") + log_execution_error(self, e, options) raise IntegrityError(str(e)) from e except PsycopgError as e: - self.log(logging.ERROR, f"PostgreSQL error in batch: {str(e)}") + log_execution_error(self, e, options) raise DatabaseError(str(e)) from e except Exception as e: - self.log(logging.ERROR, f"Unexpected error during batch execution: {str(e)}") + log_execution_error(self, e, options) raise QueryError(str(e)) from e finally: if cursor: @@ -586,7 +599,7 @@ async def ping(self, reconnect: bool = True) -> bool: await self.connect() return True except Exception as connect_error: - self.log(logging.ERROR, f"Failed to reconnect after ping failure: {str(connect_error)}") + self.log(logging.WARNING, f"Failed to reconnect after ping failure: {str(connect_error)}") return False return False @@ -602,7 +615,7 @@ async def _reconnect(self) -> bool: await self.connect() return True except Exception as e: - self.log(logging.ERROR, f"Failed to reconnect: {str(e)}") + self.log(logging.WARNING, f"Failed to reconnect: {str(e)}") return False async def execute( @@ -630,8 +643,6 @@ async def execute( Returns: QueryResult containing the query results """ - from rhosocial.activerecord.backend.options import StatementType - # If no options provided, create default options from kwargs if options is None: # Determine statement type based on SQL @@ -675,7 +686,7 @@ async def execute( if await self._reconnect(): continue # If reconnection fails, break and raise the error - self.log(logging.ERROR, "Failed to reconnect after connection error") + self.log(logging.WARNING, "Failed to reconnect after connection error") break raise @@ -689,30 +700,30 @@ async def _handle_error(self, error: Exception) -> None: if isinstance(error, PsycopgIntegrityError): if "duplicate key value violates unique constraint" in error_msg.lower(): - self.log(logging.ERROR, f"Unique constraint violation: {error_msg}") + self.log(logging.DEBUG, f"Unique constraint violation: {error_msg}") raise IntegrityError(f"Unique constraint violation: {error_msg}") from error elif "violates foreign key constraint" in error_msg.lower(): - self.log(logging.ERROR, f"Foreign key constraint violation: {error_msg}") + self.log(logging.DEBUG, f"Foreign key constraint violation: {error_msg}") raise IntegrityError(f"Foreign key constraint violation: {error_msg}") from error - self.log(logging.ERROR, f"Integrity error: {error_msg}") + self.log(logging.DEBUG, f"Integrity error: {error_msg}") raise IntegrityError(error_msg) from error elif isinstance(error, PsycopgOperationalError): if "deadlock detected" in error_msg.lower(): - self.log(logging.ERROR, f"Deadlock error: {error_msg}") + self.log(logging.DEBUG, f"Deadlock error: {error_msg}") raise DeadlockError(error_msg) from error - self.log(logging.ERROR, f"Operational error: {error_msg}") + self.log(logging.DEBUG, f"Operational error: {error_msg}") raise OperationalError(error_msg) from error elif isinstance(error, PsycopgProgrammingError): - self.log(logging.ERROR, f"Programming error: {error_msg}") + self.log(logging.DEBUG, f"Programming error: {error_msg}") raise QueryError(error_msg) from error elif isinstance(error, PsycopgDeadlockError): - self.log(logging.ERROR, f"Deadlock error: {error_msg}") + self.log(logging.DEBUG, f"Deadlock error: {error_msg}") raise DeadlockError(error_msg) from error elif isinstance(error, PsycopgError): - self.log(logging.ERROR, f"PostgreSQL error: {error_msg}") + self.log(logging.DEBUG, f"PostgreSQL error: {error_msg}") raise DatabaseError(error_msg) from error else: - self.log(logging.ERROR, f"Unexpected error: {error_msg}") + self.log(logging.DEBUG, f"Unexpected error: {error_msg}") raise error async def _try_rollback_transaction(self) -> None: @@ -725,7 +736,7 @@ async def _try_rollback_transaction(self) -> None: try: # First, try the transaction manager if active if self.in_transaction: - self.log(logging.INFO, "Attempting to rollback transaction after error") + self.log(logging.DEBUG, "Attempting to rollback transaction after error") await self._transaction_manager.rollback() # Also try direct connection rollback to handle edge cases @@ -733,7 +744,7 @@ async def _try_rollback_transaction(self) -> None: if self._connection and not self._connection.closed: try: await self._connection.rollback() - self.log(logging.INFO, "Direct connection rollback completed") + self.log(logging.DEBUG, "Direct connection rollback completed") except Exception as direct_error: self.log(logging.DEBUG, f"Direct rollback not needed or failed: {direct_error}") except Exception as rollback_error: diff --git a/src/rhosocial/activerecord/backend/impl/postgres/backend/backend.py b/src/rhosocial/activerecord/backend/impl/postgres/backend/backend.py index 60c1a795..879237ee 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/backend/backend.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/backend/backend.py @@ -28,6 +28,11 @@ ) from rhosocial.activerecord.backend.base import StorageBackend +from rhosocial.activerecord.backend.base.execution_logging import ( + log_batch_start, + log_batch_summary, + log_execution_error, +) from rhosocial.activerecord.backend.introspection.backend_mixin import IntrospectorBackendMixin from rhosocial.activerecord.backend.explain import SyncExplainBackendMixin from rhosocial.activerecord.backend.errors import ( @@ -38,8 +43,9 @@ OperationalError, QueryError, ) -from rhosocial.activerecord.backend.options import ExecutionOptions +from rhosocial.activerecord.backend.options import ExecutionOptions, StatementType from rhosocial.activerecord.backend.result import QueryResult +from rhosocial.activerecord.logging.redaction import unwrap_sensitive from ..config import PostgresConnectionConfig from ..dialect import PostgresDialect from .base import PostgresBackendMixin, PostgresConcurrencyMixin @@ -162,7 +168,7 @@ def __init__(self, **kwargs: Any) -> None: # Initialize transaction manager (will use backend.execute()) self._transaction_manager = PostgresTransactionManager(self, self.logger) - self.log(logging.INFO, "PostgresBackend initialized") + self.log(logging.DEBUG, "PostgresBackend initialized") def _create_introspector(self) -> Any: """Create and return a PostgreSQLIntrospector with a sync executor.""" @@ -254,7 +260,7 @@ def connect(self) -> None: f"Connected to PostgreSQL database: {self.config.host}:{self.config.port}/{self.config.database}", ) except PsycopgError as e: - self.log(logging.ERROR, f"Failed to connect to PostgreSQL database: {str(e)}") + self.log(logging.DEBUG, f"Failed to connect to PostgreSQL database: {str(e)}") raise ConnectionError(f"Failed to connect to PostgreSQL: {str(e)}") from e def disconnect(self) -> None: @@ -269,7 +275,7 @@ def disconnect(self) -> None: self._connection = None self.log(logging.INFO, "Disconnected from PostgreSQL database") except PsycopgError as e: - self.log(logging.ERROR, f"Error during disconnection: {str(e)}") + self.log(logging.DEBUG, f"Error during disconnection: {str(e)}") raise OperationalError(f"Error during PostgreSQL disconnection: {str(e)}") from e def _get_cursor(self) -> Any: @@ -373,22 +379,32 @@ def copy_from( self._try_rollback_transaction() raise - def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: - """Execute the same SQL statement multiple times with different parameters.""" + def execute_many( + self, + sql: str, + params_list: List[Tuple], + *, + options: Optional[ExecutionOptions] = None, + ) -> QueryResult: + """Execute the same SQL statement multiple times with different parameters. + + The backend owns the canonical DEBUG batch record and INFO batch + summary; callers only pass the logging context through ``options``. + """ if not self._connection: self.connect() + if options is None: + options = ExecutionOptions(stmt_type=StatementType.DML) + params_list = [unwrap_sensitive(params) for params in params_list] + log_batch_start(self, sql, params_list, options) + cursor = None start_time = datetime.datetime.now() try: cursor = self._get_cursor() - # Log the batch operation if logging is enabled - if getattr(self.config, "log_queries", False): - self.log(logging.DEBUG, f"Executing batch operation: {sql}") - self.log(logging.DEBUG, f"With {len(params_list)} parameter sets") - # Execute multiple statements affected_rows = 0 for params in params_list: @@ -399,20 +415,17 @@ def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: result = QueryResult(affected_rows=affected_rows, data=None, duration=duration) - self.log( - logging.INFO, - f"Batch operation completed, affected {affected_rows} rows, duration={duration:.3f}s", - ) + log_batch_summary(self, sql, params_list, affected_rows, duration, options) return result except PsycopgIntegrityError as e: - self.log(logging.ERROR, f"Integrity error in batch: {str(e)}") + log_execution_error(self, e, options) raise IntegrityError(str(e)) from e except PsycopgError as e: - self.log(logging.ERROR, f"PostgreSQL error in batch: {str(e)}") + log_execution_error(self, e, options) raise DatabaseError(str(e)) from e except Exception as e: - self.log(logging.ERROR, f"Unexpected error during batch execution: {str(e)}") + log_execution_error(self, e, options) raise QueryError(str(e)) from e finally: if cursor: @@ -565,7 +578,7 @@ def ping(self, reconnect: bool = True) -> bool: self.connect() return True except Exception as connect_error: - self.log(logging.ERROR, f"Failed to reconnect after ping failure: {str(connect_error)}") + self.log(logging.WARNING, f"Failed to reconnect after ping failure: {str(connect_error)}") return False return False @@ -581,7 +594,7 @@ def _reconnect(self) -> bool: self.connect() return True except Exception as e: - self.log(logging.ERROR, f"Failed to reconnect: {str(e)}") + self.log(logging.WARNING, f"Failed to reconnect: {str(e)}") return False def execute( @@ -609,8 +622,6 @@ def execute( Returns: QueryResult containing the query results """ - from rhosocial.activerecord.backend.options import StatementType - # If no options provided, create default options from kwargs if options is None: # Determine statement type based on SQL @@ -654,7 +665,7 @@ def execute( if self._reconnect(): continue # If reconnection fails, break and raise the error - self.log(logging.ERROR, "Failed to reconnect after connection error") + self.log(logging.WARNING, "Failed to reconnect after connection error") break raise @@ -668,30 +679,30 @@ def _handle_error(self, error: Exception) -> None: if isinstance(error, PsycopgIntegrityError): if "duplicate key value violates unique constraint" in error_msg.lower(): - self.log(logging.ERROR, f"Unique constraint violation: {error_msg}") + self.log(logging.DEBUG, f"Unique constraint violation: {error_msg}") raise IntegrityError(f"Unique constraint violation: {error_msg}") from error elif "violates foreign key constraint" in error_msg.lower(): - self.log(logging.ERROR, f"Foreign key constraint violation: {error_msg}") + self.log(logging.DEBUG, f"Foreign key constraint violation: {error_msg}") raise IntegrityError(f"Foreign key constraint violation: {error_msg}") from error - self.log(logging.ERROR, f"Integrity error: {error_msg}") + self.log(logging.DEBUG, f"Integrity error: {error_msg}") raise IntegrityError(error_msg) from error elif isinstance(error, PsycopgOperationalError): if "deadlock detected" in error_msg.lower(): - self.log(logging.ERROR, f"Deadlock error: {error_msg}") + self.log(logging.DEBUG, f"Deadlock error: {error_msg}") raise DeadlockError(error_msg) from error - self.log(logging.ERROR, f"Operational error: {error_msg}") + self.log(logging.DEBUG, f"Operational error: {error_msg}") raise OperationalError(error_msg) from error elif isinstance(error, PsycopgProgrammingError): - self.log(logging.ERROR, f"Programming error: {error_msg}") + self.log(logging.DEBUG, f"Programming error: {error_msg}") raise QueryError(error_msg) from error elif isinstance(error, PsycopgDeadlockError): - self.log(logging.ERROR, f"Deadlock error: {error_msg}") + self.log(logging.DEBUG, f"Deadlock error: {error_msg}") raise DeadlockError(error_msg) from error elif isinstance(error, PsycopgError): - self.log(logging.ERROR, f"PostgreSQL error: {error_msg}") + self.log(logging.DEBUG, f"PostgreSQL error: {error_msg}") raise DatabaseError(error_msg) from error else: - self.log(logging.ERROR, f"Unexpected error: {error_msg}") + self.log(logging.DEBUG, f"Unexpected error: {error_msg}") raise error def _try_rollback_transaction(self) -> None: @@ -704,7 +715,7 @@ def _try_rollback_transaction(self) -> None: try: # First, try the transaction manager if active if self.in_transaction: - self.log(logging.INFO, "Attempting to rollback transaction after error") + self.log(logging.DEBUG, "Attempting to rollback transaction after error") self._transaction_manager.rollback() # Also try direct connection rollback to handle edge cases @@ -712,7 +723,7 @@ def _try_rollback_transaction(self) -> None: if self._connection and not self._connection.closed: try: self._connection.rollback() - self.log(logging.INFO, "Direct connection rollback completed") + self.log(logging.DEBUG, "Direct connection rollback completed") except Exception as direct_error: self.log(logging.DEBUG, f"Direct rollback not needed or failed: {direct_error}") except Exception as rollback_error: diff --git a/src/rhosocial/activerecord/backend/impl/postgres/backend/base.py b/src/rhosocial/activerecord/backend/impl/postgres/backend/base.py index 2f074f63..a654efd9 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/backend/base.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/backend/base.py @@ -24,9 +24,18 @@ class PostgresBackendMixin: - self._dialect: PostgresDialect instance - self.adapter_registry: Type adapter registry - self.config: Connection configuration - - self._logger: Logger instance + + Logging is inherited from ``BackendLoggingMixin``: the mixin pins the + library logger name so the sync and async backends share + ``rhosocial.activerecord.backend.postgres`` and keeps the canonical + execution records in one place. """ + # Both PostgresBackend and AsyncPostgresBackend report under the same + # library logger; without this the derived Async* name would produce + # ``rhosocial.activerecord.backend.asyncpostgres``. + _logger_name = "rhosocial.activerecord.backend.postgres" + # PostgreSQL connection error SQLSTATE codes # Reference: https://www.postgresql.org/docs/current/errcodes-appendix.html CONNECTION_ERROR_SQLSTATES = { @@ -43,14 +52,6 @@ class PostgresBackendMixin: "57P04", # DATABASE_DROPPED } - def log(self, level: int, message: str): - """Log a message with the specified level.""" - if hasattr(self, "_logger") and self._logger: - self._logger.log(level, message) - else: - # Fallback logging - print(f"[{logging.getLevelName(level)}] {message}") - def get_default_schema(self) -> str: """Get the default schema name for PostgreSQL. diff --git a/src/rhosocial/activerecord/backend/impl/postgres/backend/sync.py b/src/rhosocial/activerecord/backend/impl/postgres/backend/sync.py index 7ab91246..6dd035bf 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/backend/sync.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/backend/sync.py @@ -28,6 +28,11 @@ ) from rhosocial.activerecord.backend.base import StorageBackend +from rhosocial.activerecord.backend.base.execution_logging import ( + log_batch_start, + log_batch_summary, + log_execution_error, +) from rhosocial.activerecord.backend.introspection.backend_mixin import IntrospectorBackendMixin from rhosocial.activerecord.backend.explain import SyncExplainBackendMixin from rhosocial.activerecord.backend.errors import ( @@ -38,8 +43,9 @@ OperationalError, QueryError, ) -from rhosocial.activerecord.backend.options import ExecutionOptions +from rhosocial.activerecord.backend.options import ExecutionOptions, StatementType from rhosocial.activerecord.backend.result import QueryResult +from rhosocial.activerecord.logging.redaction import unwrap_sensitive from ..config import PostgresConnectionConfig from ..dialect import PostgresDialect from .base import PostgresBackendMixin, PostgresConcurrencyMixin @@ -162,7 +168,7 @@ def __init__(self, **kwargs: Any) -> None: # Initialize transaction manager (will use backend.execute()) self._transaction_manager = PostgresTransactionManager(self, self.logger) - self.log(logging.INFO, "PostgresBackend initialized") + self.log(logging.DEBUG, "PostgresBackend initialized") def _create_introspector(self) -> Any: """Create and return a PostgreSQLIntrospector with a sync executor.""" @@ -254,7 +260,7 @@ def connect(self) -> None: f"Connected to PostgreSQL database: {self.config.host}:{self.config.port}/{self.config.database}", ) except PsycopgError as e: - self.log(logging.ERROR, f"Failed to connect to PostgreSQL database: {str(e)}") + self.log(logging.DEBUG, f"Failed to connect to PostgreSQL database: {str(e)}") raise ConnectionError(f"Failed to connect to PostgreSQL: {str(e)}") from e def disconnect(self) -> None: @@ -269,7 +275,7 @@ def disconnect(self) -> None: self._connection = None self.log(logging.INFO, "Disconnected from PostgreSQL database") except PsycopgError as e: - self.log(logging.ERROR, f"Error during disconnection: {str(e)}") + self.log(logging.DEBUG, f"Error during disconnection: {str(e)}") raise OperationalError(f"Error during PostgreSQL disconnection: {str(e)}") from e def _get_cursor(self) -> Any: @@ -373,22 +379,32 @@ def copy_from( self._try_rollback_transaction() raise - def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: - """Execute the same SQL statement multiple times with different parameters.""" + def execute_many( + self, + sql: str, + params_list: List[Tuple], + *, + options: Optional[ExecutionOptions] = None, + ) -> QueryResult: + """Execute the same SQL statement multiple times with different parameters. + + The backend owns the canonical DEBUG batch record and INFO batch + summary; callers only pass the logging context through ``options``. + """ if not self._connection: self.connect() + if options is None: + options = ExecutionOptions(stmt_type=StatementType.DML) + params_list = [unwrap_sensitive(params) for params in params_list] + log_batch_start(self, sql, params_list, options) + cursor = None start_time = datetime.datetime.now() try: cursor = self._get_cursor() - # Log the batch operation if logging is enabled - if getattr(self.config, "log_queries", False): - self.log(logging.DEBUG, f"Executing batch operation: {sql}") - self.log(logging.DEBUG, f"With {len(params_list)} parameter sets") - # Execute multiple statements affected_rows = 0 for params in params_list: @@ -399,20 +415,17 @@ def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: result = QueryResult(affected_rows=affected_rows, data=None, duration=duration) - self.log( - logging.INFO, - f"Batch operation completed, affected {affected_rows} rows, duration={duration:.3f}s", - ) + log_batch_summary(self, sql, params_list, affected_rows, duration, options) return result except PsycopgIntegrityError as e: - self.log(logging.ERROR, f"Integrity error in batch: {str(e)}") + log_execution_error(self, e, options) raise IntegrityError(str(e)) from e except PsycopgError as e: - self.log(logging.ERROR, f"PostgreSQL error in batch: {str(e)}") + log_execution_error(self, e, options) raise DatabaseError(str(e)) from e except Exception as e: - self.log(logging.ERROR, f"Unexpected error during batch execution: {str(e)}") + log_execution_error(self, e, options) raise QueryError(str(e)) from e finally: if cursor: @@ -565,7 +578,7 @@ def ping(self, reconnect: bool = True) -> bool: self.connect() return True except Exception as connect_error: - self.log(logging.ERROR, f"Failed to reconnect after ping failure: {str(connect_error)}") + self.log(logging.WARNING, f"Failed to reconnect after ping failure: {str(connect_error)}") return False return False @@ -581,7 +594,7 @@ def _reconnect(self) -> bool: self.connect() return True except Exception as e: - self.log(logging.ERROR, f"Failed to reconnect: {str(e)}") + self.log(logging.WARNING, f"Failed to reconnect: {str(e)}") return False def execute( @@ -609,8 +622,6 @@ def execute( Returns: QueryResult containing the query results """ - from rhosocial.activerecord.backend.options import StatementType - # If no options provided, create default options from kwargs if options is None: # Determine statement type based on SQL @@ -654,7 +665,7 @@ def execute( if self._reconnect(): continue # If reconnection fails, break and raise the error - self.log(logging.ERROR, "Failed to reconnect after connection error") + self.log(logging.WARNING, "Failed to reconnect after connection error") break raise @@ -668,30 +679,30 @@ def _handle_error(self, error: Exception) -> None: if isinstance(error, PsycopgIntegrityError): if "duplicate key value violates unique constraint" in error_msg.lower(): - self.log(logging.ERROR, f"Unique constraint violation: {error_msg}") + self.log(logging.DEBUG, f"Unique constraint violation: {error_msg}") raise IntegrityError(f"Unique constraint violation: {error_msg}") from error elif "violates foreign key constraint" in error_msg.lower(): - self.log(logging.ERROR, f"Foreign key constraint violation: {error_msg}") + self.log(logging.DEBUG, f"Foreign key constraint violation: {error_msg}") raise IntegrityError(f"Foreign key constraint violation: {error_msg}") from error - self.log(logging.ERROR, f"Integrity error: {error_msg}") + self.log(logging.DEBUG, f"Integrity error: {error_msg}") raise IntegrityError(error_msg) from error elif isinstance(error, PsycopgOperationalError): if "deadlock detected" in error_msg.lower(): - self.log(logging.ERROR, f"Deadlock error: {error_msg}") + self.log(logging.DEBUG, f"Deadlock error: {error_msg}") raise DeadlockError(error_msg) from error - self.log(logging.ERROR, f"Operational error: {error_msg}") + self.log(logging.DEBUG, f"Operational error: {error_msg}") raise OperationalError(error_msg) from error elif isinstance(error, PsycopgProgrammingError): - self.log(logging.ERROR, f"Programming error: {error_msg}") + self.log(logging.DEBUG, f"Programming error: {error_msg}") raise QueryError(error_msg) from error elif isinstance(error, PsycopgDeadlockError): - self.log(logging.ERROR, f"Deadlock error: {error_msg}") + self.log(logging.DEBUG, f"Deadlock error: {error_msg}") raise DeadlockError(error_msg) from error elif isinstance(error, PsycopgError): - self.log(logging.ERROR, f"PostgreSQL error: {error_msg}") + self.log(logging.DEBUG, f"PostgreSQL error: {error_msg}") raise DatabaseError(error_msg) from error else: - self.log(logging.ERROR, f"Unexpected error: {error_msg}") + self.log(logging.DEBUG, f"Unexpected error: {error_msg}") raise error def _try_rollback_transaction(self) -> None: @@ -704,7 +715,7 @@ def _try_rollback_transaction(self) -> None: try: # First, try the transaction manager if active if self.in_transaction: - self.log(logging.INFO, "Attempting to rollback transaction after error") + self.log(logging.DEBUG, "Attempting to rollback transaction after error") self._transaction_manager.rollback() # Also try direct connection rollback to handle edge cases @@ -712,7 +723,7 @@ def _try_rollback_transaction(self) -> None: if self._connection and not self._connection.closed: try: self._connection.rollback() - self.log(logging.INFO, "Direct connection rollback completed") + self.log(logging.DEBUG, "Direct connection rollback completed") except Exception as direct_error: self.log(logging.DEBUG, f"Direct rollback not needed or failed: {direct_error}") except Exception as rollback_error: diff --git a/src/rhosocial/activerecord/backend/impl/postgres/cli/info.py b/src/rhosocial/activerecord/backend/impl/postgres/cli/info.py index cd5b6cd5..83951735 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/cli/info.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/cli/info.py @@ -8,7 +8,6 @@ import argparse import inspect import json -import logging from typing import Any, Dict, List, Optional, Tuple from rhosocial.activerecord.backend.dialect.protocols import ( @@ -72,10 +71,12 @@ PostgresFeaturesSupport, ) +from rhosocial.activerecord.logging.defaults import get_logger + from .connection import add_connection_args, add_version_arg, resolve_connection_config_from_args from .output import INFO_OUTPUT_CHOICES, create_provider, RICH_AVAILABLE -logger = logging.getLogger(__name__) +logger = get_logger("rhosocial.activerecord.backend.postgres") # Groups that are specific to PostgreSQL dialect DIALECT_SPECIFIC_GROUPS = {"PostgreSQL Native", "PostgreSQL Extensions"} diff --git a/src/rhosocial/activerecord/backend/impl/postgres/cli/query.py b/src/rhosocial/activerecord/backend/impl/postgres/cli/query.py index 881119db..840a3c8c 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/cli/query.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/cli/query.py @@ -12,11 +12,15 @@ from rhosocial.activerecord.backend.impl.postgres.backend.async_backend import AsyncPostgresBackend from rhosocial.activerecord.backend.impl.postgres.backend import PostgresBackend from rhosocial.activerecord.backend.errors import ConnectionError, QueryError +from rhosocial.activerecord.logging.defaults import get_logger from .connection import add_connection_args, resolve_connection_config_from_args from .output import OUTPUT_CHOICES, create_provider, RICH_AVAILABLE +logger = get_logger("rhosocial.activerecord.backend.postgres") + + def create_parser(subparsers): """Create the query subcommand parser.""" parser = subparsers.add_parser( @@ -120,7 +124,7 @@ def handle(args): with open(args.file, "r", encoding="utf-8") as f: sql_source = f.read() except FileNotFoundError: - logging.error(f"Error: File not found at {args.file}") + logger.error(f"Error: File not found at {args.file}") sys.exit(1) elif not sys.stdin.isatty(): sql_source = sys.stdin.read() @@ -132,7 +136,7 @@ def handle(args): # Ensure only one statement is provided if ";" in sql_source.strip().rstrip(";"): - logging.error("Error: Multiple SQL statements are not supported.") + logger.error("Error: Multiple SQL statements are not supported.") sys.exit(1) config = resolve_connection_config_from_args(args) diff --git a/src/rhosocial/activerecord/backend/impl/postgres/transaction.py b/src/rhosocial/activerecord/backend/impl/postgres/transaction.py index 6e57ad7a..701e36d8 100644 --- a/src/rhosocial/activerecord/backend/impl/postgres/transaction.py +++ b/src/rhosocial/activerecord/backend/impl/postgres/transaction.py @@ -169,10 +169,10 @@ def defer_constraint(self, constraint_name: str) -> None: ).to_sql() self._backend.execute(sql, params) self._deferred_constraints.append(constraint_name) - self.log(logging.INFO, f"Deferred constraint: {constraint_name}") + self.log(logging.DEBUG, f"Deferred constraint: {constraint_name}") except Exception as e: error_msg = f"Failed to defer constraint {constraint_name}: {str(e)}" - self.log(logging.ERROR, error_msg) + self.log(logging.DEBUG, error_msg) raise TransactionError(error_msg) from e def get_current_isolation_level(self) -> IsolationLevel: @@ -198,7 +198,7 @@ def get_current_isolation_level(self) -> IsolationLevel: return IsolationLevel.READ_COMMITTED except Exception as e: error_msg = f"Failed to get transaction isolation level: {str(e)}" - self.log(logging.ERROR, error_msg) + self.log(logging.DEBUG, error_msg) raise TransactionError(error_msg) from e def commit(self) -> None: @@ -261,10 +261,10 @@ async def defer_constraint(self, constraint_name: str) -> None: ).to_sql() await self._backend.execute(sql, params) self._deferred_constraints.append(constraint_name) - self.log(logging.INFO, f"Deferred constraint: {constraint_name}") + self.log(logging.DEBUG, f"Deferred constraint: {constraint_name}") except Exception as e: error_msg = f"Failed to defer constraint {constraint_name}: {str(e)}" - self.log(logging.ERROR, error_msg) + self.log(logging.DEBUG, error_msg) raise TransactionError(error_msg) from e async def get_current_isolation_level(self) -> IsolationLevel: @@ -290,7 +290,7 @@ async def get_current_isolation_level(self) -> IsolationLevel: return IsolationLevel.READ_COMMITTED except Exception as e: error_msg = f"Failed to get transaction isolation level: {str(e)}" - self.log(logging.ERROR, error_msg) + self.log(logging.DEBUG, error_msg) raise TransactionError(error_msg) from e async def commit(self) -> None: diff --git a/tests/rhosocial/activerecord_postgres_test/feature/basic/nopk/test_keyless_models.py b/tests/rhosocial/activerecord_postgres_test/feature/basic/nopk/test_keyless_models.py new file mode 100644 index 00000000..ec0a3c2a --- /dev/null +++ b/tests/rhosocial/activerecord_postgres_test/feature/basic/nopk/test_keyless_models.py @@ -0,0 +1,4 @@ +# tests/rhosocial/activerecord_postgres_test/feature/basic/nopk/test_keyless_models.py +"""Bridge file for the testsuite keyless model contract (sync and async).""" +from rhosocial.activerecord.testsuite.feature.basic.nopk.test_keyless_models import * # noqa: F403 +from rhosocial.activerecord.testsuite.feature.basic.nopk.test_keyless_models_async import * # noqa: F403 diff --git a/tests/rhosocial/activerecord_postgres_test/feature/basic/readonly/test_readonly_models.py b/tests/rhosocial/activerecord_postgres_test/feature/basic/readonly/test_readonly_models.py new file mode 100644 index 00000000..f9b39047 --- /dev/null +++ b/tests/rhosocial/activerecord_postgres_test/feature/basic/readonly/test_readonly_models.py @@ -0,0 +1,4 @@ +# tests/rhosocial/activerecord_postgres_test/feature/basic/readonly/test_readonly_models.py +"""Bridge file for the testsuite read-only model contract (sync and async).""" +from rhosocial.activerecord.testsuite.feature.basic.readonly.test_readonly_models import * # noqa: F403 +from rhosocial.activerecord.testsuite.feature.basic.readonly.test_readonly_models_async import * # noqa: F403 diff --git a/tests/rhosocial/activerecord_postgres_test/feature/logging/test_execution_logging_unit.py b/tests/rhosocial/activerecord_postgres_test/feature/logging/test_execution_logging_unit.py new file mode 100644 index 00000000..5df170ec --- /dev/null +++ b/tests/rhosocial/activerecord_postgres_test/feature/logging/test_execution_logging_unit.py @@ -0,0 +1,465 @@ +# tests/rhosocial/activerecord_postgres_test/feature/logging/test_execution_logging_unit.py +"""Database-free coverage for PostgreSQL execution logging. + +The PostgreSQL package keeps two identical sync backend modules (``backend.py`` +and ``sync.py``) plus the async module. Coverage only reaches one of them through +normal imports, so this module instantiates every class and drives its execution +logging against fake connections. No PostgreSQL server is required. + +The module also exercises the transaction managers' deferred-constraint +logging and imports the CLI modules so their module-level logger bindings count. +Every backend module is loaded lazily, after a minimal ``psycopg`` stub is +installed when the real driver is absent, so the constructor, batch, transaction +and CLI tests do not depend on psycopg. When the driver is installed its +exception classes drive the error mappings. +""" + +import importlib +import logging +import sys +import types +from unittest.mock import AsyncMock, MagicMock + +import pytest + +from rhosocial.activerecord.backend.errors import ( + DatabaseError, + DeadlockError, + IntegrityError, + OperationalError, + QueryError, +) +from rhosocial.activerecord.backend.options import ( + ExecutionOptions, + LogContext, + StatementType, +) +from rhosocial.activerecord.backend.result import QueryResult +from rhosocial.activerecord.logging.redaction import SensitiveValue + +POSTGRES_LOGGER = "rhosocial.activerecord.backend.postgres" + +MODULE_PATHS = { + "backend": "rhosocial.activerecord.backend.impl.postgres.backend.backend", + "sync": "rhosocial.activerecord.backend.impl.postgres.backend.sync", + "async_backend": "rhosocial.activerecord.backend.impl.postgres.backend.async_backend", + "base": "rhosocial.activerecord.backend.impl.postgres.backend.base", + "transaction": "rhosocial.activerecord.backend.impl.postgres.transaction", + "cli_info": "rhosocial.activerecord.backend.impl.postgres.cli.info", + "cli_query": "rhosocial.activerecord.backend.impl.postgres.cli.query", +} + + +def _ensure_psycopg(): + """Import psycopg, or install minimal stubs so the DB-free tests can run.""" + try: + import psycopg + import psycopg.errors # noqa: F401 + return psycopg + except ImportError: + pass + + class _Error(Exception): + pass + + class _IntegrityError(_Error): + pass + + class _OperationalError(_Error): + pass + + class _ProgrammingError(_Error): + pass + + class _DeadlockDetected(_OperationalError): + pass + + psycopg = types.ModuleType("psycopg") + psycopg.Connection = object + psycopg.AsyncConnection = object + + errors = types.ModuleType("psycopg.errors") + for name, cls in ( + ("Error", _Error), + ("IntegrityError", _IntegrityError), + ("OperationalError", _OperationalError), + ("ProgrammingError", _ProgrammingError), + ("DeadlockDetected", _DeadlockDetected), + ): + setattr(errors, name, cls) + psycopg.errors = errors + + psycopg_types = types.ModuleType("psycopg.types") + psycopg_types.json = types.ModuleType("psycopg.types.json") + psycopg_types.json.Jsonb = dict + psycopg.types = psycopg_types + + sys.modules["psycopg"] = psycopg + sys.modules["psycopg.errors"] = errors + sys.modules["psycopg.types"] = psycopg_types + sys.modules["psycopg.types.json"] = psycopg_types.json + return psycopg + + +# Must run before any PostgreSQL backend module is imported lazily below. +psycopg = _ensure_psycopg() + + +def _load(name): + """Import one of the backend/CLI modules under test.""" + return importlib.import_module(MODULE_PATHS[name]) + + +class FakeCursor: + """Minimal synchronous cursor that records executed parameters.""" + + def __init__(self, rowcount: int = 1) -> None: + self.rowcount = rowcount + self.executed = [] + self.close_calls = 0 + + def execute(self, sql, params=None): + self.executed.append((sql, params)) + + def close(self) -> None: + self.close_calls += 1 + + +class FakeAsyncCursor(FakeCursor): + """Minimal asynchronous cursor that records executed parameters.""" + + async def execute(self, sql, params=None): + self.executed.append((sql, params)) + + async def close(self) -> None: + self.close_calls += 1 + + +class FakeConnection: + """Minimal synchronous connection, open and healthy enough for ``_get_cursor``.""" + + closed = False + broken = False + + def __init__(self, cursor) -> None: + self._cursor = cursor + self.rollback_calls = 0 + + def cursor(self): + return self._cursor + + def rollback(self) -> None: + self.rollback_calls += 1 + + +class FakeAsyncConnection(FakeConnection): + """Minimal asynchronous connection, open and healthy enough for ``_get_cursor``.""" + + async def rollback(self) -> None: + self.rollback_calls += 1 + + +class UnexpectedError(Exception): + """Non-psycopg exception used to cover the re-raise branch.""" + + +def _messages(caplog) -> str: + return "\n".join(record.getMessage() for record in caplog.records) + + +def _driver_error_cases(): + """Return (error, framework error, log fragment) triples for mapped branches.""" + errors = psycopg.errors + return { + "unique_violation": ( + errors.IntegrityError( + "duplicate key value violates unique constraint users_email_key" + ), + IntegrityError, + "Unique constraint violation", + ), + "foreign_key_violation": ( + errors.IntegrityError("insert violates foreign key constraint fk_orders_user"), + IntegrityError, + "Foreign key constraint violation", + ), + "integrity_other": ( + errors.IntegrityError("integrity constraint failed"), + IntegrityError, + "Integrity error", + ), + "deadlock": ( + errors.OperationalError("deadlock detected"), + DeadlockError, + "Deadlock error", + ), + "operational_other": ( + errors.OperationalError("server closed the connection unexpectedly"), + OperationalError, + "Operational error", + ), + "programming": ( + errors.ProgrammingError("syntax error at or near SELECT"), + QueryError, + "Programming error", + ), + "postgres_other": ( + errors.Error("some PostgreSQL failure"), + DatabaseError, + "PostgreSQL error", + ), + "unexpected": ( + UnexpectedError("unexpected failure"), + UnexpectedError, + "Unexpected error", + ), + } + + +@pytest.fixture(params=["backend", "sync"]) +def sync_backend_module(request): + """Return the duplicate sync backend module under test.""" + return _load(request.param) + + +@pytest.fixture +def sync_backend(sync_backend_module): + """Instantiate the sync backend from the selected duplicate module (no connect).""" + return sync_backend_module.PostgresBackend(database="logging_unit_db") + + +@pytest.fixture +def async_backend(): + """Instantiate the async backend (no connect).""" + return _load("async_backend").AsyncPostgresBackend(database="logging_unit_db") + + +@pytest.fixture( + params=[ + "unique_violation", + "foreign_key_violation", + "integrity_other", + "deadlock", + "operational_other", + "programming", + "postgres_other", + "unexpected", + ] +) +def driver_error(request): + """Build one mapped exception per test invocation.""" + return _driver_error_cases()[request.param] + + +class TestSyncExecutionLogging: + """Synchronous execution logging, run once per duplicate backend module.""" + + def test_constructor_logs_initialized(self, sync_backend_module, caplog): + """Construction logs its init record without opening a connection.""" + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + backend = sync_backend_module.PostgresBackend(database="logging_unit_db") + + assert backend._connection is None + assert backend._get_logger_name() == POSTGRES_LOGGER + assert backend.logger.name == POSTGRES_LOGGER + assert "PostgresBackend initialized" in _messages(caplog) + assert _load("base").PostgresBackendMixin._logger_name == POSTGRES_LOGGER + + def test_execute_many_logs_counts_not_values(self, sync_backend, caplog): + """The batch record carries counts, never parameter values.""" + cursor = FakeCursor(rowcount=1) + sync_backend._connection = FakeConnection(cursor) + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + + params_list = [ + ("alice", SensitiveValue("hunter2")), + ("bob", SensitiveValue("hunter3")), + ] + options = ExecutionOptions( + stmt_type=StatementType.DML, + log_context=LogContext(operation="insert_many", object_name="users"), + ) + + result = sync_backend.execute_many( + "INSERT INTO users (name, password) VALUES (%s, %s)", + params_list, + options=options, + ) + + assert result.affected_rows == 2 + assert cursor.close_calls == 1 + # SensitiveValue is unwrapped before binding, so the driver sees values. + assert cursor.executed[0][1] == ("alice", "hunter2") + assert cursor.executed[1][1] == ("bob", "hunter3") + + messages = _messages(caplog) + assert "parameter_sets: 2" in messages + assert "hunter2" not in messages + assert "hunter3" not in messages + + # The default-options path builds its own DML ExecutionOptions. + default_result = sync_backend.execute_many( + "UPDATE users SET name = %s", + [("carol",)], + ) + assert default_result.affected_rows == 1 + + def test_handle_error_maps_driver_errors(self, sync_backend, driver_error, monkeypatch, caplog): + """Each mapped error branch logs at DEBUG and raises the framework error.""" + error, framework_error, fragment = driver_error + + manager = sync_backend._transaction_manager + manager._transaction_level = 1 + monkeypatch.setattr(manager, "rollback", lambda: None) + connection = FakeConnection(FakeCursor()) + sync_backend._connection = connection + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + + with pytest.raises(framework_error): + sync_backend._handle_error(error) + + assert fragment in _messages(caplog) + # Active transaction rolls back through the manager, then the connection. + assert connection.rollback_calls == 1 + + def test_defer_constraint_logs_deferred_name(self, sync_backend, monkeypatch, caplog): + """defer_constraint logs the accepted constraint once it is registered.""" + monkeypatch.setattr( + sync_backend, + "execute", + MagicMock(return_value=QueryResult(affected_rows=1)), + ) + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + + sync_backend.transaction_manager.defer_constraint("users_email_key") + + assert sync_backend.transaction_manager.get_deferred_constraints() == [ + "users_email_key" + ] + assert "Deferred constraint: users_email_key" in _messages(caplog) + + +class TestAsyncExecutionLogging: + """Asynchronous counterparts of the synchronous logging tests.""" + + @pytest.mark.asyncio + async def test_constructor_logs_initialized(self, caplog): + """Async construction logs its init record without opening a connection.""" + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + backend = _load("async_backend").AsyncPostgresBackend(database="logging_unit_db") + + assert backend._connection is None + assert backend._get_logger_name() == POSTGRES_LOGGER + assert backend.logger.name == POSTGRES_LOGGER + assert "AsyncPostgresBackend initialized" in _messages(caplog) + + @pytest.mark.asyncio + async def test_execute_many_logs_counts_not_values(self, async_backend, caplog): + """The async batch record carries counts, never parameter values.""" + cursor = FakeAsyncCursor(rowcount=1) + async_backend._connection = FakeAsyncConnection(cursor) + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + + params_list = [ + ("alice", SensitiveValue("hunter2")), + ("bob", SensitiveValue("hunter3")), + ] + options = ExecutionOptions( + stmt_type=StatementType.DML, + log_context=LogContext(operation="insert_many", object_name="users"), + ) + + result = await async_backend.execute_many( + "INSERT INTO users (name, password) VALUES (%s, %s)", + params_list, + options=options, + ) + + assert result.affected_rows == 2 + assert cursor.close_calls == 1 + assert cursor.executed[0][1] == ("alice", "hunter2") + assert cursor.executed[1][1] == ("bob", "hunter3") + + messages = _messages(caplog) + assert "parameter_sets: 2" in messages + assert "hunter2" not in messages + assert "hunter3" not in messages + + # The default-options path builds its own DML ExecutionOptions. + default_result = await async_backend.execute_many( + "UPDATE users SET name = %s", + [("carol",)], + ) + assert default_result.affected_rows == 1 + + @pytest.mark.asyncio + async def test_handle_error_maps_driver_errors( + self, async_backend, driver_error, monkeypatch, caplog + ): + """Each mapped error branch logs at DEBUG and raises the framework error.""" + error, framework_error, fragment = driver_error + + async def _noop() -> None: + return None + + manager = async_backend._transaction_manager + manager._transaction_level = 1 + monkeypatch.setattr(manager, "rollback", _noop) + connection = FakeAsyncConnection(FakeAsyncCursor()) + async_backend._connection = connection + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + + with pytest.raises(framework_error): + await async_backend._handle_error(error) + + assert fragment in _messages(caplog) + assert connection.rollback_calls == 1 + + @pytest.mark.asyncio + async def test_defer_constraint_logs_deferred_name(self, async_backend, monkeypatch, caplog): + """Async defer_constraint logs the accepted constraint once registered.""" + monkeypatch.setattr( + async_backend, + "execute", + AsyncMock(return_value=QueryResult(affected_rows=1)), + ) + caplog.set_level(logging.DEBUG, logger=POSTGRES_LOGGER) + + await async_backend.transaction_manager.defer_constraint("users_email_key") + + assert async_backend.transaction_manager.get_deferred_constraints() == [ + "users_email_key" + ] + assert "Deferred constraint: users_email_key" in _messages(caplog) + + +class TestCLILogging: + """CLI modules bind their module-level logger to the shared backend logger.""" + + def test_cli_modules_use_postgres_logger(self): + assert _load("cli_info").logger.name == POSTGRES_LOGGER + assert _load("cli_query").logger.name == POSTGRES_LOGGER + + +class TestModuleReexecution: + """Re-execute module bodies so lines pre-imported before coverage still count.""" + + @pytest.mark.parametrize( + "module_name", + [ + "backend", + "sync", + "async_backend", + "base", + "transaction", + "cli_info", + "cli_query", + ], + ) + def test_module_body_is_reexecuted(self, module_name): + module = _load(module_name) + importlib.reload(module) + + assert _load("base").PostgresBackendMixin._logger_name == POSTGRES_LOGGER + assert _load("cli_info").logger.name == POSTGRES_LOGGER + assert _load("cli_query").logger.name == POSTGRES_LOGGER diff --git a/tests/rhosocial/activerecord_postgres_test/feature/query/basic/test_find_one_or_create.py b/tests/rhosocial/activerecord_postgres_test/feature/query/basic/test_find_one_or_create.py new file mode 100644 index 00000000..cc8fd3a4 --- /dev/null +++ b/tests/rhosocial/activerecord_postgres_test/feature/query/basic/test_find_one_or_create.py @@ -0,0 +1,4 @@ +# tests/rhosocial/activerecord_postgres_test/feature/query/basic/test_find_one_or_create.py +"""Bridge file for the testsuite natural-key find_one_or_create contract.""" +from rhosocial.activerecord.testsuite.feature.query.basic.test_find_one_or_create import * # noqa: F403 +from rhosocial.activerecord.testsuite.feature.query.basic.test_find_one_or_create_async import * # noqa: F403 diff --git a/tests/rhosocial/activerecord_postgres_test/feature/relation/ordering/test_has_many_order_by.py b/tests/rhosocial/activerecord_postgres_test/feature/relation/ordering/test_has_many_order_by.py new file mode 100644 index 00000000..c3ba5e03 --- /dev/null +++ b/tests/rhosocial/activerecord_postgres_test/feature/relation/ordering/test_has_many_order_by.py @@ -0,0 +1,4 @@ +# tests/rhosocial/activerecord_postgres_test/feature/relation/ordering/test_has_many_order_by.py +"""Bridge file for the testsuite ordered HasMany contract (sync and async).""" +from rhosocial.activerecord.testsuite.feature.relation.ordering.test_has_many_order_by import * # noqa: F403 +from rhosocial.activerecord.testsuite.feature.relation.ordering.test_has_many_order_by_async import * # noqa: F403