From c41f7e716790787d2d659910ec9479e9afeb9728 Mon Sep 17 00:00:00 2001 From: Chris Von Bargen Date: Fri, 13 Mar 2026 01:09:43 -0400 Subject: [PATCH] Add RDLog::CaptureErrorLog for capturing error log messages (#9138) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Add RDLog::CaptureLog for capturing log messages Adds an RAII `CaptureLog` class to `namespace RDLog` (alongside the existing `LogStateSetter`) that redirects an RDKit logger's output to an internal `std::stringstream` for the duration of its lifetime. On destruction the original stream destination and enabled state are fully restored. Nesting is supported: an inner capture shadows the outer one and each collects its own messages independently. The default constructor captures `rdErrorLog`; an explicit constructor accepts any `RDLogger`. Both enable the logger if it was previously disabled and restore that state on destruction. Python bindings expose `rdBase.CaptureLog` as a context manager with a `messages` read-only property, mirroring the existing `rdBase.BlockLogs` pattern. Messages remain accessible after the `with` block exits. C++ tests are added to `catch_logs.cpp` (6 Catch2 sections covering basic capture, empty state, enable/restore, stream restore, explicit logger, and nested captures). Python tests are added to `UnitTestLogging.py` (6 unittest cases covering the same scenarios). Co-Authored-By: Claude Sonnet 4.6 * CaptureLog: add per-level properties (error_messages, warning_messages, etc.) The Python CaptureLog wrapper now captures all four log levels simultaneously. Per-level properties (error_messages, warning_messages, info_messages, debug_messages) give access to messages from each logger independently; the existing messages property returns them all combined. The C++ RDLog::CaptureLog class is unchanged — it remains a clean single-logger RAII type. The Python wrapper composes four instances of it, one per log level. Suggested by bp-kelley in PR review. Co-Authored-By: Claude Sonnet 4.6 * Refactor CaptureLog: add named per-level subclasses Add CaptureErrorLog, CaptureWarningLog, CaptureInfoLog, and CaptureDebugLog as named convenience subclasses of CaptureLog, each capturing a specific logger. Update Python bindings to expose the four named classes directly (dropping the combined multi-capture approach), and update tests accordingly. Co-Authored-By: Claude Sonnet 4.6 * Simplify CaptureLog: no argument, captures rdErrorLog only Remove the RDLogger argument overload, the four named subclasses, and the PyCaptureLog template in favor of a single no-argument CaptureLog that mirrors the Schrödinger CaptureRDErrorLog from which it was inspired. Co-Authored-By: Claude Sonnet 4.6 * CaptureLog tests: add dp_dest restoration and LogStateSetter interaction Co-Authored-By: Claude Sonnet 4.6 * Rename CaptureLog to CaptureErrorLog The name CaptureLog was ambiguous; CaptureErrorLog is explicit about which logger it captures and avoids redundancy within namespace RDLog. Co-Authored-By: Claude Sonnet 4.6 * Generalize CaptureErrorLog into CaptureLog with logger parameter Replace CaptureErrorLog with CaptureLog, which accepts any RDLogger in its constructor (e.g. rdErrorLog, rdWarningLog). Add CaptureErrorLog as a convenience subclass that pre-fills rdErrorLog, preserving backward compatibility for existing callers. Co-Authored-By: Claude Sonnet 4.6 --------- Co-authored-by: Claude Sonnet 4.6 --- Code/RDBoost/Wrap/RDBase.cpp | 36 +++++++++++++ Code/RDGeneral/RDLog.cpp | 23 +++++++++ Code/RDGeneral/RDLog.h | 36 +++++++++++++ Code/RDGeneral/catch_logs.cpp | 96 +++++++++++++++++++++++++++++++++++ rdkit/UnitTestLogging.py | 53 +++++++++++++++++++ 5 files changed, 244 insertions(+) diff --git a/Code/RDBoost/Wrap/RDBase.cpp b/Code/RDBoost/Wrap/RDBase.cpp index 181bffd02..ce5540fd8 100644 --- a/Code/RDBoost/Wrap/RDBase.cpp +++ b/Code/RDBoost/Wrap/RDBase.cpp @@ -208,6 +208,25 @@ class BlockLogs : public boost::noncopyable { std::unique_ptr m_log_setter; }; +struct PyCaptureErrorLog : boost::noncopyable { + PyCaptureErrorLog *enter() { return this; } + void exit(python::object /*exc_type*/, python::object /*exc_val*/, + python::object /*traceback*/) { + if (m_capturer) { + m_messages = m_capturer->messages(); + m_capturer.reset(); + } + } + std::string messages() const { + return m_capturer ? m_capturer->messages() : m_messages; + } + + private: + std::unique_ptr m_capturer{ + new RDLog::CaptureErrorLog}; + std::string m_messages; +}; + namespace { struct python_streambuf_wrapper { typedef boost_adaptbx::python::streambuf wt; @@ -428,4 +447,21 @@ BOOST_PYTHON_MODULE(rdBase) { .def("__enter__", &BlockLogs::enter, python::return_internal_reference<>()) .def("__exit__", &BlockLogs::exit); + + python::class_( + "CaptureErrorLog", + "Captures messages from rdErrorLog while this instance is in scope.\n" + "Can be used as a context manager. The ``messages`` property is\n" + "accessible both inside the context and after it exits.\n" + "Nesting is supported: inner captures shadow outer ones.\n\n" + "Example::\n\n" + " with rdBase.CaptureErrorLog() as capture:\n" + " rdkit_function_that_may_fail()\n" + " print(capture.messages)\n", + python::init<>(python::args("self"))) + .def("__enter__", &PyCaptureErrorLog::enter, + python::return_internal_reference<>()) + .def("__exit__", &PyCaptureErrorLog::exit) + .add_property("messages", &PyCaptureErrorLog::messages, + "Messages captured from rdErrorLog."); } diff --git a/Code/RDGeneral/RDLog.cpp b/Code/RDGeneral/RDLog.cpp index 00caf4eb7..2abb2da8e 100644 --- a/Code/RDGeneral/RDLog.cpp +++ b/Code/RDGeneral/RDLog.cpp @@ -149,6 +149,29 @@ void InitLogs() { rdErrorLog = std::make_shared(&std::cerr); } +CaptureLog::CaptureLog(RDLogger log) : d_log(std::move(log)) { + if (!d_log) { + return; + } + d_logWasEnabled = d_log->df_enabled; + d_log->df_enabled = true; + d_savedDest = d_log->dp_dest; + d_log->dp_dest = &d_messages; + d_savedTeestream = d_log->teestream; + d_log->teestream = nullptr; +} + +CaptureLog::~CaptureLog() { + if (!d_log) { + return; + } + d_log->dp_dest = d_savedDest; + d_log->teestream = d_savedTeestream; + d_log->df_enabled = d_logWasEnabled; +} + +std::string CaptureLog::messages() const { return d_messages.str(); } + std::ostream &toStream(std::ostream &logstrm) { char buffer[16]; time_t t = time(nullptr); diff --git a/Code/RDGeneral/RDLog.h b/Code/RDGeneral/RDLog.h index cc569c027..a14f471f9 100644 --- a/Code/RDGeneral/RDLog.h +++ b/Code/RDGeneral/RDLog.h @@ -18,6 +18,7 @@ #include #include "BoostEndInclude.h" #include +#include #include #include @@ -148,6 +149,41 @@ class RDKIT_RDGENERAL_EXPORT LogStateSetter : public boost::noncopyable { std::uint64_t d_origState = 0; }; +//! RAII class to capture messages from a given \c RDLogger. +//! +//! The log is enabled when this object is constructed and its original enabled +//! state is restored when this object is destroyed. The stream destination is +//! also restored on destruction. Nesting is supported: inner captures shadow +//! outer ones. +//! +//! \b Example: +//! \code +//! RDLog::CaptureLog capture{rdErrorLog}; +//! functionThatMayFail(); +//! std::string errs = capture.messages(); +//! \endcode +class RDKIT_RDGENERAL_EXPORT CaptureLog : public boost::noncopyable { + public: + explicit CaptureLog(RDLogger log); + ~CaptureLog(); + + //! Returns all messages captured since construction. + std::string messages() const; + + private: + RDLogger d_log; + std::stringstream d_messages; + std::ostream *d_savedDest = nullptr; + boost::logging::RDTeeStream *d_savedTeestream = nullptr; + bool d_logWasEnabled = true; +}; + +//! Convenience subclass of \c CaptureLog that captures \c rdErrorLog. +class RDKIT_RDGENERAL_EXPORT CaptureErrorLog : public CaptureLog { + public: + CaptureErrorLog() : CaptureLog(rdErrorLog) {} +}; + inline void deprecationWarning(const std::string &message) { BOOST_LOG(rdWarningLog) << "DEPRECATION WARNING: " << message << std::endl; } diff --git a/Code/RDGeneral/catch_logs.cpp b/Code/RDGeneral/catch_logs.cpp index 62cbde6a0..862fc376b 100644 --- a/Code/RDGeneral/catch_logs.cpp +++ b/Code/RDGeneral/catch_logs.cpp @@ -113,6 +113,102 @@ TEST_CASE("GitHub Issue #5172", "[bug][logging]") { rdWarningLog->ClearTee(); } +TEST_CASE("CaptureLog") { + RDLog::InitLogs(); + + SECTION("basic capture of rdErrorLog") { + RDLog::CaptureLog capture{rdErrorLog}; + BOOST_LOG(rdErrorLog) << "test error" << std::endl; + CHECK(capture.messages().find("test error") != std::string::npos); + } + + SECTION("basic capture of rdWarningLog") { + RDLog::CaptureLog capture{rdWarningLog}; + BOOST_LOG(rdWarningLog) << "test warning" << std::endl; + CHECK(capture.messages().find("test warning") != std::string::npos); + } + + SECTION("empty when nothing logged") { + RDLog::CaptureLog capture{rdErrorLog}; + CHECK(capture.messages().empty()); + } + + SECTION("enables a disabled log and restores its state") { + rdErrorLog->df_enabled = false; + { + RDLog::CaptureLog capture{rdErrorLog}; + CHECK(rdErrorLog->df_enabled); + BOOST_LOG(rdErrorLog) << "captured despite disabled" << std::endl; + CHECK(capture.messages().find("captured despite disabled") != + std::string::npos); + } + // enabled state restored to false + CHECK(!rdErrorLog->df_enabled); + rdErrorLog->df_enabled = true; + } + + SECTION("restores original stream destination") { + { + RDLog::CaptureLog capture{rdErrorLog}; + BOOST_LOG(rdErrorLog) << "captured" << std::endl; + } + // After capture, logs go to the original destination again + std::stringstream ss; + rdErrorLog->SetTee(ss); + BOOST_LOG(rdErrorLog) << "after restore" << std::endl; + rdErrorLog->ClearTee(); + CHECK(ss.str().find("after restore") != std::string::npos); + } + + SECTION("only captures the specified log") { + RDLog::CaptureLog capture{rdErrorLog}; + BOOST_LOG(rdWarningLog) << "test warning" << std::endl; + BOOST_LOG(rdErrorLog) << "test error" << std::endl; + CHECK(capture.messages().find("test error") != std::string::npos); + CHECK(capture.messages().find("test warning") == std::string::npos); + } + + SECTION("restores dp_dest to original stream") { + auto *original_dest = rdErrorLog->dp_dest; + { + RDLog::CaptureLog capture{rdErrorLog}; + CHECK(rdErrorLog->dp_dest != original_dest); + } + CHECK(rdErrorLog->dp_dest == original_dest); + } + + SECTION("re-enables log even when silenced by LogStateSetter") { + RDLog::CaptureLog outer{rdErrorLog}; + RDLog::LogStateSetter silence; + + BOOST_LOG(rdErrorLog) << "silenced" << std::endl; + CHECK(outer.messages().empty()); + + { + RDLog::CaptureLog inner{rdErrorLog}; + BOOST_LOG(rdErrorLog) << "captured despite silence" << std::endl; + CHECK(inner.messages().find("captured despite silence") != + std::string::npos); + } + + BOOST_LOG(rdErrorLog) << "silenced again" << std::endl; + CHECK(outer.messages().empty()); + } + + SECTION("nested captures") { + RDLog::CaptureLog outer{rdErrorLog}; + BOOST_LOG(rdErrorLog) << "outer message" << std::endl; + { + RDLog::CaptureLog inner{rdErrorLog}; + BOOST_LOG(rdErrorLog) << "inner message" << std::endl; + CHECK(inner.messages().find("inner message") != std::string::npos); + CHECK(inner.messages().find("outer message") == std::string::npos); + } + CHECK(outer.messages().find("outer message") != std::string::npos); + CHECK(outer.messages().find("inner message") == std::string::npos); + } +} + TEST_CASE("Tee to file") { const std::string filename = "error_log.txt"; rdErrorLog->SetTee(filename); diff --git a/rdkit/UnitTestLogging.py b/rdkit/UnitTestLogging.py index af791268c..22303da50 100644 --- a/rdkit/UnitTestLogging.py +++ b/rdkit/UnitTestLogging.py @@ -407,5 +407,58 @@ class TestWrapLogs(unittest.TestCase): self.assertEqual(captured, {'sys.stderr': expect, 'std::cerr': expect}) +class TestCaptureErrorLog(unittest.TestCase): + + @classmethod + def setUpClass(cls): + rdBase.LogToCppStreams() + rdBase.EnableLog('rdApp.error') + + def testBasicCapture(self): + with rdBase.CaptureErrorLog() as capture: + rdBase.LogErrorMsg("captured error") + self.assertIn("captured error", capture.messages) + + def testOnlyCapturesErrorLog(self): + with rdBase.CaptureErrorLog() as capture: + rdBase.LogErrorMsg("an error") + rdBase.LogWarningMsg("a warning") + self.assertIn("an error", capture.messages) + self.assertNotIn("a warning", capture.messages) + + def testEmptyWhenNothingLogged(self): + with rdBase.CaptureErrorLog() as capture: + pass + self.assertEqual(capture.messages, "") + + def testMessagesAccessibleAfterContextExit(self): + with rdBase.CaptureErrorLog() as capture: + rdBase.LogErrorMsg("persistent error") + self.assertIn("persistent error", capture.messages) + + def testLoggingRestoredAfterContextExit(self): + with rdBase.CaptureErrorLog() as capture: + rdBase.LogErrorMsg("inside") + with rdBase.CaptureErrorLog() as capture2: + rdBase.LogErrorMsg("outside") + self.assertNotIn("inside", capture2.messages) + self.assertIn("outside", capture2.messages) + + def testNestedCaptures(self): + with rdBase.CaptureErrorLog() as outer: + rdBase.LogErrorMsg("outer message") + with rdBase.CaptureErrorLog() as inner: + rdBase.LogErrorMsg("inner message") + self.assertIn("inner message", inner.messages) + self.assertNotIn("outer message", inner.messages) + self.assertIn("outer message", outer.messages) + self.assertNotIn("inner message", outer.messages) + + def testMessagesReadableInsideContext(self): + with rdBase.CaptureErrorLog() as capture: + rdBase.LogErrorMsg("first") + self.assertIn("first", capture.messages) + + if __name__ == '__main__': # pragma: nocover unittest.main()