diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index b076c5dd..fa86d81d 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -54,7 +54,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -144,7 +144,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -234,7 +234,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -324,7 +324,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -414,7 +414,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -504,7 +504,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -595,7 +595,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -685,7 +685,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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 @@ -784,7 +784,7 @@ jobs: - name: Install activerecord and testsuite from PyPI 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/14.changed.md b/changelog.d/14.changed.md new file mode 100644 index 00000000..fb085a36 --- /dev/null +++ b/changelog.d/14.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/src/rhosocial/activerecord/backend/impl/sqlserver/async_transaction.py b/src/rhosocial/activerecord/backend/impl/sqlserver/async_transaction.py index 313f28ab..c6f38d21 100644 --- a/src/rhosocial/activerecord/backend/impl/sqlserver/async_transaction.py +++ b/src/rhosocial/activerecord/backend/impl/sqlserver/async_transaction.py @@ -136,7 +136,7 @@ async def commit(self) -> None: try: await super().commit() except Exception as e: - self.log(logging.ERROR, f"Failed to commit async transaction: {str(e)}") + self.log(logging.DEBUG, f"Failed to commit async transaction: {str(e)}") raise async def rollback(self, savepoint: Optional[str] = None) -> None: @@ -155,7 +155,7 @@ async def rollback(self, savepoint: Optional[str] = None) -> None: try: await super().rollback() except Exception as e: - self.log(logging.ERROR, f"Failed to rollback async transaction: {str(e)}") + self.log(logging.DEBUG, f"Failed to rollback async transaction: {str(e)}") raise async def savepoint(self, name: Optional[str] = None) -> str: diff --git a/src/rhosocial/activerecord/backend/impl/sqlserver/backend/async_backend.py b/src/rhosocial/activerecord/backend/impl/sqlserver/backend/async_backend.py index 9cd4d0e4..2292db64 100644 --- a/src/rhosocial/activerecord/backend/impl/sqlserver/backend/async_backend.py +++ b/src/rhosocial/activerecord/backend/impl/sqlserver/backend/async_backend.py @@ -13,6 +13,13 @@ from typing import Any, AsyncIterator, Dict, List, Optional, Set, Tuple from rhosocial.activerecord.backend.base import AsyncStorageBackend +from rhosocial.activerecord.backend.base.execution_logging import ( + log_batch_start, + log_batch_summary, + log_execution_error, + log_execution_start, + log_execution_summary, +) from rhosocial.activerecord.backend.base.operations import AsyncSQLOperationsMixin from rhosocial.activerecord.backend.base.transaction_management import AsyncTransactionManagementMixin from rhosocial.activerecord.backend.errors import ( @@ -23,7 +30,9 @@ OperationalError, QueryError, ) +from rhosocial.activerecord.backend.options import ExecutionOptions, StatementType from rhosocial.activerecord.backend.result import QueryResult +from rhosocial.activerecord.logging.redaction import unwrap_sensitive from rhosocial.activerecord.backend.introspection.backend_mixin import IntrospectorBackendMixin from ..config import SQLServerConnectionConfig from ..dialect import SQLServerDialect @@ -70,7 +79,12 @@ class AsyncSQLServerBackend( >>> print(result.data) >>> await backend.disconnect() """ - + + # ``AsyncSQLServerBackend`` would otherwise be named + # ``rhosocial.activerecord.backend.asyncsqlserver``; share the sync name so + # both halves of the backend emit to one library logger. + _logger_name = "rhosocial.activerecord.backend.sqlserver" + CONNECTION_ERROR_CODES = { 53, 64, 232, 233, 18456, 4060, 40197, 40501, 40613, 11001, } @@ -227,7 +241,7 @@ async def connect(self) -> None: await self.introspect_and_adapt() except Exception as e: - self.log(logging.ERROR, f"Failed to connect to SQL Server: {str(e)}") + self.log(logging.DEBUG, f"Failed to connect to SQL Server: {str(e)}") raise ConnectionError(f"Failed to connect to SQL Server: {str(e)}") from e async def disconnect(self) -> None: @@ -366,10 +380,11 @@ async def _cursor_noscan(self, cursor: Any, noscan: Optional[bool]) -> AsyncIter async def _execute_statement( self, sql: str, params: Optional[Tuple], options, start_time: Optional[float] = None ) -> QueryResult: - from rhosocial.activerecord.backend.options import StatementType - + """Execute one statement without re-entering the backend overrides.""" sql_upper = sql.strip().upper() - + params = unwrap_sensitive(params) + log_execution_start(self, sql, params, options) + if not self._connection: await self.connect() @@ -438,10 +453,9 @@ async def _execute_statement( duration = time.perf_counter() - start_time await self._handle_auto_commit_if_needed() - - self.log( - logging.DEBUG, - f"Query executed in {duration:.3f}s, affected {cursor.rowcount} rows" + + log_execution_summary( + self, options.stmt_type, sql, cursor, data, duration, options ) result = self._build_query_result(cursor, data, duration) @@ -454,43 +468,55 @@ async def _execute_statement( return result except Exception as e: - self.log(logging.ERROR, f"Error executing query: {str(e)}") + log_execution_error(self, e, options) await self._handle_error(e) - async def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: + async def execute_many( + self, + sql: str, + params_list: List[Tuple], + *, + options: Optional[ExecutionOptions] = None, + ) -> Optional[QueryResult]: """Execute the same SQL statement multiple times asynchronously. - + Args: sql: SQL statement to execute params_list: List of parameter tuples - + options: ExecutionOptions carrying the logging context + Returns: QueryResult with affected_rows populated """ + 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) + if not self._connection: await self.connect() start_time = time.perf_counter() try: - if not params_list: - self.log(logging.DEBUG, "Empty parameter list, returning zero affected rows") - return QueryResult(affected_rows=0, data=None, duration=0.0) - async with await self._get_cursor() as cursor: + if not params_list: + duration = time.perf_counter() - start_time + log_batch_summary(self, sql, params_list, 0, duration, options) + return QueryResult(affected_rows=0, data=None, duration=duration) + await cursor.executemany(sql, params_list) - + duration = time.perf_counter() - start_time affected_rows = cursor.rowcount - + + log_batch_summary(self, sql, params_list, affected_rows, duration, options) await self._handle_auto_commit_if_needed() - - self.log(logging.INFO, f"Batch operation completed, affected {affected_rows} rows") - + return QueryResult(affected_rows=affected_rows, data=None, duration=duration) - + except Exception as e: - self.log(logging.ERROR, f"Error in batch operation: {str(e)}") + log_execution_error(self, e, options) await self._handle_error(e) async def get_server_version(self) -> Tuple[int, int, int]: @@ -556,7 +582,7 @@ async def ping(self, reconnect: bool = True) -> bool: await self.connect() return True except Exception as connect_error: - self.log(logging.ERROR, f"Reconnect failed: {str(connect_error)}") + self.log(logging.WARNING, f"Reconnect failed: {str(connect_error)}") return False return False @@ -580,7 +606,7 @@ async def executescript(self, sql_script: str) -> None: Args: sql_script: SQL script with GO separators """ - self.log(logging.INFO, "Executing SQL script (async)") + self.log(logging.DEBUG, "Executing SQL script (async)") start_time = time.perf_counter() if not self._connection: @@ -600,7 +626,7 @@ async def executescript(self, sql_script: str) -> None: self.log(logging.INFO, f"SQL script executed successfully, duration={duration:.3f}s") except Exception as e: - self.log(logging.ERROR, f"Error executing SQL script: {str(e)}") + self.log(logging.DEBUG, f"Error executing SQL script: {str(e)}") await self._handle_error(e) async def _handle_error(self, error: Exception) -> None: @@ -621,23 +647,23 @@ async def _handle_error(self, error: Exception) -> None: or 'cannot insert the value null' in error_msg ): if "duplicate" in error_msg or "unique" in error_msg: - self.log(logging.ERROR, f"Unique constraint violation: {str(error)}") + self.log(logging.DEBUG, f"Unique constraint violation: {str(error)}") raise IntegrityError(f"Unique constraint violation: {str(error)}") elif "foreign key" in error_msg or "reference" in error_msg: - self.log(logging.ERROR, f"Foreign key constraint violation: {str(error)}") + self.log(logging.DEBUG, f"Foreign key constraint violation: {str(error)}") raise IntegrityError(f"Foreign key constraint violation: {str(error)}") - self.log(logging.ERROR, f"Integrity error: {str(error)}") + self.log(logging.DEBUG, f"Integrity error: {str(error)}") raise IntegrityError(self._normalize_integrity_message(str(error))) if 'deadlock' in error_msg or '1205' in error_msg: - self.log(logging.ERROR, f"Deadlock detected: {str(error)}") + self.log(logging.DEBUG, f"Deadlock detected: {str(error)}") raise DeadlockError(str(error)) if 'timeout' in error_msg or 'connection' in error_msg: - self.log(logging.ERROR, f"Operational error: {str(error)}") + self.log(logging.DEBUG, f"Operational error: {str(error)}") raise OperationalError(str(error)) - self.log(logging.ERROR, f"Database error: {str(error)}") + self.log(logging.DEBUG, f"Database error: {str(error)}") raise DatabaseError(str(error)) async def _handle_auto_commit_if_needed(self) -> None: diff --git a/src/rhosocial/activerecord/backend/impl/sqlserver/backend/backend.py b/src/rhosocial/activerecord/backend/impl/sqlserver/backend/backend.py index 5b7bd378..750226fc 100644 --- a/src/rhosocial/activerecord/backend/impl/sqlserver/backend/backend.py +++ b/src/rhosocial/activerecord/backend/impl/sqlserver/backend/backend.py @@ -16,6 +16,11 @@ from pyodbc import Error as PyODBCError, InterfaceError, DatabaseError as PyODBCDatabaseError 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.errors import ( ConnectionError, DatabaseError, @@ -24,8 +29,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 rhosocial.activerecord.backend.introspection.backend_mixin import IntrospectorBackendMixin from rhosocial.activerecord.backend.explain import SyncExplainBackendMixin from ..config import SQLServerConnectionConfig @@ -83,7 +89,11 @@ class SQLServerBackend( >>> print(result.data) >>> backend.disconnect() """ - + + # Keep the library logger name stable even though this class lives in the + # extension package (rhosocial.activerecord.backend.impl.sqlserver). + _logger_name = "rhosocial.activerecord.backend.sqlserver" + CONNECTION_ERROR_CODES = { 53, 64, @@ -252,7 +262,7 @@ def connect(self) -> None: self.introspect_and_adapt() except PyODBCError as e: - self.log(logging.ERROR, f"Failed to connect to SQL Server: {str(e)}") + self.log(logging.DEBUG, f"Failed to connect to SQL Server: {str(e)}") raise ConnectionError(f"Failed to connect to SQL Server: {str(e)}") from e def disconnect(self) -> None: @@ -403,47 +413,55 @@ def _execute_query(self, cursor: Any, sql: str, params: Optional[Tuple]) -> Any: finally: cursor.noscan = previous - def execute_many(self, sql: str, params_list: List[Tuple]) -> QueryResult: + def execute_many( + self, + sql: str, + params_list: List[Tuple], + *, + options: Optional[ExecutionOptions] = None, + ) -> Optional[QueryResult]: """Execute the same SQL statement multiple times with different parameters. - + Args: sql: SQL statement to execute params_list: List of parameter tuples - + options: ExecutionOptions carrying the logging context + Returns: QueryResult with affected_rows populated """ - if not self._connection: - self.connect() - - cursor = None + 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) start_time = time.perf_counter() + cursor = None try: - cursor = self._get_cursor() + if not self._connection: + self.connect() - self.log(logging.DEBUG, f"Executing batch operation: {sql}") - self.log(logging.DEBUG, f"With {len(params_list)} parameter sets") + cursor = self._get_cursor() if not params_list: - self.log(logging.DEBUG, "Empty parameter list, returning zero affected rows") - return QueryResult(affected_rows=0, data=None, duration=0.0) + duration = time.perf_counter() - start_time + log_batch_summary(self, sql, params_list, 0, duration, options) + return QueryResult(affected_rows=0, data=None, duration=duration) cursor.executemany(sql, params_list) - + duration = time.perf_counter() - start_time affected_rows = cursor.rowcount - + + log_batch_summary(self, sql, params_list, affected_rows, duration, options) self._handle_auto_commit_if_needed() - - self.log(logging.INFO, f"Batch operation completed, affected {affected_rows} rows") - + return QueryResult(affected_rows=affected_rows, data=None, duration=duration) - + except PyODBCError as e: - self.log(logging.ERROR, f"Error in batch operation: {str(e)}") + log_execution_error(self, e, options) self._handle_error(e) - + finally: if cursor: cursor.close() @@ -517,7 +535,7 @@ def ping(self, reconnect: bool = True) -> bool: self.connect() return True except Exception as connect_error: - self.log(logging.ERROR, f"Reconnect failed: {str(connect_error)}") + self.log(logging.WARNING, f"Reconnect failed: {str(connect_error)}") return False return False @@ -548,7 +566,7 @@ def executescript(self, sql_script: str) -> None: Args: sql_script: SQL script with GO separators """ - self.log(logging.INFO, "Executing SQL script") + self.log(logging.DEBUG, "Executing SQL script") start_time = time.perf_counter() if not self._connection: @@ -569,7 +587,7 @@ def executescript(self, sql_script: str) -> None: self.log(logging.INFO, f"SQL script executed successfully, duration={duration:.3f}s") except PyODBCError as e: - self.log(logging.ERROR, f"Error executing SQL script: {str(e)}") + self.log(logging.DEBUG, f"Error executing SQL script: {str(e)}") self._handle_error(e) def _handle_error(self, error: Exception) -> None: @@ -590,34 +608,34 @@ def _handle_error(self, error: Exception) -> None: if isinstance(error, pyodbc.IntegrityError): if "duplicate" in error_msg or "unique" in error_msg: - self.log(logging.ERROR, f"Unique constraint violation: {str(error)}") + self.log(logging.DEBUG, f"Unique constraint violation: {str(error)}") raise IntegrityError(f"Unique constraint violation: {str(error)}") elif "foreign key" in error_msg or "reference" in error_msg: - self.log(logging.ERROR, f"Foreign key constraint violation: {str(error)}") + self.log(logging.DEBUG, f"Foreign key constraint violation: {str(error)}") raise IntegrityError(f"Foreign key constraint violation: {str(error)}") - self.log(logging.ERROR, f"Integrity error: {str(error)}") + self.log(logging.DEBUG, f"Integrity error: {str(error)}") raise IntegrityError(self._normalize_integrity_message(str(error))) elif isinstance(error, pyodbc.DatabaseError): if hasattr(error, 'args') and len(error.args) > 0: error_code = error.args[0] if error_code == 1205: - self.log(logging.ERROR, f"Deadlock detected: {str(error)}") + self.log(logging.DEBUG, f"Deadlock detected: {str(error)}") raise DeadlockError(str(error)) - self.log(logging.ERROR, f"Database error: {str(error)}") + self.log(logging.DEBUG, f"Database error: {str(error)}") raise DatabaseError(str(error)) elif isinstance(error, pyodbc.OperationalError): - self.log(logging.ERROR, f"Operational error: {str(error)}") + self.log(logging.DEBUG, f"Operational error: {str(error)}") raise OperationalError(str(error)) elif isinstance(error, PyODBCError): - self.log(logging.ERROR, f"SQL Server error: {str(error)}") + self.log(logging.DEBUG, f"SQL Server error: {str(error)}") raise DatabaseError(str(error)) else: - self.log(logging.ERROR, f"Unexpected error: {str(error)}") + self.log(logging.DEBUG, f"Unexpected error: {str(error)}") raise error def _handle_auto_commit_if_needed(self) -> None: diff --git a/src/rhosocial/activerecord/backend/impl/sqlserver/cli/info.py b/src/rhosocial/activerecord/backend/impl/sqlserver/cli/info.py index 848db971..7191d870 100644 --- a/src/rhosocial/activerecord/backend/impl/sqlserver/cli/info.py +++ b/src/rhosocial/activerecord/backend/impl/sqlserver/cli/info.py @@ -8,7 +8,6 @@ import argparse import inspect import json -import logging import sys from typing import Any, Dict, List, Optional, Tuple @@ -52,8 +51,9 @@ from .connection import add_connection_args, add_version_arg, resolve_connection_config_from_args from .output import INFO_OUTPUT_CHOICES, create_provider, RICH_AVAILABLE +from rhosocial.activerecord.logging.defaults import get_logger -logger = logging.getLogger(__name__) +logger = get_logger(__name__) DIALECT_SPECIFIC_GROUPS = {"SQL Server Native"} diff --git a/src/rhosocial/activerecord/backend/impl/sqlserver/mixins/backend_mixin.py b/src/rhosocial/activerecord/backend/impl/sqlserver/mixins/backend_mixin.py index 326e5e1b..d9eafcaa 100644 --- a/src/rhosocial/activerecord/backend/impl/sqlserver/mixins/backend_mixin.py +++ b/src/rhosocial/activerecord/backend/impl/sqlserver/mixins/backend_mixin.py @@ -303,10 +303,6 @@ def is_case_sensitive(self) -> bool: return "_CS" in collation or collation.endswith("_CS_AS") return False - def log(self, level: int, message: str) -> None: - if hasattr(self, '_logger') and self._logger: - self._logger.log(level, message) - def get_default_adapter_suggestions(self) -> Dict[Type, Tuple[Any, Type]]: if hasattr(self, '_default_suggestions_cache') and self._default_suggestions_cache is not None: return self._default_suggestions_cache diff --git a/src/rhosocial/activerecord/backend/impl/sqlserver/transaction.py b/src/rhosocial/activerecord/backend/impl/sqlserver/transaction.py index 9993d331..8dc25045 100644 --- a/src/rhosocial/activerecord/backend/impl/sqlserver/transaction.py +++ b/src/rhosocial/activerecord/backend/impl/sqlserver/transaction.py @@ -144,7 +144,7 @@ def commit(self) -> None: try: super().commit() except Exception as e: - self.log(logging.ERROR, f"Failed to commit transaction: {str(e)}") + self.log(logging.DEBUG, f"Failed to commit transaction: {str(e)}") raise def rollback(self, savepoint: Optional[str] = None) -> None: @@ -164,7 +164,7 @@ def rollback(self, savepoint: Optional[str] = None) -> None: try: super().rollback() except Exception as e: - self.log(logging.ERROR, f"Failed to rollback transaction: {str(e)}") + self.log(logging.DEBUG, f"Failed to rollback transaction: {str(e)}") raise def _do_rollback(self) -> None: diff --git a/tests/rhosocial/activerecord_sqlserver_test/feature/basic/nopk/test_keyless_models.py b/tests/rhosocial/activerecord_sqlserver_test/feature/basic/nopk/test_keyless_models.py new file mode 100644 index 00000000..a0dd8778 --- /dev/null +++ b/tests/rhosocial/activerecord_sqlserver_test/feature/basic/nopk/test_keyless_models.py @@ -0,0 +1,3 @@ +# tests/rhosocial/activerecord_sqlserver_test/feature/basic/nopk/test_keyless_models.py +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_sqlserver_test/feature/basic/readonly/test_readonly_models.py b/tests/rhosocial/activerecord_sqlserver_test/feature/basic/readonly/test_readonly_models.py new file mode 100644 index 00000000..61b36ea8 --- /dev/null +++ b/tests/rhosocial/activerecord_sqlserver_test/feature/basic/readonly/test_readonly_models.py @@ -0,0 +1,3 @@ +# tests/rhosocial/activerecord_sqlserver_test/feature/basic/readonly/test_readonly_models.py +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_sqlserver_test/feature/logging/test_execution_logging_unit.py b/tests/rhosocial/activerecord_sqlserver_test/feature/logging/test_execution_logging_unit.py new file mode 100644 index 00000000..6c52380b --- /dev/null +++ b/tests/rhosocial/activerecord_sqlserver_test/feature/logging/test_execution_logging_unit.py @@ -0,0 +1,458 @@ +# tests/rhosocial/activerecord_sqlserver_test/feature/logging/test_execution_logging_unit.py +"""Database-free coverage tests for SQL Server execution logging. + +Every case here drives the backend through fakes: no SQL Server, no pyodbc +connection and no aioodbc connection is opened. The tests pin the canonical +library logger name, the batch logging contract (parameter sets, never +parameter values), the ``_handle_error`` branches and the transaction +commit/rollback failure guards. + +The sync and async cases share method names; the async execution path also +needs its own ``_execute_statement`` coverage because that statement splitter +has no sync twin. +""" + +import logging + +import pytest + +pyodbc = pytest.importorskip("pyodbc") + +from rhosocial.activerecord.backend.errors import ( # noqa: E402 + DatabaseError, + DeadlockError, + IntegrityError, + OperationalError, + TransactionError, +) +from rhosocial.activerecord.backend.options import ExecutionOptions, StatementType # noqa: E402 +from rhosocial.activerecord.logging.redaction import SensitiveValue # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver.backend import backend as backend_mod # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver.backend import async_backend as async_backend_mod # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver.backend.backend import SQLServerBackend # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver.backend.async_backend import ( # noqa: E402 + AsyncSQLServerBackend, +) +from rhosocial.activerecord.backend.impl.sqlserver.mixins import backend_mixin # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver import transaction as transaction_mod # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver import async_transaction as async_transaction_mod # noqa: E402 +from rhosocial.activerecord.backend.impl.sqlserver.cli import info as cli_info_mod # noqa: E402 + + +LOGGER_NAME = "rhosocial.activerecord.backend.sqlserver" +BATCH_SQL = "INSERT INTO unit_users (name, token) VALUES (?, ?)" + + +class FakeSyncCursor: + """Minimal DB-API cursor recording the calls the backend makes.""" + + def __init__(self, rowcount=2, execute_error=None): + self.rowcount = rowcount + self.execute_error = execute_error + self.description = None + self.executed = [] + self.batches = [] + self.closed = 0 + + def execute(self, sql, params=()): + self.executed.append((sql, params)) + if self.execute_error is not None: + raise self.execute_error + return self + + def executemany(self, sql, params_list): + self.batches.append((sql, list(params_list))) + + def fetchone(self): + return (1,) + + def fetchall(self): + return [] + + def close(self): + self.closed += 1 + + +class FakeSyncConnection: + """Connection stand-in whose cursors never touch a driver.""" + + def __init__(self, **cursor_kwargs): + self.cursors = [] + self._cursor_kwargs = cursor_kwargs + self.commits = 0 + + def cursor(self): + cursor = FakeSyncCursor(**self._cursor_kwargs) + self.cursors.append(cursor) + return cursor + + def commit(self): + self.commits += 1 + + +class FakeAsyncCursor: + """Async cursor stand-in supporting the ``async with`` protocol.""" + + def __init__(self, rowcount=2, execute_error=None): + self.rowcount = rowcount + self.execute_error = execute_error + self.description = None + self.lastrowid = None + self.executed = [] + self.batches = [] + self.closed = 0 + + async def __aenter__(self): + return self + + async def __aexit__(self, exc_type, exc, tb): + return False + + async def execute(self, sql, params=()): + self.executed.append((sql, params)) + if self.execute_error is not None: + raise self.execute_error + return self + + async def executemany(self, sql, params_list): + self.batches.append((sql, list(params_list))) + + async def fetchone(self): + return (1,) + + async def fetchall(self): + return [] + + async def close(self): + self.closed += 1 + + +class FakeAsyncConnection: + """Async connection stand-in whose cursors never touch a driver.""" + + def __init__(self, **cursor_kwargs): + self.cursors = [] + self._cursor_kwargs = cursor_kwargs + + async def cursor(self): + cursor = FakeAsyncCursor(**self._cursor_kwargs) + self.cursors.append(cursor) + return cursor + + async def close(self): + pass + + +@pytest.fixture +def log_records(): + """Capture records emitted on the canonical SQL Server logger.""" + logger = logging.getLogger(LOGGER_NAME) + previous_level = logger.level + previous_propagate = logger.propagate + records = [] + + class _Capture(logging.Handler): + def emit(self, record): + records.append(record) + + handler = _Capture() + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + logger.propagate = False + try: + yield records + finally: + logger.removeHandler(handler) + logger.setLevel(previous_level) + logger.propagate = previous_propagate + + +@pytest.fixture +def sqlserver_backend(): + """Construct a backend without connecting to a server.""" + return SQLServerBackend(database="unit_db", autocommit=True) + + +@pytest.fixture +def async_sqlserver_backend(monkeypatch): + """Construct an async backend without an aioodbc installation. + + ``AsyncSQLServerBackend.__init__`` only rejects a missing driver; the + driver is not used until ``connect``. Substituting a sentinel keeps these + tests runnable on machines where aioodbc is not installed while CI still + exercises the same constructor with the real package. + """ + if async_backend_mod.aioodbc is None: + monkeypatch.setattr(async_backend_mod, "aioodbc", object()) + return AsyncSQLServerBackend(database="unit_db", autocommit=True) + + +def _messages(records): + return [record.getMessage() for record in records] + + +class TestExecutionLogging: + """Synchronous execution logging coverage.""" + + def test_changed_modules_use_the_expected_objects(self): + assert backend_mod.SQLServerBackend is SQLServerBackend + assert async_backend_mod.AsyncSQLServerBackend is AsyncSQLServerBackend + assert backend_mixin.SQLServerBackendMixin is not None + assert transaction_mod.SQLServerTransactionManager is not None + assert async_transaction_mod.AsyncSQLServerTransactionManager is not None + + def test_backend_logger_name(self, sqlserver_backend): + assert sqlserver_backend._logger_name == LOGGER_NAME + assert sqlserver_backend._get_logger_name() == LOGGER_NAME + assert sqlserver_backend.logger.name == LOGGER_NAME + + def test_execute_many_logs_parameter_sets_not_values( + self, sqlserver_backend, log_records + ): + sqlserver_backend._connection = FakeSyncConnection() + params_list = [ + ("alice", SensitiveValue("s3cr3t-value")), + ("bob", SensitiveValue("s3cr3t-value")), + ] + + result = sqlserver_backend.execute_many(BATCH_SQL, params_list) + + assert result.affected_rows == 2 + cursor = sqlserver_backend._connection.cursors[-1] + assert cursor.batches == [( + BATCH_SQL, + [("alice", "s3cr3t-value"), ("bob", "s3cr3t-value")], + )] + text = "\n".join(_messages(log_records)) + assert "parameter_sets: 2" in text + assert "s3cr3t-value" not in text + + def test_execute_many_empty_parameter_list(self, sqlserver_backend, log_records): + sqlserver_backend._connection = FakeSyncConnection() + + result = sqlserver_backend.execute_many(BATCH_SQL, []) + + assert result.affected_rows == 0 + assert result.data is None + text = "\n".join(_messages(log_records)) + assert "parameter_sets: 0" in text + assert "rows_affected=0" in text + + def test_executescript_logs_script_start(self, sqlserver_backend, log_records): + sqlserver_backend._connection = FakeSyncConnection() + + sqlserver_backend.executescript("SELECT 1\nGO\nSELECT 2") + + executed = [ + call for cursor in sqlserver_backend._connection.cursors + for call in cursor.executed + ] + assert ("SELECT 1", ()) in executed + assert ("SELECT 2", ()) in executed + text = "\n".join(_messages(log_records)) + assert "Executing SQL script" in text + assert "SQL script executed successfully" in text + + def test_handle_error_branches(self, sqlserver_backend, log_records): + with pytest.raises(IntegrityError, match="Unique constraint violation"): + sqlserver_backend._handle_error( + pyodbc.IntegrityError("23000", "[23000] Duplicate key") + ) + with pytest.raises(IntegrityError, match="Foreign key constraint violation"): + sqlserver_backend._handle_error( + pyodbc.IntegrityError("23000", "[23000] Foreign key reference") + ) + with pytest.raises(IntegrityError): + sqlserver_backend._handle_error( + pyodbc.IntegrityError("23000", "[23000] Integrity constraint") + ) + with pytest.raises(DatabaseError): + sqlserver_backend._handle_error( + pyodbc.DatabaseError("HY000", "[HY000] General database failure") + ) + with pytest.raises(DeadlockError): + sqlserver_backend._handle_error( + pyodbc.DatabaseError(1205, "Deadlock victim") + ) + + text = "\n".join(_messages(log_records)) + assert "Unique constraint violation" in text + assert "Foreign key constraint violation" in text + assert "Integrity error" in text + assert "Database error" in text + assert "Deadlock detected" in text + + def test_transaction_failure_guards(self, log_records): + manager = transaction_mod.SQLServerTransactionManager( + object(), logging.getLogger(LOGGER_NAME) + ) + manager._transaction_level = 1 + + def fail(): + raise RuntimeError("simulated driver failure") + + manager._do_commit = fail + with pytest.raises(TransactionError): + manager.commit() + + manager._do_rollback = fail + with pytest.raises(TransactionError): + manager.rollback() + + text = "\n".join(_messages(log_records)) + assert "Failed to commit transaction" in text + assert "Failed to rollback transaction" in text + + def test_cli_info_uses_the_library_logger(self): + assert cli_info_mod.logger.name == cli_info_mod.__name__ + + +class TestAsyncExecutionLogging: + """Asynchronous execution logging coverage (same method names as sync).""" + + async def test_changed_modules_use_the_expected_objects(self): + assert backend_mod.SQLServerBackend is SQLServerBackend + assert async_backend_mod.AsyncSQLServerBackend is AsyncSQLServerBackend + assert backend_mixin.SQLServerBackendMixin is not None + assert transaction_mod.SQLServerTransactionManager is not None + assert async_transaction_mod.AsyncSQLServerTransactionManager is not None + + async def test_backend_logger_name(self, async_sqlserver_backend): + assert async_sqlserver_backend._logger_name == LOGGER_NAME + assert async_sqlserver_backend._get_logger_name() == LOGGER_NAME + assert async_sqlserver_backend.logger.name == LOGGER_NAME + + async def test_execute_many_logs_parameter_sets_not_values( + self, async_sqlserver_backend, log_records + ): + async_sqlserver_backend._connection = FakeAsyncConnection() + params_list = [ + ("alice", SensitiveValue("s3cr3t-value")), + ("bob", SensitiveValue("s3cr3t-value")), + ] + + result = await async_sqlserver_backend.execute_many(BATCH_SQL, params_list) + + assert result.affected_rows == 2 + cursor = async_sqlserver_backend._connection.cursors[-1] + assert cursor.batches == [( + BATCH_SQL, + [("alice", "s3cr3t-value"), ("bob", "s3cr3t-value")], + )] + text = "\n".join(_messages(log_records)) + assert "parameter_sets: 2" in text + assert "s3cr3t-value" not in text + + async def test_execute_many_empty_parameter_list( + self, async_sqlserver_backend, log_records + ): + async_sqlserver_backend._connection = FakeAsyncConnection() + + result = await async_sqlserver_backend.execute_many(BATCH_SQL, []) + + assert result.affected_rows == 0 + assert result.data is None + text = "\n".join(_messages(log_records)) + assert "parameter_sets: 0" in text + assert "rows_affected=0" in text + + async def test_executescript_logs_script_start( + self, async_sqlserver_backend, log_records + ): + async_sqlserver_backend._connection = FakeAsyncConnection() + + await async_sqlserver_backend.executescript("SELECT 1\nGO\nSELECT 2") + + executed = [ + call for cursor in async_sqlserver_backend._connection.cursors + for call in cursor.executed + ] + assert ("SELECT 1", ()) in executed + assert ("SELECT 2", ()) in executed + text = "\n".join(_messages(log_records)) + assert "Executing SQL script (async)" in text + assert "SQL script executed successfully" in text + + async def test_handle_error_branches(self, async_sqlserver_backend, log_records): + with pytest.raises(IntegrityError, match="Unique constraint violation"): + await async_sqlserver_backend._handle_error( + Exception("integrity violation: duplicate key") + ) + with pytest.raises(IntegrityError, match="Foreign key constraint violation"): + await async_sqlserver_backend._handle_error( + Exception("integrity violation: foreign key constraint") + ) + with pytest.raises(IntegrityError): + await async_sqlserver_backend._handle_error( + Exception("integrity violation") + ) + with pytest.raises(DeadlockError): + await async_sqlserver_backend._handle_error( + Exception("deadlock detected, error 1205") + ) + with pytest.raises(OperationalError): + await async_sqlserver_backend._handle_error( + Exception("connection timeout expired") + ) + with pytest.raises(DatabaseError): + await async_sqlserver_backend._handle_error( + Exception("unexpected database failure") + ) + + text = "\n".join(_messages(log_records)) + assert "Unique constraint violation" in text + assert "Foreign key constraint violation" in text + assert "Integrity error" in text + assert "Deadlock detected" in text + assert "Operational error" in text + assert "Database error" in text + + async def test_execute_statement_logs_and_reports_failures( + self, async_sqlserver_backend, log_records + ): + options = ExecutionOptions(stmt_type=StatementType.DQL) + async_sqlserver_backend._connection = FakeAsyncConnection() + + result = await async_sqlserver_backend._execute_statement( + "SELECT 1", None, options + ) + + assert result.data is None + text = "\n".join(_messages(log_records)) + assert "Executing SQL: SELECT 1" in text + assert "parameters: None" in text + + log_records.clear() + async_sqlserver_backend._connection = FakeAsyncConnection( + execute_error=RuntimeError("unexpected query failure") + ) + with pytest.raises(DatabaseError): + await async_sqlserver_backend._execute_statement( + "SELECT 1", None, options + ) + text = "\n".join(_messages(log_records)) + assert "Query failed, exception will be re-raised" in text + + async def test_transaction_failure_guards(self, log_records): + manager = async_transaction_mod.AsyncSQLServerTransactionManager( + object(), logging.getLogger(LOGGER_NAME) + ) + manager._transaction_level = 1 + + async def fail(): + raise RuntimeError("simulated driver failure") + + manager._do_commit = fail + with pytest.raises(TransactionError): + await manager.commit() + + manager._do_rollback = fail + with pytest.raises(TransactionError): + await manager.rollback() + + text = "\n".join(_messages(log_records)) + assert "Failed to commit async transaction" in text + assert "Failed to rollback async transaction" in text + + async def test_cli_info_uses_the_library_logger(self): + assert cli_info_mod.logger.name == cli_info_mod.__name__ diff --git a/tests/rhosocial/activerecord_sqlserver_test/feature/query/basic/test_find_one_or_create.py b/tests/rhosocial/activerecord_sqlserver_test/feature/query/basic/test_find_one_or_create.py new file mode 100644 index 00000000..c87b5482 --- /dev/null +++ b/tests/rhosocial/activerecord_sqlserver_test/feature/query/basic/test_find_one_or_create.py @@ -0,0 +1,3 @@ +# tests/rhosocial/activerecord_sqlserver_test/feature/query/basic/test_find_one_or_create.py +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_sqlserver_test/feature/relation/ordering/test_has_many_order_by.py b/tests/rhosocial/activerecord_sqlserver_test/feature/relation/ordering/test_has_many_order_by.py new file mode 100644 index 00000000..59300264 --- /dev/null +++ b/tests/rhosocial/activerecord_sqlserver_test/feature/relation/ordering/test_has_many_order_by.py @@ -0,0 +1,3 @@ +# tests/rhosocial/activerecord_sqlserver_test/feature/relation/ordering/test_has_many_order_by.py +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