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

mssql_python/pybind/connection/connection.cpp

@@ -56,10 +56,17 @@ Connection::~Connection() {
 
 // Allocates connection handle
 void Connection::allocateDbcHandle() {
-    auto _envHandle = getEnvHandle();
+    // 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.
+    auto envHandle = [&] {
+        py::gil_scoped_release gil_release;
+        return getEnvHandle();
+    }();
     SQLHANDLE dbc = nullptr;
     LOG("Allocating SQL Connection Handle");
-    SQLRETURN ret = SQLAllocHandle_ptr(SQL_HANDLE_DBC, _envHandle->get(), &dbc);
+    SQLRETURN ret = SQLAllocHandle_ptr(SQL_HANDLE_DBC, envHandle->get(), &dbc);
     checkError(ret);
     _dbcHandle = std::make_shared<SqlHandle>(static_cast<SQLSMALLINT>(SQL_HANDLE_DBC), dbc);
 }
@@ -90,13 +97,21 @@ void Connection::connect(const py::dict& attrs_before) {
 }
 
 void Connection::disconnect() {
+    // Determine GIL state once, up front. disconnect() runs both from
+    // pybind11-bound methods (GIL held) and from GIL-less destructor / shutdown
+    // paths: Connection::~Connection() dropping the last shared_ptr, or teardown
+    // running after the interpreter has been finalized. Every LOG()/LOG_ERROR()
+    // below is gated on hasGil because LOG() acquires the GIL internally via
+    // py::gil_scoped_acquire, which is unsafe when the GIL is not held — it can
+    // hang or std::terminate during interpreter shutdown / stack unwinding.
+    // Py_IsInitialized() is checked first: after Py_Finalize() the interpreter is
+    // gone and PyGILState_Check() is unreliable, so treat "not initialized" as
+    // "no GIL" and skip all Python calls. (#671 follow-up)
+    bool hasGil = Py_IsInitialized() != 0 && PyGILState_Check() != 0;
     if (_dbcHandle) {
-        LOG("Disconnecting from database");
-
-        // Check if we hold the GIL so we can conditionally release it.
-        // The GIL is held when called from pybind11-bound methods but may NOT
-        // be held in destructor paths (C++ shared_ptr ref-count drop, shutdown).
-        bool hasGil = PyGILState_Check() != 0;
+        if (hasGil) {
+            LOG("Disconnecting from database");
+        }
 
         // CRITICAL FIX: Mark all child statement handles as implicitly freed
         // When we free the DBC handle below, the ODBC driver will automatically free
@@ -105,30 +120,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();
@@ -138,6 +148,19 @@ 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. Also gated on
+        // hasGil so the GIL-less destructor / shutdown path never tries to log.
+        if (hasGil) {
+            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.
@@ -160,7 +183,7 @@ void Connection::disconnect() {
         }
         // triggers SQLFreeHandle via destructor, if last owner
         _dbcHandle.reset();
-    } else {
+    } else if (hasGil) {
         LOG("No connection handle to disconnect");
     }
 }
@@ -265,6 +288,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);
 
@@ -277,18 +302,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

@@ -107,7 +107,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;
                     break;
@@ -232,7 +236,10 @@ std::shared_ptr<Connection> ConnectionPool::acquire(const std::u16string& connSt
         if (have_pending_token) {
             std::lock_guard<std::mutex> lock(_mutex);
             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 constructor emits GIL-acquiring log
+                // records, and holding _mutex across a GIL acquisition
+                // deadlocks a thread that holds the GIL and waits on _mutex (#671).
                 ++_current_size;
                 needs_connect = true;
                 break;
@@ -245,9 +252,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 {
+            // Construct the Connection outside _mutex (#671): the constructor
+            // allocates ODBC handles and emits log records that acquire the GIL,
+            // so it must not run while _mutex is held.
+            valid_conn = std::make_shared<Connection>(connStr, true);
             if (have_pending_token) {
                 // Reopen with the fresh token captured during expiry-aware
                 // checkout (the previous connection's token had rotated).
@@ -270,7 +281,7 @@ std::shared_ptr<Connection> ConnectionPool::acquire(const std::u16string& connSt
                 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;
@@ -378,6 +389,7 @@ std::shared_ptr<Connection> ConnectionPoolManager::acquireConnection(const std::
     // else fall back to the connection string (legacy behavior).
     const std::u16string& key = pool_key.empty() ? connStr : pool_key;
     std::shared_ptr<ConnectionPool> pool;
+    bool created = false;
     std::vector<std::shared_ptr<ConnectionPool>> evicted;
     {
         std::lock_guard<std::mutex> lock(_manager_mutex);
@@ -429,11 +441,17 @@ std::shared_ptr<Connection> ConnectionPoolManager::acquireConnection(const std::
         }
         auto& pool_ref = _pools[key];
         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");
+    }
     // Close evicted pools outside _manager_mutex: close() disconnects ODBC
     // handles (releasing the GIL), which must never run while holding
     // _manager_mutex or we risk 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;