Commit 74a0abe5 authored by Jelte Jansen's avatar Jelte Jansen
Browse files

[master] Merge branch 'trac2445'

parents 044c4779 27442da4
......@@ -1376,6 +1376,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
......
......@@ -147,7 +147,7 @@ main(int argc, char* argv[]) {
// Initialize logging. If verbose, we'll use maximum verbosity.
isc::log::initLogger(AUTH_NAME,
(verbose ? isc::log::DEBUG : isc::log::INFO),
isc::log::MAX_DEBUG_LEVEL, NULL);
isc::log::MAX_DEBUG_LEVEL, NULL, true);
int ret = 0;
......@@ -256,7 +256,9 @@ main(int argc, char* argv[]) {
// If we haven't registered callback for data sources, this will be just
// no-op.
config_session->removeRemoteConfig("data_sources");
if (config_session != NULL) {
config_session->removeRemoteConfig("data_sources");
}
delete xfrin_session;
delete config_session;
......
......@@ -48,7 +48,7 @@ else:
PREFIX = "@prefix@"
DATAROOTDIR = "@datarootdir@"
SPECFILE_LOCATION = "@datadir@/@PACKAGE@/bob.spec".replace("${datarootdir}", DATAROOTDIR).replace("${prefix}", PREFIX)
import subprocess
import signal
import re
......@@ -76,7 +76,7 @@ import isc.bind10.socket_cache
import libutil_io_python
import tempfile
isc.log.init("b10-boss")
isc.log.init("b10-boss", buffer=True)
logger = isc.log.Logger("boss")
# Pending system-wide debug level definitions, the ones we
......@@ -166,14 +166,14 @@ class ProcessStartError(Exception): pass
class BoB:
"""Boss of BIND class."""
def __init__(self, msgq_socket_file=None, data_path=None,
config_filename=None, clear_config=False,
verbose=False, nokill=False, setuid=None, setgid=None,
username=None, cmdctl_port=None, wait_time=10):
"""
Initialize the Boss of BIND. This is a singleton (only one can run).
The msgq_socket_file specifies the UNIX domain socket file that the
msgq process listens on. If verbose is True, then the boss reports
what it is doing.
......@@ -407,7 +407,7 @@ class BoB:
logger.error(BIND10_STARTUP_UNEXPECTED_MESSAGE, msg)
except:
logger.error(BIND10_STARTUP_UNRECOGNISED_MESSAGE, msg)
return False
# The next few methods start the individual processes of BIND-10. They
......@@ -486,7 +486,7 @@ class BoB:
time.sleep(1)
time_remaining = time_remaining - 1
msg, env = self.cc_session.group_recvmsg()
if not self.process_running(msg, "ConfigManager"):
raise ProcessStartError("Configuration manager process has not started")
......@@ -503,7 +503,7 @@ class BoB:
process, the log_starting/log_started methods are not used.
"""
logger.info(BIND10_STARTING_CC)
self.ccs = isc.config.ModuleCCSession(SPECFILE_LOCATION,
self.ccs = isc.config.ModuleCCSession(SPECFILE_LOCATION,
self.config_handler,
self.command_handler,
socket_file = self.msgq_socket_file)
......@@ -700,7 +700,7 @@ class BoB:
except:
pass
# XXX: some delay probably useful... how much is uncertain
# I have changed the delay from 0.5 to 1, but sometime it's
# I have changed the delay from 0.5 to 1, but sometime it's
# still not enough.
time.sleep(1)
self.reap_children()
......@@ -749,8 +749,8 @@ class BoB:
return os.waitpid(-1, os.WNOHANG)
def reap_children(self):
"""Check to see if any of our child processes have exited,
and note this for later handling.
"""Check to see if any of our child processes have exited,
and note this for later handling.
"""
while True:
try:
......@@ -783,11 +783,11 @@ class BoB:
"""
Restart any dead processes:
* Returns the time when the next process is ready to be restarted.
* Returns the time when the next process is ready to be restarted.
* If the server is shutting down, returns 0.
* If there are no processes, returns None.
The values returned can be safely passed into select() as the
The values returned can be safely passed into select() as the
timeout value.
"""
......@@ -1031,7 +1031,7 @@ boss_of_bind = None
def reaper(signal_number, stack_frame):
"""A child process has died (SIGCHLD received)."""
# don't do anything...
# don't do anything...
# the Python signal handler has been set up to write
# down a pipe, waking up our select() bit
pass
......@@ -1198,7 +1198,7 @@ and the created lock file must be writable for that user.
except KeyError:
pass
# Next try getting information about the user, assuming user name
# Next try getting information about the user, assuming user name
# passed.
# If the information is both a valid user name and user number, we
# prefer the name because we try it second. A minor point, hopefully.
......
......@@ -27,7 +27,7 @@ import glob
import os.path
import imp
import isc.log
isc.log.init("b10-cfgmgr")
isc.log.init("b10-cfgmgr", buffer=True)
from isc.config.cfgmgr import ConfigManager, ConfigManagerDataReadError, logger
from isc.log_messages.cfgmgr_messages import *
......
......@@ -49,7 +49,7 @@ from hashlib import sha1
from isc.util import socketserver_mixin
from isc.log_messages.cmdctl_messages import *
isc.log.init("b10-cmdctl")
isc.log.init("b10-cmdctl", buffer=True)
logger = isc.log.Logger("cmdctl")
# Debug level for communication with BIND10
......
......@@ -45,7 +45,7 @@ import os.path
import signal
import socket
isc.log.init("b10-ddns")
isc.log.init("b10-ddns", buffer=True)
logger = isc.log.Logger("ddns")
TRACE_BASIC = logger.DBGLVL_TRACE_BASIC
......
......@@ -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);
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")
......@@ -112,6 +114,10 @@ main(int argc, char* argv[]) {
LOG_ERROR(dhcp4_logger, DHCP4_SESSION_FAIL).arg(ex.what());
// Let's continue. It is useful to have the ability to run
// DHCP server in stand-alone mode, e.g. for testing
// We do need to make sure logging is no longer buffered
// since then it would not print until dhcp6 is stopped
isc::log::LoggerManager log_manager;
log_manager.process();
}
} else {
LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_STANDALONE);
......
......@@ -17,6 +17,7 @@
#include <dhcp6/ctrl_dhcp6_srv.h>
#include <dhcp6/dhcp6_log.h>
#include <log/logger_support.h>
#include <log/logger_manager.h>
#include <boost/lexical_cast.hpp>
......@@ -103,9 +104,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);
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")
......@@ -119,8 +121,12 @@ main(int argc, char* argv[]) {
server.establishSession();
} catch (const std::exception& ex) {
LOG_ERROR(dhcp6_logger, DHCP6_SESSION_FAIL).arg(ex.what());
// Let's continue. It is useful to have the ability to run
// Let's continue. It is useful to have the ability to run
// DHCP server in stand-alone mode, e.g. for testing
// We do need to make sure logging is no longer buffered
// since then it would not print until dhcp6 is stopped
isc::log::LoggerManager log_manager;
log_manager.process();
}
} else {
LOG_DEBUG(dhcp6_logger, DBG_DHCP6_START, DHCP6_STANDALONE);
......
......@@ -143,7 +143,7 @@ main(int argc, char* argv[]) {
// temporary initLogger() code. If verbose, we'll use maximum verbosity.
isc::log::initLogger(RESOLVER_NAME,
(verbose ? isc::log::DEBUG : isc::log::INFO),
isc::log::MAX_DEBUG_LEVEL, NULL);
isc::log::MAX_DEBUG_LEVEL, NULL, true);
// Print the starting message
string cmdline = argv[0];
......@@ -177,7 +177,7 @@ main(int argc, char* argv[]) {
isc::cache::ResolverCache cache;
resolver->setCache(cache);
// TODO priming query, remove root from direct
// Fake a priming query result here (TODO2 how to flag non-expiry?)
// propagation to runningquery. And check for forwarder mode?
......@@ -185,21 +185,21 @@ main(int argc, char* argv[]) {
isc::dns::Name("."),
isc::dns::RRClass::IN(),
isc::dns::RRType::NS()));
isc::dns::RRsetPtr root_ns_rrset(new isc::dns::RRset(isc::dns::Name("."),
isc::dns::RRsetPtr root_ns_rrset(new isc::dns::RRset(isc::dns::Name("."),
isc::dns::RRClass::IN(),
isc::dns::RRType::NS(),
isc::dns::RRTTL(8888)));
root_ns_rrset->addRdata(isc::dns::rdata::createRdata(isc::dns::RRType::NS(),
isc::dns::RRClass::IN(),
"l.root-servers.net."));
isc::dns::RRsetPtr root_a_rrset(new isc::dns::RRset(isc::dns::Name("l.root-servers.net"),
isc::dns::RRsetPtr root_a_rrset(new isc::dns::RRset(isc::dns::Name("l.root-servers.net"),
isc::dns::RRClass::IN(),
isc::dns::RRType::A(),
isc::dns::RRTTL(8888)));
root_a_rrset->addRdata(isc::dns::rdata::createRdata(isc::dns::RRType::A(),
isc::dns::RRClass::IN(),
"199.7.83.42"));
isc::dns::RRsetPtr root_aaaa_rrset(new isc::dns::RRset(isc::dns::Name("l.root-servers.net"),
isc::dns::RRsetPtr root_aaaa_rrset(new isc::dns::RRset(isc::dns::Name("l.root-servers.net"),
isc::dns::RRClass::IN(),
isc::dns::RRType::AAAA(),
isc::dns::RRTTL(8888)));
......@@ -216,7 +216,7 @@ main(int argc, char* argv[]) {
cache.update(root_ns_rrset);
cache.update(root_a_rrset);
cache.update(root_aaaa_rrset);
DNSService dns_service(io_service, checkin, lookup, answer);
resolver->setDNSService(dns_service);
LOG_DEBUG(resolver_logger, RESOLVER_DBG_INIT, RESOLVER_SERVICE_CREATED);
......
......@@ -31,7 +31,7 @@ import isc.util.process
import isc.log
from isc.log_messages.stats_messages import *
isc.log.init("b10-stats")
isc.log.init("b10-stats", buffer=True)
logger = isc.log.Logger("stats")
# Some constants for debug levels.
......@@ -682,7 +682,7 @@ if __name__ == "__main__":
help="enable maximum debug logging")
(options, args) = parser.parse_args()
if options.verbose:
isc.log.init("b10-stats", "DEBUG", 99)
isc.log.init("b10-stats", "DEBUG", 99, buffer=True)
stats = Stats()
stats.start()
except OptionValueError as ove:
......
......@@ -39,7 +39,7 @@ import isc.util.process
import isc.log
from isc.log_messages.stats_httpd_messages import *
isc.log.init("b10-stats-httpd")
isc.log.init("b10-stats-httpd", buffer=True)
logger = isc.log.Logger("stats-httpd")
# Some constants for debug levels.
......@@ -609,7 +609,7 @@ if __name__ == "__main__":
help="enable maximum debug logging")
(options, args) = parser.parse_args()
if options.verbose:
isc.log.init("b10-stats-httpd", "DEBUG", 99)
isc.log.init("b10-stats-httpd", "DEBUG", 99, buffer=True)
stats_httpd = StatsHttpd()
stats_httpd.start()
except OptionValueError as ove:
......
......@@ -36,7 +36,7 @@ from isc.xfrin.diff import Diff
from isc.server_common.auth_command import auth_loadzone_command
from isc.log_messages.xfrin_messages import *
isc.log.init("b10-xfrin")
isc.log.init("b10-xfrin", buffer=True)
logger = isc.log.Logger("xfrin")
# Pending system-wide debug level definitions, the ones we
......
......@@ -38,7 +38,7 @@ import isc.server_common.tsig_keyring
from isc.log_messages.xfrout_messages import *
isc.log.init("b10-xfrout")
isc.log.init("b10-xfrout", buffer=True)
logger = isc.log.Logger("xfrout")
# Pending system-wide debug level definitions, the ones we
......
......@@ -42,7 +42,7 @@ from isc.log_messages.zonemgr_messages import *
from isc.notify import notify_out
# Initialize logging for called modules.
isc.log.init("b10-zonemgr")
isc.log.init("b10-zonemgr", buffer=True)
logger = isc.log.Logger("zonemgr")
# Pending system-wide debug level definitions, the ones we
......
......@@ -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_impl.cc buffer_appender_impl.h
EXTRA_DIST = README
EXTRA_DIST += logimpl_messages.mes
......
......@@ -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,17 @@ 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 you
are using the built-in logging configuration handling in ModuleCCSession,
this is automatically handled). If the program exits before this is done,
all log messages are dumped in a raw format to stdout (so that no messages
get lost).
Variant #2, Used by Unit Tests
------------------------------
......
// Copyright (C) 2012 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/buffer_appender_impl.h>
#include <log4cplus/loglevel.h>
#include <boost/scoped_ptr.hpp>
#include <cstdio>
namespace isc {
namespace log {
namespace internal {
BufferAppender::~BufferAppender() {
// 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
try {
flushStdout();
} catch (...) {
// Ok if we can't even seem to dump to stdout, never mind.
}
}
void
BufferAppender::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
// be a good idea; as we can't reliably know whether in what
// state the logger instance is now (or what the specific logger's
// settings were).
LogEventList::const_iterator it;
for (it = stored_.begin(); it != stored_.end(); ++it) {
const std::string level(it->first);
LogEventPtr event(it->second);
std::printf("%s [%s]: %s\n", level.c_str(),
event->getLoggerName().c_str(),
event->getMessage().c_str());
}
stored_.clear();
}
void
BufferAppender::flush() {
LogEventList stored_copy;
stored_.swap(stored_copy);
LogEventList::const_iterator it;
for (it = stored_copy.begin(); it != stored_copy.end(); ++it) {
LogEventPtr event(it->second);
log4cplus::Logger logger =
log4cplus::Logger::getInstance(event->getLoggerName());
logger.log(event->getLogLevel(), event->getMessage());
}
flushed_ = true;
}
size_t
BufferAppender::getBufferSize() const {
return (stored_.size());
}
void
BufferAppender::append(const log4cplus::spi::InternalLoggingEvent& event) {
if (flushed_) {
isc_throw(LogBufferAddAfterFlush,
"Internal log buffer has been flushed already");
}
// get a clone, and put the pointer in a shared_ptr in the list
std::auto_ptr<log4cplus::spi::InternalLoggingEvent> event_aptr =
event.clone();
// Also store the string representation of the log level, to be
// used in flushStdout if necessary
stored_.push_back(LevelAndEvent(
log4cplus::LogLevelManager().toString(event.getLogLevel()),
LogEventPtr(event_aptr.release())));
}
} // end namespace internal
} // end namespace log
} // end namespace isc
// Copyright (C) 2012 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.
#ifndef LOG_BUFFER_H
#define LOG_BUFFER_H
#include <exceptions/exceptions.h>
#include <log4cplus/logger.h>
#include <log4cplus/spi/loggingevent.h>
#include <boost/shared_ptr.hpp>
namespace isc {
namespace log {
namespace internal {
/// \brief Buffer add after flush
///
/// This exception is thrown if the log buffer's add() method
/// is called after the log buffer has been flushed; the buffer
/// is only supposed to be used once (until the first time a
/// logger specification is processed)
class LogBufferAddAfterFlush : public isc::Exception {
public:
LogBufferAddAfterFlush(const char* file, size_t line, const char* what) :
isc::Exception(file, line, what)
{}
};
/// Convenience typedef for a pointer to a log event
typedef boost::shared_ptr<log4cplus::spi::InternalLoggingEvent> LogEventPtr;
/// Convenience typedef for a pair string/logeventptr, the string representing
/// the logger level, as returned by LogLevelManager::toString() at the
/// time of initial logging
typedef std::pair<std::string, LogEventPtr> LevelAndEvent;
/// Convenience typedef for a vector of LevelAndEvent instances
typedef std::vector<LevelAndEvent> LogEventList;
/// \brief Buffering Logger Appender
///
/// This class can be set as an Appender for log4cplus loggers,
/// and is used to store logging events; it simply keeps any
/// event that is passed to \c append(), and will replay them to the
/// logger that they were originally created for when \c flush() is
/// called.
///
/// The idea is that initially, a program may want to do some logging,
/// but does not know where to yet (for instance because it has yet to
/// read and parse its configuration). Any log messages before this time
/// would normally go to some default (say, stdout), and be lost in the
/// real logging destination. By buffering them (and flushing them once
/// the logger has been configured), these log messages are kept in a
/// consistent place, and are not lost.
///
/// Given this goal, this class has an extra check; it will raise
/// an exception if \c append() is called after flush().
///
/// If the BufferAppender instance is destroyed before being flushed,
/// it will dump any event it has left to stdout.
class BufferAppender : public log4cplus::Appender {
public:
/// \brief Constructor
///
/// Constructs a BufferAppender that buffers log evens
BufferAppender() : flushed_(false) {}
/// \brief Destructor
///
/// Any remaining events are flushed to stdout (there should
/// only be any events remaining if flush() was never called)
virtual ~BufferAppender();
/// \brief Close the appender
///
/// This class has no specialized handling for this method
virtual void close() {}
/// \brief Flush the internal buffer
///
/// Events that have been stored (after calls to \c append()
/// are replayed to the logger. Should only be called after
/// new appenders have been set to the logger.
void flush();
/// \brief Returns the number of stored logging events
///
/// Mainly useful for testing
size_t getBufferSize() const;
protected:
virtual void append(const log4cplus::spi::InternalLoggingEvent& event);
private:
/// \brief Helper for the destructor, flush events to stdout
void flushStdout();
LogEventList stored_;
bool flushed_;
};
} // end namespace internal
} // end namespace log
} // end namespace isc
#endif // LOG_BUFFER_H
......@@ -94,7 +94,7 @@ LoggerManager::processEnd() {
void
LoggerManager::init(const std::string& root, isc::log::Severity severity,
int dbglevel, const char* file)
int dbglevel, const char* file, bool buffer)
{
// Load in the messages declared in the program and registered by
// statically-declared MessageInitializer objects.
......@@ -114,7 +114,9 @@ LoggerManager::init(const std::string& root, isc::log::Severity severity,
// Initialize the implementation logging. After this point, some basic
// logging has been set up and messages can be logged.
LoggerManagerImpl::init(severity, dbglevel);
// However, they will not appear until a logging specification has been
// processed (or the program exits), see TODO
LoggerManagerImpl::init(severity, dbglevel, buffer);
setLoggingInitialized();
// Check if there were any duplicate message IDs in the default dictionary
......
......@@ -76,6 +76,21 @@ public:
processEnd();
}