disable Info and Debug logs by default (#5065)

* disable the info and debug logs by default

* adjust tests to the newly disabled logs

* add LogStateSetter

* namespace reorg

* add some tests

* remove vestigial code

* switch to using std::vector

Code/GraphMol/Deprotect/Deprotect.cpp

@@ -126,7 +126,7 @@ std::unique_ptr<ROMol> deprotect(
       for (auto &prods : deprotect.rxn->runReactant(m, 0)) {
         m = prods[0];
         try {
-          RDLog::BlockLogs blocker;
+          RDLog::LogStateSetter blocker;
           MolOps::sanitizeMol(*dynamic_cast<RWMol *>(m.get()));
         } catch (MolSanitizeException &) {
           continue;
@@ -164,7 +164,7 @@ bool deprotectInPlace(RWMol &mol,
       bool changes = deprotect.rxn->runReactant(mol);
       if (changes) {
         try {
-          RDLog::BlockLogs blocker;
+          RDLog::LogStateSetter blocker;
           MolOps::sanitizeMol(mol);
         } catch (MolSanitizeException &) {
           continue;

Code/GraphMol/ForceFieldHelpers/CrystalFF/TorsionPreferences.cpp

@@ -160,6 +160,8 @@ void getExperimentalTorsions(const RDKit::ROMol &mol, CrystalFFDetails &details,
     throw ValueErrorException("molecule has no atoms");
   }
 
+  RDLog::LogStateSetter logs(
+      RDLog::RDLoggerList({rdInfoLog, rdErrorLog, rdWarningLog}));
   // check that vectors are empty
   details.expTorsionAtoms.clear();
   details.expTorsionAngles.clear();

Code/GraphMol/MolDraw2D/MolDraw2D.cpp

@@ -900,7 +900,7 @@ void MolDraw2D::makeReactionDrawMol(
   if (drawOptions().prepareMolsBeforeDrawing) {
     mol.updatePropertyCache(false);
     try {
-      RDLog::BlockLogs blocker;
+      RDLog::LogStateSetter blocker;
       MolOps::Kekulize(mol, false);  // kekulize, but keep the aromatic flags!
     } catch (const MolSanitizeException &) {
       // don't need to do anything

Code/GraphMol/MolEnumerator/LinkNode.cpp

@@ -151,7 +151,7 @@ std::unique_ptr<ROMol> LinkNodeOp::operator()(
     ROMOL_SPTR reactant(new ROMol(*res));
     std::vector<MOL_SPTR_VECT> ps;
     {
-      RDLog::BlockLogs blocker;
+      RDLog::LogStateSetter blocker;
       ps = rxn->runReactant(reactant, 0);
     }
     ASSERT_INVARIANT(!ps.empty(), "no products from reaction");

Code/GraphMol/MolStandardize/testNormalize.cpp

@@ -455,6 +455,8 @@ Azide to N=N+=N-	[N:2]=[N:3]#[N:4]>>[N:2]=[N+:3]=[N-:4]
 Broken azide to N=N+=N-	[N:2]=[N:3]=[N:4]>>[NH0:2]=[NH0+:3]=[NH0-:4])DATA";
   std::stringstream azideNormalizationsStream(azideNormalizations);
   std::stringstream captureLog;
+  auto ostate = rdInfoLog->df_enabled;
+  rdInfoLog->df_enabled = true;
   rdInfoLog->SetTee(captureLog);
   Normalizer nn(azideNormalizationsStream, 200);
   const std::string brokenAzideSmi = "CN=[N+]=[NH-]";
@@ -470,6 +472,7 @@ Broken azide to N=N+=N-	[N:2]=[N:3]=[N:4]>>[NH0:2]=[NH0+:3]=[NH0-:4])DATA";
       ++count;
     }
   }
+  rdInfoLog->df_enabled = ostate;
   TEST_ASSERT(count == 1);
   BOOST_LOG(rdInfoLog) << "Finished" << std::endl;
 }
@@ -479,12 +482,15 @@ void testGithub3460() {
                           "Normalization rule incorrectly matches sulfones"
                        << std::endl;
   std::stringstream captureLog;
+  auto ostate = rdInfoLog->df_enabled;
+  rdInfoLog->df_enabled = true;
   rdInfoLog->SetTee(captureLog);
   Normalizer nn;
   auto mol = "[O-][S+]1Nc2c(Cl)cc(Cl)c3c(Cl)cc(Cl)c(c23)N1"_smiles;
   TEST_ASSERT(mol);
   ROMOL_SPTR normalized(nn.normalize(*mol));
   rdInfoLog->ClearTee();
+  rdInfoLog->df_enabled = ostate;
   auto logged = captureLog.str();
   TEST_ASSERT(logged.find("Running Normalizer") != std::string::npos);
   TEST_ASSERT(logged.find("Rule applied: C/S+NtoC/S=N+") == std::string::npos);
@@ -509,9 +515,12 @@ void testGithub4281() {
   auto mol = "Cn1c(=O)c2nc[nH][n+](=O)c2n(C)c1=O"_smiles;
   std::stringstream captureLog;
   rdInfoLog->SetTee(captureLog);
+  auto ostate = rdInfoLog->df_enabled;
+  rdInfoLog->df_enabled = true;
   Normalizer nn;
   std::unique_ptr<ROMol> normalized(nn.normalize(*mol));
   rdInfoLog->ClearTee();
+  rdInfoLog->df_enabled = ostate;
   auto logged = captureLog.str();
   TEST_ASSERT(logged.find("FAILED sanitizeMol") == std::string::npos);
 }

Code/GraphMol/RGroupDecomposition/RGroupDecompData.h

@@ -404,7 +404,7 @@ struct RGroupDecompData {
     addAtoms(mol, atomsToAdd);
 
     if (params.removeHydrogensPostMatch) {
-      RDLog::BlockLogs blocker;
+      RDLog::LogStateSetter blocker;
       bool implicitOnly = false;
       bool updateExplicitCount = false;
       bool sanitize = false;

Code/RDBoost/Wrap/RDBase.cpp

@@ -319,7 +319,7 @@ BOOST_PYTHON_MODULE(rdBase) {
   python_streambuf_wrapper::wrap();
   python_ostream_wrapper::wrap();
 
-  python::class_<RDLog::BlockLogs, boost::noncopyable>(
+  python::class_<RDLog::LogStateSetter, boost::noncopyable>(
       "BlockLogs",
       "Temporarily block logs from outputting while this instance is in "
       "scope.");

Code/RDGeneral/CMakeLists.txt

@@ -80,4 +80,7 @@ rdkit_test(testConcurrentQueue testConcurrentQueue.cpp LINK_LIBRARIES RDGeneral)
 endif(RDK_BUILD_THREADSAFE_SSS)
 
 rdkit_catch_test(dictTestsCatch catch_dict.cpp catch_main.cpp
+           LINK_LIBRARIES RDGeneral )
+
+rdkit_catch_test(logTestsCatch catch_logs.cpp catch_main.cpp
            LINK_LIBRARIES RDGeneral )

Code/RDGeneral/RDLog.cpp

@@ -1,6 +1,5 @@
-// $Id$
 //
-// Copyright (C)  2005-2010 Greg Landrum and Rational Discovery LLC
+// Copyright (C)  2005-2022 Greg Landrum and other RDKit contributors
 //
 //  @@ All Rights Reserved @@
 //  This file is part of the RDKit.
@@ -23,7 +22,37 @@ RDLogger rdInfoLog = nullptr;
 RDLogger rdErrorLog = nullptr;
 RDLogger rdWarningLog = nullptr;
 RDLogger rdStatusLog = nullptr;
+namespace RDLog {
 
+LogStateSetter::LogStateSetter() {
+  std::vector<RDLogger> allLogs = {rdAppLog,   rdDebugLog,   rdInfoLog,
+                                   rdErrorLog, rdWarningLog, rdStatusLog};
+  for (auto i = 0u; i < allLogs.size(); ++i) {
+    if (allLogs[i] && allLogs[i]->df_enabled) {
+      d_origState |= 1 << i;
+      allLogs[i]->df_enabled = false;
+    }
+  }
+}
+
+LogStateSetter::LogStateSetter(RDLoggerList toEnable) : LogStateSetter() {
+  for (auto &log : toEnable) {
+    if (log) {
+      log->df_enabled = true;
+    }
+  }
+}
+
+LogStateSetter::~LogStateSetter() {
+  std::vector<RDLogger> allLogs = {rdAppLog,   rdDebugLog,   rdInfoLog,
+                                   rdErrorLog, rdWarningLog, rdStatusLog};
+  for (auto i = 0u; i < allLogs.size(); ++i) {
+    if (allLogs[i]) {
+      allLogs[i]->df_enabled = d_origState & 1 << i;
+    }
+  }
+}
+}  // namespace RDLog
 namespace boost {
 namespace logging {
 
@@ -77,17 +106,15 @@ void disable_logs(const std::string &arg) {
 };
 
 bool is_log_enabled(RDLogger log) {
-  if (log && log.get() != nullptr) {
-    if (log->df_enabled) {
-      return true;
-    }
+  if (log && log->df_enabled) {
+    return true;
   }
   return false;
 }
 
 void get_log_status(std::ostream &ss, const std::string &name, RDLogger log) {
   ss << name << ":";
-  if (log && log.get() != nullptr) {
+  if (log) {
     if (log->df_enabled) {
       ss << "enabled";
     } else {
@@ -116,7 +143,9 @@ std::string log_status() {
 namespace RDLog {
 void InitLogs() {
   rdDebugLog = std::make_shared<boost::logging::rdLogger>(&std::cerr);
+  rdDebugLog->df_enabled = false;
   rdInfoLog = std::make_shared<boost::logging::rdLogger>(&std::cout);
+  rdInfoLog->df_enabled = false;
   rdWarningLog = std::make_shared<boost::logging::rdLogger>(&std::cerr);
   rdErrorLog = std::make_shared<boost::logging::rdLogger>(&std::cerr);
 }

Code/RDGeneral/RDLog.h

@@ -1,5 +1,5 @@
 //
-// Copyright (C)  2005-2008 Greg Landrum and Rational Discovery LLC
+// Copyright (C)  2005-2022 Greg Landrum and other RDKit contributors
 //
 //  @@ All Rights Reserved @@
 //  This file is part of the RDKit.
@@ -9,8 +9,8 @@
 //
 
 #include <RDGeneral/export.h>
-#ifndef _RDLOG_H_29JUNE2005_
-#define _RDLOG_H_29JUNE2005_
+#ifndef RDLOG_H_29JUNE2005
+#define RDLOG_H_29JUNE2005
 
 #if 1
 #include "BoostStartInclude.h"
@@ -18,6 +18,8 @@
 #include <boost/iostreams/stream.hpp>
 #include "BoostEndInclude.h"
 #include <iostream>
+#include <vector>
+
 #include <vector>
 namespace boost {
 namespace logging {
@@ -114,7 +116,23 @@ BOOST_DECLARE_LOG(rdStatusLog)
 namespace RDLog {
 RDKIT_RDGENERAL_EXPORT void InitLogs();
 
+using RDLoggerList = std::vector<RDLogger>;
+class RDKIT_RDGENERAL_EXPORT LogStateSetter {
+ public:
+  //! enables only the logs in the list, the current state will be restored when
+  //! this object is destroyed
+  LogStateSetter(RDLoggerList toEnable);
+  //! disables all logs, the current state will be restored when this object is
+  //! destroyed
+  LogStateSetter();
+  ~LogStateSetter();
+
+ private:
+  std::uint64_t d_origState = 0;
+};
+
 // ! Temporarily block logging until this object goes out of scope
+// DEPRECATED, please use LogStateSetter() instead
 struct RDKIT_RDGENERAL_EXPORT BlockLogs {
   std::vector<RDLogger> logs_to_reenable;
   BlockLogs();

Code/RDGeneral/catch_logs.cpp

@@ -0,0 +1,65 @@
+//
+//  Copyright (C) 2022 Greg Landrum
+//
+//   @@ All Rights Reserved @@
+//  This file is part of the RDKit.
+//  The contents are covered by the terms of the BSD license
+//  which is included in the file license.txt, found at the root
+//  of the RDKit source tree.
+//
+#include <string>
+#include <sstream>
+#include "catch.hpp"
+#include "RDLog.h"
+
+TEST_CASE("LogStateSetter") {
+  RDLog::RDLoggerList allLogs({rdErrorLog, rdWarningLog, rdInfoLog});
+  SECTION("disable all") {
+    for (auto strm : allLogs) {
+      // explicitly enable the stream so that we know something is happening
+      std::stringstream ostrm;
+      strm->df_enabled = true;
+      strm->SetTee(ostrm);
+      {
+        RDLog::LogStateSetter disabler;
+        BOOST_LOG(strm) << "should be silent" << std::endl;
+        auto txt = ostrm.str();
+        CHECK(txt.find("should") == std::string::npos);
+      }
+      BOOST_LOG(strm) << "should not be silent" << std::endl;
+      auto txt = ostrm.str();
+      CHECK(txt.find("should") != std::string::npos);
+      strm->ClearTee();
+    }
+  }
+  SECTION("enable one") {
+    for (auto strm : allLogs) {
+      strm->df_enabled = true;
+      RDLog::LogStateSetter disabler;
+      {
+        RDLog::LogStateSetter justone(RDLog::RDLoggerList({strm}));
+        for (auto strm2 : allLogs) {
+          std::stringstream ostrm;
+          strm2->SetTee(ostrm);
+          BOOST_LOG(strm2) << "should not be silent" << std::endl;
+          auto txt = ostrm.str();
+          if (strm == strm2) {
+            CHECK(txt.find("should") != std::string::npos);
+          } else {
+            CHECK(txt.find("should") == std::string::npos);
+          }
+
+          strm2->ClearTee();
+        }
+      }
+
+      // should be disabled again
+      std::stringstream ostrm;
+      strm->SetTee(ostrm);
+      BOOST_LOG(strm) << "should be silent" << std::endl;
+      auto txt = ostrm.str();
+      CHECK(txt.find("should") == std::string::npos);
+      strm->ClearTee();
+    }
+  }
+}

ReleaseNotes.md

@@ -4,6 +4,9 @@
 ## Backwards incompatible changes
 - When running in Jupyter Notebook, logs are now sent only to Python's
   standard error stream, and no longer include the `RDKit LEVEL` prefix.
+- The Debug and Info logs are now disabled by default. If you would like to
+  enable them within your code you can call `rdBase.EnableLog("rdApp.info")`
+  and/or `rdBase.EnableLog("rdApp.debug")`.
 - The MolHash functions now reassign stereochemistry after modifying the
   molecule and before calculating the hash. Previous versions would still
   include information about atom/bond stereochemistry in the output hash even if
@@ -27,6 +30,7 @@
   `rdkit.rdBase.LogWarning()`.
 - Python function `rdkit.Chem.LogError()` is deprecated in favor of
   `rdkit.rdBase.LogError()`.
+- The C++ class `RDLog::BlockLogs` is deprecated in favor of the the class `RDLog::LogStateSetter`.
 
 # Release_2021.09.1
 (Changes relative to Release_2021.03.1)

rdkit/UnitTestLogging.py

@@ -221,6 +221,8 @@ class TestLogToCppStreams(unittest.TestCase):
   @classmethod
   def setUpClass(cls):
     rdBase.LogToCppStreams()
+    rdBase.EnableLog('rdApp.debug')
+    rdBase.EnableLog('rdApp.info')
 
   def testDebug(self):
     with CaptureOutput() as captured:
@@ -384,6 +386,8 @@ class TestWrapLogs(unittest.TestCase):
   def setUpClass(cls):
     rdBase.LogToCppStreams()
     rdBase.WrapLogs()
+    rdBase.EnableLog('rdApp.debug')
+    rdBase.EnableLog('rdApp.info')
 
   def testDebug(self):
     with CaptureOutput() as captured: