diff --git a/mssql_python/pybind/connection/connection.cpp b/mssql_python/pybind/connection/connection.cpp index 3502abad..511555bc 100644 --- a/mssql_python/pybind/connection/connection.cpp +++ b/mssql_python/pybind/connection/connection.cpp @@ -56,7 +56,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); @@ -90,13 +98,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 +121,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(); @@ -138,6 +149,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 +184,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 +289,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); @@ -277,18 +303,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 34086d71..c4c3418d 100644 --- a/mssql_python/pybind/connection/connection_pool.cpp +++ b/mssql_python/pybind/connection/connection_pool.cpp @@ -107,7 +107,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; break; @@ -232,7 +236,10 @@ std::shared_ptr ConnectionPool::acquire(const std::u16string& connSt if (have_pending_token) { std::lock_guard lock(_mutex); 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 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 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(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 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 lock(_mutex); if (_current_size > 0) --_current_size; @@ -378,6 +389,7 @@ std::shared_ptr 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 pool; + bool created = false; std::vector> evicted; { std::lock_guard lock(_manager_mutex); @@ -429,11 +441,17 @@ std::shared_ptr ConnectionPoolManager::acquireConnection(const std:: } auto& pool_ref = _pools[key]; 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"); + } // 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. 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..98cd75f5 --- /dev/null +++ b/tests/test_025_logging_concurrency_deadlock.py @@ -0,0 +1,218 @@ +""" +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 + + +def _forward_pythonpath(): + """Build the PYTHONPATH used to forward the parent's import path to a child + process, preserving every entry including an empty one. + + An empty ``sys.path`` entry means "the current working directory". A child + launched as a script (``python /abs/path/to/this_file.py``) has ``sys.path[0]`` + set to the script's own directory, not the parent's cwd, so dropping the empty + entry can leave the child unable to import the same local ``mssql_python`` the + parent used. Mirrors the established pattern in + ``test_023_ssh_tunnel_gil_release.py``. (#671 review follow-up) + """ + return os.pathsep.join(sys.path) + + +@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, + scenario="concurrency", + marker="WORKLOAD_OK", +): + """Run one of this file's ``__main__`` child scenarios in a subprocess 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 verbatim 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_SCENARIO"] = scenario + env["MSSQL671_WORKERS"] = str(workers) + env["MSSQL671_ITERS"] = str(iters) + env["MSSQL671_LOG_FILE"] = log_file + env["PYTHONPATH"] = _forward_pythonpath() + + 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"{scenario} workload ({workers} threads x {iters} iters) with DEBUG " + f"logging did not finish within {timeout}s - the connection/logging " + f"path deadlocked (#671)." + ) + + assert ( + proc.returncode == 0 and marker 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 test_child_pythonpath_forwards_cwd_entry(): + """Regression for the #671 review (connection.cpp deadlock PR): the child + PYTHONPATH must forward the parent's import path verbatim, including an empty + entry that stands for the current working directory. Filtering empty entries + (the earlier ``if p`` form) drops cwd, so a script-launched child can fail to + import the same local ``mssql_python`` the parent used. This asserts the + empty entry survives, which is exactly what the filter used to remove.""" + saved = sys.path + try: + sys.path = ["", "/fake/site-packages", "/fake/repo-root"] + forwarded = _forward_pythonpath().split(os.pathsep) + finally: + sys.path = saved + assert "" in forwarded, ( + "empty (current-working-directory) sys.path entry must be preserved in the " + "child PYTHONPATH; filtering it can break the child's local mssql_python import" + ) + assert forwarded == ["", "/fake/site-packages", "/fake/repo-root"] + + +def test_debug_logging_pooled_connection_shutdown_exits_cleanly(conn_str, tmp_path): + """Guard for the connection-teardown logging path with DEBUG logging on. + + The child opens and closes pooled connections, then exits without draining + the pool. At interpreter shutdown the pooling ``atexit`` handler + (``shutdown_pooling`` -> ``disable_pooling()`` -> ``closePools()``) + disconnects the pooled physical connections, and ``disconnect()`` logs while + doing so. This asserts that DEBUG-logged connection teardown at process exit + completes cleanly and promptly; a hang or crash there trips the timeout. + + Note: this is a teardown smoke guard, not a strict revert-detector for the + hasGil gating in connection.cpp. The pure GIL-less path (the static + ConnectionPoolManager destructor running after Py_Finalize) is not + deterministically reachable from Python because the atexit handler drains the + pool with the GIL still held, before finalization. + """ + _run_workload( + conn_str, + workers=1, + iters=8, + log_file=str(tmp_path / "trace.log"), + timeout=60, + scenario="shutdown", + marker="SHUTDOWN_WORKLOAD_OK", + ) + + +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") + + +def _run_child_shutdown_workload(): + """Child-process entry point for the shutdown/teardown guard. Enables DEBUG + logging, then opens and closes pooled connections. It returns without draining + the pool, so the pooling ``atexit`` handler disconnects the pooled physical + connections at interpreter shutdown while DEBUG logging is on. Reaching the + exit marker and returning 0 is the assertion.""" + conn_str = os.environ["DB_CONNECTION_STRING"] + iters = int(os.environ["MSSQL671_ITERS"]) + mssql_python.setup_logging(output="file", log_file_path=os.environ["MSSQL671_LOG_FILE"]) + + for _ in range(iters): + conn = connect(conn_str, autocommit=True) + cursor = conn.cursor() + cursor.execute("SELECT 1") + cursor.fetchone() + cursor.close() + conn.close() # returns the physical connection to the pool + + # Deliberately do NOT drain the pool here: let interpreter shutdown (the + # pooling atexit handler, then process exit) disconnect the pooled + # connections with DEBUG logging on. + print("SHUTDOWN_WORKLOAD_OK", flush=True) + + +if __name__ == "__main__": + _scenario = os.environ.get("MSSQL671_SCENARIO", "concurrency") + if _scenario == "shutdown": + _run_child_shutdown_workload() + else: + _run_child_workload()