Skip to content
GitLab
Commit b8b931c5 authored by Shawn Routhier's avatar Shawn Routhier
Browse files

[4480] Add debug logging for evaluation of classification expressions 

This patch adds a set of log messages to indicate what values are
being popped from or pushed to the classification value stack.  This
is meant to be used by an administrator when debugging the expression
statements.
parent 7258f494
Expand all Hide whitespace changes
Inline Side-by-side
ChangeLog
View file @ b8b931c5
11XX. [func] sar
Add debug logging to the classification tokens.
(Trac #4480, git TBD)
1114. [bug] stephen
Adjusted variable type in a MySQL-related file to overcome a
type mismatch problem reported by one particular compiler.
......
doc/guide/classify.xml
View file @ b8b931c5
......@@ -625,4 +625,62 @@
</para>
</section>
<section>
<title>Debugging Expressions</title>
<para>
While you are constructing your classification expressions you may
find it useful to enable logging see <xref linkend="logging"/> for
a more complete description of the logging facility.
</para>
<para>
To enable the debug statements in the classifciaton system you will
need to set the severity to "DEBUG" and the debug level to at least 55.
The specific loggers are "kea-dhcp4.eval" and "kea-dhcp6.eval".
</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
off of the value stack and any objects that were pushed onto the value
stack.
</para>
<para>
The values will be displayed as either text if the command is known
to use text values or hex if the command either uses binary values or
can manipulate either text or binary values. For expressions that
pop multiple values off the stack the values will be displayed in
the order they were popped. For most expressions this won't matter
but for the concat expression the values are displayed in reverse
order from how they are written in the expression.
</para>
<para>
Let us assume that the following test has been entered into the configuration.
This example skips most of the configuration to concentrate on the test.
<screen>
"test": "substring(option[61].hex,0,3) == 'foo'",
</screen>
The logging might then resemble this:
<screen>
2016-05-19 13:35:04.163 DEBUG [kea.eval/44478] EVAL_DEBUG_OPTION Pushing option 61 with value 0x666F6F626172
2016-05-19 13:35:04.164 DEBUG [kea.eval/44478] EVAL_DEBUG_STRING Pushing text string "0"
2016-05-19 13:35:04.165 DEBUG [kea.eval/44478] EVAL_DEBUG_STRING Pushing text string "3"
2016-05-19 13:35:04.166 DEBUG [kea.eval/44478] EVAL_DEBUG_SUBSTRING Popping length 3, start 0,
string 0x666F6F626172 pushing result 0x666F6F
2016-05-19 13:35:04.167 DEBUG [kea.eval/44478] EVAL_DEBUG_STRING Pushing text string "foo"
2016-05-19 13:35:04.168 DEBUG [kea.eval/44478] EVAL_DEBUG_EQUAL Popping 0x666F6F and 0x666F6F pushing result "true"
</screen>
</para>
<note><para>
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.
</para></note>
</section>
</chapter>
src/lib/eval/eval_log.h
View file @ b8b931c5
// Copyright (C) 2015 Internet Systems Consortium, Inc. ("ISC")
// Copyright (C) 2015-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
......@@ -21,11 +21,11 @@ namespace dhcp {
// The first level traces normal operations,
const int EVAL_DBG_TRACE = DBGLVL_TRACE_BASIC;
// The next level traces each call to hook code.
// The next level traces each call to eval code.
const int EVAL_DBG_CALLS = DBGLVL_TRACE_BASIC_DATA;
// Additional information on the calls. Report each call to a callout (even
// if there are multiple callouts on a hook) and each status return.
// 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;
/// @brief Eval Logger
......
src/lib/eval/eval_messages.mes
View file @ b8b931c5
# Copyright (C) 2015 Internet Systems Consortium, Inc. ("ISC")
# Copyright (C) 2015-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
......@@ -6,6 +6,107 @@
$NAMESPACE isc::dhcp
# For use with TokenAnd
% EVAL_DEBUG_AND Popping %1 and %2 pushing %3
This debug message indicates that two values are popped from
the value stack. Then are then combined via logical and and
the result is pushed onto the value stack.
# For use with TokenConcat
% EVAL_DEBUG_CONCAT Popping %1 and %2 pushing %3
This debug message indicates that the two strings are being popped off
of the stack. They are then concatenated and the resulting string is
pushed onto the stack. The strings are displayed in hex.
# For use with TokenEqual
# Start with binary for the inputs for now, we may add text in the future.
% EVAL_DEBUG_EQUAL Popping %1 and %2 pushing result %3
This debug message indicates that the two strings are being popped off
of the value stack and the result of comparing them is being pushed onto
the value stack. The strings are displayed in hex.
# For use with TokenHexString
% EVAL_DEBUG_HEXSTRING Pushing hex string %1
This debug message indicates that the given binary string is being pushed
onto the value stack. The string is displayed in hex.
# For use with TokenIpAddress
% EVAL_DEBUG_IPADDRESS Pushing IPAddress %1
This debug message indicates that the given binary string is being pushed
onto the value stack. This represents either an IPv4 or IPv6 address.
The string is displayed in hex.
# For use with TokenNot
% EVAL_DEBUG_NOT Popping %1 pushing %2
This debug message indicates that the first value is popped from
the value stack, negated and then pushed onto the value stack.
The string is displayed in text.
# For use with TokenOption based classes. These include TokenOpton,
# TokenRelay4Option and TokenRelay6Option.
% EVAL_DEBUG_OPTION Pushing option %1 with value %2
This debug message indicates that the given string representing the
value of the requested option is being pushed onto the value stack.
The string may be the text or binary value of the string based on the
representation type requested (.text or .hex) or "true" or "false" if
the requested type is .exists. The option code may be for either an
option or a sub-option as requested in the classification statement.
# For use with TokenOr
% EVAL_DEBUG_OR Popping %1 and %2 pushing %3
This debug message indicates that two values are popped from
the value stack. Then are then combined via logical or and
the result is pushed onto the value stack. The string is displayed
in text.
# For use with TokenPkt4
% EVAL_DEBUG_PKT4 Pushing PKT4 field %1 with value %2
This debug message indicates that the given binary string representing
the value of the requested fied is being pushed onto the value stack.
The string is displayed in hex.
# For use with TokenPkt6
% EVAL_DEBUG_PKT6 Pushing PKT6 field %1 with value %2
This debug message indicates that the given binary string representing
the value of the requested fied is being pushed onto the value stack.
The string is displayed in hex.
# For use with TokenRelay6Field
% EVAL_DEBUG_RELAY6 Pushing PKT6 relay field %1 nest %2 with value %3
This debug message indicates that the given binary string representing
the value of the requested fied is being pushed onto the value stack.
The string is displayed in hex.
% EVAL_DEBUG_RELAY6_RANGE Pushing PKT6 relay field %1 nest %2 with value %3
This debug message is generated if the nest field is out of range. The
empty string will always be the value pushed onto the stack.
# For use with TokenString
% EVAL_DEBUG_STRING Pushing text string %1
This debug message indicates that the given text string is being pushed
onto the value stack. The string is displayed in text.
# For use with TokenSubstring
# Start with binary for the strings for now, we may add text in the future.
% EVAL_DEBUG_SUBSTRING Popping length %1, start %2, string %3 pushing result %4
This debug message indicates that three values are being popped from
the value stack and a result is being pushed onto the value stack. The
values being popped are the starting point and length of a substring to
extract from the given string. The resulting string is pushed onto
the stack. The strings are displayed in hex.
% EVAL_DEBUG_SUBSTRING_EMPTY Popping length %1, start %2, string %3 pushing result %4
This debug message indicates that the string popped from the stack was empty
and so the result will also be empty. The start, length and string are
still popped from the stack and the result is still pushed.
% EVAL_DEBUG_SUBSTRING_RANGE Popping length %1, start %2, string %3 pushing result %4
This debug message indicates that the value of start is outside of the
string and an empty result will be pushed onto the stack. The start,
length and string are still popped from the stack and the result is
still pushed. The strings are displayed in hex.
% EVAL_RESULT Expression %1 evaluated to %2
This debug message indicates that the expression has been evaluated
to said value. This message is mostly useful during debugging of the
......
src/lib/eval/tests/token_unittest.cc
View file @ b8b931c5
This diff is collapsed.
src/lib/eval/token.cc
View file @ b8b931c5
......@@ -21,6 +21,10 @@ void
TokenString::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
// Literals only push, nothing to pop
values.push(value_);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_STRING)
.arg('"' + value_ + '"');
}
TokenHexString::TokenHexString(const string& str) : value_("") {
......@@ -55,6 +59,11 @@ void
TokenHexString::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
// Literals only push, nothing to pop
values.push(value_);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_HEXSTRING)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value_.begin(),
value_.end())));
}
TokenIpAddress::TokenIpAddress(const string& addr) : value_("") {
......@@ -76,6 +85,11 @@ void
TokenIpAddress::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
// Literals only push, nothing to pop
values.push(value_);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_IPADDRESS)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value_.begin(),
value_.end())));
}
OptionPtr
......@@ -106,6 +120,20 @@ TokenOption::evaluate(const Pkt& pkt, ValueStack& values) {
// Push value of the option or empty string if there was no such option
// in the packet.
values.push(opt_str);
// Log what we pushed, both exists and textual are simple text
// 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)
.arg(option_code_)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(opt_str.begin(),
opt_str.end())));
} else {
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_OPTION)
.arg(option_code_)
.arg('"' + opt_str + '"');
}
}
TokenRelay4Option::TokenRelay4Option(const uint16_t option_code,
......@@ -129,6 +157,7 @@ void
TokenPkt4::evaluate(const Pkt& pkt, ValueStack& values) {
vector<uint8_t> binary;
string type_str;
try {
// Check if it's a Pkt4. If it's not, the dynamic_cast will throw
// std::bad_cast (failed dynamic_cast returns NULL for pointers and
......@@ -145,22 +174,27 @@ TokenPkt4::evaluate(const Pkt& pkt, ValueStack& values) {
"Packet does not have hardware address");
}
binary = hwaddr->hwaddr_;
type_str = "mac";
break;
}
case GIADDR:
binary = pkt4.getGiaddr().toBytes();
type_str = "giaddr";
break;
case CIADDR:
binary = pkt4.getCiaddr().toBytes();
type_str = "ciaddr";
break;
case YIADDR:
binary = pkt4.getYiaddr().toBytes();
type_str = "yiaddr";
break;
case SIADDR:
binary = pkt4.getSiaddr().toBytes();
type_str = "siaddr";
break;
case HLEN:
......@@ -169,6 +203,7 @@ TokenPkt4::evaluate(const Pkt& pkt, ValueStack& values) {
binary.push_back(0);
binary.push_back(0);
binary.push_back(pkt4.getHlen());
type_str = "hlen";
break;
case HTYPE:
......@@ -177,6 +212,7 @@ TokenPkt4::evaluate(const Pkt& pkt, ValueStack& values) {
binary.push_back(0);
binary.push_back(0);
binary.push_back(pkt4.getHtype());
type_str = "htype";
break;
default:
......@@ -194,6 +230,12 @@ TokenPkt4::evaluate(const Pkt& pkt, ValueStack& values) {
memmove(&value[0], &binary[0], binary.size());
}
values.push(value);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_PKT4)
.arg(type_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
value.end())));
}
void
......@@ -209,10 +251,21 @@ TokenEqual::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
string op2 = values.top();
values.pop(); // Dammit, std::stack interface is awkward.
string result;
if (op1 == op2)
values.push("true");
result = "true";
else
values.push("false");
result = "false";
values.push(result);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, 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 + '"');
}
void
......@@ -233,6 +286,13 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
// If we have no string to start with we push an empty string and leave
if (string_str.empty()) {
values.push("");
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_SUBSTRING_EMPTY)
.arg(len_str)
.arg(start_str)
.arg("0x")
.arg("0x");
return;
}
......@@ -266,6 +326,14 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
// empty string and leave
if ((start_pos < -string_length) || (start_pos >= string_length)) {
values.push("");
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_SUBSTRING_RANGE)
.arg(len_str)
.arg(start_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(string_str.begin(),
string_str.end())))
.arg("0x");
return;
}
......@@ -286,8 +354,19 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
}
}
// and finally get the substring
values.push(string_str.substr(start_pos, length));
string result = string_str.substr(start_pos, length);
values.push(result);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, 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())));
}
void
......@@ -304,7 +383,17 @@ 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
values.push(op2 + op1);
string result = op2 + op1;
values.push(result);
// Log what we popped and pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, 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())));
}
void
......@@ -318,11 +407,18 @@ TokenNot::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop();
bool val = toBool(op);
string result;
if (!val) {
values.push("true");
result = "true";
} else {
values.push("false");
result = "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 + '"');
}
void
......@@ -340,11 +436,19 @@ TokenAnd::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop(); // Dammit, std::stack interface is awkward.
bool val2 = toBool(op2);
string result;
if (val1 && val2) {
values.push("true");
result = "true";
} else {
values.push("false");
result = "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 + "\"");
}
void
......@@ -362,11 +466,19 @@ TokenOr::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
values.pop(); // Dammit, std::stack interface is awkward.
bool val2 = toBool(op2);
string result;
if (val1 || val2) {
values.push("true");
result = "true";
} else {
values.push("false");
result = "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 + '"');
}
OptionPtr TokenRelay6Option::getOption(const Pkt& pkt) {
......@@ -399,6 +511,7 @@ void
TokenRelay6Field::evaluate(const Pkt& pkt, ValueStack& values) {
vector<uint8_t> binary;
string type_str;
try {
// Check if it's a Pkt6. If it's not the dynamic_cast will
// throw std::bad_cast.
......@@ -409,9 +522,11 @@ TokenRelay6Field::evaluate(const Pkt& pkt, ValueStack& values) {
// Now that we have the right type of packet we can
// get the option and return it.
case LINKADDR:
type_str = "linkaddr";
binary = pkt6.getRelay6LinkAddress(nest_level_).toBytes();
break;
case PEERADDR:
type_str = "peeraddr";
binary = pkt6.getRelay6PeerAddress(nest_level_).toBytes();
break;
}
......@@ -419,6 +534,11 @@ TokenRelay6Field::evaluate(const Pkt& pkt, ValueStack& values) {
// The only exception we expect is OutOfRange if the nest
// 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)
.arg(type_str)
.arg(unsigned(nest_level_))
.arg("0x");
return;
}
} catch (const std::bad_cast&) {
......@@ -431,12 +551,20 @@ TokenRelay6Field::evaluate(const Pkt& pkt, ValueStack& values) {
memmove(&value[0], &binary[0], binary.size());
}
values.push(value);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_RELAY6)
.arg(type_str)
.arg(unsigned(nest_level_))
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
value.end())));
}
void
TokenPkt6::evaluate(const Pkt& pkt, ValueStack& values) {
vector<uint8_t> binary;
string type_str;
try {
// Check if it's a Pkt6. If it's not the dynamic_cast will throw
// std::bad_cast (failed dynamic_cast returns NULL for pointers and
......@@ -450,6 +578,7 @@ TokenPkt6::evaluate(const Pkt& pkt, ValueStack& values) {
binary.push_back(0);
binary.push_back(0);
binary.push_back(pkt6.getType());
type_str = "msgtype";
break;
}
case TRANSID: {
......@@ -459,6 +588,7 @@ TokenPkt6::evaluate(const Pkt& pkt, ValueStack& values) {
binary.push_back((transid >> 16) & 0xFF);
binary.push_back((transid >> 8) & 0xFF);
binary.push_back(transid & 0xFF);
type_str = "transid";
break;
}
default:
......@@ -474,4 +604,10 @@ TokenPkt6::evaluate(const Pkt& pkt, ValueStack& values) {
value.resize(binary.size());
memmove(&value[0], &binary[0], binary.size());
values.push(value);
// Log what we pushed
LOG_DEBUG(eval_logger, EVAL_DBG_EXTENDED_CALLS, EVAL_DEBUG_PKT6)
.arg(type_str)
.arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
value.end())));
}
src/lib/eval/token.h
View file @ b8b931c5
......@@ -650,7 +650,7 @@ public:
/// @brief enum value that determines the field.
enum FieldType {
MSGTYPE, ///< msg type
TRANSID ///< transaction id (integer but manipulated as as string)
TRANSID ///< transaction id (integer but manipulated as a string)
};
/// @brief Constructor (does nothing)
......
Supports Markdown
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