[trac899] Basic changes for log4cplus

The code compilers and produces basic output.  Still to be done is
1) Add idea of debug levels.
2) Modify tests to copy with new format output.

configure.ac

@@ -447,6 +447,55 @@ AC_LINK_IFELSE(
 CPPFLAGS=$CPPFLAGS_SAVED
 LDFLAGS=$LDFLAGS_SAVED
 
+# Check for log4cplus
+log4cplus_path="yes"
+AC_ARG_WITH([log4cplus],
+  AC_HELP_STRING([--with-log4cplus=PATH],
+    [specify exact directory of log4cplus library and headers]),
+    [log4cplus_path="$withval"])
+if test "${log4cplus_path}" == "no" ; then
+    AC_MSG_ERROR([Need log4cplus])
+elif test "${log4cplus_path}" != "yes" ; then
+  LOG4CPLUS_INCLUDES="-I${log4cplus_path}/include"
+  LOG4CPLUS_LDFLAGS="-L${log4cplus_path}/lib"
+else
+# If not specified, try some common paths.
+	log4cplusdirs="/usr/local /usr/pkg /opt /opt/local"
+	for d in $log4cplusdirs
+	do
+		if test -f $d/include/log4cplus/logger.h; then
+			LOG4CPLUS_INCLUDES="-I$d/include"
+			LOG4CPLUS_LDFLAGS="-L$d/lib"
+			break
+		fi
+	done
+fi
+
+LOG4CPLUS_LDFLAGS="$LOG4CPLUS_LDFLAGS -llog4cplus $MULTITHREADING_FLAG"
+
+AC_SUBST(LOG4CPLUS_LDFLAGS)
+AC_SUBST(LOG4CPLUS_INCLUDES)
+
+CPPFLAGS_SAVED=$CPPFLAGS
+CPPFLAGS="$LOG4CPLUS_INCLUDES $CPPFLAGS"
+LDFLAGS_SAVED="$LDFLAGS"
+LDFLAGS="$LOG4CPLUS_LDFLAGS $LDFLAGS"
+
+AC_CHECK_HEADERS([log4cplus/logger.h],,AC_MSG_ERROR([Missing required header files.]))
+AC_LINK_IFELSE(
+        [AC_LANG_PROGRAM([#include <log4cplus/logger.h>
+                         ],
+                         [using namespace log4cplus;
+                          Logger logger = Logger::getInstance("main");
+                         ])],
+        [AC_MSG_RESULT([checking for log4cplus library... yes])],
+        [AC_MSG_RESULT([checking for log4cplus library... no])
+         AC_MSG_ERROR([Needs log4cplus library])]
+)
+
+CPPFLAGS=$CPPFLAGS_SAVED
+LDFLAGS=$LDFLAGS_SAVED
+
 #
 # Configure Boost header path
 #
@@ -902,6 +951,8 @@ dnl includes too
   Boost:         ${BOOST_INCLUDES}
   Botan:         ${BOTAN_INCLUDES}
                  ${BOTAN_LDFLAGS}
+  Log4cplus:     ${LOG4CPLUS_INCLUDES}
+                 ${LOG4CPLUS_LDFLAGS}
   SQLite:        $SQLITE_CFLAGS
                  $SQLITE_LIBS
 

src/lib/log/Makefile.am

 SUBDIRS = . compiler tests
 
 AM_CPPFLAGS = -I$(top_builddir)/src/lib -I$(top_srcdir)/src/lib
-AM_CPPFLAGS += $(BOOST_INCLUDES)
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/log -I$(top_builddir)/src/lib/log
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/util -I$(top_builddir)/src/lib/util
+AM_CPPFLAGS += $(BOOST_INCLUDES) $(LOG4CPLUS_INCLUDES)
 
 CLEANFILES = *.gcno *.gcda
 

src/lib/log/compiler/Makefile.am

 SUBDIRS = .
 
 AM_CPPFLAGS = -I$(top_srcdir)/src/lib -I$(top_builddir)/src/lib
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/log -I$(top_builddir)/src/lib/log
-AM_CPPFLAGS += -I$(top_srcdir)/src/lib/util -I$(top_builddir)/src/lib/util
 AM_CPPFLAGS += $(BOOST_INCLUDES)
 
 AM_CXXFLAGS = $(B10_CXXFLAGS)
@@ -17,4 +15,4 @@ noinst_PROGRAMS = message
 message_SOURCES = message.cc
 message_LDADD  = $(top_builddir)/src/lib/log/liblog.la
 message_LDADD += $(top_builddir)/src/lib/util/libutil.la
-
+message_LDADD += $(LOG4CPLUS_LDFLAGS)

src/lib/log/log_formatter.h

@@ -17,6 +17,7 @@
 
 #include <string>
 #include <boost/lexical_cast.hpp>
+#include <log/logger_levels.h>
 
 namespace isc {
 namespace log {
@@ -73,13 +74,18 @@ private:
     ///
     /// If NULL, we are not active and should not produce anything.
     mutable Logger* logger_;
-    /// \brief Prefix (eg. "ERROR", "DEBUG" or like that)
-    const char* prefix_;
+
+    /// \brief Message severity
+    Severity severity_;
+
     /// \brief The messages with %1, %2... placeholders
     std::string* message_;
+
     /// \brief Which will be the next placeholder to replace
     unsigned nextPlaceholder_;
+
     Formatter& operator =(const Formatter& other);
+
 public:
     /// \brief Constructor of "active" formatter
     ///
@@ -89,21 +95,21 @@ public:
     ///
     /// It is not expected to be called by user of logging system directly.
     ///
-    /// \param prefix The severity prefix, like "ERROR" or "DEBUG"
+    /// \param severity The severity of the message (DEBUG, ERROR etc.)
     /// \param message The message with placeholders. We take ownership of
     ///     it and we will modify the string. Must not be NULL unless
     ///     logger is also NULL, but it's not checked.
     /// \param logger The logger where the final output will go, or NULL
     ///     if no output is wanted.
-    Formatter(const char* prefix = NULL, std::string* message = NULL,
+    Formatter(const Severity& severity = NONE, std::string* message = NULL,
               Logger* logger = NULL) :
-        logger_(logger), prefix_(prefix), message_(message),
-        nextPlaceholder_(1)
+        logger_(logger), severity_(severity), message_(message),
+        nextPlaceholder_(0)
     {
     }
 
     Formatter(const Formatter& other) :
-        logger_(other.logger_), prefix_(other.prefix_),
+        logger_(other.logger_), severity_(other.severity_),
         message_(other.message_), nextPlaceholder_(other.nextPlaceholder_)
     {
         other.logger_ = false;
@@ -113,7 +119,7 @@ public:
     /// This is the place where output happens if the formatter is active.
     ~ Formatter() {
         if (logger_) {
-            logger_->output(prefix_, *message_);
+            logger_->output(severity_, *message_);
             delete message_;
         }
     }
@@ -134,11 +140,10 @@ public:
     /// \brief String version of arg.
     Formatter& arg(const std::string& arg) {
         if (logger_) {
-            // FIXME: This logic has a problem. If we had a message like
-            // "%1 %2" and called .arg("%2").arg(42), we would get "42 %2".
-            // But we consider this to be rare enough not to complicate
-            // matters.
-            replacePlaceholder(message_, arg, nextPlaceholder_ ++);
+            // Note that if we had a message like "%1 %2" and called
+            // .arg(42).arg("%1"), we would get "42 %1" (i.e. no recursive
+            // replacements).  This is a limitation but not a problem.
+            replacePlaceholder(message_, arg, ++nextPlaceholder_ );
         }
         return (*this);
     }

src/lib/log/logger.cc

@@ -112,14 +112,14 @@ Logger::isFatalEnabled() {
 // Output methods
 
 void
-Logger::output(const char* sevText, const string& message) {
-    getLoggerPtr()->outputRaw(sevText, message);
+Logger::output(const Severity& severity, const string& message) {
+    getLoggerPtr()->outputRaw(severity, message);
 }
 
 Logger::Formatter
 Logger::debug(int dbglevel, const isc::log::MessageID& ident) {
     if (isDebugEnabled(dbglevel)) {
-        return (Formatter("DEBUG", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(DEBUG, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -129,7 +129,7 @@ Logger::debug(int dbglevel, const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::info(const isc::log::MessageID& ident) {
     if (isInfoEnabled()) {
-        return (Formatter("INFO ", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(INFO, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -139,7 +139,7 @@ Logger::info(const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::warn(const isc::log::MessageID& ident) {
     if (isWarnEnabled()) {
-        return (Formatter("WARN ", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(WARN, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -149,7 +149,7 @@ Logger::warn(const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::error(const isc::log::MessageID& ident) {
     if (isErrorEnabled()) {
-        return (Formatter("ERROR", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(ERROR, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());
@@ -159,7 +159,7 @@ Logger::error(const isc::log::MessageID& ident) {
 Logger::Formatter
 Logger::fatal(const isc::log::MessageID& ident) {
     if (isFatalEnabled()) {
-        return (Formatter("FATAL", getLoggerPtr()->lookupMessage(ident),
+        return (Formatter(FATAL, getLoggerPtr()->lookupMessage(ident),
                           this));
     } else {
         return (Formatter());

src/lib/log/logger.h

@@ -95,7 +95,6 @@ public:
     /// \return The full name of the logger (including the root name)
     virtual std::string getName();
 
-
     /// \brief Set Severity Level for Logger
     ///
     /// Sets the level at which this logger will log messages.  If none is set,
@@ -107,14 +106,12 @@ public:
     /// outside these limits is silently coerced to the nearest boundary.
     virtual void setSeverity(isc::log::Severity severity, int dbglevel = 1);
 
-
     /// \brief Get Severity Level for Logger
     ///
     /// \return The current logging level of this logger.  In most cases though,
     /// the effective logging level is what is required.
     virtual isc::log::Severity getSeverity();
 
-
     /// \brief Get Effective Severity Level for Logger
     ///
     /// \return The effective severity level of the logger.  This is the same
@@ -122,14 +119,12 @@ public:
     /// is the severity of the parent.
     virtual isc::log::Severity getEffectiveSeverity();
 
-
     /// \brief Return DEBUG Level
     ///
     /// \return Current setting of debug level.  This is returned regardless of
     /// whether the severity is set to debug.
     virtual int getDebugLevel();
 
-
     /// \brief Returns if Debug Message Should Be Output
     ///
     /// \param dbglevel Level for which debugging is checked.  Debugging is
@@ -137,23 +132,18 @@ public:
     /// checked is less than or equal to the debug level set for the logger.
     virtual bool isDebugEnabled(int dbglevel = MIN_DEBUG_LEVEL);
 
-
     /// \brief Is INFO Enabled?
     virtual bool isInfoEnabled();
 
-
     /// \brief Is WARNING Enabled?
     virtual bool isWarnEnabled();
 
-
     /// \brief Is ERROR Enabled?
     virtual bool isErrorEnabled();
 
-
     /// \brief Is FATAL Enabled?
     virtual bool isFatalEnabled();
 
-
     /// \brief Output Debug Message
     ///
     /// \param dbglevel Debug level, ranging between 0 and 99.  Higher numbers
@@ -161,25 +151,21 @@ public:
     /// \param ident Message identification.
     Formatter debug(int dbglevel, const MessageID& ident);
 
-
     /// \brief Output Informational Message
     ///
     /// \param ident Message identification.
     Formatter info(const MessageID& ident);
 
-
     /// \brief Output Warning Message
     ///
     /// \param ident Message identification.
     Formatter warn(const MessageID& ident);
 
-
     /// \brief Output Error Message
     ///
     /// \param ident Message identification.
     Formatter error(const MessageID& ident);
 
-
     /// \brief Output Fatal Message
     ///
     /// \param ident Message identification.
@@ -203,10 +189,14 @@ protected:
 
 private:
     friend class isc::log::Formatter<Logger>;
+
     /// \brief Raw output function
     ///
     /// This is used by the formatter to output formatted output.
-    void output(const char* sevText, const std::string& message);
+    ///
+    /// \param severity Severity of the message being output.
+    /// \param message Text of the message to be output.
+    void output(const Severity& severity, const std::string& message);
 
     /// \brief Copy Constructor
     ///

src/lib/log/logger_impl.cc

@@ -19,10 +19,14 @@
 #include <stdarg.h>
 #include <stdio.h>
 #include <boost/lexical_cast.hpp>
+#include <boost/static_assert.hpp>
+
+#include <log4cplus/configurator.h>
 
 #include <log/debug_levels.h>
 #include <log/root_logger_name.h>
 #include <log/logger.h>
+#include <log/logger_levels.h>
 #include <log/logger_impl.h>
 #include <log/message_dictionary.h>
 #include <log/message_types.h>
@@ -37,8 +41,6 @@ namespace log {
 
 // Static initializations
 
-LoggerImpl::LoggerInfoMap LoggerImpl::logger_info_;
-LoggerImpl::LoggerInfo LoggerImpl::root_logger_info_(isc::log::INFO, 0);
 
 // Constructor
 LoggerImpl::LoggerImpl(const std::string& name, bool)
@@ -51,6 +53,13 @@ LoggerImpl::LoggerImpl(const std::string& name, bool)
         is_root_ = false;
         name_ = getRootLoggerName() + "." + name;
     }
+    fmt_name_ = std::string("[") + name_ + std::string("] ");
+
+    // Initialize log4cplus if not already done
+    initLog4cplus();
+
+    // Return existing instance of logger, creating it if it does not exist.
+    logger_ = log4cplus::Logger::getInstance(name_);
 }
 
 // Destructor. (Here because of virtual declaration.)
@@ -59,54 +68,22 @@ LoggerImpl::~LoggerImpl() {
 }
 
 // Set the severity for logging.
+// TODO IGNORE DEBUG LEVEL FOR NOW
 
 void
-LoggerImpl::setSeverity(isc::log::Severity severity, int dbglevel) {
+LoggerImpl::setSeverity(isc::log::Severity severity, int /*dbglevel*/) {
 
     // Silently coerce the debug level into the valid range of 0 to 99
 
-    int debug_level = max(MIN_DEBUG_LEVEL, min(MAX_DEBUG_LEVEL, dbglevel));
-    if (is_root_) {
-
-        // Can only set severity for the root logger, you can't disable it.
-        // Any attempt to do so is silently ignored.
-        if (severity != isc::log::DEFAULT) {
-            root_logger_info_ = LoggerInfo(severity, debug_level);
-        }
-
-    } else if (severity == isc::log::DEFAULT) {
-
-        // Want to set to default; this means removing the information
-        // about this logger from the logger_info_ if it is set.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-            logger_info_.erase(i);
-        }
-
-    } else {
-
-        // Want to set this information
-        logger_info_[name_] = LoggerInfo(severity, debug_level);
-    }
+    //int debug_level = max(MIN_DEBUG_LEVEL, min(MAX_DEBUG_LEVEL, dbglevel));
+    logger_.setLogLevel(convertFromBindSeverity(severity));
 }
 
 // Return severity level
 
 isc::log::Severity
 LoggerImpl::getSeverity() {
-
-    if (is_root_) {
-        return (root_logger_info_.severity);
-    }
-    else {
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-           return ((i->second).severity);
-        }
-        else {
-            return (isc::log::DEFAULT);
-        }
-    }
+    return convertToBindSeverity(logger_.getLogLevel());
 }
 
 // Get effective severity.  Either the current severity or, if not set, the
@@ -114,86 +91,29 @@ LoggerImpl::getSeverity() {
 
 isc::log::Severity
 LoggerImpl::getEffectiveSeverity() {
-
-    if (!is_root_ && !logger_info_.empty()) {
-
-        // Not root logger and there is at least one item in the info map for a
-        // logger.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-
-            // Found, so return the severity.
-            return ((i->second).severity);
-        }
-    }
-
-    // Must be the root logger, or this logger is defaulting to the root logger
-    // settings.
-    return (root_logger_info_.severity);
+    return convertToBindSeverity(logger_.getChainedLogLevel());
 }
 
+
 // Get the debug level.  This returns 0 unless the severity is DEBUG.
+// TODO: DEBUG LEVEL IGNORED FOR NOW
 
 int
 LoggerImpl::getDebugLevel() {
-
-    if (!is_root_ && !logger_info_.empty()) {
-
-        // Not root logger and there is something in the map, check if there
-        // is a setting for this one.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-
-            // Found, so return the debug level.
-            if ((i->second).severity == isc::log::DEBUG) {
-                return ((i->second).dbglevel);
-            } else {
-                return (0);
-            }
-        }
-    }
-
-    // Must be the root logger, or this logger is defaulting to the root logger
-    // settings.
-    if (root_logger_info_.severity == isc::log::DEBUG) {
-        return (root_logger_info_.dbglevel);
-    } else {
-        return (0);
-    }
+    return (0);
 }
 
 // The code for isXxxEnabled is quite simple and is in the header.  The only
 // exception is isDebugEnabled() where we have the complication of the debug
 // levels.
+// TODO: DEBUG LEVEL IGNORED FOR NOW
 
 bool
 LoggerImpl::isDebugEnabled(int dbglevel) {
-
-    if (!is_root_ && !logger_info_.empty()) {
-
-        // Not root logger and there is something in the map, check if there
-        // is a setting for this one.
-        LoggerInfoMap::iterator i = logger_info_.find(name_);
-        if (i != logger_info_.end()) {
-
-            // Found, so return the debug level.
-            if ((i->second).severity <= isc::log::DEBUG) {
-                return ((i->second).dbglevel >= dbglevel);
-            } else {
-                return (false); // Nothing lower than debug
-            }
-        }
-    }
-
-    // Must be the root logger, or this logger is defaulting to the root logger
-    // settings.
-    if (root_logger_info_.severity <= isc::log::DEBUG) {
-        return (root_logger_info_.dbglevel >= dbglevel);
-    } else {
-       return (false);
-    }
+    return logger_.isEnabledFor(log4cplus::DEBUG_LOG_LEVEL);
 }
 
+
 // Output a general message
 string*
 LoggerImpl::lookupMessage(const MessageID& ident) {
@@ -202,18 +122,103 @@ LoggerImpl::lookupMessage(const MessageID& ident) {
 }
 
 void
-LoggerImpl::outputRaw(const char* sevText, const string& message) {
-    // Get the time in a struct tm format, and convert to text
-    time_t t_time;
-    time(&t_time);
-    struct tm* tm_time = localtime(&t_time);
-
-    char chr_time[32];
-    (void) strftime(chr_time, sizeof(chr_time), "%Y-%m-%d %H:%M:%S", tm_time);
-
-    // Now output.
-    cout << chr_time << " " << sevText << " [" << getName() << "] " <<
-        message << endl;
+LoggerImpl::outputRaw(const Severity& severity, const string& message) {
+    switch (severity) {
+        case DEBUG:
+            LOG4CPLUS_DEBUG(logger_, fmt_name_ << message);
+            break;
+
+        case INFO:
+            LOG4CPLUS_INFO(logger_, fmt_name_ << message);
+            break;
+
+        case WARN:
+            LOG4CPLUS_WARN(logger_, fmt_name_ << message);
+            break;
+
+        case ERROR:
+            LOG4CPLUS_ERROR(logger_, fmt_name_ << message);
+            break;
+
+        case FATAL:
+            LOG4CPLUS_FATAL(logger_, fmt_name_ << message);
+    }
+}
+
+// Convert levels - from BIND 10 level to log4cplus level.
+// Namespaces explicitly used to clarify what level we are talking about
+log4cplus::LogLevel
+LoggerImpl::convertFromBindSeverity(const isc::log::Severity& inlevel) {
+
+    // BIND 10 logging levels are small integers so we can do a table lookup
+    static const log4cplus::LogLevel level[] = {
+        log4cplus::NOT_SET_LOG_LEVEL,
+        log4cplus::DEBUG_LOG_LEVEL,
+        log4cplus::INFO_LOG_LEVEL,
+        log4cplus::WARN_LOG_LEVEL,
+        log4cplus::ERROR_LOG_LEVEL,
+        log4cplus::FATAL_LOG_LEVEL,
+        log4cplus::OFF_LOG_LEVEL
+    };
+
+    // ... with compile-time checks to ensure that table indexes are correct.
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::DEFAULT) == 0);
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::DEBUG) == 1);
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::INFO) == 2);
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::WARN) == 3);
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::ERROR) == 4);
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::FATAL) == 5);
+    BOOST_STATIC_ASSERT(static_cast<int>(isc::log::NONE) == 6);
+
+    // No need to check that the iundex is out of range.  Setting the type of
+    // the argument to isc::log::Severity ensures that it must be one of the
+    // Severity enum members - conversion of a numeric value to an enum is not
+    // permitted.
+    return (level[inlevel]);
+}
+
+// Convert levels - from log4plus level to BIND 10 level
+// Namespaces explicitly used to clarify what level we are talking about
+isc::log::Severity
+LoggerImpl::convertToBindSeverity(const log4cplus::LogLevel& inlevel) {
+
+    // Not easy to do a table lookup as the numerical values of log4cplus levels
+    // are quite high.
+    switch (inlevel) {
+        case log4cplus::NOT_SET_LOG_LEVEL:
+            return (isc::log::DEFAULT);
+
+        case log4cplus::DEBUG_LOG_LEVEL:
+            return (isc::log::DEBUG);
+
+        case log4cplus::INFO_LOG_LEVEL:
+            return (isc::log::INFO);
+
+        case log4cplus::WARN_LOG_LEVEL:
+            return (isc::log::WARN);
+
+        case log4cplus::ERROR_LOG_LEVEL:
+            return (isc::log::ERROR);
+
+        case log4cplus::FATAL_LOG_LEVEL:
+            return (isc::log::FATAL);
+    }
+
+    return (isc::log::NONE);
+}
+
+// One-time initialization of log4cplus
+
+
+void
+LoggerImpl::initLog4cplus() {
+    static bool not_initialized = true;
+
+    if (not_initialized) {
+        log4cplus::BasicConfigurator config;
+        config.configure();
+        not_initialized = false;
+    }
 }
 
 } // namespace log