[trac899] Miscellaneous fixes

src/lib/log/Makefile.am

@@ -7,7 +7,7 @@ CLEANFILES = *.gcno *.gcda
 
 lib_LTLIBRARIES = liblog.la
 liblog_la_SOURCES  = b.cc
-liblog_la_SOURCES += logger_levels.h
+liblog_la_SOURCES += logger_level.h
 liblog_la_SOURCES += dummylog.h dummylog.cc
 liblog_la_SOURCES += log_formatter.h log_formatter.cc
 liblog_la_SOURCES += logger.cc logger.h

src/lib/log/logger.cc

@@ -166,9 +166,19 @@ Logger::fatal(const isc::log::MessageID& ident) {
     }
 }
 
-bool Logger::operator==(Logger& other) {
+// Comparison (testing only)
+
+bool
+Logger::operator==(Logger& other) {
     return (*getLoggerPtr() == *other.getLoggerPtr());
 }
 
+// Reset (used in testing only).  This is a static method.
+
+void
+Logger::reset() {
+    LoggerImpl::reset();
+}
+
 } // namespace log
 } // namespace isc

src/lib/log/logger.h

@@ -148,11 +148,16 @@ public:
     /// \brief Equality
     ///
     /// Check if two instances of this logger refer to the same stream.
-    /// (This method is principally for testing.)
     ///
     /// \return true if the logger objects are instances of the same logger.
     bool operator==(Logger& other);
 
+protected:
+    /// \brief Clear logging hierachy
+    ///
+    /// This is for test use only, hence is protected.
+    static void reset();
+
 private:
     friend class isc::log::Formatter<Logger>;
 

src/lib/log/logger_impl.cc

@@ -33,17 +33,17 @@
 
 #include <util/strutil.h>
 
+// Note: as log4cplus and th3e BIND 10 logger have many concepts in common, and
+// thus many similar names, to disambiguate types we don't "use" the log4cplus
+// namespace: instead, all log4cplus types are explicitly qualified.
+
 using namespace std;
-using namespace log4cplus;
 
 namespace isc {
 namespace log {
 
-// Static initializations
-
-
 // Constructor
-LoggerImpl::LoggerImpl(const std::string& name)
+LoggerImpl::LoggerImpl(const string& name)
 {
     // Initialize log4cplus if not already done
     initLog4cplus();
@@ -55,12 +55,8 @@ LoggerImpl::LoggerImpl(const std::string& name)
 
     } else {
         name_ = getRootLoggerName() + "." + name;
-        logger_ = log4cplus::Logger::getInstance(name_);
+        logger_ = log4cplus::Logger::getInstance(name);
     }
-
-    // Create a formatted name for use in messages (speeds up formatting if
-    // we do it now.)
-    fmt_name_ = std::string("[") + name_ + std::string("] ");
 }
 
 // Destructor. (Here because of virtual declaration.)
@@ -71,23 +67,21 @@ LoggerImpl::~LoggerImpl() {
 // Set the severity for logging.
 void
 LoggerImpl::setSeverity(isc::log::Severity severity, int dbglevel) {
-    isc::log::Level level(severity, dbglevel);
+    Level level(severity, dbglevel);
     logger_.setLogLevel(LoggerLevelImpl::convertFromBindLevel(level));
 }
 
 // Return severity level
 isc::log::Severity
 LoggerImpl::getSeverity() {
-    isc::log::Level level =
-        LoggerLevelImpl::convertToBindLevel(logger_.getLogLevel());
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getLogLevel());
     return level.severity;
 }
 
 // Return current debug level (only valid if current severity level is DEBUG).
 int
 LoggerImpl::getDebugLevel() {
-    isc::log::Level level =
-        LoggerLevelImpl::convertToBindLevel(logger_.getLogLevel());
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getLogLevel());
     return level.dbglevel;
 }
 
@@ -95,8 +89,7 @@ LoggerImpl::getDebugLevel() {
 // severity of the root level.
 isc::log::Severity
 LoggerImpl::getEffectiveSeverity() {
-    isc::log::Level level = 
-        LoggerLevelImpl::convertToBindLevel(logger_.getChainedLogLevel());
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getChainedLogLevel());
     return level.severity;
 }
 
@@ -104,8 +97,7 @@ LoggerImpl::getEffectiveSeverity() {
 // is DEBUG).
 int
 LoggerImpl::getEffectiveDebugLevel() {
-    isc::log::Level level =
-        LoggerLevelImpl::convertToBindLevel(logger_.getChainedLogLevel());
+    Level level = LoggerLevelImpl::convertToBindLevel(logger_.getChainedLogLevel());
     return level.dbglevel;
 }
 
@@ -121,45 +113,101 @@ void
 LoggerImpl::outputRaw(const Severity& severity, const string& message) {
     switch (severity) {
         case DEBUG:
-            LOG4CPLUS_DEBUG(logger_, fmt_name_ << message);
+            LOG4CPLUS_DEBUG(logger_, message);
             break;
 
         case INFO:
-            LOG4CPLUS_INFO(logger_, fmt_name_ << message);
+            LOG4CPLUS_INFO(logger_, message);
             break;
 
         case WARN:
-            LOG4CPLUS_WARN(logger_, fmt_name_ << message);
+            LOG4CPLUS_WARN(logger_, message);
             break;
 
         case ERROR:
-            LOG4CPLUS_ERROR(logger_, fmt_name_ << message);
+            LOG4CPLUS_ERROR(logger_, message);
             break;
 
         case FATAL:
-            LOG4CPLUS_FATAL(logger_, fmt_name_ << message);
+            LOG4CPLUS_FATAL(logger_, message);
     }
 }
 
-// One-time initialization of log4cplus
+// Initialization.  This is one initialization for all loggers, so requires
+// a singleton to hold the initialization flag.  The flag is held within a
+// static method to ensure that it is created (and initialized) when needed.
+// This avoids a static initialization fiasco.
 
+bool&
+LoggerImpl::initialized() {
+    static bool initialized = false;
+    return (initialized);
+}
 
 void
 LoggerImpl::initLog4cplus() {
-    static bool not_initialized = true;
 
-    if (not_initialized) {
-        // Set up basic configurator
+    if (! initialized()) {
+
+        // Set up basic configurator.  This attaches a ConsoleAppender to the
+        // root logger with suitable output.  This is used until we we have
+        // actually read the logging configuration, in which case the output
+        // may well be changed.
         log4cplus::BasicConfigurator config;
         config.configure();
+        setRootAppenderLayout();
 
         // Add additional debug levels
         LoggerLevelImpl::init();
 
         // All done.
-        not_initialized = false;
+        initialized() = true;
+    }
+}
+
+void LoggerImpl::setRootAppenderLayout() {
+
+    // Create the pattern we want for the output - local time.
+    string pattern = "%D{%Y-%m-%d %H:%M:%S.%q} %-5p [";
+    pattern += getRootLoggerName() + string(".%c] %m\n");
+
+    // Retrieve the appenders on the root instance and set the layout to
+    // use that pattern.
+    log4cplus::SharedAppenderPtrList list =
+        log4cplus::Logger::getRoot().getAllAppenders();
+
+    for (log4cplus::SharedAppenderPtrList::iterator i = list.begin();
+         i != list.end(); ++i) {
+        auto_ptr<log4cplus::Layout> layout(
+            new log4cplus::PatternLayout(pattern));
+        (*i)->setLayout(layout);
     }
 }
 
+// Reset.  Just reset logger hierarchy to default settings (don't remove the
+// loggers - this appears awkward); this is effectively the same as removing
+// them.
+void
+LoggerImpl::reset() {
+    log4cplus::Logger::getDefaultHierarchy().resetConfiguration();
+    initialized() = false;
+
+    // N.B.  The documentation is not clear, but it does not appear that the
+    // methods used to format the new logging levels are removed from the
+    // log4cxx LogLevelManager class - indeed, there appears to be no way
+    // to do this.  This would seem to suggest that a re-initialization may
+    // well add another instance of the toString/fromString to the manager's
+    // list of methods.
+    //
+    // We could get round this by making setting the LogManager a truly
+    // one-shot process.  However, apart from taking up memory there is little
+    // overhead if multiple instances are added.  The manager walks the list and
+    // uses the first method that processes the argument, so multiple methods
+    // doing the same think will not affect functionality.  Besides, this
+    // reset() method is only used in testing and not in the distributed
+    // software.
+}
+
+
 } // namespace log
 } // namespace isc

src/lib/log/logger_impl.h

@@ -44,12 +44,25 @@ namespace log {
 /// This particular implementation is based on log4cplus (from sourceforge:
 /// http://log4cplus.sourceforge.net).  Particular items of note:
 ///
-/// a) BIND 10 loggers have names of the form "root.sublogger".  Log4cplus
-/// loggers are always subloggers of a "root" logger.  In this implementation,
-/// the name of the logger is checked.  If it is the root name (as evidenced
-/// by the setting of the BIND 10 root logger name), the log4cplus root logger
-/// is used.  Otherwise the name is used as the name of a logger and a log4cplus
-/// sub-logger created.
+/// a) BIND 10 loggers have names of the form "program.sublogger".  In other
+/// words, each of the loggers is a sub-logger of the main program logger.
+/// In log4cplus, there is a root logger (called "root" according to the
+/// documentation, but actually unnamed) and all loggers created are subloggers
+/// if it.
+///
+/// In this implementation, the name of the logger is checked.  If it is the
+/// name of the program (as set in the call to isc::log::setRootLoggerName),
+/// the log4cplus root logger is used.  Otherwise the name passed is used as
+/// the name of a logger when a log4cplus logger is created.
+///
+/// To clarify: if the program is "b10auth" (and that is used to set the BIND 10
+/// root logger name via a call to isc::log::setRootLoggerName()), the BIND 10
+/// logger "b10auth" corresponds to the log4cplus root logger instance (returned
+/// by a call to log4cplus::Logger::getRoot()).  The BIND 10 sub-logger "cache"
+/// corresponds to the log4cplus logger "cache", created by a call to
+/// log4cplus::Logger::getInstance("cache").  The distinction is, however,
+/// invisible to users as the logger reported in messages is always
+/// "programm.sublogger".
 ///
 /// b) The idea of debug levels is implemented.  Seee logger_level.h and
 /// logger_level_impl.h for more details on this.
@@ -171,17 +184,32 @@ public:
         return (name_ == other.name_);
     }
 
+    /// \brief Reset logging
+    ///
+    /// Resets (clears) the log4cplus logging, requiring that an initialization
+    /// call be performed again.
+    static void reset();
+
 
 private:
 
     /// \brief Initialize log4cplus
     ///
-    /// Static method to perform one-time initialization of the log4cplus
-    /// system.
+    /// Static method to perform initialization of the log4cplus system.
     static void initLog4cplus();
 
+    /// \brief Initialization Flag
+    ///
+    /// Static method to access an initialization flag.  Doing it this
+    /// way means that there is no static initialization fiasco.
+    static bool& initialized();
+
+    /// \brief Set layout pattern
+    ///
+    /// Sets the layout for root logger appender(s)
+    static void setRootAppenderLayout();
+
     std::string         name_;              ///< Full name of this logger
-    std::string         fmt_name_;          ///< Formatted name for output
     log4cplus::Logger   logger_;            ///< Underlying log4cplus logger
 };
 

src/lib/log/tests/logger_unittest.cc

@@ -25,17 +25,37 @@ using namespace isc;
 using namespace isc::log;
 using namespace std;
 
+/// \brief Derived logger
+///
+/// Only exists to make the protected static methods in Logger public for
+/// test purposes.
+
+class DerivedLogger : public isc::log::Logger {
+public:
+    DerivedLogger(std::string name) : isc::log::Logger(name)
+    {}
+    virtual ~DerivedLogger()
+    {}
+
+    static void reset() {
+        isc::log::Logger::reset();
+    }
+};
+
+
 /// \brief Logger Test
 ///
 /// As the logger is only a shell around the implementation, this tests also
 /// checks the logger implementation class as well.
 
 class LoggerTest : public ::testing::Test {
-protected:
+public:
     LoggerTest()
     {}
     ~LoggerTest()
-    {}
+    {
+        DerivedLogger::reset();
+    }
 };
 
 

src/lib/log/tests/run_time_init_test.sh.in

@@ -37,43 +37,43 @@ cat > $localmes << .
 
 echo -n "1. runInitTest default parameters: "
 cat > $tempfile << .
-FATAL - [alpha.example] MSG_WRITERR, error writing to test1: 42
-ERROR - [alpha.example] MSG_RDLOCMES, reading local message file dummy/file
-WARN - [alpha.dlm] MSG_READERR, error reading from message file a.txt: dummy reason
-INFO - [alpha.dlm] MSG_OPENIN, unable to open message file example.msg for input: dummy reason
+FATAL [alpha.example] MSG_WRITERR, error writing to test1: 42
+ERROR [alpha.example] MSG_RDLOCMES, reading local message file dummy/file
+WARN  [alpha.dlm] MSG_READERR, error reading from message file a.txt: dummy reason
+INFO  [alpha.dlm] MSG_OPENIN, unable to open message file example.msg for input: dummy reason
 .
-./logger_support_test | diff $tempfile -
+./logger_support_test | cut -d' ' -f3- | diff $tempfile -
 passfail $?
 
 echo -n "2. Severity filter: "
 cat > $tempfile << .
-FATAL - [alpha.example] MSG_WRITERR, error writing to test1: 42
-ERROR - [alpha.example] MSG_RDLOCMES, reading local message file dummy/file
+FATAL [alpha.example] MSG_WRITERR, error writing to test1: 42
+ERROR [alpha.example] MSG_RDLOCMES, reading local message file dummy/file
 .
-./logger_support_test -s error | diff $tempfile -
+./logger_support_test -s error | cut -d' ' -f3- | diff $tempfile -
 passfail $?
 
 echo -n "3. Debug level: "
 cat > $tempfile << .
-FATAL - [alpha.example] MSG_WRITERR, error writing to test1: 42
-ERROR - [alpha.example] MSG_RDLOCMES, reading local message file dummy/file
-WARN - [alpha.dlm] MSG_READERR, error reading from message file a.txt: dummy reason
-INFO - [alpha.dlm] MSG_OPENIN, unable to open message file example.msg for input: dummy reason
-DEBUG - [alpha.example] MSG_RDLOCMES, reading local message file dummy/0
-DEBUG - [alpha.example] MSG_RDLOCMES, reading local message file dummy/24
-DEBUG - [alpha.example] MSG_RDLOCMES, reading local message file dummy/25
+FATAL [alpha.example] MSG_WRITERR, error writing to test1: 42
+ERROR [alpha.example] MSG_RDLOCMES, reading local message file dummy/file
+WARN  [alpha.dlm] MSG_READERR, error reading from message file a.txt: dummy reason
+INFO  [alpha.dlm] MSG_OPENIN, unable to open message file example.msg for input: dummy reason
+DEBUG [alpha.example] MSG_RDLOCMES, reading local message file dummy/0
+DEBUG [alpha.example] MSG_RDLOCMES, reading local message file dummy/24
+DEBUG [alpha.example] MSG_RDLOCMES, reading local message file dummy/25
 .
-./logger_support_test -s debug -d 25 | diff $tempfile -
+./logger_support_test -s debug -d 25 | cut -d' ' -f3- | diff $tempfile -
 passfail $?
 
 echo -n "4. Local message replacement: "
 cat > $tempfile << .
-WARN - [alpha.log] MSG_IDNOTFND, could not replace message text for 'MSG_NOTHERE': no such message
-FATAL - [alpha.example] MSG_WRITERR, error writing to test1: 42
-ERROR - [alpha.example] MSG_RDLOCMES, replacement read local message file, parameter is 'dummy/file'
-WARN - [alpha.dlm] MSG_READERR, replacement read error, parameters: 'a.txt' and 'dummy reason'
+WARN  [alpha.log] MSG_IDNOTFND, could not replace message text for 'MSG_NOTHERE': no such message
+FATAL [alpha.example] MSG_WRITERR, error writing to test1: 42
+ERROR [alpha.example] MSG_RDLOCMES, replacement read local message file, parameter is 'dummy/file'
+WARN  [alpha.dlm] MSG_READERR, replacement read error, parameters: 'a.txt' and 'dummy reason'
 .
-./logger_support_test -s warn $localmes | diff $tempfile -
+./logger_support_test -s warn $localmes | cut -d' ' -f3- | diff $tempfile -
 passfail $?
 
 rm -f $localmes