Allow Python Handling of log messages

This change lets Python LogHandlers handle the log messages
produced by nmslib.

This lets python control the behaviour
of the log messages at run time, meaning that the loglevel
can be adjusted and that the output of the messages can
be handled any python loghandler.

This basically involves transforming the existing logger class into
an abstract base, and then creating a python version that adapts
the nmslib log system to the python version.

python_bindings/docs/index.rst

@@ -14,6 +14,7 @@ Contents:
 
     Quickstart <quickstart>
     API Reference <api>
+    Logging <logging>
 
 
 Indices and tables

python_bindings/docs/logging.rst

@@ -0,0 +1,32 @@
+Configuring Logging for NMSLIB
+==============================
+
+This library logs to a Python logger named ``nmslib``. This lets
+you fully control the log messages produced by nmslib in Python.
+
+For instance, to log everything produced by nmslib to a default
+python logger:
+
+.. code-block:: python
+
+    # setup basic python logging
+    import logging
+    logging.basicConfig(level=logging.DEBUG)
+
+    # importing nmslib logs some debug messages on startup, that
+    # that will be output to the python log handler created above
+    import nmslib
+
+To quiet these messages you can just set the level for nmslib
+as appropiate:
+
+.. code-block:: python
+
+    # setup basic python logging
+    import logging
+    logging.basicConfig(level=logging.DEBUG)
+
+    # Only log WARNING messages and above from nmslib
+    logging.getLogger('nmslib').setLevel(logging.WARNING)
+
+    import nmslib

python_bindings/nmslib.cc

@@ -317,9 +317,47 @@ struct IndexWrapper {
   ObjectVector data;
 };
 
+class PythonLogger
+  : public Logger {
+ public:
+  py::object inner;
+  explicit PythonLogger(const py::object & inner)
+    : inner(inner) {
+  }
+
+  void log(LogSeverity severity,
+           const char * file,
+           int line,
+           const char * function,
+           const std::string & message) {
+    py::gil_scoped_acquire l;
+    switch(severity) {
+      case LIB_DEBUG:
+        inner.attr("debug")(message);
+        break;
+      case LIB_INFO:
+        inner.attr("info")(message);
+        break;
+      case LIB_WARNING:
+        inner.attr("warning")(message);
+        break;
+      case LIB_ERROR:
+        inner.attr("error")(message);
+        break;
+      case LIB_FATAL:
+        inner.attr("critical")(message);
+        break;
+    }
+  }
+};
+
 PYBIND11_PLUGIN(nmslib) {
-  // TODO(@benfred): configurable logging
-  initLibrary(LIB_LOGSTDERR, NULL);
+  // Log using the python logger, instead of defaults built in here
+  py::module logging = py::module::import("logging");
+  py::module nmslibLogger = logging.attr("getLogger")("nmslib");
+  setGlobalLogger(new PythonLogger(nmslibLogger));
+
+  initLibrary(LIB_LOGCUSTOM, NULL);
 
   py::module m(module_name, "Bindings for Non-Metric Space Library (NMSLIB)");
 

similarity_search/apps/tune_vptree.cc

@@ -231,7 +231,7 @@ void RunExper(unsigned AddRestartQty,
     }
     LOG(LIB_INFO) << "Recall: " << recall;
     LOG(LIB_INFO) << "Best time: " << time_best;
-    LOG(LIB_INFO) << "Best impr. " << impr_best << " (" << getOptimMetricName(metric) << ")" << endl;
+    LOG(LIB_INFO) << "Best impr. " << impr_best << " (" << getOptimMetricName(metric) << ")";
     LOG(LIB_INFO) << "alpha_left: " << alpha_left;
     LOG(LIB_INFO) << "exp_left: " << exp_left;
     LOG(LIB_INFO) << "alpha_right: " << alpha_right;

similarity_search/include/logging.h

@@ -5,8 +5,8 @@
  * With contributions from Lawrence Cayton (http://lcayton.com/) and others.
  *
  * For the complete list of contributors and further details see:
- * https://github.com/searchivarius/NonMetricSpaceLib 
- * 
+ * https://github.com/searchivarius/NonMetricSpaceLib
+ *
  * Copyright (c) 2014
  *
  * This code is released under the
@@ -30,30 +30,82 @@ using std::stringstream;
 using std::runtime_error;
 using std::string;
 
-enum LogSeverity {LIB_INFO, LIB_WARNING, LIB_ERROR, LIB_FATAL};
-enum LogChoice  {LIB_LOGNONE, LIB_LOGFILE, LIB_LOGSTDERR};
+enum LogSeverity {LIB_DEBUG, LIB_INFO, LIB_WARNING, LIB_ERROR, LIB_FATAL};
+enum LogChoice  {LIB_LOGNONE, LIB_LOGFILE, LIB_LOGSTDERR, LIB_LOGCUSTOM};
 
 std::string LibGetCurrentTime();
 
 // write log to file
 void InitializeLogger(LogChoice choice = LIB_LOGNONE, const char* logfile = NULL);
 
+// Abstract base class that all loggers must override
 class Logger {
  public:
-  Logger(LogSeverity severity, const std::string& file, int line, const char* function);
-  ~Logger();
+  virtual ~Logger();
+  virtual void log(LogSeverity severity,
+                   const char * file,
+                   int line,
+                   const char * function,
+                   const std::string & message) = 0;
+};
 
-  static std::ostream& stream() { return *currstrm_ ; }
+void setGlobalLogger(Logger * logger);
+Logger * getGlobalLogger();
 
- private:
-  LogSeverity severity_;
+class StdErrLogger
+  : public Logger {
+ public:
+  void log(LogSeverity severity,
+           const char * file,
+           int line,
+           const char * function,
+           const std::string & message);
+};
+
+class FileLogger
+  : public Logger {
+ public:
+  FileLogger(const char * logfile);
+  void log(LogSeverity severity,
+           const char * file,
+           int line,
+           const char * function,
+           const std::string & message);
+ protected:
+  std::ofstream logfile;
+};
 
-  static ofstream logfile_;
+// A single entry in the log
+class LogItem {
+ public:
+  LogItem(LogSeverity severity, const char * file, int line, const char * function,
+          Logger * logger)
+    : severity(severity), file(file), line(line), function(function), logger(logger) {
+  }
 
-  static ostream* currstrm_;
+  template <typename T>
+  LogItem & operator << (T t) {
+    message << t;
+    return *this;
+  }
 
-  // If choice != LIB_LOGFILE the second argument is ignored
-  friend void InitializeLogger(LogChoice choice, const char* logfile);
+  ~LogItem() {
+    if (logger) {
+        logger->log(severity, file, line, function, message.str());
+    }
+    // TODO: probably better to throw an exception here rather than die outright
+    // but this matches previous behaviour
+    if (severity == LIB_FATAL) {
+      exit(1);
+    }
+  }
+
+  LogSeverity severity;
+  const char * file;
+  int line;
+  const char * function;
+  Logger * logger;
+  std::stringstream message;
 };
 
 class RuntimeErrorWrapper {
@@ -66,9 +118,9 @@ class RuntimeErrorWrapper {
   stringstream currstrm_;
 };
 
-
+// TODO: zero cost log abstraction
 #define LOG(severity) \
-  Logger(severity, __FILE__, __LINE__, __FUNCTION__).stream()
+  LogItem(severity, __FILE__, __LINE__, __FUNCTION__, getGlobalLogger())
 
 #define CHECK(condition) \
   if (!(condition)) {\

similarity_search/src/init.cc

@@ -35,5 +35,4 @@ void initLibrary(LogChoice choice, const char* pLogFile) {
   initSpaces();
   initMethods();
 }
-
 }

similarity_search/src/logging.cc

@@ -28,19 +28,24 @@
 
 #include "logging.h"
 
-const char* log_severity[] = {"INFO", "WARNING", "ERROR", "FATAL"};
+const char* log_severity[] = {"DEBUG", "INFO", "WARNING", "ERROR", "FATAL"};
 
 using namespace std;
 
-// allocate the static member
-std::ofstream Logger::logfile_;
+namespace {
+  std::unique_ptr<Logger> global_log(new StdErrLogger());
+}
 
-static struct voidstream : public ostream {
-  template <class T> ostream& operator<< (T) { return *this; }
-  template <class T> ostream& operator<< (T*) { return *this; }
-  template <class T> ostream& operator<< (T&) { return *this; }
-  voidstream() : ostream(0) {}
-} voidstream_;
+void setGlobalLogger(Logger * logger) {
+  global_log.reset(logger);
+}
+
+Logger * getGlobalLogger() {
+  return global_log.get();
+}
+
+Logger::~Logger() {
+}
 
 std::string LibGetCurrentTime() {
   time_t now;
@@ -51,48 +56,59 @@ std::string LibGetCurrentTime() {
   return std::string(time_string);
 }
 
-ostream* Logger::currstrm_ = &cerr;
-
-Logger::Logger(LogSeverity severity, const std::string& _file, int line, const char* function)
-    : severity_(severity) {
+template <typename T>
+void defaultOutput(T & stream, LogSeverity severity,
+                   const std::string& _file, int line, const char* function,
+                   const std::string & message) {
   std::string file = _file;
   size_t n = file.rfind('/');
   if (n != std::string::npos) {
     file.erase(file.begin(), file.begin() + n + 1);
   }
-  stream() << LibGetCurrentTime() << " " << file << ":" << line
-           << " (" << function << ") [" << log_severity[severity] << "] ";
+  stream << LibGetCurrentTime() << " " << file << ":" << line
+         << " (" << function << ") [" << log_severity[severity] << "] " << message << std::endl;
 }
 
-Logger::~Logger() {
-  stream() << '\n';
-  if (severity_ == LIB_FATAL) {
-    stream().flush();
-    if (logfile_.is_open())
-      logfile_.close();
-    // TODO(@leo/@bileg) do we want to abort here?
-    //abort();
-    exit(1); 
+void StdErrLogger::log(LogSeverity severity,
+                       const char * file,
+                       int line,
+                       const char * function,
+                       const std::string & message) {
+  defaultOutput(std::cerr, severity, file, line, function, message);
+}
+
+FileLogger::FileLogger(const char * logfilename)
+  : logfile(logfilename) {
+  if (!logfile) {
+    LOG(LIB_FATAL) << "Can't open the logfile: '" << logfilename << "'";
   }
 }
 
+void FileLogger::log(LogSeverity severity,
+                     const char * file,
+                     int line,
+                     const char * function,
+                     const std::string & message) {
+  defaultOutput(logfile, severity, file, line, function, message);
+}
+
 void InitializeLogger(LogChoice choice, const char* logfile) {
-  if (choice == LIB_LOGNONE) {
-    Logger::currstrm_ = &voidstream_;
-  }
-  if (choice == LIB_LOGFILE) {
-    Logger::logfile_.open(logfile);
-    if (!Logger::logfile_) {
-      LOG(LIB_FATAL) << "Can't open the logfile: '" << logfile << "'";
-    }
-    Logger::currstrm_ = &Logger::logfile_;
-  }
-  if (choice == LIB_LOGSTDERR) {
-    Logger::currstrm_ = &cerr;
+  switch (choice) {
+    case LIB_LOGNONE:
+      setGlobalLogger(NULL);
+      break;
+    case LIB_LOGSTDERR:
+      setGlobalLogger(new StdErrLogger());
+      break;
+    case LIB_LOGFILE:
+      setGlobalLogger(new FileLogger(logfile));
+      break;
+    case LIB_LOGCUSTOM:
+      // don't set a logger here: setGlobalLogger will be called already
+      break;
   }
 }
 
-
 RuntimeErrorWrapper::RuntimeErrorWrapper(const std::string& _file, int line, const char* function) {
   std::string file = _file;
   size_t n = file.rfind('/');

similarity_search/src/space/space_bit_hamming.cc

@@ -65,9 +65,9 @@ void SpaceBitHamming::ReadBitMaskVect(std::string line, LabelType& label, std::v
       v.push_back(val);
     }
   } catch (const std::exception &e) {
-    LOG(LIB_ERROR) << "Exception: " << e.what() << std::endl;
+    LOG(LIB_ERROR) << "Exception: " << e.what();
     PREPARE_RUNTIME_ERR(err) << "Failed to parse the line: '" << line << "'";
-    LOG(LIB_ERROR) << err.stream().str() << std::endl;
+    LOG(LIB_ERROR) << err.stream().str();
     THROW_RUNTIME_ERR(err);
   }
   Binarize(v, 1, binVect);      // Create the binary vector

similarity_search/src/space/space_dummy.cc

@@ -26,7 +26,7 @@ namespace similarity {
 
 template <typename dist_t>
 dist_t SpaceDummy<dist_t>::HiddenDistance(const Object* obj1, const Object* obj2) const {
-  LOG(LIB_INFO) << "Calculating the distance between objects: " << obj1->id() << " and " << obj2->id() << endl;
+  LOG(LIB_INFO) << "Calculating the distance between objects: " << obj1->id() << " and " << obj2->id();
   CHECK(obj1->datalength() > 0);
   CHECK(obj1->datalength() == obj2->datalength());
   /* 
@@ -83,7 +83,7 @@ bool SpaceDummy<dist_t>::ReadNextObjStr(DataFileInputState &inpStateBase, string
 template <typename dist_t>
 void SpaceDummy<dist_t>::WriteNextObj(const Object& obj, const string& externId, DataFileOutputState &outState) const {
   string s = CreateStrFromObj(&obj, externId);
-  outState.out_file_ << s << endl;
+  outState.out_file_ << s;
 }
 /** End of standard functions to read/write/create objects */ 
 

similarity_search/src/space/space_sparse_vector.cc

@@ -70,9 +70,9 @@ void SpaceSparseVector<dist_t>::ReadSparseVec(std::string line, size_t line_num,
       }
     }
   } catch (const std::exception &e) {
-    LOG(LIB_ERROR) << "Exception: " << e.what() << std::endl;
+    LOG(LIB_ERROR) << "Exception: " << e.what();
     PREPARE_RUNTIME_ERR(err) << "Failed to parse the line # " << line_num << ": '" << line << "'" << std::endl;
-    LOG(LIB_ERROR) << err.stream().str() << std::endl;
+    LOG(LIB_ERROR) << err.stream().str();
     THROW_RUNTIME_ERR(err);
   }
 

similarity_search/test/test_distfunc.cc

@@ -912,8 +912,8 @@ bool TestPivotIndex(const string& spaceName,
                     const string& dataFile, size_t dataQty,
                     const string& pivotFile, size_t pivotQty) {
 
-  LOG(LIB_INFO) << "space: " << spaceName << " real pivot index?: " << !useDummyIndex << endl <<
-                   " dataFile: " << dataFile << endl <<
+  LOG(LIB_INFO) << "space: " << spaceName << " real pivot index?: " << !useDummyIndex << " " <<
+                   " dataFile: " << dataFile << " " <<
                    " pivotFile: " << pivotFile;
   try {
     typedef float T;