From f868597b7be6889204de61ec162290d370a8783a Mon Sep 17 00:00:00 2001 From: Gaurav Sharma Date: Mon, 13 Jul 2026 19:44:30 +0530 Subject: [PATCH 1/4] FIX: prevent GIL/mutex deadlock when logging under concurrent multithreaded use native LOG() routes records through Python's logging, so it acquires the GIL from C++. several sites did that while holding a native mutex (the connection-pool mutexes, the per-connection child-handles mutex, the logger's own mutex) or the getEnvHandle static-init guard. under concurrent use with DEBUG logging on, that inverts lock order against a thread that holds the GIL and is waiting on the same native lock, so the process deadlocks at 0% cpu. this makes native logging never hold a native lock across a GIL acquisition: build the log values under the lock, release the lock, then log; construct the Connection and close pools outside the pool mutexes; release the GIL around the env-handle init. verified no deadlock at 1/2/4/8/12/16 threads with logging on (was 100% deadlock at 4 threads). logging output and the pooling/logging/stress test suites are unchanged. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- mssql_python/pybind/connection/connection.cpp | 51 +++++++++++++------ .../pybind/connection/connection_pool.cpp | 46 ++++++++++++----- mssql_python/pybind/logger_bridge.cpp | 8 +-- 3 files changed, 75 insertions(+), 30 deletions(-) diff --git a/mssql_python/pybind/connection/connection.cpp b/mssql_python/pybind/connection/connection.cpp index 4b366575c..0a93d1d42 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 db891d081..8fb33a9d0 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. @@ -209,14 +221,24 @@ void ConnectionPoolManager::configure(int max_size, int idle_timeout_secs) { } void ConnectionPoolManager::closePools() { - std::lock_guard lock(_manager_mutex); - // Keep _manager_mutex held for the full close operation so that - // acquireConnection()/returnConnection() cannot create or use pools - // while closePools() is in progress. - for (auto& [conn_str, pool] : _pools) { - if (pool) { - pool->close(); + std::vector> pools_to_close; + { + std::lock_guard lock(_manager_mutex); + // Detach the pools under the lock so acquireConnection()/returnConnection() + // immediately start fresh and cannot use the pools being closed. + for (auto& [conn_str, pool] : _pools) { + if (pool) { + pools_to_close.push_back(pool); + } } + _pools.clear(); + } + // Close outside _manager_mutex (#671): pool->close() disconnects connections, + // which emit log records (acquiring the GIL) and release/reacquire the GIL + // around the blocking ODBC disconnect. Holding _manager_mutex across a GIL + // acquisition deadlocks a thread that holds the GIL and is waiting on + // _manager_mutex. + for (auto& pool : pools_to_close) { + pool->close(); } - _pools.clear(); } diff --git a/mssql_python/pybind/logger_bridge.cpp b/mssql_python/pybind/logger_bridge.cpp index 657301cd3..04698a503 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; From 19b927cff550c2623309d1c2fffa92a9c5f0870a Mon Sep 17 00:00:00 2001 From: Gaurav Sharma Date: Tue, 14 Jul 2026 10:26:52 +0530 Subject: [PATCH 2/4] FIX: keep closePools() change out of this PR, scope to the reported #671 paths the close-pooling path has the same lock/GIL shape but a different trigger (close running concurrently with active connects) and it interacts with a separate, pre-existing pool-accounting concern in the return path. reverting that hunk here keeps this PR limited to the connect / normal-use deadlock the issue reports. closePools() returns to its original behavior; the five fixed sites (logger bridge, pool acquire, acquireConnection, getEnvHandle, child handle logging) are unchanged. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../pybind/connection/connection_pool.cpp | 26 ++++++------------- 1 file changed, 8 insertions(+), 18 deletions(-) diff --git a/mssql_python/pybind/connection/connection_pool.cpp b/mssql_python/pybind/connection/connection_pool.cpp index 8fb33a9d0..52a9af93d 100644 --- a/mssql_python/pybind/connection/connection_pool.cpp +++ b/mssql_python/pybind/connection/connection_pool.cpp @@ -221,24 +221,14 @@ void ConnectionPoolManager::configure(int max_size, int idle_timeout_secs) { } void ConnectionPoolManager::closePools() { - std::vector> pools_to_close; - { - std::lock_guard lock(_manager_mutex); - // Detach the pools under the lock so acquireConnection()/returnConnection() - // immediately start fresh and cannot use the pools being closed. - for (auto& [conn_str, pool] : _pools) { - if (pool) { - pools_to_close.push_back(pool); - } + std::lock_guard lock(_manager_mutex); + // Keep _manager_mutex held for the full close operation so that + // acquireConnection()/returnConnection() cannot create or use pools + // while closePools() is in progress. + for (auto& [conn_str, pool] : _pools) { + if (pool) { + pool->close(); } - _pools.clear(); - } - // Close outside _manager_mutex (#671): pool->close() disconnects connections, - // which emit log records (acquiring the GIL) and release/reacquire the GIL - // around the blocking ODBC disconnect. Holding _manager_mutex across a GIL - // acquisition deadlocks a thread that holds the GIL and is waiting on - // _manager_mutex. - for (auto& pool : pools_to_close) { - pool->close(); } + _pools.clear(); } From 54b001a6cb65cff0b7bcfa7fefce70980fceaa04 Mon Sep 17 00:00:00 2001 From: Gaurav Sharma Date: Wed, 15 Jul 2026 12:47:06 +0530 Subject: [PATCH 3/4] CHORE: add regression tests for the #671 logging concurrency deadlock adds a functional test (default suite) and a stress test (@pytest.mark.stress) that run DEBUG logging + concurrent connect/execute and assert the process does not deadlock. the workload runs in a child process with a wall-clock timeout so a real GIL/native-mutex deadlock (which freezes the interpreter and can't be interrupted in-process) is turned into a clean failure, and each run gets a fresh logging singleton so it can't leak into the rest of the suite. verified the functional test fails (times out) against the pre-fix build and passes in ~5s against the fixed build. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- tests/_issue671_deadlock_workload.py | 69 ++++++++++++ .../test_025_logging_concurrency_deadlock.py | 103 ++++++++++++++++++ 2 files changed, 172 insertions(+) create mode 100644 tests/_issue671_deadlock_workload.py create mode 100644 tests/test_025_logging_concurrency_deadlock.py diff --git a/tests/_issue671_deadlock_workload.py b/tests/_issue671_deadlock_workload.py new file mode 100644 index 000000000..0c0890d69 --- /dev/null +++ b/tests/_issue671_deadlock_workload.py @@ -0,0 +1,69 @@ +""" +Copyright (c) Microsoft Corporation. +Licensed under the MIT license. + +Standalone workload for the issue #671 deadlock regression tests. + +This module is intentionally NOT named ``test_*`` so pytest does not collect +it. It is executed as a separate process by +``tests/test_025_logging_concurrency_deadlock.py``. + +Why a separate process: issue #671 is a hard GIL/native-mutex deadlock. When it +triggers, the interpreter freezes at 0% CPU and cannot be interrupted from +within (a thread- or signal-based timeout in the same process is unreliable +because the main thread is stuck holding/awaiting the GIL). Running the workload +in a child process lets the parent test enforce a wall-clock timeout and kill it, +turning a would-be hang into a clean test failure. + +Configuration comes from the environment: + DB_CONNECTION_STRING connection string (required) + MSSQL671_WORKERS number of worker threads (default 8) + MSSQL671_ITERS connect/execute cycles per worker (default 25) + MSSQL671_LOG_FILE absolute path for the DEBUG log file (.log/.txt/.csv) + +On success it prints ``WORKLOAD_OK`` and exits 0. On any error it lets the +exception propagate (non-zero exit with a traceback on stderr). +""" + +import os +import sys +from concurrent.futures import ThreadPoolExecutor + +import mssql_python + + +def main() -> int: + conn_str = os.environ["DB_CONNECTION_STRING"] + workers = int(os.environ.get("MSSQL671_WORKERS", "8")) + iters = int(os.environ.get("MSSQL671_ITERS", "25")) + log_file = os.environ.get("MSSQL671_LOG_FILE") + + # The deadlock only reproduces with DEBUG logging enabled (that is what + # routes native log records through Python's logging under the GIL). + if log_file: + mssql_python.setup_logging(output="file", log_file_path=log_file) + else: + mssql_python.setup_logging(output="file") + + def worker(n: int) -> int: + for i in range(iters): + conn = mssql_python.connect(conn_str, autocommit=True) + cur = conn.cursor() + cur.execute("SELECT @@SPID, {}, {}".format(n, i)) + cur.fetchone() + cur.execute("SELECT name FROM sys.objects WHERE object_id < 50") + cur.fetchall() + cur.close() + conn.close() + return n + + with ThreadPoolExecutor(max_workers=workers) as pool: + # Force every future to be evaluated so exceptions propagate. + list(pool.map(worker, range(workers))) + + print("WORKLOAD_OK", flush=True) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tests/test_025_logging_concurrency_deadlock.py b/tests/test_025_logging_concurrency_deadlock.py new file mode 100644 index 000000000..87db0a3f0 --- /dev/null +++ b/tests/test_025_logging_concurrency_deadlock.py @@ -0,0 +1,103 @@ +""" +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 multiple threads +concurrently permanently deadlocked the process at 0% CPU. + +Root cause was a lock-order inversion: native ``LOG()`` acquires the GIL to route +records through Python's ``logging``, and several native code paths did that while +holding a native mutex (connection-pool mutexes, the per-connection child-handle +mutex, the logger's own mutex) or the env-handle static-init guard. A thread that +held the GIL and then blocked on one of those native locks completed the cycle. + +These tests assert a binary correctness property (the concurrent, DEBUG-logged +workload runs to completion), not a performance threshold, so they are stable +across hardware. + +The workload runs in a **separate process** (``_issue671_deadlock_workload.py``) +so the parent can enforce a wall-clock timeout and kill it. A GIL/native-mutex +deadlock freezes the interpreter and cannot be interrupted reliably from within +the same process, so an in-process (thread/signal) timeout would itself hang. +Isolating in a child process also gives every run a fresh logging singleton, so +enabling DEBUG logging here never leaks into the rest of the suite. +""" + +import os +import subprocess +import sys +import tempfile + +import pytest + +_WORKLOAD = os.path.join(os.path.dirname(os.path.abspath(__file__)), "_issue671_deadlock_workload.py") + + +def _run_workload(conn_str, workers, iters, timeout): + """Run the concurrent DEBUG-logging workload in a child process. + + Returns nothing on success; calls pytest.fail on deadlock (timeout) or on a + non-zero exit. Propagates the parent's import paths via PYTHONPATH so the + child imports the same mssql_python the test suite uses (installed or + in-place build), without any sys.path juggling in the workload. + """ + log_dir = tempfile.mkdtemp(prefix="mssql671_") + env = dict(os.environ) + env["DB_CONNECTION_STRING"] = conn_str + env["MSSQL671_WORKERS"] = str(workers) + env["MSSQL671_ITERS"] = str(iters) + env["MSSQL671_LOG_FILE"] = os.path.join(log_dir, "trace.log") + env["PYTHONPATH"] = os.pathsep.join(p for p in sys.path if p) + + try: + proc = subprocess.run( + [sys.executable, _WORKLOAD], + env=env, + capture_output=True, + text=True, + timeout=timeout, + ) + except subprocess.TimeoutExpired as exc: + # subprocess.run kills the child on timeout. A timeout here means the + # workload never returned == the deadlock reproduced. + pytest.fail( + "issue #671 regression: concurrent DEBUG-logged workload did not " + "finish within {}s ({} workers x {} iters) - likely deadlocked.\n" + "stdout so far:\n{}\nstderr so far:\n{}".format( + timeout, workers, iters, exc.stdout or "", exc.stderr or "" + ) + ) + finally: + # Best-effort cleanup of the log directory. + try: + for name in os.listdir(log_dir): + os.remove(os.path.join(log_dir, name)) + os.rmdir(log_dir) + except OSError: + pass + + if proc.returncode != 0 or "WORKLOAD_OK" not in proc.stdout: + pytest.fail( + "concurrent DEBUG-logged workload failed (rc={}).\n" + "stdout:\n{}\nstderr:\n{}".format(proc.returncode, proc.stdout, proc.stderr) + ) + + +def test_concurrent_debug_logging_does_not_deadlock(conn_str): + """Functional guard: DEBUG logging + concurrent connect/execute must not hang. + + Small and fast on a healthy driver (a few seconds); the generous timeout only + ever elapses if the deadlock regresses. + """ + if not conn_str: + pytest.skip("DB_CONNECTION_STRING environment variable not set") + _run_workload(conn_str, workers=8, iters=25, timeout=90) + + +@pytest.mark.stress +def test_concurrent_debug_logging_does_not_deadlock_stress(conn_str): + """Stress guard: sustained high-concurrency DEBUG-logged load must not hang.""" + if not conn_str: + pytest.skip("DB_CONNECTION_STRING environment variable not set") + _run_workload(conn_str, workers=16, iters=100, timeout=300) From 2abe62488706c5b32b979560647100fa68d7f15c Mon Sep 17 00:00:00 2001 From: Gaurav Sharma Date: Wed, 15 Jul 2026 13:02:38 +0530 Subject: [PATCH 4/4] CHORE: fold #671 deadlock workload into the test file and lighten default run removes the standalone tests/_issue671_deadlock_workload.py script (an odd non-test file in tests/) and moves the workload into a __main__ block in test_025, which the tests invoke as the child process. one self-contained file, matching the layout of the other test modules. also drops the default (non-stress) test to 2 threads to match the repo's lightest concurrency baseline (test_020's (2, 50)); 2 threads is issue #671's stated minimum and still deadlocks the pre-fix build 3/3 runs, so the guard stays reliable without loading PR validation. the heavy 16-thread variant stays under @pytest.mark.stress. log file now uses pytest's tmp_path (auto-cleaned). Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- tests/_issue671_deadlock_workload.py | 69 --------- .../test_025_logging_concurrency_deadlock.py | 145 ++++++++++-------- 2 files changed, 80 insertions(+), 134 deletions(-) delete mode 100644 tests/_issue671_deadlock_workload.py diff --git a/tests/_issue671_deadlock_workload.py b/tests/_issue671_deadlock_workload.py deleted file mode 100644 index 0c0890d69..000000000 --- a/tests/_issue671_deadlock_workload.py +++ /dev/null @@ -1,69 +0,0 @@ -""" -Copyright (c) Microsoft Corporation. -Licensed under the MIT license. - -Standalone workload for the issue #671 deadlock regression tests. - -This module is intentionally NOT named ``test_*`` so pytest does not collect -it. It is executed as a separate process by -``tests/test_025_logging_concurrency_deadlock.py``. - -Why a separate process: issue #671 is a hard GIL/native-mutex deadlock. When it -triggers, the interpreter freezes at 0% CPU and cannot be interrupted from -within (a thread- or signal-based timeout in the same process is unreliable -because the main thread is stuck holding/awaiting the GIL). Running the workload -in a child process lets the parent test enforce a wall-clock timeout and kill it, -turning a would-be hang into a clean test failure. - -Configuration comes from the environment: - DB_CONNECTION_STRING connection string (required) - MSSQL671_WORKERS number of worker threads (default 8) - MSSQL671_ITERS connect/execute cycles per worker (default 25) - MSSQL671_LOG_FILE absolute path for the DEBUG log file (.log/.txt/.csv) - -On success it prints ``WORKLOAD_OK`` and exits 0. On any error it lets the -exception propagate (non-zero exit with a traceback on stderr). -""" - -import os -import sys -from concurrent.futures import ThreadPoolExecutor - -import mssql_python - - -def main() -> int: - conn_str = os.environ["DB_CONNECTION_STRING"] - workers = int(os.environ.get("MSSQL671_WORKERS", "8")) - iters = int(os.environ.get("MSSQL671_ITERS", "25")) - log_file = os.environ.get("MSSQL671_LOG_FILE") - - # The deadlock only reproduces with DEBUG logging enabled (that is what - # routes native log records through Python's logging under the GIL). - if log_file: - mssql_python.setup_logging(output="file", log_file_path=log_file) - else: - mssql_python.setup_logging(output="file") - - def worker(n: int) -> int: - for i in range(iters): - conn = mssql_python.connect(conn_str, autocommit=True) - cur = conn.cursor() - cur.execute("SELECT @@SPID, {}, {}".format(n, i)) - cur.fetchone() - cur.execute("SELECT name FROM sys.objects WHERE object_id < 50") - cur.fetchall() - cur.close() - conn.close() - return n - - with ThreadPoolExecutor(max_workers=workers) as pool: - # Force every future to be evaluated so exceptions propagate. - list(pool.map(worker, range(workers))) - - print("WORKLOAD_OK", flush=True) - return 0 - - -if __name__ == "__main__": - sys.exit(main()) diff --git a/tests/test_025_logging_concurrency_deadlock.py b/tests/test_025_logging_concurrency_deadlock.py index 87db0a3f0..e66850bc0 100644 --- a/tests/test_025_logging_concurrency_deadlock.py +++ b/tests/test_025_logging_concurrency_deadlock.py @@ -3,101 +3,116 @@ Licensed under the MIT license. Regression tests for issue #671: enabling DEBUG logging via ``setup_logging()`` -and then opening connections / executing statements from multiple threads -concurrently permanently deadlocked the process at 0% CPU. - -Root cause was a lock-order inversion: native ``LOG()`` acquires the GIL to route -records through Python's ``logging``, and several native code paths did that while -holding a native mutex (connection-pool mutexes, the per-connection child-handle -mutex, the logger's own mutex) or the env-handle static-init guard. A thread that -held the GIL and then blocked on one of those native locks completed the cycle. - -These tests assert a binary correctness property (the concurrent, DEBUG-logged -workload runs to completion), not a performance threshold, so they are stable -across hardware. - -The workload runs in a **separate process** (``_issue671_deadlock_workload.py``) -so the parent can enforce a wall-clock timeout and kill it. A GIL/native-mutex -deadlock freezes the interpreter and cannot be interrupted reliably from within -the same process, so an in-process (thread/signal) timeout would itself hang. -Isolating in a child process also gives every run a fresh logging singleton, so -enabling DEBUG logging here never leaks into the rest of the suite. +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 -import tempfile +from concurrent.futures import ThreadPoolExecutor import pytest -_WORKLOAD = os.path.join(os.path.dirname(os.path.abspath(__file__)), "_issue671_deadlock_workload.py") +import mssql_python +from mssql_python import connect -def _run_workload(conn_str, workers, iters, timeout): - """Run the concurrent DEBUG-logging workload in a child process. +@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 + - Returns nothing on success; calls pytest.fail on deadlock (timeout) or on a - non-zero exit. Propagates the parent's import paths via PYTHONPATH so the - child imports the same mssql_python the test suite uses (installed or - in-place build), without any sys.path juggling in the workload. +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. """ - log_dir = tempfile.mkdtemp(prefix="mssql671_") env = dict(os.environ) env["DB_CONNECTION_STRING"] = conn_str env["MSSQL671_WORKERS"] = str(workers) env["MSSQL671_ITERS"] = str(iters) - env["MSSQL671_LOG_FILE"] = os.path.join(log_dir, "trace.log") + 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, _WORKLOAD], + [sys.executable, os.path.abspath(__file__)], env=env, capture_output=True, text=True, timeout=timeout, ) - except subprocess.TimeoutExpired as exc: - # subprocess.run kills the child on timeout. A timeout here means the - # workload never returned == the deadlock reproduced. - pytest.fail( - "issue #671 regression: concurrent DEBUG-logged workload did not " - "finish within {}s ({} workers x {} iters) - likely deadlocked.\n" - "stdout so far:\n{}\nstderr so far:\n{}".format( - timeout, workers, iters, exc.stdout or "", exc.stderr or "" - ) - ) - finally: - # Best-effort cleanup of the log directory. - try: - for name in os.listdir(log_dir): - os.remove(os.path.join(log_dir, name)) - os.rmdir(log_dir) - except OSError: - pass - - if proc.returncode != 0 or "WORKLOAD_OK" not in proc.stdout: + except subprocess.TimeoutExpired: + # subprocess.run kills the child on timeout; not finishing means the + # workload deadlocked (issue #671 regression). pytest.fail( - "concurrent DEBUG-logged workload failed (rc={}).\n" - "stdout:\n{}\nstderr:\n{}".format(proc.returncode, proc.stdout, proc.stderr) + 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_concurrent_debug_logging_does_not_deadlock(conn_str): - """Functional guard: DEBUG logging + concurrent connect/execute must not hang. - Small and fast on a healthy driver (a few seconds); the generous timeout only - ever elapses if the deadlock regresses. - """ - if not conn_str: - pytest.skip("DB_CONNECTION_STRING environment variable not set") - _run_workload(conn_str, workers=8, iters=25, timeout=90) +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_concurrent_debug_logging_does_not_deadlock_stress(conn_str): - """Stress guard: sustained high-concurrency DEBUG-logged load must not hang.""" - if not conn_str: - pytest.skip("DB_CONNECTION_STRING environment variable not set") - _run_workload(conn_str, workers=16, iters=100, timeout=300) +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()