FIX: prevent GIL/mutex deadlock when logging under concurrent multithreaded use

mssql_python/pybind/connection/connection.cpp

@@ -57,7 +57,15 @@ Connection::~Connection() {
 
 // Allocates connection handle
 void Connection::allocateDbcHandle() {
-    auto _envHandle = getEnvHandle();
+    SqlHandlePtr _envHandle;
+    {
+        // Fetch/initialize the shared env handle without holding the GIL (#671):
+        // its first-time initialization runs under a C++ static-init guard and
+        // emits log records; a thread waiting on that guard while holding the GIL
+        // would deadlock the initializing thread that needs the GIL to log.
+        py::gil_scoped_release gil_release;
+        _envHandle = getEnvHandle();
+    }
     SQLHANDLE dbc = nullptr;
     LOG("Allocating SQL Connection Handle");
     SQLRETURN ret = SQLAllocHandle_ptr(SQL_HANDLE_DBC, _envHandle->get(), &dbc);
@@ -106,30 +114,25 @@ void Connection::disconnect() {
 
         // THREAD-SAFETY: Lock mutex to safely access _childStatementHandles
         // This protects against concurrent allocStatementHandle() calls or GC finalizers
+        size_t originalSize = 0, afterCompactSize = 0, badHandleCount = 0;
         {
             std::lock_guard<std::mutex> lock(_childHandlesMutex);
 
             // First compact: remove expired weak_ptrs (they're already destroyed)
-            size_t originalSize = _childStatementHandles.size();
+            originalSize = _childStatementHandles.size();
             _childStatementHandles.erase(
                 std::remove_if(_childStatementHandles.begin(), _childStatementHandles.end(),
                                [](const std::weak_ptr<SqlHandle>& wp) { return wp.expired(); }),
                 _childStatementHandles.end());
-
-            LOG("Compacted child handles: %zu -> %zu (removed %zu expired)",
-                originalSize, _childStatementHandles.size(),
-                originalSize - _childStatementHandles.size());
-
-            LOG("Marking %zu child statement handles as implicitly freed",
-                _childStatementHandles.size());
+            afterCompactSize = _childStatementHandles.size();
+
             for (auto& weakHandle : _childStatementHandles) {
                 if (auto handle = weakHandle.lock()) {
                     // SAFETY ASSERTION: Only STMT handles should be in this vector
                     // This is guaranteed by allocStatementHandle() which only creates STMT handles
                     // If this assertion fails, it indicates a serious bug in handle tracking
                     if (handle->type() != SQL_HANDLE_STMT) {
-                        LOG_ERROR("CRITICAL: Non-STMT handle (type=%d) found in _childStatementHandles. "
-                                  "This will cause a handle leak!", handle->type());
+                        ++badHandleCount;
                         continue;  // Skip marking to prevent leak
                     }
                     handle->markImplicitlyFreed();
@@ -139,6 +142,16 @@ void Connection::disconnect() {
             _allocationsSinceCompaction = 0;
         }  // Release lock before potentially slow SQLDisconnect call
 
+        // Log after releasing _childHandlesMutex (#671): LOG()/LOG_ERROR() acquire
+        // the GIL and must not run while a native mutex is held.
+        LOG("Compacted child handles: %zu -> %zu (removed %zu expired)",
+            originalSize, afterCompactSize, originalSize - afterCompactSize);
+        LOG("Marking %zu child statement handles as implicitly freed", afterCompactSize);
+        if (badHandleCount > 0) {
+            LOG_ERROR("CRITICAL: %zu non-STMT handle(s) found in _childStatementHandles. "
+                      "This will cause a handle leak!", badHandleCount);
+        }
+
         SQLRETURN ret;
         if (hasGil) {
             // Release the GIL during the blocking ODBC disconnect call.
@@ -266,6 +279,8 @@ SqlHandlePtr Connection::allocStatementHandle() {
     // THREAD-SAFETY: Lock mutex before modifying _childStatementHandles
     // This protects against concurrent disconnect() or allocStatementHandle() calls,
     // or GC finalizers running from different threads
+    bool compacted = false;
+    size_t compactBefore = 0, compactAfter = 0;
     {
         std::lock_guard<std::mutex> lock(_childHandlesMutex);
 
@@ -278,18 +293,24 @@ SqlHandlePtr Connection::allocStatementHandle() {
         // This keeps allocation fast (O(1) amortized) while preventing unbounded growth
         // disconnect() also compacts, so this is just for long-lived connections with many cursors
         if (_allocationsSinceCompaction >= COMPACTION_INTERVAL) {
-            size_t originalSize = _childStatementHandles.size();
+            compactBefore = _childStatementHandles.size();
             _childStatementHandles.erase(
                 std::remove_if(_childStatementHandles.begin(), _childStatementHandles.end(),
                                [](const std::weak_ptr<SqlHandle>& wp) { return wp.expired(); }),
                 _childStatementHandles.end());
+            compactAfter = _childStatementHandles.size();
             _allocationsSinceCompaction = 0;
-            LOG("Periodic compaction: %zu -> %zu handles (removed %zu expired)",
-                originalSize, _childStatementHandles.size(),
-                originalSize - _childStatementHandles.size());
+            compacted = true;
         }
     }  // Release lock
 
+    // Log after releasing _childHandlesMutex (#671): LOG() acquires the GIL and
+    // must not run while a native mutex is held.
+    if (compacted) {
+        LOG("Periodic compaction: %zu -> %zu handles (removed %zu expired)",
+            compactBefore, compactAfter, compactBefore - compactAfter);
+    }
+
     return stmtHandle;
 }
 

mssql_python/pybind/connection/connection_pool.cpp

@@ -57,7 +57,11 @@ std::shared_ptr<Connection> ConnectionPool::acquire(const std::u16string& connSt
             if (_pool.empty()) {
                 // No more candidates — try to reserve a slot for a new connection.
                 if (_current_size < _max_size) {
-                    valid_conn = std::make_shared<Connection>(connStr, true);
+                    // Reserve the slot here but construct the Connection outside
+                    // _mutex (Phase 3): the Connection constructor allocates ODBC
+                    // handles and emits log records that acquire the GIL, and
+                    // holding _mutex across a GIL acquisition deadlocks a thread
+                    // that holds the GIL and is waiting on _mutex (#671).
                     ++_current_size;
                     needs_connect = true;
                 } else {
@@ -94,12 +98,13 @@ std::shared_ptr<Connection> ConnectionPool::acquire(const std::u16string& connSt
         }
     }
 
-    // Phase 3: Connect the new connection outside the mutex.
+    // Phase 3: Construct and connect the new connection outside the mutex.
     if (needs_connect) {
         try {
+            valid_conn = std::make_shared<Connection>(connStr, true);
             valid_conn->connect(attrs_before);
         } catch (...) {
-            // Connect failed — release the reserved slot
+            // Construct/connect failed — release the reserved slot
             {
                 std::lock_guard<std::mutex> lock(_mutex);
                 if (_current_size > 0) --_current_size;
@@ -171,15 +176,22 @@ ConnectionPoolManager& ConnectionPoolManager::getInstance() {
 std::shared_ptr<Connection> ConnectionPoolManager::acquireConnection(const std::u16string& connStr,
                                                                      const py::dict& attrs_before) {
     std::shared_ptr<ConnectionPool> pool;
+    bool created = false;
     {
         std::lock_guard<std::mutex> lock(_manager_mutex);
         auto& pool_ref = _pools[connStr];
         if (!pool_ref) {
-            LOG("Creating new connection pool");
             pool_ref = std::make_shared<ConnectionPool>(_default_max_size, _default_idle_secs);
+            created = true;
         }
         pool = pool_ref;
     }
+    // Log after releasing _manager_mutex (#671): LOG() acquires the GIL, and
+    // holding a native mutex across a GIL acquisition deadlocks a thread that
+    // holds the GIL and is waiting on the same mutex.
+    if (created) {
+        LOG("Creating new connection pool");
+    }
     // Call acquire() outside _manager_mutex.  acquire() may release the GIL
     // during the ODBC connect call; holding _manager_mutex across that would
     // create a mutex/GIL lock-ordering deadlock.

mssql_python/pybind/logger_bridge.cpp

@@ -181,9 +181,11 @@ void LoggerBridge::log(int level, const char* file, int line, const char* format
         complete_message.resize(MAX_LOG_SIZE);
     }
 
-    // Lock for Python call (minimize critical section)
-    std::lock_guard<std::mutex> lock(mutex_);
-
+    // No native mutex here (#671): the GIL acquired below already serializes the
+    // Python API calls, and cached_logger_ is immutable after initialize().
+    // Taking a std::mutex before the GIL inverts lock order against the normal
+    // path (a thread that holds the GIL enters native code that logs), which
+    // deadlocks under concurrent logging.
     try {
         // Acquire GIL for Python API call
         py::gil_scoped_acquire gil;

tests/test_025_logging_concurrency_deadlock.py

@@ -0,0 +1,118 @@
+"""
+Copyright (c) Microsoft Corporation.
+Licensed under the MIT license.
+
+Regression tests for issue #671: enabling DEBUG logging via ``setup_logging()``
+and then opening connections / executing statements from several threads at once
+permanently deadlocked the process at 0% CPU.
+
+Native ``LOG()`` acquires the GIL to route records through Python's ``logging``.
+Several native paths did that while holding a native mutex (the connection-pool
+mutexes, the per-connection child-handle mutex, the logger's own mutex) or the
+env-handle static-init guard. A thread holding the GIL and then blocking on one
+of those native locks closed the cycle. The trigger is DEBUG logging + more than
+one thread; logging off, or a single thread, never deadlocks.
+
+These tests assert a binary property (the concurrent, DEBUG-logged workload runs
+to completion), not a timing threshold, so they are stable across hardware. The
+workload runs in a child process so the parent can enforce a wall-clock timeout
+and kill it: a GIL/native-mutex deadlock freezes the interpreter and cannot be
+interrupted from within the same process. Running it out-of-process also gives
+each run a fresh logging singleton so it never leaks into the rest of the suite.
+"""
+
+import os
+import subprocess
+import sys
+from concurrent.futures import ThreadPoolExecutor
+
+import pytest
+
+import mssql_python
+from mssql_python import connect
+
+
+@pytest.fixture(scope="module")
+def conn_str():
+    conn_str = os.getenv("DB_CONNECTION_STRING")
+    if not conn_str:
+        pytest.skip("DB_CONNECTION_STRING environment variable not set")
+    return conn_str
+
+
+def _run_workload(conn_str, workers, iters, log_file, timeout):
+    """Run the DEBUG-logged concurrent workload (this file's ``__main__`` block)
+    in a child process and fail if it deadlocks or errors.
+
+    The child imports mssql_python the same way this process did (the parent's
+    sys.path is forwarded via PYTHONPATH), and its configuration is passed via
+    the environment so the connection string never appears in the process list.
+    """
+    env = dict(os.environ)
+    env["DB_CONNECTION_STRING"] = conn_str
+    env["MSSQL671_WORKERS"] = str(workers)
+    env["MSSQL671_ITERS"] = str(iters)
+    env["MSSQL671_LOG_FILE"] = log_file
+    env["PYTHONPATH"] = os.pathsep.join(p for p in sys.path if p)
+
+    try:
+        proc = subprocess.run(
+            [sys.executable, os.path.abspath(__file__)],
+            env=env,
+            capture_output=True,
+            text=True,
+            timeout=timeout,
+        )
+    except subprocess.TimeoutExpired:
+        # subprocess.run kills the child on timeout; not finishing means the
+        # workload deadlocked (issue #671 regression).
+        pytest.fail(
+            f"{workers} threads x {iters} iters with DEBUG logging did not finish "
+            f"within {timeout}s - the connection/logging path deadlocked (#671)."
+        )
+
+    assert (
+        proc.returncode == 0 and "WORKLOAD_OK" in proc.stdout
+    ), f"workload exited {proc.returncode}\nstdout:\n{proc.stdout}\nstderr:\n{proc.stderr}"
+
+
+def test_debug_logging_concurrent_connect_does_not_deadlock(conn_str, tmp_path):
+    """Two threads opening connections and executing with DEBUG logging on must
+    not deadlock. Completes in a few seconds on a healthy driver; the timeout
+    only elapses if the deadlock regresses."""
+    _run_workload(conn_str, workers=2, iters=50, log_file=str(tmp_path / "trace.log"), timeout=60)
+
+
+@pytest.mark.stress
+def test_debug_logging_concurrent_connect_does_not_deadlock_stress(conn_str, tmp_path):
+    """Sustained high-concurrency version of the guard above."""
+    _run_workload(
+        conn_str, workers=16, iters=100, log_file=str(tmp_path / "trace.log"), timeout=300
+    )
+
+
+def _run_child_workload():
+    """Child-process entry point (invoked by ``_run_workload``, never collected
+    by pytest). Enables DEBUG logging, then hammers connect/execute/close from
+    ``MSSQL671_WORKERS`` threads."""
+    conn_str = os.environ["DB_CONNECTION_STRING"]
+    workers = int(os.environ["MSSQL671_WORKERS"])
+    iters = int(os.environ["MSSQL671_ITERS"])
+    mssql_python.setup_logging(output="file", log_file_path=os.environ["MSSQL671_LOG_FILE"])
+
+    def worker(_):
+        for _ in range(iters):
+            conn = connect(conn_str, autocommit=True)
+            cursor = conn.cursor()
+            cursor.execute("SELECT 1")
+            cursor.fetchone()
+            cursor.close()
+            conn.close()
+
+    with ThreadPoolExecutor(max_workers=workers) as pool:
+        list(pool.map(worker, range(workers)))
+    print("WORKLOAD_OK")
+
+
+if __name__ == "__main__":
+    _run_child_workload()