Commit 6b118748 authored by Stephen Morris's avatar Stephen Morris
Browse files

Minor modifications to logging code made after review.

parent 635c6e46
// Copyright (C) 2010 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.
// $Id$
#ifndef __MESSAGE_H
#define __MESSAGE_H
/// \brief Log Message
///
/// This class represents a message in which information about a logging event
/// is encoded. This is invisible to the author of code doing logging unless
/// they are planning on writing an Appender.
class Message {
public:
// The following is a placeholder. It will be replaced with a finer-
// grained time definition during implementation.
typedef time_t Time; ///< To be replaced with a finer-grained time later
// Constructor/destructor stll to be determined
/// \brief Return Timestamp
///
/// \return Timestamp associated with the message.
Time getTimestamp() const;
/// \brief Return Source
///
/// \return Returns the source of the message. This is a "."-separated
/// string containing the hierarchy of the logger than generated this
/// message.
std::string getSource() const;
/// \brief Return ID
///
/// \return Returns the ID of the message, a 32-bit integer.
uint32_t getId() const;
/// \brief Return Parameters
///
/// \return The parameters of the message in the form of a vector of
/// strings. Numeric parameters have been converted to strings and
/// included in the message.
std::vector<std::string> getParameters() const;
/// \brief Return Encoded Message
///
/// The contents of the message are encoded as a string in the form
///
/// <message ID><'\0'><param 1><'\0'>...
///
/// Some Appenders may find this format useful, so the ability to retrieve
/// it directly is provided.
std::string getRawMessage() const;
};
#endif // __MESSAGE_H
......@@ -17,5 +17,4 @@ CLEANFILES = *.gcno *.gcda
pkglibexec_PROGRAMS = message
message_SOURCES = message.cc
message_LDADD = $(top_builddir)/src/lib/log/liblog.la
message_LDADD += $(LOG4CXX_LDFLAGS)
......@@ -268,6 +268,91 @@ To use the current version of the logging:
At present, the only logging is to the console.
Severity Guidelines
===================
When using logging, the question arises, what severity should a message be
logged at? The following is a suggestion - as always, the decision must be
made in the context of which the message is logged.
FATAL
-----
The program has encountered an error that is so severe that it cannot
continue (or there is no point in continuing). When a fatal error has been
logged, the program will usually exit immediately (via a call to abort()) or
shortly afterwards, after dumping some diagnostic information.
ERROR
-----
Something has happened such that the program can continue but the results
for the current (or future) operations cannot be guaranteed to be correct,
or the results will be correct but the service is impaired. For example,
the program started but attempts to open one or more network interfaces failed.
WARN
----
An unusual event happened. Although the program will continue working
normally, the event was sufficiently out of the ordinary to warrant drawings
attention to it. For example, at program start-up a zone was loaded that
contained no resource records,
INFO
----
A normal but significant event has occurred that should be recorded,
e.g. the program has started or is just about to terminate, a new zone has
been created, etc.
DEBUG
-----
This severity is only enabled on for debugging purposes. A debug level is
associated with debug messages, level 0 (the default) being for high-level
messages and level 99 (the maximum) for the lowest level. How the messages
are distributed between the levels is up to the developer. So if debugging
the NSAS (for example), a level 0 message might record the creation of a new
zone, a level 10 recording a timeout when trying to get a nameserver address,
but a level 50 would record every query for an address. (And we might add
level 51 to record every update of the RTT.)
Note that like severities, levels are cumulative; so if level 25 is set as the
debug level, all debug levels from 0 to 25 will be output. In fact, it is
probably easier to visualise the debug levels as part of the severity system:
FATAL High
ERROR
WARN
INFO
DEBUG level 0
DEBUG level 1
:
DEBUG level 99 Low
When a particular severity is set, it - and all severities and/or debug
levels above it - will be logged.
Logging Sources v Logging Severities
------------------------------------
When logging events, make a distinction between events related to the server
and events related to DNS messages received. Caution needs to be exercised
with the latter as, if the logging is enabled in the normal course of events,
such logging could be a denoial of service vector. For example, suppose that
the main authoritiative service logger were to log both zone loading and
unloading as INFO and a warning message if it received an invalid packet. An
attacker could make the INFO messages unusable by flooding the server with
malformed packets.
There are two approaches to get round this:
a) Make the logging of packet-dependent events a DEBUG-severity message.
DEBUG is not enabled by default, so these events will not be recorded unless
DEBUG is specifically chosen.
b) Record system-related and packet-related messages via different loggers
(e.g. in the example given, sever events could be logged using the logger
"auth" and packet-related events at that level logged using the logger
"pkt-auth".)
As the loggers are independent and the severity levels independent, fine-tuning
of what and what is not recorded can be achieved.
Outstanding Issues
==================
* Ability to configure system according to configuration database.
......
......@@ -32,12 +32,13 @@ namespace log {
// Split string into components. Any backslashes are assumed to have
// been replaced by forward slashes.
void Filename::split(const string& full_name, string& directory,
void
Filename::split(const string& full_name, string& directory,
string& name, string& extension) const
{
directory = name = extension = "";
bool dir_present = false;
if (! full_name.empty()) {
if (!full_name.empty()) {
// Find the directory.
size_t last_slash = full_name.find_last_of('/');
......@@ -84,7 +85,8 @@ void Filename::split(const string& full_name, string& directory,
// Expand the stored filename with the default.
string Filename::expandWithDefault(const string& defname) const {
string
Filename::expandWithDefault(const string& defname) const {
string def_directory("");
string def_name("");
......@@ -92,7 +94,9 @@ string Filename::expandWithDefault(const string& defname) const {
// Normalize the input string.
string copy_defname = isc::strutil::trim(defname);
#ifdef WIN32
isc::strutil::normalizeSlash(copy_defname);
#endif
// Split into the components
split(copy_defname, def_directory, def_name, def_extension);
......@@ -107,7 +111,8 @@ string Filename::expandWithDefault(const string& defname) const {
// Use the stored name as default for a given name
string Filename::useAsDefault(const string& name) const {
string
Filename::useAsDefault(const string& name) const {
string name_directory("");
string name_name("");
......@@ -115,7 +120,9 @@ string Filename::useAsDefault(const string& name) const {
// Normalize the input string.
string copy_name = isc::strutil::trim(name);
#ifdef WIN32
isc::strutil::normalizeSlash(copy_name);
#endif
// Split into the components
split(copy_name, name_directory, name_name, name_extension);
......
......@@ -51,11 +51,12 @@ Logger::~Logger() {
// Initialize logger - create a logger as a child of the root logger. With
// log4cxx this is assured by naming the logger <parent>.<child>.
void Logger::initLogger() {
void
Logger::initLogger() {
// Initialize basic logging if not already done. This is a one-off for
// all loggers.
if (! init_) {
if (!init_) {
// TEMPORARY
// Add a suitable console logger to the log4cxx root logger. (This
......@@ -100,13 +101,13 @@ void Logger::initLogger() {
// Set the severity for logging. There is a 1:1 mapping between the logging
// severity and the log4cxx logging levels, apart from DEBUG.
//
// In log4cxx, each of the logging levels (DEBUG, INFO, WARNING etc.) has a
// numeric value. The level is set to one of these and any numeric level equal
// to or above it that is reported. For example INFO has a value of 20000 and
// ERROR a value of 40000. So if a message of WARNING severity (= 30000) is
// logged, it is not logged when the logger's severity level is ERROR (as
// 30000 !>= 40000). It is reported if the logger's severity level is set to
// WARNING (as 30000 >= 30000) or INFO (30000 >= 20000).
// In log4cxx, each of the logging levels (DEBUG, INFO, WARN etc.) has a numeric
// value. The level is set to one of these and any numeric level equal to or
// above it that is reported. For example INFO has a value of 20000 and ERROR
// a value of 40000. So if a message of WARN severity (= 30000) is logged, it is
// not logged when the logger's severity level is ERROR (as 30000 !>= 40000).
// It is reported if the logger's severity level is set to WARN (as 30000 >=
/// 30000) or INFO (30000 >= 20000).
//
// This gives a simple system for handling different debug levels. The debug
// level is a number between 0 and 99, with 0 being least verbose and 99 the
......@@ -122,7 +123,8 @@ void Logger::initLogger() {
//
// The extended set of logging levels is implemented by the XDebugLevel class.
void Logger::setSeverity(Severity severity, int dbglevel) {
void
Logger::setSeverity(Severity severity, int dbglevel) {
switch (severity) {
case NONE:
getLogger()->setLevel(log4cxx::Level::getOff());
......@@ -136,7 +138,7 @@ void Logger::setSeverity(Severity severity, int dbglevel) {
getLogger()->setLevel(log4cxx::Level::getError());
break;
case WARNING:
case WARN:
getLogger()->setLevel(log4cxx::Level::getWarn());
break;
......@@ -159,7 +161,8 @@ void Logger::setSeverity(Severity severity, int dbglevel) {
// Convert between numeric log4cxx logging level and BIND-10 logging severity.
Logger::Severity Logger::convertLevel(int value) const {
Logger::Severity
Logger::convertLevel(int value) const {
// The order is optimised. This is only likely to be called when testing
// for writing debug messages, so the check for DEBUG_INT is first.
......@@ -168,7 +171,7 @@ Logger::Severity Logger::convertLevel(int value) const {
} else if (value <= log4cxx::Level::INFO_INT) {
return (INFO);
} else if (value <= log4cxx::Level::WARN_INT) {
return (WARNING);
return (WARN);
} else if (value <= log4cxx::Level::ERROR_INT) {
return (ERROR);
} else if (value <= log4cxx::Level::FATAL_INT) {
......@@ -181,7 +184,8 @@ Logger::Severity Logger::convertLevel(int value) const {
// Return the logging severity associated with this logger.
Logger::Severity Logger::getSeverityCommon(const log4cxx::LoggerPtr& ptrlogger,
Logger::Severity
Logger::getSeverityCommon(const log4cxx::LoggerPtr& ptrlogger,
bool check_parent) const {
log4cxx::LevelPtr level = ptrlogger->getLevel();
......@@ -212,7 +216,8 @@ Logger::Severity Logger::getSeverityCommon(const log4cxx::LoggerPtr& ptrlogger,
// Get the debug level. This returns 0 unless the severity is DEBUG.
int Logger::getDebugLevel() {
int
Logger::getDebugLevel() {
log4cxx::LevelPtr level = getLogger()->getLevel();
if (level == log4cxx::LevelPtr()) {
......@@ -252,7 +257,8 @@ int Logger::getDebugLevel() {
// Output methods
void Logger::debug(int dbglevel, isc::log::MessageID ident, ...) {
void
Logger::debug(int dbglevel, isc::log::MessageID ident, ...) {
if (isDebugEnabled(dbglevel)) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
......@@ -260,7 +266,8 @@ void Logger::debug(int dbglevel, isc::log::MessageID ident, ...) {
}
}
void Logger::info(isc::log::MessageID ident, ...) {
void
Logger::info(isc::log::MessageID ident, ...) {
if (isInfoEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
......@@ -268,7 +275,8 @@ void Logger::info(isc::log::MessageID ident, ...) {
}
}
void Logger::warn(isc::log::MessageID ident, ...) {
void
Logger::warn(isc::log::MessageID ident, ...) {
if (isWarnEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
......@@ -276,7 +284,8 @@ void Logger::warn(isc::log::MessageID ident, ...) {
}
}
void Logger::error(isc::log::MessageID ident, ...) {
void
Logger::error(isc::log::MessageID ident, ...) {
if (isErrorEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
......@@ -284,7 +293,8 @@ void Logger::error(isc::log::MessageID ident, ...) {
}
}
void Logger::fatal(isc::log::MessageID ident, ...) {
void
Logger::fatal(isc::log::MessageID ident, ...) {
if (isFatalEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
......
......@@ -36,13 +36,10 @@ public:
DEFAULT, // Default to logging level of parent
DEBUG,
INFO,
WARNING,
WARN,
ERROR,
CRITICAL,
NONE, // Disable logging
INFORMATION = INFO,
WARN = WARNING,
FATAL = CRITICAL
FATAL,
NONE // Disable logging
} Severity;
/// \brief Constructor
......@@ -60,7 +57,7 @@ public:
/// destroyed causes a MutexException to be thrown (this is described in
/// https://issues.apache.org/jira/browse/LOGCXX-322). As this only occurs
/// during program rundown, the issue is not serious - it just looks bad to
/// have the program crash instead of shut down cleanly.<BR>
/// have the program crash instead of shut down cleanly.\n\n
/// The original implementation of the isc::log::Logger had as a member a
/// log4cxx logger (actually a LoggerPtr). If the isc:: Logger was declared
/// statically, when it was destroyed at the end of the program the internal
......@@ -68,7 +65,7 @@ public:
/// not occur if the isc::log::Logger was created on the stack. To get
/// round this, the internal LoggerPtr is now created dynamically. The
/// exit_delete argument controls its destruction: if true, it is destroyed
/// in the ISC Logger destructor. If false, it is not.<BR>
/// in the ISC Logger destructor. If false, it is not.\n\n
/// When creating an isc::log::Logger on the stack, the argument should be
/// false (the default); when the Logger is destroyed, all the internal
/// log4cxx objects are destroyed. As only the logger (and not the internal
......@@ -171,27 +168,13 @@ public:
}
/// \brief Is WARNING Enabled?
virtual bool isWarningEnabled() {
return (getLogger()->isWarnEnabled());
}
/// \brief Is ERROR Enabled?
virtual bool isErrorEnabled() {
return (getLogger()->isErrorEnabled());
}
/// \brief Is CRITICAL Enabled?
virtual bool isCriticalEnabled() {
return (getLogger()->isFatalEnabled());
}
/// \brief Is FATAL Enabled?
///
/// FATAL is a synonym for CRITICAL.
virtual bool isFatalEnabled() {
return (getLogger()->isFatalEnabled());
}
......@@ -321,6 +304,11 @@ protected:
static void readLocalMessageFile(const char* file);
private:
// Note that loggerptr_ is a pointer to a LoggerPtr, which is itself a
// pointer to the underlying log4cxx logger. This is due to the problems
// with memory deletion on program exit, explained in the comments for
// the "exit_delete" parameter in this class's constructor.
log4cxx::LoggerPtr* loggerptr_; ///< Pointer to the underlying logger
std::string name_; ///< Name of this logger]
bool exit_delete_; ///< Delete loggerptr_ on exit?
......
......@@ -55,7 +55,8 @@ Logger logger("log");
/// dictionary, they are listed in a warning message.
///
/// \param file Name of the local message file
static void readLocalMessageFile(const char* file) {
static void
readLocalMessageFile(const char* file) {
MessageDictionary* dictionary = MessageDictionary::globalDictionary();
MessageReader reader(dictionary);
......@@ -89,7 +90,8 @@ static void readLocalMessageFile(const char* file) {
/// Logger Run-Time Initialization
void runTimeInit(Logger::Severity severity, int dbglevel, const char* file) {
void
runTimeInit(Logger::Severity severity, int dbglevel, const char* file) {
// Create the application root logger. This is the logger that has the
// name of the application (and is one level down from the log4cxx root
......
......@@ -30,8 +30,8 @@ MessageDictionary::~MessageDictionary() {
// Add message and note if ID already exists
bool MessageDictionary::add(const MessageID& ident, const std::string& text)
{
bool
MessageDictionary::add(const MessageID& ident, const std::string& text) {
map<MessageID, string>::iterator i = dictionary_.find(ident);
bool not_found = (i == dictionary_.end());
if (not_found) {
......@@ -45,8 +45,8 @@ bool MessageDictionary::add(const MessageID& ident, const std::string& text)
// Add message and note if ID does not already exist
bool MessageDictionary::replace(const MessageID& ident, const std::string& text)
{
bool
MessageDictionary::replace(const MessageID& ident, const std::string& text) {
map<MessageID, string>::iterator i = dictionary_.find(ident);
bool found = (i != dictionary_.end());
if (found) {
......@@ -60,7 +60,8 @@ bool MessageDictionary::replace(const MessageID& ident, const std::string& text)
// Load a set of messages
vector<MessageID> MessageDictionary::load(const char* messages[]) {
vector<MessageID>
MessageDictionary::load(const char* messages[]) {
vector<MessageID> duplicates;
int i = 0;
while (messages[i]) {
......@@ -75,7 +76,7 @@ vector<MessageID> MessageDictionary::load(const char* messages[]) {
// Add ID and text to message dictionary, noting if the ID was
// already present.
bool added = add(ident, text);
if (! added) {
if (!added) {
duplicates.push_back(ident);
}
}
......@@ -85,7 +86,8 @@ vector<MessageID> MessageDictionary::load(const char* messages[]) {
// Return message text or blank string
string MessageDictionary::getText(const MessageID& ident) const {
string
MessageDictionary::getText(const MessageID& ident) const {
map<MessageID, string>::const_iterator i = dictionary_.find(ident);
if (i == dictionary_.end()) {
return string("");
......@@ -97,7 +99,8 @@ string MessageDictionary::getText(const MessageID& ident) const {
// Return global dictionary
MessageDictionary* MessageDictionary::globalDictionary() {
MessageDictionary*
MessageDictionary::globalDictionary() {
static MessageDictionary* global = NULL;
if (global == NULL) {
......
......@@ -59,7 +59,7 @@ MessageReader::readFile(const string& file, MessageReader::Mode mode) {
}
// Why did the loop terminate?
if (! infile.eof()) {
if (!infile.eof()) {
throw MessageException(MSG_READERR, file, strerror(errno));
}
infile.close();
......@@ -175,7 +175,7 @@ MessageReader::parseMessage(const std::string& text, MessageReader::Mode mode) {
else {
added = dictionary_->replace(ident, text.substr(first_text));
}
if (! added) {
if (!added) {
not_added_.push_back(ident);
}
}
......
......@@ -27,8 +27,9 @@ namespace strutil {
// Normalize slashes
void normalizeSlash(std::string& name) {
if (! name.empty()) {
void
normalizeSlash(std::string& name) {
if (!name.empty()) {
size_t pos = 0;
while ((pos = name.find('\\', pos)) != std::string::npos) {
name[pos] = '/';
......@@ -38,11 +39,12 @@ void normalizeSlash(std::string& name) {
// Trim String
string trim(const string& instring) {
string
trim(const string& instring) {
static const char* blanks = " \t\n";
string retstring = "";
if (! instring.empty()) {
if (!instring.empty()) {
// Search for first non-blank character in the string
size_t first = instring.find_first_not_of(blanks);
......
......@@ -56,8 +56,8 @@ std::string trim(const std::string& instring);
/// that adjacent delimiters are considered to be a single delimiter.
///
/// Special cases are:
/// 1) The empty string is considered to be zero tokens.
/// 2) A string comprising nothing but delimiters is considered to be zero
/// -# The empty string is considered to be zero tokens.
/// -# A string comprising nothing but delimiters is considered to be zero
/// tokens.
///
/// The reasoning behind this is that the string can be thought of as having
......@@ -79,9 +79,10 @@ std::vector<std::string> tokens(const std::string text,
/// \brief Uppercase Character
///
/// Needed to pass as an argument to transform() in uppercase(), as the
/// function std::toupper() takes an "int" as its argument and the template
/// expansion mechanism gets confused.
/// Used in uppercase() to pass as an argument to std::transform(). The
/// function std::toupper() can't be used as it takes an "int" as its argument;
/// this confuses the template expansion mechanism because defererencing a
/// string::iterator returns a char.
///
/// \param chr Character to be upper-cased.
///
......@@ -103,9 +104,10 @@ inline void uppercase(std::string& text) {
/// \brief Lowercase Character
///
/// Needed to pass as an argument to transform() in lowercase(), as the
/// function std::tolower() takes an "int" as its argument and the template
/// expansion mechanism gets confused.
/// Used in lowercase() to pass as an argument to std::transform(). The
/// function std::tolower() can't be used as it takes an "int" as its argument;
/// this confuses the template expansion mechanism because defererencing a
/// string::iterator returns a char.
///
/// \param chr Character to be lower-cased.
///
......
......@@ -35,7 +35,6 @@ logger_support_test_SOURCES = logger_support_test.cc
logger_support_test_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
logger_support_test_LDFLAGS = $(AM_LDFLAGS)
logger_support_test_LDADD = $(top_builddir)/src/lib/log/liblog.la
logger_support_test_LDADD += -llog4cxx
noinst_PROGRAMS = $(TESTS)
......
......@@ -131,10 +131,10 @@ TEST_F(LoggerTest, ConvertLevel) {
EXPECT_EQ(Logger::DEBUG, logger.convertLevel(log4cxx::Level::DEBUG_INT));
EXPECT_EQ(Logger::INFO, logger.convertLevel(log4cxx::Level::INFO_INT));
EXPECT_EQ(Logger::WARN, logger.convertLevel(log4cxx::Level::WARN_INT));
EXPECT_EQ(Logger::WARNING, logger.convertLevel(log4cxx::Level::WARN_INT));
EXPECT_EQ(Logger::WARN, logger.convertLevel(log4cxx::Level::WARN_INT));
EXPECT_EQ(Logger::ERROR, logger.convertLevel(log4cxx::Level::ERROR_INT));
EXPECT_EQ(Logger::FATAL, logger.convertLevel(log4cxx::Level::FATAL_INT));
EXPECT_EQ(Logger::CRITICAL, logger.convertLevel(log4cxx::Level::FATAL_INT));
EXPECT_EQ(Logger::FATAL, logger.convertLevel(log4cxx::Level::FATAL_INT));
EXPECT_EQ(Logger::NONE, logger.convertLevel(log4cxx::Level::OFF_INT));
// Now some debug levels
......@@ -158,14 +158,14 @@ TEST_F(LoggerTest, Severity) {
logger.setSeverity(Logger::NONE);
EXPECT_EQ(Logger::NONE, logger.getSeverity());
logger.setSeverity(Logger::CRITICAL);
EXPECT_EQ(Logger::CRITICAL, logger.getSeverity());