diff --git a/src/lib/log/README b/src/lib/log/README index 9be37a2f33..613779e4e5 100644 --- a/src/lib/log/README +++ b/src/lib/log/README @@ -368,7 +368,9 @@ specification is processed (even an empty one), the buffered log messages will be flushed according to the specification. Note that if this option is used, the program SHOULD call one of the LoggerManager's process() calls. If the program exits before this is done, all log messages are dumped in a shortened -format to stdout (so that no messages get lost). +format to stdout (so that no messages get lost). If you are using the built-in +logging configuration handling in ModuleCCSession, this is automatically +handled. Variant #2, Used by Unit Tests ------------------------------ diff --git a/src/lib/log/log_buffer.cc b/src/lib/log/log_buffer.cc index d98805dadb..7890226fee 100644 --- a/src/lib/log/log_buffer.cc +++ b/src/lib/log/log_buffer.cc @@ -15,6 +15,7 @@ #include #include +#include namespace isc { namespace log { @@ -26,17 +27,17 @@ LogBuffer& getLogBuffer() { return (*log_buffer); } -LogBuffer::LogBuffer() { - flushed_ = false; -} - LogBuffer::~LogBuffer() { // If there is anything left in the buffer, // it means no reconfig has been done, and // we can assume the logging system was either // never setup, or broke while doing so. // So dump all that is left to stdout - flush_stdout(); + try { + flushStdout(); + } catch (...) { + // Ok if we can't even seem to dump to stdout, never mind. + } } void @@ -45,11 +46,16 @@ LogBuffer::add(const log4cplus::spi::InternalLoggingEvent& event) { isc_throw(LogBufferAddAfterFlush, "Internal log buffer has been flushed already"); } - stored_.push_back(log4cplus::spi::InternalLoggingEvent(event)); + // get a clone, and put the pointer in a shared_pt + std::auto_ptr event_aptr = + event.clone(); + boost::shared_ptr event_sptr( + event_aptr.release()); + stored_.push_back(event_sptr); } void -LogBuffer::flush_stdout() { +LogBuffer::flushStdout() { // This does not show a bit of information normal log messages // do, so perhaps we should try and setup a new logger here // However, as this is called from a destructor, it may not @@ -58,30 +64,35 @@ LogBuffer::flush_stdout() { // settings were). // So we print a slightly shortened format (it really only excludes // the time and the pid) - std::vector::const_iterator it; + LoggerEventPtrList::const_iterator it; const log4cplus::LogLevelManager& manager = log4cplus::getLogLevelManager(); for (it = stored_.begin(); it != stored_.end(); ++it) { - std::cout << manager.toString(it->getLogLevel()) << " " << - "[" << it->getLoggerName() << "] " << - it->getMessage() << std::endl; + std::cout << manager.toString((*it)->getLogLevel()) << " " << + "[" << (*it)->getLoggerName() << "] " << + (*it)->getMessage() << std::endl; } stored_.clear(); } void LogBuffer::flush() { - for (size_t i = 0; i < stored_.size(); ++i) { - const log4cplus::spi::InternalLoggingEvent event(stored_.at(i)); + LoggerEventPtrList::const_iterator it; + for (it = stored_.begin(); it != stored_.end(); ++it) { log4cplus::Logger logger = - log4cplus::Logger::getInstance(event.getLoggerName()); + log4cplus::Logger::getInstance((*it)->getLoggerName()); - logger.log(event.getLogLevel(), event.getMessage()); + logger.log((*it)->getLogLevel(), (*it)->getMessage()); } stored_.clear(); flushed_ = true; } +size_t +LogBuffer::getBufferSize() const { + return (stored_.size()); +} + void BufferAppender::append(const log4cplus::spi::InternalLoggingEvent& event) { buffer_.add(event); diff --git a/src/lib/log/log_buffer.h b/src/lib/log/log_buffer.h index 34c0cfa579..9e41533a63 100644 --- a/src/lib/log/log_buffer.h +++ b/src/lib/log/log_buffer.h @@ -19,7 +19,7 @@ #include #include -#include +#include namespace isc { namespace log { @@ -37,6 +37,10 @@ public: {} }; +/// Convenience typedef for a list of logger events +typedef std::vector > + LoggerEventPtrList; + /// \brief Buffering class for logging event /// /// This class is used to store logging events; it simply keeps any @@ -58,13 +62,12 @@ public: /// If the LogBuffer instance is destroyed before being flushed, it will /// dump any event it has left to stdout. class LogBuffer { - // For testing purposes, we make this a friend class, so that - // it can inspect the stored_ vector - friend class LogBufferTest; public: - LogBuffer(); + LogBuffer() : flushed_(false) {}; + ~LogBuffer(); + /// \brief add the given event to the list of stored events /// /// This is called by the BufferAppender. @@ -73,10 +76,27 @@ public: /// \exception LogBufferAddAfterFlush if this method is called /// when \c flush() has been called previously void add(const log4cplus::spi::InternalLoggingEvent& event); + + /// \brief Flush all stored events to their loggers + /// + /// All events are replayed to their loggers (which should have + /// other appenders when this is called. + /// Once this method has been called, no more events can be + /// added trough calls to \c add(); if \c add() is called after flush(), + /// an exception will be raised. void flush(); + + /// \brief Returns number of stored events + /// + /// Mostly for testing purposes + size_t getBufferSize() const; private: - void flush_stdout(); - std::vector stored_; + /// \brief Simplified flush() to stdout + /// + /// Used in the desctructor; all remainging stored events are + /// printed to stdout, in case flush() was never called. + void flushStdout(); + LoggerEventPtrList stored_; bool flushed_; }; @@ -97,6 +117,7 @@ public: /// that can be reached using \c getLogBuffer() BufferAppender(LogBuffer& buffer) : buffer_(buffer) {} virtual void close() {} +protected: virtual void append(const log4cplus::spi::InternalLoggingEvent& event); private: LogBuffer& buffer_; diff --git a/src/lib/log/logger_manager_impl.cc b/src/lib/log/logger_manager_impl.cc index 1605b6ff44..4f961b351e 100644 --- a/src/lib/log/logger_manager_impl.cc +++ b/src/lib/log/logger_manager_impl.cc @@ -32,8 +32,6 @@ #include #include -#include - using namespace std; namespace isc { diff --git a/src/lib/log/logger_manager_impl.h b/src/lib/log/logger_manager_impl.h index 1e8fe55ebd..6302ac77a2 100644 --- a/src/lib/log/logger_manager_impl.h +++ b/src/lib/log/logger_manager_impl.h @@ -142,7 +142,6 @@ private: /// flushed (which is done at the end of \c ProcessSpecification(). /// /// \param logger Log4cplus logger to which the appender must be attached. - /// \param opt Output options for this appender. static void createBufferAppender(log4cplus::Logger& logger); /// \brief Set default layout and severity for root logger diff --git a/src/lib/log/tests/buffer_logger_test.cc b/src/lib/log/tests/buffer_logger_test.cc index 23c1e849bf..8d1b3cf519 100644 --- a/src/lib/log/tests/buffer_logger_test.cc +++ b/src/lib/log/tests/buffer_logger_test.cc @@ -20,9 +20,11 @@ using namespace isc::log; +namespace { void usage() { std::cout << "Usage: buffer_logger_test [-n]" << std::endl; } +} // end unnamed namespace /// \brief Test InitLogger /// diff --git a/src/lib/log/tests/log_buffer_unittest.cc b/src/lib/log/tests/log_buffer_unittest.cc index c8d1b21618..0d6da8f7f9 100644 --- a/src/lib/log/tests/log_buffer_unittest.cc +++ b/src/lib/log/tests/log_buffer_unittest.cc @@ -23,6 +23,7 @@ #include #include #include +#include using namespace isc::log; @@ -41,6 +42,10 @@ protected: ~LogBufferTest() { // If any log messages are left, we don't care, get rid of them, // by flushing them to a null appender + // Given the 'messages should not get lost' approach of the logging + // system, not flushing them to a null appender would cause them + // to be dumped to stdout as the test is destroyed, making + // unnecessarily messy test output. log4cplus::SharedAppenderPtr null_appender( new log4cplus::NullAppender()); logger.removeAllAppenders(); @@ -49,10 +54,6 @@ protected: buffer2.flush(); } - void checkBufferedSize(const LogBuffer& buffer, size_t expected) const { - ASSERT_EQ(expected, buffer.stored_.size()); - } - LogBuffer buffer1; LogBuffer buffer2; log4cplus::SharedAppenderPtr appender1; @@ -63,28 +64,28 @@ protected: // Test that log events are indeed stored, and that they are // flushed to the new appenders of their logger TEST_F(LogBufferTest, flush) { - checkBufferedSize(buffer1, 0); - checkBufferedSize(buffer2, 0); + ASSERT_EQ(0, buffer1.getBufferSize()); + ASSERT_EQ(0, buffer2.getBufferSize()); // Create a Logger, log a few messages with the first appender logger.addAppender(appender1); LOG4CPLUS_INFO(logger, "Foo"); - checkBufferedSize(buffer1, 1); + ASSERT_EQ(1, buffer1.getBufferSize()); LOG4CPLUS_INFO(logger, "Foo"); - checkBufferedSize(buffer1, 2); + ASSERT_EQ(2, buffer1.getBufferSize()); LOG4CPLUS_INFO(logger, "Foo"); - checkBufferedSize(buffer1, 3); + ASSERT_EQ(3, buffer1.getBufferSize()); // Second buffer should still be empty - checkBufferedSize(buffer2, 0); + ASSERT_EQ(0, buffer2.getBufferSize()); // Replace the appender by the second one, and call flush; // this should cause all events to be moved to the second buffer logger.removeAllAppenders(); logger.addAppender(appender2); buffer1.flush(); - checkBufferedSize(buffer1, 0); - checkBufferedSize(buffer2, 3); + ASSERT_EQ(0, buffer1.getBufferSize()); + ASSERT_EQ(3, buffer2.getBufferSize()); } // Once flushed, logging new messages with the same buffer should fail @@ -93,13 +94,38 @@ TEST_F(LogBufferTest, addAfterFlush) { buffer1.flush(); EXPECT_THROW(LOG4CPLUS_INFO(logger, "Foo"), LogBufferAddAfterFlush); // It should not have been added - checkBufferedSize(buffer1, 0); + ASSERT_EQ(0, buffer1.getBufferSize()); // But logging should work again as long as a different buffer is used logger.removeAllAppenders(); logger.addAppender(appender2); LOG4CPLUS_INFO(logger, "Foo"); - checkBufferedSize(buffer2, 1); + ASSERT_EQ(1, buffer2.getBufferSize()); +} + +TEST_F(LogBufferTest, addDirectly) { + // A few direct calls + log4cplus::spi::InternalLoggingEvent event("buffer", + log4cplus::INFO_LOG_LEVEL, + "Bar", "file", 123); + buffer1.add(event); + ASSERT_EQ(1, buffer1.getBufferSize()); + + // Do one from a smaller scope to make sure destruction doesn't harm + { + log4cplus::spi::InternalLoggingEvent event2("buffer", + log4cplus::INFO_LOG_LEVEL, + "Bar", "file", 123); + buffer1.add(event2); + } + ASSERT_EQ(2, buffer1.getBufferSize()); + + // And flush them to the next + logger.removeAllAppenders(); + logger.addAppender(appender2); + buffer1.flush(); + ASSERT_EQ(0, buffer1.getBufferSize()); + ASSERT_EQ(2, buffer2.getBufferSize()); } } diff --git a/src/lib/python/isc/config/cfgmgr.py b/src/lib/python/isc/config/cfgmgr.py index f2d9f18900..a200dfc6b4 100644 --- a/src/lib/python/isc/config/cfgmgr.py +++ b/src/lib/python/isc/config/cfgmgr.py @@ -224,9 +224,12 @@ class ConfigManager: def check_logging_config(self, config): if self.log_module_name in config: + # If there is logging config, apply it. ccsession.default_logconfig_handler(config[self.log_module_name], self.log_config_data) else: + # If there is no logging config, we still need to trigger the + # handler, so make it use defaults (and flush any buffered logs) ccsession.default_logconfig_handler({}, self.log_config_data) def notify_boss(self): diff --git a/src/lib/python/isc/log/log.cc b/src/lib/python/isc/log/log.cc index 2905a31fbe..7b95201a28 100644 --- a/src/lib/python/isc/log/log.cc +++ b/src/lib/python/isc/log/log.cc @@ -278,13 +278,13 @@ PyMethodDef methods[] = { "Arguments:\n" "name: root logger name\n" "severity (optional): one of 'DEBUG', 'INFO', 'WARN', 'ERROR' or " - "'FATAL')\n" + "'FATAL'\n" "debuglevel (optional): a debug level (integer in the range 0-99) " "file (optional): a file name of a dictionary with message text " "translations\n" "buffer (optional), boolean, when True, causes all log messages " "to be stored internally until log_config_update is called, at " - "which pointed they shall be logged."}, + "which point they shall be logged."}, {"resetUnitTestRootLogger", resetUnitTestRootLogger, METH_VARARGS, "Resets the configuration of the root logger to that set by the " "B10_XXX environment variables. It is aimed at unit tests, where " diff --git a/src/lib/python/isc/log/tests/log_test.py b/src/lib/python/isc/log/tests/log_test.py index 13376549b4..2059caa7a7 100644 --- a/src/lib/python/isc/log/tests/log_test.py +++ b/src/lib/python/isc/log/tests/log_test.py @@ -56,6 +56,28 @@ class Manager(unittest.TestCase): # ignore errors like missing file? isc.log.init("root", "INFO", 0, "/no/such/file"); + def test_init_keywords(self): + isc.log.init(name="root", severity="DEBUG", debuglevel=50, file=None, + buffer=True) + # unknown keyword + self.assertRaises(TypeError, isc.log.init, name="root", foo="bar") + # Replace the values for each keyword by a wrong type, one by one + self.assertRaises(TypeError, isc.log.init, name=1, + severity="DEBUG", debuglevel=50, file=None, + buffer=True) + self.assertRaises(TypeError, isc.log.init, name="root", + severity=2, debuglevel=50, file=None, + buffer=True) + self.assertRaises(TypeError, isc.log.init, name="root", + severity="DEBUG", debuglevel="50", file=None, + buffer=True) + self.assertRaises(TypeError, isc.log.init, name="root", + severity="DEBUG", debuglevel=50, file=1, + buffer=True) + self.assertRaises(TypeError, isc.log.init, name="root", + severity="DEBUG", debuglevel=50, file=None, + buffer=None) + def test_log_config_update(self): log_spec = json.dumps(isc.config.module_spec_from_file(path_search('logging.spec', bind10_config.PLUGIN_PATHS)).get_full_spec())