Commit e5687a75 authored by Stephen Morris's avatar Stephen Morris
Browse files

[trac900] Merge branch 'master' into trac900

Conflicts:
	src/lib/log/README
	src/lib/log/logger_support.cc
	src/lib/log/messagedef.cc
	src/lib/log/messagedef.h
	src/lib/log/messagedef.mes
	src/lib/log/tests/logger_support_test.cc
	src/lib/log/tests/run_time_init_test.sh.in
parents 27a4c936 119678f7
231. [func]*
The logging interface changed slightly. We use
logger.foo(MESSAGE_ID).arg(bar); instead of logger.foo(MESSAGE_ID, bar);
internally. The message definitions use '%1,%2,...' instead of '%s,%d',
which allows us to cope better with mismatched placeholders and allows
reordering of them in case of translation.
(Trac901, git 4903410e45670b30d7283f5d69dc28c2069237d6)
230. [bug] naokikambe
Removed too repeated verbose messages in two cases of:
- when auth sends statistics data to stats
......
......@@ -8,12 +8,17 @@ AM_CPPFLAGS += -I$(top_srcdir)/src/lib/util -I$(top_builddir)/src/lib/util
AM_CXXFLAGS = $(B10_CXXFLAGS)
CLEANFILES = *.gcno *.gcda
CLEANFILES = *.gcno *.gcda asiodef.h asiodef.cc
# Define rule to build logging source files from message file
asiodef.h asiodef.cc: asiodef.msg
$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/lib/asiodns/asiodef.msg
BUILT_SOURCES = asiodef.h asiodef.cc
lib_LTLIBRARIES = libasiodns.la
libasiodns_la_SOURCES = dns_answer.h
libasiodns_la_SOURCES += asiodns.h
libasiodns_la_SOURCES += asiodef.cc asiodef.h
libasiodns_la_SOURCES += dns_lookup.h
libasiodns_la_SOURCES += dns_server.h
libasiodns_la_SOURCES += dns_service.cc dns_service.h
......@@ -21,6 +26,8 @@ libasiodns_la_SOURCES += tcp_server.cc tcp_server.h
libasiodns_la_SOURCES += udp_server.cc udp_server.h
libasiodns_la_SOURCES += io_fetch.cc io_fetch.h
nodist_libasiodns_la_SOURCES = asiodef.cc asiodef.h
EXTRA_DIST = asiodef.msg
# Note: the ordering matters: -Wno-... must follow -Wextra (defined in
......
// File created from asiodef.msg on Mon Feb 28 17:15:30 2011
#include <cstddef>
#include <log/message_types.h>
#include <log/message_initializer.h>
namespace isc {
namespace asiodns {
extern const isc::log::MessageID ASIODNS_FETCHCOMP = "FETCHCOMP";
extern const isc::log::MessageID ASIODNS_FETCHSTOP = "FETCHSTOP";
extern const isc::log::MessageID ASIODNS_OPENSOCK = "OPENSOCK";
extern const isc::log::MessageID ASIODNS_RECVSOCK = "RECVSOCK";
extern const isc::log::MessageID ASIODNS_RECVTMO = "RECVTMO";
extern const isc::log::MessageID ASIODNS_SENDSOCK = "SENDSOCK";
extern const isc::log::MessageID ASIODNS_UNKORIGIN = "UNKORIGIN";
extern const isc::log::MessageID ASIODNS_UNKRESULT = "UNKRESULT";
} // namespace asiodns
} // namespace isc
namespace {
const char* values[] = {
"FETCHCOMP", "upstream fetch to %s(%d) has now completed",
"FETCHSTOP", "upstream fetch to %s(%d) has been stopped",
"OPENSOCK", "error %d opening %s socket to %s(%d)",
"RECVSOCK", "error %d reading %s data from %s(%d)",
"RECVTMO", "receive timeout while waiting for data from %s(%d)",
"SENDSOCK", "error %d sending data using %s to %s(%d)",
"UNKORIGIN", "unknown origin for ASIO error code %d (protocol: %s, address %s)",
"UNKRESULT", "unknown result (%d) when IOFetch::stop() was executed for I/O to %s(%d)",
NULL
};
const isc::log::MessageInitializer initializer(values);
} // Anonymous namespace
// File created from asiodef.msg on Mon Feb 28 17:15:30 2011
#ifndef __ASIODEF_H
#define __ASIODEF_H
#include <log/message_types.h>
namespace isc {
namespace asiodns {
extern const isc::log::MessageID ASIODNS_FETCHCOMP;
extern const isc::log::MessageID ASIODNS_FETCHSTOP;
extern const isc::log::MessageID ASIODNS_OPENSOCK;
extern const isc::log::MessageID ASIODNS_RECVSOCK;
extern const isc::log::MessageID ASIODNS_RECVTMO;
extern const isc::log::MessageID ASIODNS_SENDSOCK;
extern const isc::log::MessageID ASIODNS_UNKORIGIN;
extern const isc::log::MessageID ASIODNS_UNKRESULT;
} // namespace asiodns
} // namespace isc
#endif // __ASIODEF_H
......@@ -15,42 +15,42 @@
$PREFIX ASIODNS_
$NAMESPACE isc::asiodns
FETCHCOMP upstream fetch to %s(%d) has now completed
FETCHCOMP upstream fetch to %1(%2) has now completed
+ A debug message, this records the the upstream fetch (a query made by the
+ resolver on behalf of its client) to the specified address has completed.
FETCHSTOP upstream fetch to %s(%d) has been stopped
FETCHSTOP upstream fetch to %1(%2) has been stopped
+ An external component has requested the halting of an upstream fetch. This
+ is an allowed operation, and the message should only appear if debug is
+ enabled.
OPENSOCK error %d opening %s socket to %s(%d)
OPENSOCK error %1 opening %2 socket to %3(%4)
+ The asynchronous I/O code encountered an error when trying to open a socket
+ of the specified protocol in order to send a message to the target address.
+ The the number of the system error that cause the problem is given in the
+ message.
RECVSOCK error %d reading %s data from %s(%d)
RECVSOCK error %1 reading %2 data from %3(%4)
+ The asynchronous I/O code encountered an error when trying read data from
+ the specified address on the given protocol. The the number of the system
+ error that cause the problem is given in the message.
SENDSOCK error %d sending data using %s to %s(%d)
SENDSOCK error %1 sending data using %2 to %3(%4)
+ The asynchronous I/O code encountered an error when trying send data to
+ the specified address on the given protocol. The the number of the system
+ error that cause the problem is given in the message.
RECVTMO receive timeout while waiting for data from %s(%d)
RECVTMO receive timeout while waiting for data from %1(%2)
+ An upstream fetch from the specified address timed out. This may happen for
+ any number of reasons and is most probably a problem at the remote server
+ or a problem on the network. The message will only appear if debug is
+ enabled.
UNKORIGIN unknown origin for ASIO error code %d (protocol: %s, address %s)
UNKORIGIN unknown origin for ASIO error code %1 (protocol: %2, address %3)
+ This message should not appear and indicates an internal error if it does.
+ Please enter a bug report.
UNKRESULT unknown result (%d) when IOFetch::stop() was executed for I/O to %s(%d)
UNKRESULT unknown result (%1) when IOFetch::stop() was executed for I/O to %2(%3)
+ The termination method of the resolver's upstream fetch class was called with
+ an unknown result code (which is given in the message). This message should
+ not appear and may indicate an internal error. Please enter a bug report.
......@@ -40,6 +40,7 @@
#include <dns/opcode.h>
#include <dns/rcode.h>
#include <log/logger.h>
#include <log/macros.h>
#include <asiodns/asiodef.h>
#include <asiodns/io_fetch.h>
......@@ -61,7 +62,17 @@ namespace asiodns {
/// Use the ASIO logger
namespace {
isc::log::Logger logger("asiolink");
// Log debug verbosity
enum {
DBG_IMPORTANT = 1,
DBG_COMMON = 20,
DBG_ALL = 50
};
}
/// \brief IOFetch Data
///
......@@ -331,42 +342,34 @@ IOFetch::stop(Result result) {
// numbers indicating the most important information. The relative
// values are somewhat arbitrary.
//
// Although Logger::debug checks the debug flag internally, doing it
// below before calling Logger::debug avoids the overhead of a string
// conversion in the common case when debug is not enabled.
//
// TODO: Update testing of stopped_ if threads are used.
data_->stopped = true;
switch (result) {
case TIME_OUT:
if (logger.isDebugEnabled(1)) {
logger.debug(20, ASIODNS_RECVTMO,
data_->remote_snd->getAddress().toText().c_str(),
static_cast<int>(data_->remote_snd->getPort()));
}
LOG_DEBUG(logger, DBG_COMMON, ASIODNS_RECVTMO).
arg(data_->remote_snd->getAddress().toText()).
arg(data_->remote_snd->getPort());
break;
case SUCCESS:
if (logger.isDebugEnabled(50)) {
logger.debug(30, ASIODNS_FETCHCOMP,
data_->remote_rcv->getAddress().toText().c_str(),
static_cast<int>(data_->remote_rcv->getPort()));
}
LOG_DEBUG(logger, DBG_ALL, ASIODNS_FETCHCOMP).
arg(data_->remote_rcv->getAddress().toText()).
arg(data_->remote_rcv->getPort());
break;
case STOPPED:
// Fetch has been stopped for some other reason. This is
// allowed but as it is unusual it is logged, but with a lower
// debug level than a timeout (which is totally normal).
logger.debug(1, ASIODNS_FETCHSTOP,
data_->remote_snd->getAddress().toText().c_str(),
static_cast<int>(data_->remote_snd->getPort()));
LOG_DEBUG(logger, DBG_IMPORTANT, ASIODNS_FETCHSTOP).
arg(data_->remote_snd->getAddress().toText()).
arg(data_->remote_snd->getPort());
break;
default:
logger.error(ASIODNS_UNKRESULT, static_cast<int>(result),
data_->remote_snd->getAddress().toText().c_str(),
static_cast<int>(data_->remote_snd->getPort()));
LOG_ERROR(logger, ASIODNS_UNKRESULT).
arg(data_->remote_snd->getAddress().toText()).
arg(data_->remote_snd->getPort());
}
// Stop requested, cancel and I/O's on the socket and shut it down,
......@@ -394,12 +397,11 @@ void IOFetch::logIOFailure(asio::error_code ec) {
(data_->origin == ASIODNS_UNKORIGIN));
static const char* PROTOCOL[2] = {"TCP", "UDP"};
logger.error(data_->origin,
ec.value(),
((data_->remote_snd->getProtocol() == IPPROTO_TCP) ?
PROTOCOL[0] : PROTOCOL[1]),
data_->remote_snd->getAddress().toText().c_str(),
static_cast<int>(data_->remote_snd->getPort()));
LOG_ERROR(logger, data_->origin).arg(ec.value()).
arg((data_->remote_snd->getProtocol() == IPPROTO_TCP) ?
PROTOCOL[0] : PROTOCOL[1]).
arg(data_->remote_snd->getAddress().toText()).
arg(data_->remote_snd->getPort());
}
} // namespace asiodns
......
......@@ -683,11 +683,12 @@ TEST_F(MessageTest, toWireWithoutRcode) {
TEST_F(MessageTest, toText) {
// Check toText() output for a typical DNS response with records in
// all sections
ifstream ifs;
unittests::openTestData("message_toText1.txt", ifs);
factoryFromFile(message_parse, "message_toText1.wire");
{
SCOPED_TRACE("Message toText test (basic case)");
ifstream ifs;
unittests::openTestData("message_toText1.txt", ifs);
unittests::matchTextData(ifs, message_parse.toText());
}
......@@ -695,12 +696,12 @@ TEST_F(MessageTest, toText) {
// from the dig output (other than replacing tabs with a space): adding
// a newline after the "OPT PSEUDOSECTION". This is an intentional change
// in our version for better readability.
ifs.close();
message_parse.clear(Message::PARSE);
unittests::openTestData("message_toText2.txt", ifs);
factoryFromFile(message_parse, "message_toText2.wire");
{
SCOPED_TRACE("Message toText test with EDNS");
ifstream ifs;
unittests::openTestData("message_toText2.txt", ifs);
unittests::matchTextData(ifs, message_parse.toText());
}
......@@ -708,12 +709,12 @@ TEST_F(MessageTest, toText) {
// from the dig output (other than replacing tabs with a space): removing
// a redundant white space at the end of TSIG RDATA. We'd rather consider
// it a dig's defect than a feature.
ifs.close();
message_parse.clear(Message::PARSE);
unittests::openTestData("message_toText3.txt", ifs);
factoryFromFile(message_parse, "message_toText3.wire");
{
SCOPED_TRACE("Message toText test with TSIG");
ifstream ifs;
unittests::openTestData("message_toText3.txt", ifs);
unittests::matchTextData(ifs, message_parse.toText());
}
}
......
......@@ -21,6 +21,8 @@ liblog_la_SOURCES += message_initializer.cc message_initializer.h
liblog_la_SOURCES += message_reader.cc message_reader.h
liblog_la_SOURCES += message_types.h
liblog_la_SOURCES += root_logger_name.cc root_logger_name.h
liblog_la_SOURCES += log_formatter.h log_formatter.cc
liblog_la_SOURCES += macros.h
EXTRA_DIST = README
EXTRA_DIST += messagedef.mes
......
......@@ -94,6 +94,7 @@ An example file could be:
$PREFIX TEST_
$NAMESPACE isc::log
% TEST1 message %1 is much too large
This message is a test for the general message code
......@@ -141,7 +142,6 @@ Points to note:
are intended to be processed by a separate program and used to generate
an error messages manual. They are ignored by the message compiler.
Message Compiler
----------------
The message compiler is a program built in the src/log/compiler directory.
......@@ -264,7 +264,7 @@ To use the current version of the logging:
4. Issue logging calls using methods on logger, e.g.
logger.error(DPS_NSTIMEOUT).arg("isc.org")
logger.error(DPS_NSTIMEOUT).arg("isc.org");
(where, in the example above we might have defined the symbol in the message
file with something along the lines of:
......
......@@ -527,9 +527,12 @@ main(int argc, char* argv[]) {
string text = e.id();
text += ", ";
text += global.getText(e.id());
// Format with arguments
text = isc::util::str::format(text, e.arguments());
vector<string> args(e.arguments());
for (size_t i(0); i < args.size(); ++ i) {
replacePlaceholder(&text, args[i], i + 1);
}
cerr << text << "\n";
return 1;
......
// 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/log_formatter.h>
using namespace std;
using namespace boost;
namespace isc {
namespace log {
void
replacePlaceholder(string* message, const string& arg,
const unsigned placeholder)
{
string mark("%" + lexical_cast<string>(placeholder));
size_t pos(message->find(mark));
if (pos != string::npos) {
do {
message->replace(pos, mark.size(), arg);
pos = message->find(mark, pos + arg.size());
} while (pos != string::npos);
} else {
// We're missing the placeholder, so add some complain
message->append(" @@Missing placeholder " + mark + " for '" + arg +
"'@@");
}
}
}
}
// 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.
#ifndef __LOG_FORMATTER_H
#define __LOG_FORMMATER_H
#include <string>
#include <boost/lexical_cast.hpp>
namespace isc {
namespace log {
/// \brief The internal replacement routine
///
/// This is used internally by the Formatter. Replaces a placeholder
/// in the message by replacement. If the placeholder is not found,
/// it adds a complain at the end.
void
replacePlaceholder(std::string* message, const std::string& replacement,
const unsigned placeholder);
///
/// \brief The log message formatter
///
/// This class allows us to format logging messages conveniently. We
/// call something like logger.warn(WARN_MSG).arg(15).arg(dnsMsg). This
/// outputs some text with placeholders replaced by the arguments, if
/// the logging verbosity is at WARN level or more.
///
/// To make this work, we use the Formatter. The warn (or whatever logging
/// function) returns a Formatter object. That one holds the string to be
/// output with the placeholders. It also remembers if there should be any
/// output at all (eg. if the logging is enabled for this level). When there's
/// no .arg call on the object, it is destroyed right away and we use the
/// destructor to output the text (but only in case we should output anything).
///
/// If there's an .arg call, we return reference to the same object, so another
/// .arg can be called on it. After the last .arg call is done, the object is
/// destroyed and, again, we can produce the output.
///
/// Of course, if the logging is turned off, we don't bother with any replacing
/// and just return.
///
/// User of logging code should not really care much about this class, only
/// call the .arg method to generate the correct output.
///
/// The class is a template to allow easy testing. Also, we want everything
/// here in the header anyway and it doesn't depend on the details of what
/// Logger really is, so it doesn't hurt anything.
///
/// Also, if you are interested in the internals, you might find the copy
/// constructor a bit strange. It deactivates the original formatter. We don't
/// really want to support copying of the Formatter by user, but C++ needs a
/// copy constructor when returning from the logging functions, so we need one.
/// And if we did not deactivate the original Formatter, that one would get
/// destroyed before any call to .arg, producing an output, and then the one
/// the .arg calls are called on would get destroyed as well, producing output
/// again. So, think of this behaviour as soul moving from one to another.
template<class Logger> class Formatter {
private:
/// \brief The logger we will use to output the final message.
///
/// 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 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
///
/// This will create a formatter. If the arguments are set, it
/// will be active (will produce output). If you leave them all as NULL,
/// it will create an inactive Formatter -- one that'll produce no output.
///
/// It is not expected to be called by user of logging system directly.
///
/// \param prefix The severity prefix, like "ERROR" or "DEBUG"
/// \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,
Logger* logger = NULL) :
logger_(logger), prefix_(prefix), message_(message),
nextPlaceholder_(1)
{
}
Formatter(const Formatter& other) :
logger_(other.logger_), prefix_(other.prefix_),
message_(other.message_), nextPlaceholder_(other.nextPlaceholder_)
{
other.logger_ = false;
}
/// \brief Destructor.
//
/// This is the place where output happens if the formatter is active.
~ Formatter() {
if (logger_) {
logger_->output(prefix_, *message_);
delete message_;
}
}
/// \brief Replaces another placeholder
///
/// Replaces another placeholder and returns a new formatter with it.
/// Deactivates the current formatter. In case the formatter is not active,
/// only produces another inactive formatter.
///
/// \param arg The argument to place into the placeholder.
template<class Arg> Formatter& arg(const Arg& value) {
return (arg(boost::lexical_cast<std::string>(value)));
}
/// \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_ ++);
}
return (*this);
}
};
}
}
#endif
......@@ -112,52 +112,57 @@ Logger::isFatalEnabled() {
// Output methods
void
Logger::debug(int dbglevel, const isc::log::MessageID& ident, ...) {
Logger::output(const char* sevText, const string& message) {
getLoggerPtr()->outputRaw(sevText, message);
}
Logger::Formatter
Logger::debug(int dbglevel, const isc::log::MessageID& ident) {
if (isDebugEnabled(dbglevel)) {
va_list ap;
va_start(ap, ident);
getLoggerPtr()->debug(ident, ap);
va_end(ap);
return (Formatter("DEBUG", getLoggerPtr()->lookupMessage(ident),
this));
} else {
return (Formatter());
}
}
void
Logger::info(const isc::log::MessageID& ident, ...) {
Logger::Formatter
Logger::info(const isc::log::MessageID& ident) {
if (isInfoEnabled()) {
va_list ap;
va_start(ap, ident);
getLoggerPtr()->info(ident, ap);
va_end(ap);
return (Formatter("INFO ", getLoggerPtr()->lookupMessage(ident),
this));
} else {
return (Formatter());
}
}
void
Logger::warn(const isc::log::MessageID& ident, ...) {
Logger::Formatter
Logger::warn(const isc::log::MessageID& ident) {
if (isWarnEnabled()) {
va_list ap;
va_start(ap, ident);
getLoggerPtr()->warn(ident, ap);
va_end(ap);
return (Formatter("WARN ", getLoggerPtr()->lookupMessage(ident),
this));
} else {
return (Formatter());
}
}
void
Logger::error(const isc::log::MessageID& ident, ...) {
Logger::Formatter
Logger::error(const isc::log::MessageID& ident) {
if (isErrorEnabled()) {
va_list ap;
va_start(ap, ident);
getLoggerPtr()->error(ident, ap);
va_end(ap);
return (Formatter("ERROR", getLoggerPtr()->lookupMessage(ident),
this));
} else {
return (Formatter());
}
}