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 1d469fc..e24edfa 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..15552a9 100644 --- a/similarity_search/src/logging.cc +++ b/similarity_search/src/logging.cc @@ -24,23 +24,29 @@ #include #include +#include #include #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 +57,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;