From 809507a20b89c54ecbc45faa2563eb699fe51dbd Mon Sep 17 00:00:00 2001 From: Ben Frederickson Date: Sat, 2 Sep 2017 21:24:43 +0200 Subject: [PATCH 1/2] 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 | 1 + python_bindings/docs/logging.rst | 32 +++++++ python_bindings/nmslib.cc | 42 ++++++++- similarity_search/apps/tune_vptree.cc | 2 +- similarity_search/include/logging.h | 82 +++++++++++++---- similarity_search/src/init.cc | 1 - similarity_search/src/logging.cc | 90 +++++++++++-------- .../src/space/space_bit_hamming.cc | 4 +- similarity_search/src/space/space_dummy.cc | 4 +- .../src/space/space_sparse_vector.cc | 4 +- similarity_search/test/test_distfunc.cc | 4 +- 11 files changed, 202 insertions(+), 64 deletions(-) create mode 100644 python_bindings/docs/logging.rst diff --git a/python_bindings/docs/index.rst b/python_bindings/docs/index.rst index c94364d..7429c67 100644 --- a/python_bindings/docs/index.rst +++ b/python_bindings/docs/index.rst @@ -14,6 +14,7 @@ Contents: Quickstart API Reference + Logging Indices and tables diff --git a/python_bindings/docs/logging.rst b/python_bindings/docs/logging.rst new file mode 100644 index 0000000..74b41bf --- /dev/null +++ b/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 diff --git a/python_bindings/nmslib.cc b/python_bindings/nmslib.cc index 25e4360..36b2207 100644 --- a/python_bindings/nmslib.cc +++ b/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)"); diff --git a/similarity_search/apps/tune_vptree.cc b/similarity_search/apps/tune_vptree.cc index 5d04b1c..bd323d6 100644 --- a/similarity_search/apps/tune_vptree.cc +++ b/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; diff --git a/similarity_search/include/logging.h b/similarity_search/include/logging.h index c5aa935..25a60c0 100644 --- a/similarity_search/include/logging.h +++ b/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 + 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)) {\ diff --git a/similarity_search/src/init.cc b/similarity_search/src/init.cc index a1504ee..9e43957 100644 --- a/similarity_search/src/init.cc +++ b/similarity_search/src/init.cc @@ -35,5 +35,4 @@ void initLibrary(LogChoice choice, const char* pLogFile) { initSpaces(); initMethods(); } - } diff --git a/similarity_search/src/logging.cc b/similarity_search/src/logging.cc index ddbac5f..804ce27 100644 --- a/similarity_search/src/logging.cc +++ b/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 global_log(new StdErrLogger()); +} -static struct voidstream : public ostream { - template ostream& operator<< (T) { return *this; } - template ostream& operator<< (T*) { return *this; } - template 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 +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('/'); diff --git a/similarity_search/src/space/space_bit_hamming.cc b/similarity_search/src/space/space_bit_hamming.cc index 0fe1ced..84aad92 100644 --- a/similarity_search/src/space/space_bit_hamming.cc +++ b/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 diff --git a/similarity_search/src/space/space_dummy.cc b/similarity_search/src/space/space_dummy.cc index 1366d4a..abbaaac 100644 --- a/similarity_search/src/space/space_dummy.cc +++ b/similarity_search/src/space/space_dummy.cc @@ -26,7 +26,7 @@ namespace similarity { template dist_t SpaceDummy::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::ReadNextObjStr(DataFileInputState &inpStateBase, string template void SpaceDummy::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 */ diff --git a/similarity_search/src/space/space_sparse_vector.cc b/similarity_search/src/space/space_sparse_vector.cc index 95556b1..077a70f 100644 --- a/similarity_search/src/space/space_sparse_vector.cc +++ b/similarity_search/src/space/space_sparse_vector.cc @@ -70,9 +70,9 @@ void SpaceSparseVector::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); } diff --git a/similarity_search/test/test_distfunc.cc b/similarity_search/test/test_distfunc.cc index ef293c5..0cb4698 100644 --- a/similarity_search/test/test_distfunc.cc +++ b/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; From d78b0f6a633980ba14d13b6bc0a4ec618a351979 Mon Sep 17 00:00:00 2001 From: Ben Frederickson Date: Sat, 2 Sep 2017 21:40:06 +0200 Subject: [PATCH 2/2] fix --- similarity_search/src/logging.cc | 1 + 1 file changed, 1 insertion(+) diff --git a/similarity_search/src/logging.cc b/similarity_search/src/logging.cc index 804ce27..15552a9 100644 --- a/similarity_search/src/logging.cc +++ b/similarity_search/src/logging.cc @@ -24,6 +24,7 @@ #include #include +#include #include #include "logging.h"