[2445] Create unit tests and fix a few issues

Also updated log's README

configure.ac

@@ -1375,6 +1375,7 @@ AC_OUTPUT([doc/version.ent
            src/lib/log/tests/console_test.sh
            src/lib/log/tests/destination_test.sh
            src/lib/log/tests/init_logger_test.sh
+           src/lib/log/tests/buffer_logger_test.sh
            src/lib/log/tests/local_file_test.sh
            src/lib/log/tests/logger_lock_test.sh
            src/lib/log/tests/severity_test.sh

src/bin/dhcp4/main.cc

@@ -17,6 +17,7 @@
 #include <dhcp4/ctrl_dhcp4_srv.h>
 #include <dhcp4/dhcp4_log.h>
 #include <log/logger_support.h>
+#include <log/logger_manager.h>
 
 #include <boost/lexical_cast.hpp>
 
@@ -93,9 +94,10 @@ main(int argc, char* argv[]) {
     }
 
     // Initialize logging.  If verbose, we'll use maximum verbosity.
+    // If standalone is enabled, do not buffer initial log messages
     isc::log::initLogger(DHCP4_NAME,
                          (verbose_mode ? isc::log::DEBUG : isc::log::INFO),
-                         isc::log::MAX_DEBUG_LEVEL, NULL, true);
+                         isc::log::MAX_DEBUG_LEVEL, NULL, !stand_alone);
     LOG_INFO(dhcp4_logger, DHCP4_STARTING);
     LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_START_INFO)
               .arg(getpid()).arg(port_number).arg(verbose_mode ? "yes" : "no")
@@ -114,6 +116,7 @@ main(int argc, char* argv[]) {
                 // DHCP server in stand-alone mode, e.g. for testing
             }
         } else {
+            std::cout << "[XX] STANDALONE" << std::endl;
             LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_STANDALONE);
         }
         server.run();

src/bin/dhcp6/main.cc

@@ -103,9 +103,10 @@ main(int argc, char* argv[]) {
     }
 
     // Initialize logging.  If verbose, we'll use maximum verbosity.
+    // If standalone is enabled, do not buffer initial log messages
     isc::log::initLogger(DHCP6_NAME,
                          (verbose_mode ? isc::log::DEBUG : isc::log::INFO),
-                         isc::log::MAX_DEBUG_LEVEL, NULL, true);
+                         isc::log::MAX_DEBUG_LEVEL, NULL, !stand_alone);
     LOG_INFO(dhcp6_logger, DHCP6_STARTING);
     LOG_DEBUG(dhcp6_logger, DBG_DHCP6_START, DHCP6_START_INFO)
               .arg(getpid()).arg(port_number).arg(verbose_mode ? "yes" : "no")

src/lib/log/Makefile.am

@@ -31,6 +31,7 @@ libb10_log_la_SOURCES += message_initializer.cc message_initializer.h
 libb10_log_la_SOURCES += message_reader.cc message_reader.h
 libb10_log_la_SOURCES += message_types.h
 libb10_log_la_SOURCES += output_option.cc output_option.h
+libb10_log_la_SOURCES += buffer_appender.cc buffer_appender.h
 
 EXTRA_DIST  = README
 EXTRA_DIST += logimpl_messages.mes

src/lib/log/README

@@ -338,7 +338,8 @@ Variant #1, Used by Production Programs
 ---------------------------------------
 void isc::log::initLogger(const std::string& root,
                           isc::log::Severity severity = isc::log::INFO,
-                          int dbglevel = 0, const char* file = NULL);
+                          int dbglevel = 0, const char* file = NULL,
+                          bool buffer = false);
 
 This is the call that should be used by production programs:
 
@@ -359,6 +360,15 @@ file
 The name of a local message file.  This will be read and its definitions used
 to replace the compiled-in text of the messages.
 
+buffer
+If set to true, initial log messages will be internally buffered, until the
+first time a logger specification is processed. This way the program can
+use logging before even processing its logging configuration. As soon as any
+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).
 
 Variant #2, Used by Unit Tests
 ------------------------------

src/lib/log/logger_manager_impl.cc

@@ -30,6 +30,7 @@
 #include <log/log_messages.h>
 #include <log/logger_name.h>
 #include <log/logger_specification.h>
+#include <log/buffer_appender.h>
 
 #include <boost/scoped_ptr.hpp>
 
@@ -38,67 +39,6 @@ using namespace std;
 namespace isc {
 namespace log {
 
-class LogBuffer {
-public:
-    LogBuffer() {
-        flushed_ = false;
-    }
-
-    ~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();
-    }
-    void add(const log4cplus::spi::InternalLoggingEvent& event) {
-        if (flushed_) {
-            isc_throw(isc::Exception, "BUFFER APPEND AFTER FLUSH");
-        }
-        stored_.push_back(log4cplus::spi::InternalLoggingEvent(event));
-    }
-    void flush_stdout() {
-        // 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
-        // be a good idea.
-        for (size_t i = 0; i < stored_.size(); ++i) {
-            std::cout << stored_.at(i).getMessage() << std::endl;
-            log4cplus::Logger logger = log4cplus::Logger::getInstance(stored_.at(i).getLoggerName());
-
-            logger.log(stored_.at(i).getLogLevel(), stored_.at(i).getMessage());
-        }
-        stored_.clear();
-    }
-    //void flush(log4cplus::Logger& logger) {
-    void flush() {
-        for (size_t i = 0; i < stored_.size(); ++i) {
-            const log4cplus::spi::InternalLoggingEvent event(stored_.at(i));
-            //logger.log(event.getLogLevel(), event.getMessage());
-            // Flush to the last defined logger
-            log4cplus::Logger logger = log4cplus::Logger::getInstance(event.getLoggerName());
-
-            logger.log(event.getLogLevel(), event.getMessage());
-        }
-        stored_.clear();
-        flushed_ = true;
-    }
-private:
-    std::vector<log4cplus::spi::InternalLoggingEvent> stored_;
-    bool flushed_;
-};
-
-LogBuffer& getLogBuffer() {
-    static boost::scoped_ptr<LogBuffer> log_buffer(NULL);
-    if (!log_buffer) {
-        log_buffer.reset(new LogBuffer);
-    }
-    return (*log_buffer);
-}
-
-
-
 // Reset hierarchy of loggers back to default settings.  This removes all
 // appenders from loggers, sets their severity to NOT_SET (so that events are
 // passed back to the parent) and resets the root logger to logging
@@ -209,25 +149,15 @@ LoggerManagerImpl::createFileAppender(log4cplus::Logger& logger,
     logger.addAppender(fileapp);
 }
 
-class BufferAppender : public log4cplus::Appender {
-public:
-    BufferAppender() {}
-
-    virtual void close() {
-        //relog();
-        //log2out();
-    }
-    virtual void append(const log4cplus::spi::InternalLoggingEvent& event) {
-        getLogBuffer().add(event);
-    }
-};
-
 void
 LoggerManagerImpl::createBufferAppender(log4cplus::Logger& logger)
 {
     log4cplus::SharedAppenderPtr bufferapp(new BufferAppender());
     bufferapp->setName("buffer");
     logger.addAppender(bufferapp);
+    // Since we do not know at what level the loggers will end up
+    // running, set it to the highest for now
+    logger.setLogLevel(log4cplus::TRACE_LOG_LEVEL);
 }
 
 // Syslog appender.

src/lib/log/tests/Makefile.am

@@ -37,6 +37,15 @@ init_logger_test_LDADD += $(top_builddir)/src/lib/util/libb10-util.la
 init_logger_test_LDADD += $(top_builddir)/src/lib/exceptions/libb10-exceptions.la
 init_logger_test_LDADD += $(AM_LDADD) $(LOG4CPLUS_LIBS)
 
+noinst_PROGRAMS += buffer_logger_test
+buffer_logger_test_SOURCES = buffer_logger_test.cc
+buffer_logger_test_CPPFLAGS = $(AM_CPPFLAGS)
+buffer_logger_test_LDFLAGS = $(AM_LDFLAGS)
+buffer_logger_test_LDADD  = $(top_builddir)/src/lib/log/libb10-log.la
+buffer_logger_test_LDADD += $(top_builddir)/src/lib/util/libb10-util.la
+buffer_logger_test_LDADD += $(top_builddir)/src/lib/exceptions/libb10-exceptions.la
+buffer_logger_test_LDADD += $(AM_LDADD) $(LOG4CPLUS_LIBS)
+
 noinst_PROGRAMS += logger_lock_test
 logger_lock_test_SOURCES = logger_lock_test.cc
 nodist_logger_lock_test_SOURCES = log_test_messages.cc log_test_messages.h
@@ -82,11 +91,13 @@ run_unittests_SOURCES += logger_specification_unittest.cc
 run_unittests_SOURCES += message_dictionary_unittest.cc
 run_unittests_SOURCES += message_reader_unittest.cc
 run_unittests_SOURCES += output_option_unittest.cc
+run_unittests_SOURCES += buffer_appender_unittest.cc
 nodist_run_unittests_SOURCES = log_test_messages.cc log_test_messages.h
 
 run_unittests_CPPFLAGS = $(AM_CPPFLAGS)
 run_unittests_CXXFLAGS = $(AM_CXXFLAGS)
 run_unittests_LDADD    = $(AM_LDADD)
+run_unittests_LDADD    +=  $(LOG4CPLUS_LIBS)
 run_unittests_LDFLAGS  = $(AM_LDFLAGS)
 
 # logging initialization tests.  These are put in separate programs to
@@ -124,6 +135,7 @@ check-local:
 	$(SHELL) $(abs_builddir)/console_test.sh
 	$(SHELL) $(abs_builddir)/destination_test.sh
 	$(SHELL) $(abs_builddir)/init_logger_test.sh
+	$(SHELL) $(abs_builddir)/buffer_logger_test.sh
 	$(SHELL) $(abs_builddir)/local_file_test.sh
 	$(SHELL) $(abs_builddir)/logger_lock_test.sh
 	$(SHELL) $(abs_builddir)/severity_test.sh
@@ -131,6 +143,7 @@ check-local:
 noinst_SCRIPTS  = console_test.sh
 noinst_SCRIPTS += destination_test.sh
 noinst_SCRIPTS += init_logger_test.sh
+noinst_SCRIPTS += buffer_logger_test.sh
 noinst_SCRIPTS += local_file_test.sh
 noinst_SCRIPTS += logger_lock_test.sh
 noinst_SCRIPTS += severity_test.sh

src/lib/log/tests/buffer_appender_unittest.cc

+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include "config.h"
+#include <gtest/gtest.h>
+
+#include <log/macros.h>
+#include <log/buffer_appender.h>
+#include <log/logger_support.h>
+#include <log/log_messages.h>
+
+#include <log4cplus/logger.h>
+#include <log4cplus/nullappender.h>
+
+using namespace isc::log;
+
+namespace isc {
+namespace log {
+
+// In these tests we are testing the LogBuffer class itself,
+// and not the singleton usage of one, so we need another
+// special appender
+class TestLogBufferAppender : public log4cplus::Appender {
+public:
+    TestLogBufferAppender(LogBuffer& buffer) : buffer_(buffer) {}
+    virtual void close() {}
+    virtual void append(const log4cplus::spi::InternalLoggingEvent& event) {
+        buffer_.add(event);
+    }
+    LogBuffer& buffer_;
+};
+
+class LogBufferTest : public ::testing::Test {
+public:
+    LogBufferTest() : appender1(new TestLogBufferAppender(buffer1)),
+                      appender2(new TestLogBufferAppender(buffer2)),
+                      logger(log4cplus::Logger::getInstance("buffer"))
+    {
+        logger.setLogLevel(log4cplus::TRACE_LOG_LEVEL);
+    }
+
+    ~LogBufferTest() {
+        // If any log messages are left, we don't care, get rid of them,
+        // by flushing them to a null appender
+        log4cplus::SharedAppenderPtr null_appender(new log4cplus::NullAppender());
+        logger.removeAllAppenders();
+        logger.addAppender(null_appender);
+        buffer1.flush();
+        buffer2.flush();
+    }
+
+    void checkBufferedSize(LogBuffer& buffer, size_t expected) {
+        ASSERT_EQ(expected, buffer.stored_.size());
+    }
+
+    LogBuffer buffer1;
+    LogBuffer buffer2;
+    log4cplus::SharedAppenderPtr appender1;
+    log4cplus::SharedAppenderPtr appender2;
+    log4cplus::Logger logger;
+};
+
+TEST_F(LogBufferTest, flush) {
+    checkBufferedSize(buffer1, 0);
+    checkBufferedSize(buffer2, 0);
+
+    // Create a Logger, log a few messages with the first appender
+    logger.addAppender(appender1);
+    LOG4CPLUS_INFO(logger, "Foo");
+    checkBufferedSize(buffer1, 1);
+    LOG4CPLUS_INFO(logger, "Foo");
+    checkBufferedSize(buffer1, 2);
+    LOG4CPLUS_INFO(logger, "Foo");
+    checkBufferedSize(buffer1, 3);
+
+    // Second buffer should still be empty
+    checkBufferedSize(buffer2, 0);
+
+    // 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);
+}
+
+TEST_F(LogBufferTest, addAfterFlush) {
+    // Once flushed, logging new messages with the same buffer should fail
+    logger.addAppender(appender1);
+    buffer1.flush();
+    EXPECT_THROW(LOG4CPLUS_INFO(logger, "Foo"), LogBufferAddAfterFlush);
+    // It should not have been added
+    checkBufferedSize(buffer1, 0);
+
+    // 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);
+}
+
+}
+}
+
+namespace {
+
+} // end unnamed namespace

src/lib/log/tests/buffer_logger_test.cc

+// Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+//
+// Permission to use, copy, modify, and/or distribute this software for any
+// purpose with or without fee is hereby granted, provided that the above
+// copyright notice and this permission notice appear in all copies.
+//
+// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+// AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+// PERFORMANCE OF THIS SOFTWARE.
+
+#include <log/macros.h>
+#include <log/logger_support.h>
+#include <log/logger_manager.h>
+#include <log/log_messages.h>
+#include <util/interprocess_sync_null.h>
+
+using namespace isc::log;
+
+void usage() {
+    std::cout << "Usage: buffer_logger_test [-n]" << std::endl;
+}
+
+/// \brief Test InitLogger
+///
+/// A program used in testing the logger that initializes logging with
+/// buffering enabled, so that initial log messages are not immediately
+/// logged, but are not lost (they should be logged the moment process()
+/// is called.
+///
+/// If -n is given as an argument, process() is never called. In this
+/// case, upon exit, all leftover log messages should be printed to
+/// stdout, but without normal logging additions (such as time and
+/// logger name)
+int
+main(int argc, char** argv) {
+    bool do_process = true;
+    int opt;
+    while ((opt = getopt(argc, argv, "n")) != -1) {
+        switch (opt) {
+        case 'n':
+            do_process = false;
+            break;
+        default:
+            usage();
+            return (1);
+        }
+    }
+
+    // Note, level is INFO, so DEBUG should normally not show
+    // up. Unless process is never called (at which point it
+    // will end up in the dump at the end).
+    initLogger("buffertest", isc::log::INFO, 0, NULL, true);
+    Logger logger("log");
+    // No need for file interprocess locking in this test
+    logger.setInterprocessSync(new isc::util::InterprocessSyncNull("logger"));
+    LOG_INFO(logger, LOG_BAD_SEVERITY).arg("info");
+    LOG_DEBUG(logger, 50, LOG_BAD_DESTINATION).arg("debug-50");
+    LOG_INFO(logger, LOG_BAD_SEVERITY).arg("info");
+    // process should cause them to be logged
+    if (do_process) {
+        LoggerManager logger_manager;
+        logger_manager.process();
+    }
+    return (0);
+}

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

+#!/bin/sh
+# Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+#
+# Permission to use, copy, modify, and/or distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+# Checks that the initLogger() call uses for unit tests respects the setting of
+# the buffer value
+#
+
+testname="bufferLogger test"
+echo $testname
+
+failcount=0
+tempfile=@abs_builddir@/buffer_logger_test_tempfile_$$
+
+passfail() {
+    if [ $1 -eq 0 ]; then
+        echo " pass"
+    else
+        echo " FAIL"
+        failcount=`expr $failcount + $1`
+    fi
+}
+
+echo "1. Checking that buffer initialization works"
+
+echo -n  "   - Buffer including process() call: "
+cat > $tempfile << .
+INFO  [buffertest.log] LOG_BAD_SEVERITY unrecognized log severity: info
+INFO  [buffertest.log] LOG_BAD_SEVERITY unrecognized log severity: info
+.
+./buffer_logger_test 2>&1 | \
+    sed -e 's/\[\([a-z0-9\.]\{1,\}\)\/\([0-9]\{1,\}\)\]/[\1]/' | \
+    cut -d' ' -f3- | diff $tempfile -
+passfail $?
+
+echo -n  "   - Buffer excluding process() call: "
+cat > $tempfile << .
+LOG_BAD_SEVERITY unrecognized log severity: info
+LOG_BAD_DESTINATION unrecognized log destination: debug-50
+LOG_BAD_SEVERITY unrecognized log severity: info
+.
+./buffer_logger_test -n 2>&1 | diff $tempfile -
+passfail $?
+
+
+
+# Tidy up.
+rm -f $tempfile
+
+exit $failcount