feat(logging): adapt execution logging and shared contracts

.github/workflows/test.yml

@@ -66,7 +66,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

changelog.d/11.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.

src/rhosocial/activerecord/backend/impl/clickhouse/backend/backend.py

@@ -7,45 +7,44 @@
 specific behaviors and SQL dialect.
 """
 
-import datetime
 import logging
+import time
 from typing import Any, List, Optional, Tuple
 
 try:
     import clickhouse_connect
     from clickhouse_connect.dbapi import connect as clickhouse_connect_dbapi_connect
     from clickhouse_connect.driver.exceptions import (
-        DatabaseError as ClickHouseDatabaseError,
         Error as ClickHouseError,
-        IntegrityError as ClickHouseIntegrityError,
         OperationalError as ClickHouseOperationalError,
     )
 except ImportError:  # pragma: no cover
     clickhouse_connect = None  # type: ignore
     clickhouse_connect_dbapi_connect = None  # type: ignore
-    ClickHouseDatabaseError = Exception
     ClickHouseError = Exception
-    ClickHouseIntegrityError = Exception
     ClickHouseOperationalError = Exception
 
 from rhosocial.activerecord.backend.base import StorageBackend
-from rhosocial.activerecord.backend.errors import (
-    ConnectionError,
-    DatabaseError,
-    IntegrityError,
-    QueryError,
+from rhosocial.activerecord.backend.base.execution_logging import (
+    log_batch_start,
+    log_batch_summary,
+    log_execution_error,
 )
+from rhosocial.activerecord.backend.base.operations import execution_log_context
+from rhosocial.activerecord.backend.errors import ConnectionError, DatabaseError
 from rhosocial.activerecord.backend.options import (
     BulkInsertOptions,
     BulkUpdateOptions,
     DeleteOptions,
     ExecutionOptions,
     InsertOptions,
+    StatementType,
     UpdateOptions,
 )
 from rhosocial.activerecord.backend.result import QueryResult
 from rhosocial.activerecord.backend.introspection.backend_mixin import IntrospectorBackendMixin
 from rhosocial.activerecord.backend.explain import SyncExplainBackendMixin
+from rhosocial.activerecord.logging.redaction import unwrap_sensitive
 from ..config import ClickHouseConnectionConfig
 from ..dialect import ClickHouseDialect
 from ..transaction import ClickHouseTransactionManager
@@ -211,6 +210,7 @@ def bulk_insert(self, options: BulkInsertOptions) -> QueryResult:
                 returning_columns=options.returning_columns,
                 auto_commit=options.auto_commit,
                 primary_key=options.primary_key,
+                log_context=execution_log_context(options, "bulk_insert"),
             )
 
         result = super().bulk_insert(options)
@@ -245,6 +245,7 @@ def update(self, options: UpdateOptions) -> QueryResult:
                     returning_columns=options.returning_columns,
                     auto_commit=options.auto_commit,
                     primary_key=options.primary_key,
+                    log_context=execution_log_context(options, "update"),
                 )
         # ClickHouse cannot report how many rows a mutation affected, so capture
         # the matching-row count BEFORE running the mutation (the WHERE columns
@@ -422,7 +423,10 @@ def connect(self) -> None:
             )
             self._fetch_concurrency_hint()
         except ClickHouseError as e:
-            self.log(logging.ERROR, f"Failed to connect to ClickHouse database: {str(e)}")
+            self.log(
+                logging.DEBUG,
+                f"Failed to connect to ClickHouse database, exception will be re-raised: {str(e)}",
+            )
             raise ConnectionError(f"Failed to connect to ClickHouse: {str(e)}") from e
 
     def disconnect(self) -> None:
@@ -479,47 +483,52 @@ def _get_cursor(self) -> Any:
 
         return self._connection.cursor()
 
-    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.
+
+        ClickHouse executes the statement once per parameter set, because the
+        driver's ``executemany`` path does not report per-row counts. The batch
+        DEBUG record and its INFO summary come from the shared execution-logging
+        helpers, so the canonical SQL line is not duplicated here.
+        """
+        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:
             self.connect()
 
         cursor = None
-        start_time = datetime.datetime.now()
+        start_time = time.perf_counter()
 
         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
             escaped_sql = self._escape_literal_percent(sql)
             affected_rows = 0
             for params in params_list:
                 cursor.execute(escaped_sql, params)
                 affected_rows += cursor.rowcount
 
-            duration = (datetime.datetime.now() - start_time).total_seconds()
+            duration = time.perf_counter() - start_time
 
             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 ClickHouseIntegrityError as e:
-            self.log(logging.ERROR, f"Integrity error in batch: {str(e)}")
-            raise IntegrityError(str(e)) from e
-        except ClickHouseError as e:
-            self.log(logging.ERROR, f"ClickHouse error in batch: {str(e)}")
-            raise DatabaseError(str(e)) from e
         except Exception as e:
-            self.log(logging.ERROR, f"Unexpected error during batch execution: {str(e)}")
-            raise QueryError(str(e)) from e
+            log_execution_error(self, e, options)
+            self._handle_error(e)
+            return None
         finally:
             if cursor:
                 cursor.close()
@@ -700,8 +709,6 @@ def execute(
         Raises:
             DatabaseError: If execution fails after all retries
         """
-        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
@@ -748,7 +755,7 @@ def execute(
                     if self._reconnect():
                         continue
                     else:
-                        self.log(logging.ERROR, "Reconnection failed, aborting retry")
+                        self.log(logging.DEBUG, "Reconnection failed, aborting retry")
                         break
                 else:
                     # Not a connection error or max retries reached
@@ -772,9 +779,7 @@ def executescript(self, sql_script: str) -> None:
             sql_script: A string containing one or more SQL statements separated
                        by semicolons.
         """
-        import time
-
-        self.log(logging.INFO, "Executing SQL script.")
+        self.log(logging.DEBUG, "Executing SQL script.")
         start_time = time.perf_counter()
 
         if not self._connection:
@@ -791,7 +796,10 @@ def executescript(self, sql_script: str) -> None:
             self.log(logging.INFO, f"SQL script executed successfully, duration={duration:.3f}s")
 
         except ClickHouseError as e:
-            self.log(logging.ERROR, f"Error executing SQL script: {str(e)}")
+            self.log(
+                logging.DEBUG,
+                f"Error executing SQL script, exception will be re-raised: {str(e)}",
+            )
             self._handle_error(e)
         finally:
             if cursor:

src/rhosocial/activerecord/backend/impl/clickhouse/cli/info.py

@@ -8,9 +8,10 @@
 import argparse
 import inspect
 import json
-import logging
 from typing import Any, Dict, List, Tuple
 
+from rhosocial.activerecord.logging.defaults import get_logger
+
 from rhosocial.activerecord.backend.dialect.protocols import (
     WindowFunctionSupport,
     CTESupport,
@@ -52,7 +53,7 @@
 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(__name__)
 
 # Groups that are specific to ClickHouse dialect
 DIALECT_SPECIFIC_GROUPS = {"ClickHouse-specific"}

src/rhosocial/activerecord/backend/impl/clickhouse/mixins/backend_mixin.py

@@ -124,13 +124,6 @@ def get_default_adapter_suggestions(self) -> Dict[Type, Tuple[SQLTypeAdapter, Ty
 
         return suggestions
 
-    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:
-            print(f"[{logging.getLevelName(level)}] {message}")
-
     CONNECTION_ERROR_CODES = {
         503,
         504,
@@ -178,19 +171,20 @@ def _handle_error(self, error: Exception) -> None:
 
         if isinstance(error, ClickHouseIntegrityError):
             if "UNIQUE constraint" in error_msg or "Violates unique constraint" in error_msg:
-                self.log(logging.ERROR, f"Unique constraint violation: {error_msg}")
                 raise IntegrityError(f"Unique constraint violation: {error_msg}")
-            self.log(logging.ERROR, f"Integrity error: {error_msg}")
             raise IntegrityError(error_msg)
         elif isinstance(error, ClickHouseDatabaseError):
-            self.log(logging.ERROR, f"Database error: {error_msg}")
+            # ClickHouse enforces NOT NULL through its type system, so a
+            # assignment of NULL to a non-nullable column arrives as a generic
+            # database error (CANNOT_CONVERT_TYPE) rather than as an integrity
+            # error.  Preserve the cross-backend contract and classify it as a
+            # not-null violation.
+            if "Cannot convert NULL to a non-nullable type" in error_msg:
+                raise IntegrityError(f"cannot be null: {error_msg}")
             raise DatabaseError(error_msg)
         elif isinstance(error, ClickHouseOperationalError):
-            self.log(logging.ERROR, f"Operational error: {error_msg}")
             raise OperationalError(error_msg)
         elif isinstance(error, ClickHouseError):
-            self.log(logging.ERROR, f"ClickHouse error: {error_msg}")
             raise DatabaseError(error_msg)
         else:
-            self.log(logging.ERROR, f"Unexpected error: {error_msg}")
             raise error

src/rhosocial/activerecord/backend/impl/clickhouse/mixins/transaction.py

@@ -27,16 +27,14 @@ def isolation_level(self, level: Optional[IsolationLevel]):
 
         self.log(logging.DEBUG, f"Setting isolation level to {level}")
         if self.is_active:
-            self.log(logging.ERROR, "Cannot change isolation level during active transaction")
             raise IsolationLevelError("Cannot change isolation level during active transaction")
 
         if level is not None and level not in self._ISOLATION_LEVELS:
             error_msg = f"Unsupported isolation level: {level}"
-            self.log(logging.ERROR, error_msg)
             raise IsolationLevelError(error_msg)
 
         self._isolation_level = level
-        self.log(logging.INFO, f"Isolation level set to {level}")
+        self.log(logging.DEBUG, f"Isolation level set to {level}")
 
     def _build_set_isolation_sql(self, level: IsolationLevel) -> Tuple[str, tuple]:
         """Build SET TRANSACTION ISOLATION LEVEL SQL statement."""

tests/rhosocial/activerecord_clickhouse_test/feature/basic/nopk/test_keyless_models.py

@@ -0,0 +1,4 @@
+# tests/rhosocial/activerecord_clickhouse_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

tests/rhosocial/activerecord_clickhouse_test/feature/basic/readonly/test_readonly_models.py

@@ -0,0 +1,4 @@
+# tests/rhosocial/activerecord_clickhouse_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