PYCBC-1811: Fix conditional GIL hold in pycbc_logger_sink

Changes
--------
* Add pycbc::gil_acquire_guard in src/gil_guard.hxx, a sibling of Ticket
  I's gil_release_guard that wraps PyGILState_Ensure/Release instead of
  PyEval_SaveThread/RestoreThread, since the sink runs on a core IO
  thread that may hold no Python thread state at all
* Replace the raw PyGILState_Ensure/Release pair and try/catch in
  pycbc_logger_sink::log_it_ with the guard. The catch(...) block only
  released the GIL when active_ was still true, so a throw racing the
  atexit deactivate() call held the GIL forever on that thread; the
  guard now releases unconditionally on every exit path, including
  exception unwind, so the try/catch is no longer needed
* Leave ~pycbc_logger_sink's conditional Ensure/Release alone, it is
  intentional and already balanced

Change-Id: I3fb7c793200dcd51dd91899a0bf06339d25a37fa
Reviewed-on: https://review.couchbase.org/c/couchbase-python-client/+/250498
Reviewed-by: Sergey Avseyev <sergey.avseyev@gmail.com>
Tested-by: Build Bot <build@couchbase.com>

Author: thejcfactor

src/gil_guard.hxx

@@ -46,4 +46,29 @@ private:
   PyThreadState* state_;
 };
 
+// Acquires the GIL for the guard's lifetime, for threads that may hold no Python thread state
+// at all (e.g. a core IO thread). Always releases on scope exit, including exception unwind,
+// unlike a bare PyGILState_Ensure/Release pair with a release site in every early return.
+class gil_acquire_guard
+{
+public:
+  gil_acquire_guard()
+    : state_(PyGILState_Ensure())
+  {
+  }
+
+  ~gil_acquire_guard()
+  {
+    PyGILState_Release(state_);
+  }
+
+  gil_acquire_guard(const gil_acquire_guard&) = delete;
+  gil_acquire_guard& operator=(const gil_acquire_guard&) = delete;
+  gil_acquire_guard(gil_acquire_guard&&) = delete;
+  gil_acquire_guard& operator=(gil_acquire_guard&&) = delete;
+
+private:
+  PyGILState_STATE state_;
+};
+
 } // namespace pycbc

src/logger.hxx

@@ -18,6 +18,7 @@
 #pragma once
 
 #include "Python.h"
+#include "gil_guard.hxx"
 #include <atomic>
 #include <core/logger/configuration.hxx>
 #include <core/logger/logger.hxx>
@@ -132,61 +133,51 @@ public:
 protected:
   void log_it_(const spdlog::details::log_msg& msg)
   {
-    PyGILState_STATE state = PyGILState_Ensure();
-    try {
+    pycbc::gil_acquire_guard gil;
 
-      // convert the log_msg_copy to a dict first...
-      auto pyObj_log_record_details = convert_log_msg(msg);
-      if (nullptr == pyObj_log_record_details) {
-        PyErr_WriteUnraisable(pyObj_logger_);
-        PyGILState_Release(state);
-        return;
-      }
+    // convert the log_msg_copy to a dict first...
+    auto pyObj_log_record_details = convert_log_msg(msg);
+    if (nullptr == pyObj_log_record_details) {
+      PyErr_WriteUnraisable(pyObj_logger_);
+      return;
+    }
 
-      // now, create an actual LogRecord from it...
-      auto pyObj_log_record = PyObject_CallObject(pyObj_log_record_type_, pyObj_log_record_details);
-      Py_DECREF(pyObj_log_record_details);
-      if (nullptr != pyObj_log_record) {
-        // we need to fixup the created time, which cannot be passed in the constructor...
-        // The created member is a float containing a float expressed as seconds since the epoch, in
-        // UTC.
-        PyObject* log_time = convert_time_to_float(msg.time);
-        if (nullptr == log_time) {
+    // now, create an actual LogRecord from it...
+    auto pyObj_log_record = PyObject_CallObject(pyObj_log_record_type_, pyObj_log_record_details);
+    Py_DECREF(pyObj_log_record_details);
+    if (nullptr != pyObj_log_record) {
+      // we need to fixup the created time, which cannot be passed in the constructor...
+      // The created member is a float containing a float expressed as seconds since the epoch, in
+      // UTC.
+      PyObject* log_time = convert_time_to_float(msg.time);
+      if (nullptr == log_time) {
+        PyErr_WriteUnraisable(pyObj_log_record);
+      } else {
+        if (-1 == PyObject_SetAttrString(pyObj_log_record, "created", log_time)) {
           PyErr_WriteUnraisable(pyObj_log_record);
-        } else {
-          if (-1 == PyObject_SetAttrString(pyObj_log_record, "created", log_time)) {
-            PyErr_WriteUnraisable(pyObj_log_record);
-          }
-          Py_DECREF(log_time);
         }
+        Py_DECREF(log_time);
+      }
 
-        // now, we want to hand this record to the logger...
-        PyObject* pyObj_args = PyTuple_Pack(1, pyObj_log_record);
-        if (nullptr == pyObj_args) {
+      // now, we want to hand this record to the logger...
+      PyObject* pyObj_args = PyTuple_Pack(1, pyObj_log_record);
+      if (nullptr == pyObj_args) {
+        PyErr_WriteUnraisable(pyObj_logger_handle_method_);
+      } else {
+        PyObject* pyObj_handle_result =
+          PyObject_CallObject(pyObj_logger_handle_method_, pyObj_args);
+        if (nullptr == pyObj_handle_result) {
           PyErr_WriteUnraisable(pyObj_logger_handle_method_);
         } else {
-          PyObject* pyObj_handle_result =
-            PyObject_CallObject(pyObj_logger_handle_method_, pyObj_args);
-          if (nullptr == pyObj_handle_result) {
-            PyErr_WriteUnraisable(pyObj_logger_handle_method_);
-          } else {
-            Py_DECREF(pyObj_handle_result);
-          }
-          Py_DECREF(pyObj_args);
+          Py_DECREF(pyObj_handle_result);
         }
-
-        // that's it, now cleanup.
-        Py_DECREF(pyObj_log_record);
-      } else {
-        PyErr_WriteUnraisable(pyObj_log_record_type_);
-      }
-      PyGILState_Release(state);
-    } catch (...) {
-      // Only release GIL if still active
-      if (active_.load(std::memory_order_acquire)) {
-        PyGILState_Release(state);
+        Py_DECREF(pyObj_args);
       }
-      throw;
+
+      // that's it, now cleanup.
+      Py_DECREF(pyObj_log_record);
+    } else {
+      PyErr_WriteUnraisable(pyObj_log_record_type_);
     }
   }