From 6838a3ad4009dd003fe3dd7197020b8fca433a6f Mon Sep 17 00:00:00 2001 From: Subrata Paitandi Date: Thu, 12 Feb 2026 17:09:06 +0000 Subject: [PATCH 1/6] bulk copy changes for logging --- mssql_python/cursor.py | 3 +++ mssql_python/logging.py | 56 +++++++++++++++++++++++++++++++++++------ 2 files changed, 51 insertions(+), 8 deletions(-) diff --git a/mssql_python/cursor.py b/mssql_python/cursor.py index 3dd7aa283..c1e4124a8 100644 --- a/mssql_python/cursor.py +++ b/mssql_python/cursor.py @@ -2623,6 +2623,8 @@ def _bulkcopy( pycore_connection = mssql_py_core.PyCoreConnection(pycore_context) pycore_cursor = pycore_connection.cursor() + # Call bulkcopy with explicit keyword arguments + # The API signature: bulkcopy(table_name, data_source, batch_size=0, timeout=30, ...) result = pycore_cursor.bulkcopy( table_name, iter(data), @@ -2635,6 +2637,7 @@ def _bulkcopy( keep_nulls=keep_nulls, fire_triggers=fire_triggers, use_internal_transaction=use_internal_transaction, + python_logger=logger, # Pass Python logger handle to pycore ) return result diff --git a/mssql_python/logging.py b/mssql_python/logging.py index 2cb9361f5..41a94ce13 100644 --- a/mssql_python/logging.py +++ b/mssql_python/logging.py @@ -145,15 +145,20 @@ def _setup_handlers(self): # Custom formatter to extract source from message and format as CSV class CSVFormatter(logging.Formatter): def format(self, record): - # Extract source from message (e.g., [Python] or [DDBC]) - msg = record.getMessage() - if msg.startswith("[") and "]" in msg: - end_bracket = msg.index("]") - source = msg[1:end_bracket] - message = msg[end_bracket + 2 :].strip() # Skip '] ' + # Check if this is from Rust (via rust_log method) + if hasattr(record, 'funcName') and record.funcName == "rust": + source = "Rust" + message = record.getMessage() else: - source = "Unknown" - message = msg + # Extract source from message (e.g., [Python] or [DDBC]) + msg = record.getMessage() + if msg.startswith("[") and "]" in msg: + end_bracket = msg.index("]") + source = msg[1:end_bracket] + message = msg[end_bracket + 2 :].strip() # Skip '] ' + else: + source = "Unknown" + message = msg # Format timestamp with milliseconds using period separator timestamp = self.formatTime(record, "%Y-%m-%d %H:%M:%S") @@ -326,6 +331,41 @@ def _write_log_header(self): pass # Even stderr notification failed # Don't crash - logging continues without header + def rust_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: int = 0): + """ + Logging method for Rust code with custom source location. + + Args: + level: Log level (DEBUG, INFO, WARNING, ERROR) + msg: Message string (already formatted) + filename: Source filename (e.g., 'cursor.rs') + lineno: Line number in source file + """ + try: + if not self._logger.isEnabledFor(level): + return + + # Create a custom LogRecord with Rust source location + import logging as log_module + record = log_module.LogRecord( + name=self._logger.name, + level=level, + pathname=filename, + lineno=lineno, + msg=msg, + args=(), + exc_info=None, + func="rust", + sinfo=None + ) + self._logger.handle(record) + except Exception: + # Fallback - use regular logging + try: + self._logger.log(level, msg) + except: + pass + def _log(self, level: int, msg: str, add_prefix: bool = True, *args, **kwargs): """ Internal logging method with exception safety. From 319867053471cc9c283993e23d2e4a3483fc1f4b Mon Sep 17 00:00:00 2001 From: Subrata Paitandi Date: Mon, 16 Feb 2026 07:50:38 +0000 Subject: [PATCH 2/6] optimized the logger --- mssql_python/cursor.py | 125 +++++++++++++++++++++++++++++++++++++--- mssql_python/logging.py | 35 +++++++---- 2 files changed, 143 insertions(+), 17 deletions(-) diff --git a/mssql_python/cursor.py b/mssql_python/cursor.py index c1e4124a8..198f09af7 100644 --- a/mssql_python/cursor.py +++ b/mssql_python/cursor.py @@ -2527,67 +2527,121 @@ def _bulkcopy( ValueError: If table_name is empty or parameters are invalid RuntimeError: If connection string is not available """ + # Fast check if logging is enabled to avoid overhead + is_logging = logger.is_debug_enabled + + if is_logging: + logger.debug( + "_bulkcopy: Starting bulk copy operation - table=%s, batch_size=%d, timeout=%d, " + "keep_identity=%s, check_constraints=%s, table_lock=%s, keep_nulls=%s, " + "fire_triggers=%s, use_internal_transaction=%s", + table_name, batch_size, timeout, keep_identity, check_constraints, + table_lock, keep_nulls, fire_triggers, use_internal_transaction + ) + try: import mssql_py_core + if is_logging: + logger.debug("_bulkcopy: mssql_py_core module imported successfully") except ImportError as exc: + if is_logging: + logger.error("_bulkcopy: Failed to import mssql_py_core module") raise ImportError( "Bulk copy requires the mssql_py_core library which is not installed. " "To install, run: pip install mssql_py_core " ) from exc # Validate inputs + if is_logging: + logger.debug("_bulkcopy: Validating input parameters") if not table_name or not isinstance(table_name, str): + if is_logging: + logger.error("_bulkcopy: Invalid table_name parameter") raise ValueError("table_name must be a non-empty string") # Validate that data is iterable (but not a string or bytes, which are technically iterable) if data is None: + if is_logging: + logger.error("_bulkcopy: data parameter is None") raise TypeError("data must be an iterable of tuples or lists, got None") if isinstance(data, (str, bytes)): + if is_logging: + logger.error("_bulkcopy: data parameter is string or bytes, not valid row collection") raise TypeError( f"data must be an iterable of tuples or lists, got {type(data).__name__}. " "Strings and bytes are not valid row collections." ) if not hasattr(data, "__iter__"): + if is_logging: + logger.error("_bulkcopy: data parameter is not iterable") raise TypeError( f"data must be an iterable of tuples or lists, got non-iterable {type(data).__name__}" ) + if is_logging: + logger.debug("_bulkcopy: Data parameter validation successful") # Validate batch_size type and value (0 means server optimal) if not isinstance(batch_size, int): + if is_logging: + logger.error("_bulkcopy: Invalid batch_size type: %s", type(batch_size).__name__) raise TypeError( f"batch_size must be a non-negative integer, got {type(batch_size).__name__}" ) if batch_size < 0: + if is_logging: + logger.error("_bulkcopy: Invalid batch_size value: %d", batch_size) raise ValueError(f"batch_size must be non-negative, got {batch_size}") # Validate timeout type and value if not isinstance(timeout, int): + if is_logging: + logger.error("_bulkcopy: Invalid timeout type: %s", type(timeout).__name__) raise TypeError(f"timeout must be a positive integer, got {type(timeout).__name__}") if timeout <= 0: + if is_logging: + logger.error("_bulkcopy: Invalid timeout value: %d", timeout) raise ValueError(f"timeout must be positive, got {timeout}") # Get and parse connection string + if is_logging: + logger.debug("_bulkcopy: Retrieving connection string") if not hasattr(self.connection, "connection_str"): + if is_logging: + logger.error("_bulkcopy: Connection string not available") raise RuntimeError("Connection string not available for bulk copy") # Use the proper connection string parser that handles braced values from mssql_python.connection_string_parser import _ConnectionStringParser + if is_logging: + logger.debug("_bulkcopy: Parsing connection string") parser = _ConnectionStringParser(validate_keywords=False) params = parser._parse(self.connection.connection_str) if not params.get("server"): + if is_logging: + logger.error("_bulkcopy: SERVER parameter missing in connection string") raise ValueError("SERVER parameter is required in connection string") if not params.get("database"): + if is_logging: + logger.error("_bulkcopy: DATABASE parameter missing in connection string") raise ValueError( "DATABASE parameter is required in connection string for bulk copy. " "Specify the target database explicitly to avoid accidentally writing to system databases." ) + + if is_logging: + logger.debug( + "_bulkcopy: Connection parameters - server=%s, database=%s", + params.get("server"), params.get("database") + ) # Build connection context for bulk copy library # Note: Password is extracted separately to avoid storing it in the main context # dict that could be accidentally logged or exposed in error messages. + if is_logging: + logger.debug("_bulkcopy: Building connection context") trust_cert = params.get("trustservercertificate", "yes").lower() in ("yes", "true") # Parse encryption setting from connection string @@ -2603,6 +2657,12 @@ def _bulkcopy( encryption = encrypt_param else: encryption = "Optional" + + if is_logging: + logger.debug( + "_bulkcopy: Connection security - encryption=%s, trust_cert=%s", + encryption, trust_cert + ) context = { "server": params.get("server"), @@ -2617,14 +2677,47 @@ def _bulkcopy( pycore_context = dict(context) pycore_context["password"] = password + # Log column mappings if provided (only when logging is enabled) + if is_logging and column_mappings: + if isinstance(column_mappings, list) and column_mappings: + if isinstance(column_mappings[0], tuple): + logger.debug( + "_bulkcopy: Using advanced column mappings with %d mapping(s)", + len(column_mappings) + ) + else: + logger.debug( + "_bulkcopy: Using simple column mappings with %d column(s)", + len(column_mappings) + ) + elif is_logging: + logger.debug("_bulkcopy: No column mappings provided, using ordinal position mapping") + pycore_connection = None pycore_cursor = None try: - pycore_connection = mssql_py_core.PyCoreConnection(pycore_context) + if is_logging: + logger.debug("_bulkcopy: Creating PyCoreConnection") + # Only pass logger to Rust if logging is enabled (performance optimization) + pycore_connection = mssql_py_core.PyCoreConnection( + pycore_context, + python_logger=logger if is_logging else None + ) + if is_logging: + logger.debug("_bulkcopy: PyCoreConnection created successfully") + + logger.debug("_bulkcopy: Creating PyCoreCursor") pycore_cursor = pycore_connection.cursor() + if is_logging: + logger.debug("_bulkcopy: PyCoreCursor created successfully") # Call bulkcopy with explicit keyword arguments # The API signature: bulkcopy(table_name, data_source, batch_size=0, timeout=30, ...) + if is_logging: + logger.info( + "_bulkcopy: Executing bulk copy operation to table '%s'", + table_name + ) result = pycore_cursor.bulkcopy( table_name, iter(data), @@ -2637,8 +2730,16 @@ def _bulkcopy( keep_nulls=keep_nulls, fire_triggers=fire_triggers, use_internal_transaction=use_internal_transaction, - python_logger=logger, # Pass Python logger handle to pycore + python_logger=logger if is_logging else None, # Only pass logger if enabled ) + + if is_logging: + logger.info( + "_bulkcopy: Bulk copy completed successfully - rows_copied=%s, batch_count=%s, elapsed_time=%s", + result.get('rows_copied', 'N/A'), + result.get('batch_count', 'N/A'), + result.get('elapsed_time', 'N/A') + ) return result @@ -2655,6 +2756,8 @@ def _bulkcopy( raise type(e)(str(e)) from None finally: + if is_logging: + logger.debug("_bulkcopy: Starting cleanup") # Clear sensitive data to minimize memory exposure password = "" if pycore_context: @@ -2664,15 +2767,23 @@ def _bulkcopy( for resource in (pycore_cursor, pycore_connection): if resource and hasattr(resource, "close"): try: + if is_logging: + logger.debug( + "_bulkcopy: Closing resource %s", + type(resource).__name__ + ) resource.close() except Exception as cleanup_error: # Log cleanup errors at debug level to aid troubleshooting # without masking the original exception - logger.debug( - "Failed to close bulk copy resource %s: %s", - type(resource).__name__, - cleanup_error, - ) + if is_logging: + logger.debug( + "Failed to close bulk copy resource %s: %s", + type(resource).__name__, + cleanup_error, + ) + if is_logging: + logger.debug("_bulkcopy: Cleanup completed") def __enter__(self): """ diff --git a/mssql_python/logging.py b/mssql_python/logging.py index 41a94ce13..cfacb5152 100644 --- a/mssql_python/logging.py +++ b/mssql_python/logging.py @@ -103,6 +103,10 @@ def __init__(self): self._handlers_initialized = False self._handler_lock = threading.RLock() # Reentrant lock for handler operations self._cleanup_registered = False # Track if atexit cleanup is registered + + # Cached level for fast checks (avoid repeated isEnabledFor calls) + self._cached_level = logging.CRITICAL + self._is_debug_enabled = False # Don't setup handlers yet - do it lazily when setLevel is called # This prevents creating log files when user changes output mode before enabling logging @@ -145,9 +149,9 @@ def _setup_handlers(self): # Custom formatter to extract source from message and format as CSV class CSVFormatter(logging.Formatter): def format(self, record): - # Check if this is from Rust (via rust_log method) - if hasattr(record, 'funcName') and record.funcName == "rust": - source = "Rust" + # Check if this is from py-core (via py_core_log method) + if hasattr(record, 'funcName') and record.funcName == "py-core": + source = "py-core" message = record.getMessage() else: # Extract source from message (e.g., [Python] or [DDBC]) @@ -331,9 +335,9 @@ def _write_log_header(self): pass # Even stderr notification failed # Don't crash - logging continues without header - def rust_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: int = 0): + def py_core_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: int = 0): """ - Logging method for Rust code with custom source location. + Logging method for py-core (Rust/TDS) code with custom source location. Args: level: Log level (DEBUG, INFO, WARNING, ERROR) @@ -355,7 +359,7 @@ def rust_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: in msg=msg, args=(), exc_info=None, - func="rust", + func="py-core", sinfo=None ) self._logger.handle(record) @@ -392,8 +396,9 @@ def _log(self, level: int, msg: str, add_prefix: bool = True, *args, **kwargs): All other failures are silently ignored to prevent app crashes. """ try: - # Fast level check (zero overhead if disabled) - if not self._logger.isEnabledFor(level): + # Fast level check using cached level (zero overhead if disabled) + # This avoids the overhead of isEnabledFor() method call + if level < self._cached_level: return # Add prefix if requested (only after level check) @@ -404,8 +409,9 @@ def _log(self, level: int, msg: str, add_prefix: bool = True, *args, **kwargs): if args: msg = msg % args - # Log the message (no args since already formatted) - self._logger.log(level, msg, **kwargs) + # Log the message with proper stack level to capture caller's location + # stacklevel=3 skips: _log -> debug/info/warning/error -> actual caller + self._logger.log(level, msg, stacklevel=3, **kwargs) except Exception: # Last resort: Try stderr fallback for any logging failure # This helps diagnose critical issues (disk full, permission denied, etc.) @@ -480,6 +486,10 @@ def _setLevel( # Set level (atomic operation, no lock needed) self._logger.setLevel(level) + + # Cache level for fast checks (avoid repeated isEnabledFor calls) + self._cached_level = level + self._is_debug_enabled = (level <= logging.DEBUG) # Notify C++ bridge of level change self._notify_cpp_level_change(level) @@ -585,6 +595,11 @@ def log_file(self) -> Optional[str]: def level(self) -> int: """Get the current logging level""" return self._logger.level + + @property + def is_debug_enabled(self) -> bool: + """Fast check if debug logging is enabled (cached for performance)""" + return self._is_debug_enabled # ============================================================================ From b8052949a0cca91fb70b64701ff005597cc7e3ad Mon Sep 17 00:00:00 2001 From: Subrata Paitandi Date: Mon, 16 Feb 2026 14:19:36 +0000 Subject: [PATCH 3/6] fixing linting --- mssql_python/cursor.py | 57 ++++++++++++++++++++++------------------- mssql_python/logging.py | 17 ++++++------ 2 files changed, 40 insertions(+), 34 deletions(-) diff --git a/mssql_python/cursor.py b/mssql_python/cursor.py index 5df363004..427ea86da 100644 --- a/mssql_python/cursor.py +++ b/mssql_python/cursor.py @@ -2529,18 +2529,26 @@ def _bulkcopy( """ # Fast check if logging is enabled to avoid overhead is_logging = logger.is_debug_enabled - + if is_logging: logger.debug( "_bulkcopy: Starting bulk copy operation - table=%s, batch_size=%d, timeout=%d, " "keep_identity=%s, check_constraints=%s, table_lock=%s, keep_nulls=%s, " "fire_triggers=%s, use_internal_transaction=%s", - table_name, batch_size, timeout, keep_identity, check_constraints, - table_lock, keep_nulls, fire_triggers, use_internal_transaction + table_name, + batch_size, + timeout, + keep_identity, + check_constraints, + table_lock, + keep_nulls, + fire_triggers, + use_internal_transaction, ) - + try: import mssql_py_core + if is_logging: logger.debug("_bulkcopy: mssql_py_core module imported successfully") except ImportError as exc: @@ -2566,7 +2574,9 @@ def _bulkcopy( raise TypeError("data must be an iterable of tuples or lists, got None") if isinstance(data, (str, bytes)): if is_logging: - logger.error("_bulkcopy: data parameter is string or bytes, not valid row collection") + logger.error( + "_bulkcopy: data parameter is string or bytes, not valid row collection" + ) raise TypeError( f"data must be an iterable of tuples or lists, got {type(data).__name__}. " "Strings and bytes are not valid row collections." @@ -2630,11 +2640,12 @@ def _bulkcopy( "DATABASE parameter is required in connection string for bulk copy. " "Specify the target database explicitly to avoid accidentally writing to system databases." ) - + if is_logging: logger.debug( "_bulkcopy: Connection parameters - server=%s, database=%s", - params.get("server"), params.get("database") + params.get("server"), + params.get("database"), ) # Build connection context for bulk copy library @@ -2657,11 +2668,12 @@ def _bulkcopy( encryption = encrypt_param else: encryption = "Optional" - + if is_logging: logger.debug( "_bulkcopy: Connection security - encryption=%s, trust_cert=%s", - encryption, trust_cert + encryption, + trust_cert, ) context = { @@ -2704,12 +2716,12 @@ def _bulkcopy( if isinstance(column_mappings[0], tuple): logger.debug( "_bulkcopy: Using advanced column mappings with %d mapping(s)", - len(column_mappings) + len(column_mappings), ) else: logger.debug( "_bulkcopy: Using simple column mappings with %d column(s)", - len(column_mappings) + len(column_mappings), ) elif is_logging: logger.debug("_bulkcopy: No column mappings provided, using ordinal position mapping") @@ -2721,12 +2733,11 @@ def _bulkcopy( logger.debug("_bulkcopy: Creating PyCoreConnection") # Only pass logger to Rust if logging is enabled (performance optimization) pycore_connection = mssql_py_core.PyCoreConnection( - pycore_context, - python_logger=logger if is_logging else None + pycore_context, python_logger=logger if is_logging else None ) if is_logging: logger.debug("_bulkcopy: PyCoreConnection created successfully") - + logger.debug("_bulkcopy: Creating PyCoreCursor") pycore_cursor = pycore_connection.cursor() if is_logging: @@ -2735,10 +2746,7 @@ def _bulkcopy( # Call bulkcopy with explicit keyword arguments # The API signature: bulkcopy(table_name, data_source, batch_size=0, timeout=30, ...) if is_logging: - logger.info( - "_bulkcopy: Executing bulk copy operation to table '%s'", - table_name - ) + logger.info("_bulkcopy: Executing bulk copy operation to table '%s'", table_name) result = pycore_cursor.bulkcopy( table_name, iter(data), @@ -2753,13 +2761,13 @@ def _bulkcopy( use_internal_transaction=use_internal_transaction, python_logger=logger if is_logging else None, # Only pass logger if enabled ) - + if is_logging: logger.info( "_bulkcopy: Bulk copy completed successfully - rows_copied=%s, batch_count=%s, elapsed_time=%s", - result.get('rows_copied', 'N/A'), - result.get('batch_count', 'N/A'), - result.get('elapsed_time', 'N/A') + result.get("rows_copied", "N/A"), + result.get("batch_count", "N/A"), + result.get("elapsed_time", "N/A"), ) return result @@ -2789,10 +2797,7 @@ def _bulkcopy( if resource and hasattr(resource, "close"): try: if is_logging: - logger.debug( - "_bulkcopy: Closing resource %s", - type(resource).__name__ - ) + logger.debug("_bulkcopy: Closing resource %s", type(resource).__name__) resource.close() except Exception as cleanup_error: # Log cleanup errors at debug level to aid troubleshooting diff --git a/mssql_python/logging.py b/mssql_python/logging.py index cfacb5152..b0291d685 100644 --- a/mssql_python/logging.py +++ b/mssql_python/logging.py @@ -103,7 +103,7 @@ def __init__(self): self._handlers_initialized = False self._handler_lock = threading.RLock() # Reentrant lock for handler operations self._cleanup_registered = False # Track if atexit cleanup is registered - + # Cached level for fast checks (avoid repeated isEnabledFor calls) self._cached_level = logging.CRITICAL self._is_debug_enabled = False @@ -150,7 +150,7 @@ def _setup_handlers(self): class CSVFormatter(logging.Formatter): def format(self, record): # Check if this is from py-core (via py_core_log method) - if hasattr(record, 'funcName') and record.funcName == "py-core": + if hasattr(record, "funcName") and record.funcName == "py-core": source = "py-core" message = record.getMessage() else: @@ -338,7 +338,7 @@ def _write_log_header(self): def py_core_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: int = 0): """ Logging method for py-core (Rust/TDS) code with custom source location. - + Args: level: Log level (DEBUG, INFO, WARNING, ERROR) msg: Message string (already formatted) @@ -348,9 +348,10 @@ def py_core_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: try: if not self._logger.isEnabledFor(level): return - + # Create a custom LogRecord with Rust source location import logging as log_module + record = log_module.LogRecord( name=self._logger.name, level=level, @@ -360,7 +361,7 @@ def py_core_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: args=(), exc_info=None, func="py-core", - sinfo=None + sinfo=None, ) self._logger.handle(record) except Exception: @@ -486,10 +487,10 @@ def _setLevel( # Set level (atomic operation, no lock needed) self._logger.setLevel(level) - + # Cache level for fast checks (avoid repeated isEnabledFor calls) self._cached_level = level - self._is_debug_enabled = (level <= logging.DEBUG) + self._is_debug_enabled = level <= logging.DEBUG # Notify C++ bridge of level change self._notify_cpp_level_change(level) @@ -595,7 +596,7 @@ def log_file(self) -> Optional[str]: def level(self) -> int: """Get the current logging level""" return self._logger.level - + @property def is_debug_enabled(self) -> bool: """Fast check if debug logging is enabled (cached for performance)""" From 2819b6bfbc9b11c052be8eec62a68a12134180ba Mon Sep 17 00:00:00 2001 From: Subrata Paitandi Date: Thu, 19 Feb 2026 09:13:04 +0000 Subject: [PATCH 4/6] test failure --- mssql_python/logging.py | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/mssql_python/logging.py b/mssql_python/logging.py index b0291d685..220d016ee 100644 --- a/mssql_python/logging.py +++ b/mssql_python/logging.py @@ -88,7 +88,7 @@ def __init__(self): # Create the underlying Python logger self._logger = logging.getLogger("mssql_python") - self._logger.setLevel(logging.CRITICAL) # Disabled by default + self._logger.setLevel(logging.WARNING) # Allow WARNING and ERROR by default self._logger.propagate = False # Don't propagate to root logger # Add trace ID filter (injects thread_id into every log record) @@ -105,10 +105,21 @@ def __init__(self): self._cleanup_registered = False # Track if atexit cleanup is registered # Cached level for fast checks (avoid repeated isEnabledFor calls) - self._cached_level = logging.CRITICAL + self._cached_level = logging.WARNING self._is_debug_enabled = False - # Don't setup handlers yet - do it lazily when setLevel is called + # Set up default stderr handler for WARNING and ERROR messages + # This ensures warnings are always visible even when logging is not enabled + import sys + + default_handler = logging.StreamHandler(sys.stderr) + default_handler.setLevel(logging.WARNING) + # Simple format for warnings - no CSV formatting needed + default_handler.setFormatter(logging.Formatter("[%(name)s] %(levelname)s: %(message)s")) + self._logger.addHandler(default_handler) + self._default_handler = default_handler # Keep reference for later removal + + # Don't setup full handlers yet - do it lazily when setLevel is called # This prevents creating log files when user changes output mode before enabling logging def _setup_handlers(self): @@ -399,7 +410,8 @@ def _log(self, level: int, msg: str, add_prefix: bool = True, *args, **kwargs): try: # Fast level check using cached level (zero overhead if disabled) # This avoids the overhead of isEnabledFor() method call - if level < self._cached_level: + # Exception: Always allow WARNING and ERROR messages through + if level < self._cached_level and level < logging.WARNING: return # Add prefix if requested (only after level check) From 617a2435104b846931614bc17f34602e0f0659a3 Mon Sep 17 00:00:00 2001 From: Subrata Paitandi Date: Thu, 19 Feb 2026 10:43:05 +0000 Subject: [PATCH 5/6] code cleanup for logging based on latest py-core changes --- mssql_python/cursor.py | 120 ++++------------------------------------- 1 file changed, 11 insertions(+), 109 deletions(-) diff --git a/mssql_python/cursor.py b/mssql_python/cursor.py index e387d435b..b209cff75 100644 --- a/mssql_python/cursor.py +++ b/mssql_python/cursor.py @@ -2577,129 +2577,72 @@ def _bulkcopy( # Fast check if logging is enabled to avoid overhead is_logging = logger.is_debug_enabled - if is_logging: - logger.debug( - "_bulkcopy: Starting bulk copy operation - table=%s, batch_size=%d, timeout=%d, " - "keep_identity=%s, check_constraints=%s, table_lock=%s, keep_nulls=%s, " - "fire_triggers=%s, use_internal_transaction=%s", - table_name, - batch_size, - timeout, - keep_identity, - check_constraints, - table_lock, - keep_nulls, - fire_triggers, - use_internal_transaction, - ) - try: import mssql_py_core - - if is_logging: - logger.debug("_bulkcopy: mssql_py_core module imported successfully") except ImportError as exc: - if is_logging: - logger.error("_bulkcopy: Failed to import mssql_py_core module") + logger.error("_bulkcopy: Failed to import mssql_py_core module") raise ImportError( "Bulk copy requires the mssql_py_core library which is not installed. " "To install, run: pip install mssql_py_core " ) from exc # Validate inputs - if is_logging: - logger.debug("_bulkcopy: Validating input parameters") if not table_name or not isinstance(table_name, str): - if is_logging: - logger.error("_bulkcopy: Invalid table_name parameter") + logger.error("_bulkcopy: Invalid table_name parameter") raise ValueError("table_name must be a non-empty string") # Validate that data is iterable (but not a string or bytes, which are technically iterable) if data is None: - if is_logging: - logger.error("_bulkcopy: data parameter is None") raise TypeError("data must be an iterable of tuples or lists, got None") if isinstance(data, (str, bytes)): - if is_logging: - logger.error( - "_bulkcopy: data parameter is string or bytes, not valid row collection" - ) raise TypeError( f"data must be an iterable of tuples or lists, got {type(data).__name__}. " "Strings and bytes are not valid row collections." ) if not hasattr(data, "__iter__"): - if is_logging: - logger.error("_bulkcopy: data parameter is not iterable") raise TypeError( f"data must be an iterable of tuples or lists, got non-iterable {type(data).__name__}" ) - if is_logging: - logger.debug("_bulkcopy: Data parameter validation successful") # Validate batch_size type and value (0 means server optimal) if not isinstance(batch_size, int): - if is_logging: - logger.error("_bulkcopy: Invalid batch_size type: %s", type(batch_size).__name__) raise TypeError( f"batch_size must be a non-negative integer, got {type(batch_size).__name__}" ) if batch_size < 0: - if is_logging: - logger.error("_bulkcopy: Invalid batch_size value: %d", batch_size) raise ValueError(f"batch_size must be non-negative, got {batch_size}") # Validate timeout type and value if not isinstance(timeout, int): - if is_logging: - logger.error("_bulkcopy: Invalid timeout type: %s", type(timeout).__name__) raise TypeError(f"timeout must be a positive integer, got {type(timeout).__name__}") if timeout <= 0: - if is_logging: - logger.error("_bulkcopy: Invalid timeout value: %d", timeout) raise ValueError(f"timeout must be positive, got {timeout}") # Get and parse connection string - if is_logging: - logger.debug("_bulkcopy: Retrieving connection string") if not hasattr(self.connection, "connection_str"): - if is_logging: - logger.error("_bulkcopy: Connection string not available") + logger.error("_bulkcopy: Connection string not available") raise RuntimeError("Connection string not available for bulk copy") # Use the proper connection string parser that handles braced values from mssql_python.connection_string_parser import _ConnectionStringParser - if is_logging: - logger.debug("_bulkcopy: Parsing connection string") parser = _ConnectionStringParser(validate_keywords=False) params = parser._parse(self.connection.connection_str) if not params.get("server"): - if is_logging: - logger.error("_bulkcopy: SERVER parameter missing in connection string") + logger.error("_bulkcopy: SERVER parameter missing in connection string") raise ValueError("SERVER parameter is required in connection string") if not params.get("database"): - if is_logging: - logger.error("_bulkcopy: DATABASE parameter missing in connection string") + logger.error("_bulkcopy: DATABASE parameter missing in connection string") raise ValueError( "DATABASE parameter is required in connection string for bulk copy. " "Specify the target database explicitly to avoid accidentally writing to system databases." ) - if is_logging: - logger.debug( - "_bulkcopy: Connection parameters - server=%s, database=%s", - params.get("server"), - params.get("database"), - ) - # Build connection context for bulk copy library # Note: Password is extracted separately to avoid storing it in the main context # dict that could be accidentally logged or exposed in error messages. - if is_logging: - logger.debug("_bulkcopy: Building connection context") trust_cert = params.get("trustservercertificate", "yes").lower() in ("yes", "true") # Parse encryption setting from connection string @@ -2716,13 +2659,6 @@ def _bulkcopy( else: encryption = "Optional" - if is_logging: - logger.debug( - "_bulkcopy: Connection security - encryption=%s, trust_cert=%s", - encryption, - trust_cert, - ) - context = { "server": params.get("server"), "database": params.get("database"), @@ -2757,43 +2693,17 @@ def _bulkcopy( pycore_context["user_name"] = params.get("uid", "") pycore_context["password"] = params.get("pwd", "") - # Log column mappings if provided (only when logging is enabled) - if is_logging and column_mappings: - if isinstance(column_mappings, list) and column_mappings: - if isinstance(column_mappings[0], tuple): - logger.debug( - "_bulkcopy: Using advanced column mappings with %d mapping(s)", - len(column_mappings), - ) - else: - logger.debug( - "_bulkcopy: Using simple column mappings with %d column(s)", - len(column_mappings), - ) - elif is_logging: - logger.debug("_bulkcopy: No column mappings provided, using ordinal position mapping") - pycore_connection = None pycore_cursor = None try: - if is_logging: - logger.debug("_bulkcopy: Creating PyCoreConnection") # Only pass logger to Rust if logging is enabled (performance optimization) pycore_connection = mssql_py_core.PyCoreConnection( pycore_context, python_logger=logger if is_logging else None ) - if is_logging: - logger.debug("_bulkcopy: PyCoreConnection created successfully") - - logger.debug("_bulkcopy: Creating PyCoreCursor") pycore_cursor = pycore_connection.cursor() - if is_logging: - logger.debug("_bulkcopy: PyCoreCursor created successfully") # Call bulkcopy with explicit keyword arguments # The API signature: bulkcopy(table_name, data_source, batch_size=0, timeout=30, ...) - if is_logging: - logger.info("_bulkcopy: Executing bulk copy operation to table '%s'", table_name) result = pycore_cursor.bulkcopy( table_name, iter(data), @@ -2832,8 +2742,6 @@ def _bulkcopy( raise type(e)(str(e)) from None finally: - if is_logging: - logger.debug("_bulkcopy: Starting cleanup") # Clear sensitive data to minimize memory exposure if pycore_context: pycore_context.pop("password", None) @@ -2843,20 +2751,14 @@ def _bulkcopy( for resource in (pycore_cursor, pycore_connection): if resource and hasattr(resource, "close"): try: - if is_logging: - logger.debug("_bulkcopy: Closing resource %s", type(resource).__name__) resource.close() except Exception as cleanup_error: - # Log cleanup errors at debug level to aid troubleshooting - # without masking the original exception - if is_logging: - logger.debug( - "Failed to close bulk copy resource %s: %s", - type(resource).__name__, - cleanup_error, - ) - if is_logging: - logger.debug("_bulkcopy: Cleanup completed") + # Log cleanup errors only - aids troubleshooting without masking original exception + logger.debug( + "Failed to close bulk copy resource %s: %s", + type(resource).__name__, + cleanup_error, + ) def __enter__(self): """ From 00d4f00c1363bed3810cf6c349cf652763781497 Mon Sep 17 00:00:00 2001 From: Subrata Paitandi Date: Thu, 19 Feb 2026 10:58:27 +0000 Subject: [PATCH 6/6] added test cases for coverage and some cleanup --- mssql_python/logging.py | 11 ++- tests/test_007_logging.py | 191 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 201 insertions(+), 1 deletion(-) diff --git a/mssql_python/logging.py b/mssql_python/logging.py index 220d016ee..8579d2cdf 100644 --- a/mssql_python/logging.py +++ b/mssql_python/logging.py @@ -357,7 +357,9 @@ def py_core_log(self, level: int, msg: str, filename: str = "cursor.rs", lineno: lineno: Line number in source file """ try: - if not self._logger.isEnabledFor(level): + # Fast level check using cached level (same optimization as _log method) + # Exception: Always allow WARNING and ERROR messages through + if level < self._cached_level and level < logging.WARNING: return # Create a custom LogRecord with Rust source location @@ -501,6 +503,13 @@ def _setLevel( self._logger.setLevel(level) # Cache level for fast checks (avoid repeated isEnabledFor calls) + # Note: These updates are not atomic across both variables, creating a brief + # window where reads might see inconsistent state (e.g., updated _cached_level + # but old _is_debug_enabled). This is an acceptable benign race condition: + # - Worst case: one log statement might be incorrectly allowed/blocked + # - Duration: nanoseconds (single Python bytecode instruction gap) + # - Impact: negligible - next check will see consistent state + # - Alternative (locking) would add overhead to every log call self._cached_level = level self._is_debug_enabled = level <= logging.DEBUG diff --git a/tests/test_007_logging.py b/tests/test_007_logging.py index 6bc0f5528..daafc6fc2 100644 --- a/tests/test_007_logging.py +++ b/tests/test_007_logging.py @@ -31,6 +31,8 @@ def cleanup_logger(): # Disable logging and clear handlers logger._logger.setLevel(logging.CRITICAL) + logger._cached_level = logging.CRITICAL # Update cached level + logger._is_debug_enabled = False # Update cached debug flag for handler in logger._logger.handlers[:]: handler.close() logger._logger.removeHandler(handler) @@ -46,6 +48,8 @@ def cleanup_logger(): # Restore state and cleanup logger._logger.setLevel(logging.CRITICAL) + logger._cached_level = logging.CRITICAL # Update cached level + logger._is_debug_enabled = False # Update cached debug flag for handler in logger._logger.handlers[:]: handler.close() logger._logger.removeHandler(handler) @@ -843,3 +847,190 @@ def __str__(self): # Application should still be running assert True + + +class TestDebugEnabledProperty: + """Test is_debug_enabled property for performance-optimized level checks""" + + def test_is_debug_enabled_false_by_default(self, cleanup_logger): + """is_debug_enabled should be False when logger is at CRITICAL level (cleanup default)""" + # cleanup_logger sets level to CRITICAL + assert logger.getLevel() == logging.CRITICAL + assert not logger.is_debug_enabled + + def test_is_debug_enabled_true_when_debug_set(self, cleanup_logger): + """is_debug_enabled should be True when DEBUG level is set""" + setup_logging() + assert logger.getLevel() == logging.DEBUG + assert logger.is_debug_enabled + + def test_is_debug_enabled_false_when_info_set(self, cleanup_logger): + """is_debug_enabled should be False when INFO level is set""" + # Set to INFO level (above DEBUG) + logger._setLevel(logging.INFO) + assert logger.getLevel() == logging.INFO + assert not logger.is_debug_enabled + + def test_is_debug_enabled_updates_with_level_change(self, cleanup_logger): + """is_debug_enabled should update when logging level changes""" + # Start disabled + assert not logger.is_debug_enabled + + # Enable debug + setup_logging() + assert logger.is_debug_enabled + + # Disable again + logger._setLevel(logging.WARNING) + assert not logger.is_debug_enabled + + # Re-enable + logger._setLevel(logging.DEBUG) + assert logger.is_debug_enabled + + def test_is_debug_enabled_matches_cached_level(self, cleanup_logger): + """is_debug_enabled should match the cached level check""" + # Test at various levels + test_levels = [ + logging.DEBUG, + logging.INFO, + logging.WARNING, + logging.ERROR, + logging.CRITICAL, + ] + + for level in test_levels: + logger._setLevel(level) + expected = level <= logging.DEBUG + assert logger.is_debug_enabled == expected, f"Failed at level {level}" + + +class TestPyCoreLog: + """Test py_core_log method for Rust/py-core integration""" + + def test_py_core_log_with_custom_location(self, cleanup_logger, temp_log_dir): + """py_core_log should create log record with custom source location""" + log_file = os.path.join(temp_log_dir, "pycore_test.log") + setup_logging(output=FILE, log_file_path=log_file) + + # Log from "Rust" code + logger.py_core_log( + logging.INFO, "Bulkcopy operation started", filename="cursor.rs", lineno=270 + ) + + # Verify log file contains custom source location + with open(log_file, "r") as f: + content = f.read() + assert "cursor.rs:270" in content + assert "py-core" in content + assert "Bulkcopy operation started" in content + + def test_py_core_log_respects_level(self, cleanup_logger, temp_log_dir): + """py_core_log should respect cached level check""" + log_file = os.path.join(temp_log_dir, "pycore_level_test.log") + setup_logging(output=FILE, log_file_path=log_file) + + # Log at DEBUG level (should appear) + logger.py_core_log(logging.DEBUG, "Debug message", "test.rs", 1) + + # Disable debug logging + logger._setLevel(logging.WARNING) + + # Log at DEBUG level (should NOT appear) + logger.py_core_log(logging.DEBUG, "Hidden debug message", "test.rs", 2) + + # Log at WARNING level (should appear) + logger.py_core_log(logging.WARNING, "Warning message", "test.rs", 3) + + # Verify file content + with open(log_file, "r") as f: + content = f.read() + assert "Debug message" in content + assert "Hidden debug message" not in content + assert "Warning message" in content + + def test_py_core_log_allows_warnings_when_disabled(self, cleanup_logger, temp_log_dir): + """py_core_log should allow WARNING/ERROR even when logging disabled""" + log_file = os.path.join(temp_log_dir, "pycore_warning_test.log") + setup_logging(output=FILE, log_file_path=log_file) + + # Disable debug logging (but WARNING should still work) + logger._setLevel(logging.CRITICAL) + + # These should NOT appear + logger.py_core_log(logging.DEBUG, "Debug blocked", "test.rs", 1) + logger.py_core_log(logging.INFO, "Info blocked", "test.rs", 2) + + # These SHOULD appear (WARNING and ERROR always allowed) + logger.py_core_log(logging.WARNING, "Warning allowed", "test.rs", 3) + logger.py_core_log(logging.ERROR, "Error allowed", "test.rs", 4) + + # Verify file content + with open(log_file, "r") as f: + content = f.read() + assert "Debug blocked" not in content + assert "Info blocked" not in content + assert "Warning allowed" in content + assert "Error allowed" in content + + def test_py_core_log_fallback_on_error(self, cleanup_logger, temp_log_dir): + """py_core_log should fallback gracefully on errors""" + log_file = os.path.join(temp_log_dir, "pycore_fallback_test.log") + setup_logging(output=FILE, log_file_path=log_file) + + # Should not crash even with invalid parameters + logger.py_core_log(logging.INFO, "Test message", None, None) # None filename/lineno + logger.py_core_log(logging.INFO, "Test 2", "", -1) # Empty filename, negative line + + # Application should still be running + assert True + + # Verify something was logged (fallback worked) + with open(log_file, "r") as f: + content = f.read() + # At least one message should have been logged + assert len(content) > 0 + + def test_py_core_log_formats_as_csv(self, cleanup_logger, temp_log_dir): + """py_core_log output should follow CSV format""" + log_file = os.path.join(temp_log_dir, "pycore_csv_test.log") + setup_logging(output=FILE, log_file_path=log_file) + + logger.py_core_log(logging.INFO, "Test message with commas, quotes", "connection.rs", 42) + + # Read and verify CSV format + with open(log_file, "r") as f: + lines = f.readlines() + # Skip header lines (starts with #) + data_lines = [line for line in lines if not line.startswith("#")] + + # Should have at least 2 lines: CSV header + data + assert len(data_lines) >= 2 + + # Check data line format: timestamp, thread_id, level, location, source, message + data_line = data_lines[-1] # Get last logged line + parts = [p.strip() for p in data_line.split(",")] + + # Should have 6 parts: timestamp, thread_id, level, location, source, message + assert len(parts) >= 6 + assert "connection.rs:42" in data_line + assert "py-core" in data_line + assert "INFO" in data_line + + def test_py_core_log_with_different_rust_files(self, cleanup_logger, temp_log_dir): + """py_core_log should handle different Rust source files""" + log_file = os.path.join(temp_log_dir, "pycore_files_test.log") + setup_logging(output=FILE, log_file_path=log_file) + + # Log from different Rust files + logger.py_core_log(logging.INFO, "Connection msg", "connection.rs", 100) + logger.py_core_log(logging.INFO, "Cursor msg", "cursor.rs", 200) + logger.py_core_log(logging.INFO, "Auth msg", "auth.rs", 300) + + # Verify all source files appear in log + with open(log_file, "r") as f: + content = f.read() + assert "connection.rs:100" in content + assert "cursor.rs:200" in content + assert "auth.rs:300" in content + assert content.count("py-core") == 3 # Three entries from py-core