diff --git a/mssql_python/pybind/connection/connection.cpp b/mssql_python/pybind/connection/connection.cpp index 4b366575..0a93d1d4 100644 --- a/mssql_python/pybind/connection/connection.cpp +++ b/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 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& 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 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& 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; } diff --git a/mssql_python/pybind/connection/connection_pool.cpp b/mssql_python/pybind/connection/connection_pool.cpp index db891d08..52a9af93 100644 --- a/mssql_python/pybind/connection/connection_pool.cpp +++ b/mssql_python/pybind/connection/connection_pool.cpp @@ -57,7 +57,11 @@ std::shared_ptr 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(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 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(connStr, true); valid_conn->connect(attrs_before); } catch (...) { - // Connect failed — release the reserved slot + // Construct/connect failed — release the reserved slot { std::lock_guard lock(_mutex); if (_current_size > 0) --_current_size; @@ -171,15 +176,22 @@ ConnectionPoolManager& ConnectionPoolManager::getInstance() { std::shared_ptr ConnectionPoolManager::acquireConnection(const std::u16string& connStr, const py::dict& attrs_before) { std::shared_ptr pool; + bool created = false; { std::lock_guard lock(_manager_mutex); auto& pool_ref = _pools[connStr]; if (!pool_ref) { - LOG("Creating new connection pool"); pool_ref = std::make_shared(_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. diff --git a/mssql_python/pybind/logger_bridge.cpp b/mssql_python/pybind/logger_bridge.cpp index 657301cd..04698a50 100644 --- a/mssql_python/pybind/logger_bridge.cpp +++ b/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 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; diff --git a/tests/test_025_logging_concurrency_deadlock.py b/tests/test_025_logging_concurrency_deadlock.py new file mode 100644 index 00000000..e66850bc --- /dev/null +++ b/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()