Commit cf62ec17 authored by Shawn Routhier's avatar Shawn Routhier
Browse files

[trac4480] Update per review comments

Create a LogContentTest class and move the functions to manipulate
a test to check on the log output there.  This will make it available
for other tests in the future.  As part of this bundle a bit more
work into the class to minimze the calls in the test routines.

Where reasonable remove extra copys of the values being pushed
onto the stack - instead of generating a copy just for the logging
simply use the value from the top of the stack directly.

Swtich to using single quotes around text values.

Added some more description in the classify document
parent b8b931c5
11XX. [func] sar
Add debug logging to the classification tokens.
Add debug logging to the classification tokens. This uses
the loggers "kea-dhcp4.eval" and "kea-dhcp6.eval" to capture
details of the classification expression evaluations.
(Trac #4480, git TBD)
1114. [bug] stephen
......
......@@ -639,6 +639,36 @@
The specific loggers are "kea-dhcp4.eval" and "kea-dhcp6.eval".
</para>
<para>
In order to understand the logging statements one must understand a
bit about how expressions are evaluated, for a more complete description
refer to the design document at <ulink url="http://kea.isc.org/wiki/KeaDesigns"/>.
In brief there are two structures used during the evaluation of an expression
a list of tokens which represent the expressions and a value stack which
represents the values being manipulated.
</para>
<para>
The list of tokens is created when the configuration file is processed with
most expressions and values being converted to a token. The list is organized
in reverse polish notation. During execution the list will be traversed
in order. As each token is executed it will be able to pop values
from the top of the stack and eventually push its result on the top of the
stack. Imagine the following expression:
<screen>
"test": "substring(option[61].hex,0,3) == 'foo'",
</screen>
This will result in the following tokens:
<screen>
option, number (0), number (3), substring, text ('foo'), equals
</screen>
In this example the first three tokens will simply push values onto the
stack. The substring token will then remove those three values and
compute a result that it places on the stack. The text option also
places a value on the stack and finally the equals token removes the
two tokens on the stack and places its result on the stack.
</para>
<para>
When debug logging is enabled each time a token is evaluated it will
emit a log line indicating the values of any objects that were popped
......@@ -678,8 +708,12 @@
The debug logging may be quite verbose if you have a number of expressions
to evaluate. It is intended as an aide in helping you create and debug
your expressions. You should plan to disable debug logging when you have your
expressions working correctly. You also may wish to debug only one set of
expressions at a time to limit the log statements.
expressions working correctly. You also may wish to include only one set of
expressions at a time in the configuration file while debugging them in order
to limit the log statements. For example when adding a new set of expressions
you might find it more convenient to create a configuration file that only
includes the new expressions until you have them working correctly and then
add the new set to the main configuration file.
</para></note>
</section>
......
......@@ -21,12 +21,9 @@ namespace dhcp {
// The first level traces normal operations,
const int EVAL_DBG_TRACE = DBGLVL_TRACE_BASIC;
// The next level traces each call to eval code.
const int EVAL_DBG_CALLS = DBGLVL_TRACE_BASIC_DATA;
// Additional information on the calls. Report the values that were
// popped from or pushed to the value stack.
const int EVAL_DBG_EXTENDED_CALLS = DBGLVL_TRACE_DETAIL_DATA;
const int EVAL_DBG_STACK = DBGLVL_TRACE_DETAIL_DATA;
/// @brief Eval Logger
///
......
......@@ -43,6 +43,7 @@ libeval_unittests_LDADD += $(top_builddir)/src/lib/log/libkea-log.la
libeval_unittests_LDADD += $(top_builddir)/src/lib/util/threads/libkea-threads.la
libeval_unittests_LDADD += $(top_builddir)/src/lib/util/libkea-util.la
libeval_unittests_LDADD += $(top_builddir)/src/lib/exceptions/libkea-exceptions.la
libeval_unittests_LDADD += $(top_builddir)/src/lib/testutils/libkea-testutils.la
libeval_unittests_LDADD += $(CRYPTO_LIBS) $(LOG4CPLUS_LIBS)
libeval_unittests_LDADD += $(BOOST_LIBS) $(GTEST_LDADD)
......
This diff is collapsed.
......@@ -23,8 +23,8 @@ TokenString::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.push(value_);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_STRING)
.arg('"' + value_ + '"');
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_STRING)
.arg('\'' + value_ + '\'');
}
TokenHexString::TokenHexString(const string& str) : value_("") {
......@@ -61,7 +61,7 @@ TokenHexString::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.push(value_);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_HEXSTRING)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_HEXSTRING)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value_.begin(),
value_.end())));
}
......@@ -87,7 +87,7 @@ TokenIpAddress::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.push(value_);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_IPADDRESS)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_IPADDRESS)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value_.begin(),
value_.end())));
}
......@@ -125,14 +125,14 @@ TokenOption::evaluate(const Pkt& pkt, ValueStack& values) {
// and can be output directly. We also include the code number
// of the requested option.
if (representation_type_ == HEXADECIMAL) {
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_OPTION)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_OPTION)
.arg(option_code_)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(opt_str.begin(),
opt_str.end())));
opt_str.end())));
} else {
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_OPTION)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_OPTION)
.arg(option_code_)
.arg('"' + opt_str + '"');
.arg('\'' + opt_str + '\'');
}
}
......@@ -232,10 +232,10 @@ TokenPkt4::evaluate(const Pkt& pkt, ValueStack& values) {
values.push(value);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_PKT4)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_PKT4)
.arg(type_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
value.end())));
value.end())));
}
void
......@@ -251,21 +251,18 @@ TokenEqual::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
string op2 = values.top();
values.pop(); // Dammit, std::stack interface is awkward.
string result;
if (op1 == op2)
result = "true";
values.push("true");
else
result = "false";
values.push(result);
values.push("false");
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_EQUAL)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_EQUAL)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(op1.begin(),
op1.end())))
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(op2.begin(),
op2.end())))
.arg('"' + result + '"');
.arg('\'' + values.top() + '\'');
}
void
......@@ -288,7 +285,7 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.push("");
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_SUBSTRING_EMPTY)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_SUBSTRING_EMPTY)
.arg(len_str)
.arg(start_str)
.arg("0x")
......@@ -328,7 +325,7 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.push("");
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_SUBSTRING_RANGE)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_SUBSTRING_RANGE)
.arg(len_str)
.arg(start_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(string_str.begin(),
......@@ -354,19 +351,17 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
}
}
// and finally get the substring
string result = string_str.substr(start_pos, length);
values.push(result);
values.push(string_str.substr(start_pos, length));
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_SUBSTRING)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_SUBSTRING)
.arg(len_str)
.arg(start_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(string_str.begin(),
string_str.end())))
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(result.begin(),
result.end())));
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(values.top().begin(),
values.top().end())));
}
void
......@@ -383,17 +378,16 @@ TokenConcat::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop(); // Dammit, std::stack interface is awkward.
// The top of the stack was evaluated last so this is the right order
string result = op2 + op1;
values.push(result);
values.push(op2 + op1);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_CONCAT)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_CONCAT)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(op1.begin(),
op1.end())))
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(op2.begin(),
op2.end())))
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(result.begin(),
result.end())));
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(values.top().begin(),
values.top().end())));
}
void
......@@ -407,18 +401,16 @@ TokenNot::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop();
bool val = toBool(op);
string result;
if (!val) {
result = "true";
values.push("true");
} else {
result = "false";
values.push("false");
}
values.push(result);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_NOT)
.arg('"' + op + '"')
.arg('"' + result + '"');
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_NOT)
.arg('\'' + op + '\'')
.arg('\'' + values.top() + '\'');
}
void
......@@ -436,19 +428,17 @@ TokenAnd::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop(); // Dammit, std::stack interface is awkward.
bool val2 = toBool(op2);
string result;
if (val1 && val2) {
result = "true";
values.push("true");
} else {
result = "false";
values.push("false");
}
values.push(result);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_AND)
.arg('"' + op1 + '"')
.arg("\"" + op2 + "\"")
.arg("\"" + result + "\"");
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_AND)
.arg('\'' + op1 + '\'')
.arg('\'' + op2 + '\'')
.arg('\'' + values.top() + '\'');
}
void
......@@ -466,19 +456,17 @@ TokenOr::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop(); // Dammit, std::stack interface is awkward.
bool val2 = toBool(op2);
string result;
if (val1 || val2) {
result = "true";
values.push("true");
} else {
result = "false";
values.push("false");
}
values.push(result);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_OR)
.arg('"' + op1 + '"')
.arg('"' + op2 + '"')
.arg('"' + result + '"');
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_OR)
.arg('\'' + op1 + '\'')
.arg('\'' + op2 + '\'')
.arg('\'' + values.top() + '\'');
}
OptionPtr TokenRelay6Option::getOption(const Pkt& pkt) {
......@@ -535,7 +523,7 @@ TokenRelay6Field::evaluate(const Pkt& pkt, ValueStack& values) {
// level is invalid. We push "" in that case.
values.push("");
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_RELAY6_RANGE)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_RELAY6_RANGE)
.arg(type_str)
.arg(unsigned(nest_level_))
.arg("0x");
......@@ -553,7 +541,7 @@ TokenRelay6Field::evaluate(const Pkt& pkt, ValueStack& values) {
values.push(value);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_RELAY6)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_RELAY6)
.arg(type_str)
.arg(unsigned(nest_level_))
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
......@@ -606,7 +594,7 @@ TokenPkt6::evaluate(const Pkt& pkt, ValueStack& values) {
values.push(value);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_PKT6)
LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_PKT6)
.arg(type_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
value.end())));
......
......@@ -568,7 +568,7 @@ protected:
uint8_t nest_level_; ///< nesting level of the relay block to use
};
/// @breif Token that represents a value of a field within a DHCPv6 relay
/// @brief Token that represents a value of a field within a DHCPv6 relay
/// encapsulation
///
/// This represents a reference to a field with a given DHCPv6 relay encapsulation.
......
......@@ -8,6 +8,7 @@ if HAVE_GTEST
noinst_LTLIBRARIES = libkea-testutils.la
libkea_testutils_la_SOURCES = io_utils.cc io_utils.h
libkea_testutils_la_SOURCES += log_utils.cc log_utils.h
libkea_testutils_la_SOURCES += unix_control_client.h unix_control_client.cc
libkea_testutils_la_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
libkea_testutils_la_LIBADD = $(top_builddir)/src/lib/asiolink/libkea-asiolink.la
......
// Copyright (C) 2016 Internet Systems Consortium, Inc. ("ISC")
//
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, You can obtain one at http://mozilla.org/MPL/2.0/.
#include <testutils/log_utils.h>
namespace isc {
namespace dhcp {
namespace test {
LogContentTest::LogContentTest() {
// Get rid of any old files
remFile();
// Set up the logger for use in checking the debug statements.
// We send the debug statements to a file which we can
// check after the evaluations have completed. We also
// set the log severity and debug levels so that the log
// statements are executed.
LoggerSpecification spec(getRootLoggerName(),
keaLoggerSeverity(isc::log::DEBUG),
keaLoggerDbglevel(isc::log::MAX_DEBUG_LEVEL));
OutputOption option;
option.destination = OutputOption::DEST_FILE;
option.filename = string(LogContentTest::LOG_FILE);
spec.addOutputOption(option);
LoggerManager manager;
manager.process(spec);
}
LogContentTest:: ~LogContentTest() {
remFile();
}
bool LogContentTest::checkFile() {
ifstream file(LOG_FILE);
EXPECT_TRUE(file.is_open());
string line, exp_line;
int i = 0;
bool found = true;
while (getline(file, line) && (i != exp_strings_.size())) {
exp_line = exp_strings_[i];
i++;
if (string::npos == line.find(exp_line)) {
found = false;
}
}
file.close();
if ((i != exp_strings_.size()) || (found == false))
return (false);
return (true);
}
void LogContentTest::remFile() {
static_cast<void>(remove(LOG_FILE));
}
void LogContentTest::addString(const string& new_string) {
exp_strings_.push_back(new_string);
}
// Set up the name of the LOG_FILE for use in checking
// the debug statements
const char *LogContentTest::LOG_FILE = "test.log";
}; // end of isc::dhcp::test namespace
}; // end of isc::dhcp namespace
}; // end of isc namespace
// Copyright (C) 2016 Internet Systems Consortium, Inc. ("ISC")
//
// This Source Code Form is subject to the terms of the Mozilla Public
// License, v. 2.0. If a copy of the MPL was not distributed with this
// file, You can obtain one at http://mozilla.org/MPL/2.0/.
#ifndef TEST_LOG_UTILS_H
#define TEST_LOG_UTILS_H
#include <string>
#include <fstream>
//#include <config.h>
#include <log/logger_manager.h>
#include <log/logger_name.h>
#include <log/logger_support.h>
//#include <boost/shared_ptr.hpp>
//#include <boost/scoped_ptr.hpp>
#include <gtest/gtest.h>
using namespace std;
using namespace isc::log;
namespace isc {
namespace dhcp {
namespace test {
/// @brief Test class for testing things that emit log entries
///
/// This class provides a convenient method for testing out
/// things that emit log entries. The class sets up the logging
/// to log everything into a file and provides a routine to
/// check the expected strings vs the actual log entries.
/// The user needs to call the addString function for each of
/// the strings they expect in the output in the order they
/// will be emitted.
class LogContentTest : public ::testing::Test {
public:
/// @brief Initializes the logger setup for using
/// in checking log statements
///
/// @todo add support to adjust the severity and debug level
/// to allow for better control over the statements that
/// get logged.
LogContentTest();
virtual ~LogContentTest();
/// @brief check that the requested strings are in the
/// test log file in the requested order.
///
/// This routine expects that the caller has properly
/// set up the vector of expected strings by calling
/// addString() with the necessary strings.
///
/// @return true if all of the strings match
bool checkFile();
/// @brief remove the test log file
void remFile();
/// @brief Add a string to the vector of expected strings
///
/// @param new_string the string to add to the end of the vector
/// @return void
void addString(const string& new_string);
vector<string> exp_strings_;
static const char* LOG_FILE;
};
}; // end of isc::dhcp::test namespace
}; // end of isc::dhcp namespace
}; // end of isc namespace
#endif // TEST_LOG_UTILS_H
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment