[master] Merge branch 'trac4480'

Add debug statements to the classification code

ChangeLog

@@ -1,3 +1,9 @@
+1119.	[func]		sar
+	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)
+
 1118.	[func]		stephen
 	Make the database connection timeout a configurable parameter with
 	a default value of five seconds.

doc/guide/classify.xml

@@ -625,4 +625,96 @@
       </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>
+     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
+     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 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>
+
 </chapter>

src/lib/eval/eval_log.h

@@ -1,4 +1,4 @@
-// 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,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 hook 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.
-const int EVAL_DBG_EXTENDED_CALLS = DBGLVL_TRACE_DETAIL_DATA;
+// Additional information on the calls.  Report the values that were
+// popped from or pushed to the value stack.
+const int EVAL_DBG_STACK = DBGLVL_TRACE_DETAIL_DATA;
 
 /// @brief Eval Logger
 ///

src/lib/eval/eval_messages.mes

@@ -1,4 +1,4 @@
-# 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/Makefile.am

@@ -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)
 

src/lib/eval/tests/token_unittest.cc

@@ -5,12 +5,17 @@
 // file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 #include <config.h>
+#include <fstream>
 #include <eval/token.h>
 #include <dhcp/pkt4.h>
 #include <dhcp/pkt6.h>
 #include <dhcp/dhcp4.h>
 #include <dhcp/dhcp6.h>
 #include <dhcp/option_string.h>
+#include <log/logger_manager.h>
+#include <log/logger_name.h>
+#include <log/logger_support.h>
+#include <testutils/log_utils.h>
 
 #include <boost/shared_ptr.hpp>
 #include <boost/scoped_ptr.hpp>
@@ -21,6 +26,8 @@
 using namespace std;
 using namespace isc::dhcp;
 using namespace isc::asiolink;
+using namespace isc::log;
+using namespace isc::dhcp::test;
 
 namespace {
 
@@ -28,7 +35,8 @@ namespace {
 ///
 /// This class provides several convenience objects to be used during testing
 /// of the Token family of classes.
-class TokenTest : public ::testing::Test {
+
+class TokenTest : public LogContentTest {
 public:
 
     /// @brief Initializes Pkt4,Pkt6 and options that can be useful for
@@ -229,6 +237,7 @@ public:
     }
 
     /// @todo: Add more option types here
+
 };
 
 // This tests the toBool() conversions
@@ -262,6 +271,12 @@ TEST_F(TokenTest, string4) {
     // Check that the evaluation put its value on the values stack.
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("foo", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_STRING Pushing text string 'foo'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This simple test checks that a TokenString, representing a constant string,
@@ -277,6 +292,12 @@ TEST_F(TokenTest, string6) {
     // Check that the evaluation put its value on the values stack.
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("foo", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_STRING Pushing text string 'foo'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This simple test checks that a TokenHexString, representing a constant
@@ -306,7 +327,8 @@ TEST_F(TokenTest, hexstring4) {
     // Store constant hexstring "0x63825363" (DHCP_OPTIONS_COOKIE).
     ASSERT_NO_THROW(cookie.reset(new TokenHexString("0x63825363")));
 
-    // Make sure that tokens can be evaluated without exceptions.
+    // Make sure that tokens can be evaluated without exceptions,
+    // and verify the debug output
     ASSERT_NO_THROW(empty->evaluate(*pkt4_, values_));
     ASSERT_NO_THROW(bad->evaluate(*pkt4_, values_));
     ASSERT_NO_THROW(nodigit->evaluate(*pkt4_, values_));
@@ -332,6 +354,18 @@ TEST_F(TokenTest, hexstring4) {
     EXPECT_EQ("", values_.top());
     values_.pop();
     EXPECT_EQ("", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x07");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x666F6F");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x63825363");
+    EXPECT_TRUE(checkFile());
 }
 
 // This simple test checks that a TokenHexString, representing a constant
@@ -387,6 +421,18 @@ TEST_F(TokenTest, hexstring6) {
     EXPECT_EQ("", values_.top());
     values_.pop();
     EXPECT_EQ("", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x07");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x666F6F");
+    addString("EVAL_DEBUG_HEXSTRING Pushing hex string 0x63825363");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks that a TokenIpAddress, representing an IP address as
@@ -432,6 +478,16 @@ TEST_F(TokenTest, ipaddress) {
     uint8_t expected4[] = { 10, 0, 0, 1 };
     EXPECT_EQ(4, values_.top().size());
     EXPECT_EQ(0, memcmp(expected4, &values_.top()[0], 4));
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_IPADDRESS Pushing IPAddress 0x0A000001");
+    addString("EVAL_DEBUG_IPADDRESS Pushing IPAddress "
+              "0x20010DB8000000000000000000000001");
+    addString("EVAL_DEBUG_IPADDRESS Pushing IPAddress 0x");
+    addString("EVAL_DEBUG_IPADDRESS Pushing IPAddress 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an option value is able to extract
@@ -460,6 +516,13 @@ TEST_F(TokenTest, optionString4) {
 
     // Then the content of the option 100.
     EXPECT_EQ("hundred4", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'hundred4'");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value ''");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing option value is able to extract
@@ -489,6 +552,13 @@ TEST_F(TokenTest, optionHexString4) {
 
     // Then the content of the option 100.
     EXPECT_EQ("hundred4", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 0x68756E6472656434");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an option value is able to check
@@ -511,6 +581,13 @@ TEST_F(TokenTest, optionExistsString4) {
     EXPECT_EQ("false", values_.top());
     values_.pop();
     EXPECT_EQ("true", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'true'");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an option value is able to extract
@@ -539,6 +616,13 @@ TEST_F(TokenTest, optionString6) {
 
     // Then the content of the option 100.
     EXPECT_EQ("hundred6", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'hundred6'");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value ''");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an option value is able to extract
@@ -568,6 +652,13 @@ TEST_F(TokenTest, optionHexString6) {
 
     // Then the content of the option 100.
     EXPECT_EQ("hundred6", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 0x68756E6472656436");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an option value is able to check
@@ -590,6 +681,13 @@ TEST_F(TokenTest, optionExistsString6) {
     EXPECT_EQ("false", values_.top());
     values_.pop();
     EXPECT_EQ("true", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'true'");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks that the existing relay4 option can be found.
@@ -610,6 +708,12 @@ TEST_F(TokenTest, relay4Option) {
     // The option should be found and relay4[13] should evaluate to the
     // content of that sub-option, i.e. "thirteen"
     EXPECT_EQ("thirteen", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 13 with value 'thirteen'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks that the code properly handles cases when
@@ -631,6 +735,12 @@ TEST_F(TokenTest, relay4OptionNoSuboption) {
     // The option should NOT be found (there is no sub-option 15),
     // so the expression should evaluate to ""
     EXPECT_EQ("", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 15 with value ''");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks that the code properly handles cases when
@@ -651,6 +761,12 @@ TEST_F(TokenTest, relay4OptionNoRai) {
     // The option should NOT be found (there is no sub-option 13),
     // so the expression should evaluate to ""
     EXPECT_EQ("", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 13 with value ''");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks that only the RAI is searched for the requested
@@ -707,6 +823,16 @@ TEST_F(TokenTest, relay4RAIOnly) {
     EXPECT_NO_THROW(t_->evaluate(*pkt4_, values_));
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("false", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 13 with value 'thirteen'");
+    addString("EVAL_DEBUG_OPTION Pushing option 1 with value 'one'");
+    addString("EVAL_DEBUG_OPTION Pushing option 70 with value ''");
+    addString("EVAL_DEBUG_OPTION Pushing option 1 with value 'true'");
+    addString("EVAL_DEBUG_OPTION Pushing option 70 with value 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // Verifies if the DHCPv4 packet fields can be extracted.
@@ -787,6 +913,18 @@ TEST_F(TokenTest, pkt4Fields) {
     clearStack();
     ASSERT_NO_THROW(t_.reset(new TokenPkt4(TokenPkt4::HLEN)));
     EXPECT_THROW(t_->evaluate(*pkt6_, values_), EvalTypeError);
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field mac with value 0x01020304050607");
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field hlen with value 0x00000007");
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field htype with value 0x0000007B");
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field giaddr with value 0xC0000201");
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field ciaddr with value 0xC0000202");
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field yiaddr with value 0xC0000203");
+    addString("EVAL_DEBUG_PKT4 Pushing PKT4 field siaddr with value 0xC0000204");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an == operator is able to
@@ -818,6 +956,13 @@ TEST_F(TokenTest, optionEqualFalse) {
     // result of "foo" == "bar" comparision.
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("false", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_EQUAL Popping 0x626172 and 0x666F6F "
+              "pushing result 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an == operator is able to
@@ -834,6 +979,13 @@ TEST_F(TokenTest, optionEqualTrue) {
     // result of "foo" == "foo" comparision.
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("true", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_EQUAL Popping 0x666F6F and 0x666F6F "
+              "pushing result 'true'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing a not is able to
@@ -867,6 +1019,13 @@ TEST_F(TokenTest, operatorNot) {
     EXPECT_NO_THROW(t_->evaluate(*pkt4_, values_));
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("true", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_NOT Popping 'true' pushing 'false'");
+    addString("EVAL_DEBUG_NOT Popping 'false' pushing 'true'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an and is able to
@@ -907,7 +1066,7 @@ TEST_F(TokenTest, operatorAndFalse) {
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("false", values_.top());
 
-    // After true and false, checks false and true
+    // After true and false, check false and true
     values_.push("true");
     EXPECT_NO_THROW(t_->evaluate(*pkt4_, values_));
     ASSERT_EQ(1, values_.size());
@@ -918,6 +1077,14 @@ TEST_F(TokenTest, operatorAndFalse) {
     EXPECT_NO_THROW(t_->evaluate(*pkt4_, values_));
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("false", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_AND Popping 'false' and 'true' pushing 'false'");
+    addString("EVAL_DEBUG_AND Popping 'true' and 'false' pushing 'false'");
+    addString("EVAL_DEBUG_AND Popping 'false' and 'false' pushing 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an and is able to
@@ -933,6 +1100,12 @@ TEST_F(TokenTest, operatorAndTrue) {
     // After evaluation there should be a single "true" value
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("true", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_AND Popping 'true' and 'true' pushing 'true'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an or is able to
@@ -972,6 +1145,12 @@ TEST_F(TokenTest, operatorOrFalse) {
     // After evaluation there should be a single "false" value
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("false", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OR Popping 'false' and 'false' pushing 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing an == operator is able to
@@ -999,9 +1178,15 @@ TEST_F(TokenTest, operatorOrTrue) {
     EXPECT_NO_THROW(t_->evaluate(*pkt4_, values_));
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("true", values_.top());
-}
 
-};
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OR Popping 'true' and 'false' pushing 'true'");
+    addString("EVAL_DEBUG_OR Popping 'false' and 'true' pushing 'true'");
+    addString("EVAL_DEBUG_OR Popping 'true' and 'true' pushing 'true'");
+    EXPECT_TRUE(checkFile());
+}
 
 // This test checks if a token representing a substring request
 // throws an exception if there aren't enough values on the stack.
@@ -1028,6 +1213,13 @@ TEST_F(TokenTest, substringNotEnoughValues) {
     // one after the evaluate
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING_EMPTY Popping length 0, start 0, "
+              "string 0x pushing result 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // Test getting the whole string in different ways
@@ -1043,6 +1235,19 @@ TEST_F(TokenTest, substringWholeString) {
 
     // Get the whole string counting from the back
     verifySubstringEval("foobar", "-6", "all", "foobar");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING Popping length 6, start 0, "
+              "string 0x666F6F626172 pushing result 0x666F6F626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length all, start 0, "
+              "string 0x666F6F626172 pushing result 0x666F6F626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 123456, start 0, "
+              "string 0x666F6F626172 pushing result 0x666F6F626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length all, start -6, "
+              "string 0x666F6F626172 pushing result 0x666F6F626172");
+    EXPECT_TRUE(checkFile());
 }
 
 // Test getting a suffix, in this case the last 3 characters
@@ -1051,6 +1256,19 @@ TEST_F(TokenTest, substringTrailer) {
     verifySubstringEval("foobar", "3", "all", "bar");
     verifySubstringEval("foobar", "-3", "all", "bar");
     verifySubstringEval("foobar", "-3", "123", "bar");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING Popping length 3, start 3, "
+              "string 0x666F6F626172 pushing result 0x626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length all, start 3, "
+              "string 0x666F6F626172 pushing result 0x626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length all, start -3, "
+              "string 0x666F6F626172 pushing result 0x626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 123, start -3, "
+              "string 0x666F6F626172 pushing result 0x626172");
+    EXPECT_TRUE(checkFile());
 }
 
 // Test getting the middle of the string in different ways
@@ -1059,6 +1277,19 @@ TEST_F(TokenTest, substringMiddle) {
     verifySubstringEval("foobar", "-5", "4", "ooba");
     verifySubstringEval("foobar", "-1", "-4", "ooba");
     verifySubstringEval("foobar", "5", "-4", "ooba");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start 1, "
+              "string 0x666F6F626172 pushing result 0x6F6F6261");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start -5, "
+              "string 0x666F6F626172 pushing result 0x6F6F6261");
+    addString("EVAL_DEBUG_SUBSTRING Popping length -4, start -1, "
+              "string 0x666F6F626172 pushing result 0x6F6F6261");
+    addString("EVAL_DEBUG_SUBSTRING Popping length -4, start 5, "
+              "string 0x666F6F626172 pushing result 0x6F6F6261");
+    EXPECT_TRUE(checkFile());
 }
 
 // Test getting the last letter in different ways
@@ -1069,6 +1300,23 @@ TEST_F(TokenTest, substringLastLetter) {
     verifySubstringEval("foobar", "-1", "all", "r");
     verifySubstringEval("foobar", "-1", "1", "r");
     verifySubstringEval("foobar", "-1", "5", "r");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING Popping length all, start 5, "
+              "string 0x666F6F626172 pushing result 0x72");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 1, start 5, "
+              "string 0x666F6F626172 pushing result 0x72");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 5, start 5, "
+              "string 0x666F6F626172 pushing result 0x72");
+    addString("EVAL_DEBUG_SUBSTRING Popping length all, start -1, "
+              "string 0x666F6F626172 pushing result 0x72");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 1, start -1, "
+              "string 0x666F6F626172 pushing result 0x72");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 5, start -1, "
+              "string 0x666F6F626172 pushing result 0x72");
+    EXPECT_TRUE(checkFile());
 }
 
 // Test we get only what is available if we ask for a longer string
@@ -1084,6 +1332,27 @@ TEST_F(TokenTest, substringLength) {
     verifySubstringEval("foobar", "4", "4", "ar");
     verifySubstringEval("foobar", "5", "4", "r");
     verifySubstringEval("foobar", "6", "4", "");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING Popping length -4, start 0, "
+              "string 0x666F6F626172 pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING Popping length -4, start 1, "
+              "string 0x666F6F626172 pushing result 0x66");
+    addString("EVAL_DEBUG_SUBSTRING Popping length -4, start 2, "
+              "string 0x666F6F626172 pushing result 0x666F");
+    addString("EVAL_DEBUG_SUBSTRING Popping length -4, start 3, "
+              "string 0x666F6F626172 pushing result 0x666F6F");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start 3, "
+              "string 0x666F6F626172 pushing result 0x626172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start 4, "
+              "string 0x666F6F626172 pushing result 0x6172");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start 5, "
+              "string 0x666F6F626172 pushing result 0x72");
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length 4, start 6, "
+              "string 0x666F6F626172 pushing result 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // Test that we get nothing if the starting postion is out of the string
@@ -1097,6 +1366,23 @@ TEST_F(TokenTest, substringStartingPosition) {
     verifySubstringEval("foobar", "6", "1", "");
     verifySubstringEval("foobar", "6", "-11", "");
     verifySubstringEval("foobar", "6", "all", "");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length 1, start -7, "
+              "string 0x666F6F626172 pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length -11, start -7, "
+              "string 0x666F6F626172 pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length all, start -7, "
+              "string 0x666F6F626172 pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length 1, start 6, "
+              "string 0x666F6F626172 pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length -11, start 6, "
+              "string 0x666F6F626172 pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING_RANGE Popping length all, start 6, "
+              "string 0x666F6F626172 pushing result 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // Check what happens if we use strings that aren't numbers for start or length
@@ -1109,6 +1395,9 @@ TEST_F(TokenTest, substringBadParams) {
     verifySubstringEval("foobar", "0", "0ick", "", true);
     verifySubstringEval("foobar", "0", "ick0", "", true);
     verifySubstringEval("foobar", "0", "allaboard", "", true);
+
+    // These should result in a throw which should generate it's own
+    // log entry
 }
 
 // lastly check that we don't get anything if the string is empty or
@@ -1116,6 +1405,15 @@ TEST_F(TokenTest, substringBadParams) {
 TEST_F(TokenTest, substringReturnEmpty) {
     verifySubstringEval("", "0", "all", "");
     verifySubstringEval("foobar", "0", "0", "");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING_EMPTY Popping length all, start 0, "
+              "string 0x pushing result 0x");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 0, start 0, "
+              "string 0x666F6F626172 pushing result 0x");
+    EXPECT_TRUE(checkFile());
 }
 
 // Check if we can use the substring and equal tokens together
@@ -1137,8 +1435,6 @@ TEST_F(TokenTest, substringEquals) {
     values_.push("ooba");
 
     // The substring values
-    // Subsring requires three values on the stack, try
-    // with 0, 1 and 2 all should throw an exception
     values_.push("foobar");
     values_.push("1");
     values_.push("4");
@@ -1160,8 +1456,6 @@ TEST_F(TokenTest, substringEquals) {
     values_.push("foob");
 
     // The substring values
-    // Subsring requires three values on the stack, try
-    // with 0, 1 and 2 all should throw an exception
     values_.push("foobar");
     values_.push("1");
     values_.push("4");
@@ -1175,6 +1469,18 @@ TEST_F(TokenTest, substringEquals) {
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("false", values_.top());
 
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start 1, "
+              "string 0x666F6F626172 pushing result 0x6F6F6261");
+    addString("EVAL_DEBUG_EQUAL Popping 0x6F6F6261 and 0x6F6F6261 "
+              "pushing result 'true'");
+    addString("EVAL_DEBUG_SUBSTRING Popping length 4, start 1, "
+              "string 0x666F6F626172 pushing result 0x6F6F6261");
+    addString("EVAL_DEBUG_EQUAL Popping 0x6F6F6261 and 0x666F6F62 "
+              "pushing result 'false'");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if a token representing a concat request
@@ -1197,6 +1503,13 @@ TEST_F(TokenTest, concat) {
     // Check the result
     ASSERT_EQ(1, values_.size());
     EXPECT_EQ("foobar", values_.top());
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_CONCAT Popping 0x626172 and 0x666F6F "
+              "pushing 0x666F6F626172");
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if we can properly extract the link and peer
@@ -1250,6 +1563,29 @@ TEST_F(TokenTest, relay6Field) {
 
     // be tidy
     clearStack();
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_RELAY6 Pushing PKT6 relay field linkaddr nest 0 "
+              "with value 0x00000000000000000000000000000000");
+    addString("EVAL_DEBUG_RELAY6 Pushing PKT6 relay field peeraddr nest 0 "
+              "with value 0x00000000000000000000000000000000");
+    addString("EVAL_DEBUG_RELAY6 Pushing PKT6 relay field linkaddr nest 1 "
+              "with value 0x00010000000000000000000000000001");
+    addString("EVAL_DEBUG_RELAY6 Pushing PKT6 relay field peeraddr nest 1 "
+              "with value 0x00010000000000000000000000000002");
+    addString("EVAL_DEBUG_RELAY6_RANGE Pushing PKT6 relay field linkaddr nest 2 "
+              "with value 0x");
+
+    addString("EVAL_DEBUG_RELAY6 Pushing PKT6 relay field linkaddr nest 1 "
+              "with value 0x00010000000000000000000000000001");
+    addString("EVAL_DEBUG_IPADDRESS Pushing IPAddress "
+              "0x00010000000000000000000000000001");
+    addString("EVAL_DEBUG_EQUAL Popping 0x00010000000000000000000000000001 "
+              "and 0x00010000000000000000000000000001 pushing result 'true'");
+
+    EXPECT_TRUE(checkFile());
 }
 
 // This test checks if we can properly extract an option
@@ -1283,6 +1619,23 @@ TEST_F(TokenTest, relay6Option) {
 
     // Level 2, no encapsulation so no options
     verifyRelay6Option(2, 100, TokenOption::TEXTUAL, "");
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'hundred.zero'");
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'true'");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value 'hundredone.zero'");
+    addString("EVAL_DEBUG_OPTION Pushing option 102 with value ''");
+    addString("EVAL_DEBUG_OPTION Pushing option 102 with value 'false'");
+
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value 'hundred.one'");
+    addString("EVAL_DEBUG_OPTION Pushing option 101 with value ''");
+    addString("EVAL_DEBUG_OPTION Pushing option 102 with value 'hundredtwo.one'");
+
+    addString("EVAL_DEBUG_OPTION Pushing option 100 with value ''");
+
+    EXPECT_TRUE(checkFile());
 }
 
 // Verifies if the DHCPv6 packet fields can be extracted.
@@ -1309,4 +1662,13 @@ TEST_F(TokenTest, pkt6Fields) {
     clearStack();
     ASSERT_NO_THROW(t_.reset(new TokenPkt6(TokenPkt6::TRANSID)));
     EXPECT_THROW(t_->evaluate(*pkt4_, values_), EvalTypeError);
+
+    // Check that the debug output was correct.  Add the strings
+    // to the test vector in the class and then call checkFile
+    // for comparison
+    addString("EVAL_DEBUG_PKT6 Pushing PKT6 field msgtype with value 0x00000001");
+    addString("EVAL_DEBUG_PKT6 Pushing PKT6 field transid with value 0x00003039");
+
+    EXPECT_TRUE(checkFile());
 }
+};

src/lib/eval/token.cc

@@ -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_STACK, 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_STACK, 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_STACK, 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_STACK, 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_STACK, 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_STACK, EVAL_DEBUG_PKT4)
+        .arg(type_str)
+        .arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
+                                                                 value.end())));
 }
 
 void
@@ -213,6 +255,14 @@ TokenEqual::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
         values.push("true");
     else
         values.push("false");
+
+    // Log what we popped and pushed
+    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('\'' + values.top() + '\'');
 }
 
 void
@@ -233,6 +283,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_STACK, EVAL_DEBUG_SUBSTRING_EMPTY)
+            .arg(len_str)
+            .arg(start_str)
+            .arg("0x")
+            .arg("0x");
         return;
     }
 
@@ -266,6 +323,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_STACK, 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;
     }
 
@@ -288,6 +353,15 @@ TokenSubstring::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
 
     // and finally get the substring
     values.push(string_str.substr(start_pos, length));
+
+    // Log what we popped and pushed
+    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>(values.top().begin(),
+                                                                 values.top().end())));
 }
 
 void
@@ -305,6 +379,15 @@ TokenConcat::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
 
     // The top of the stack was evaluated last so this is the right order
     values.push(op2 + op1);
+
+    // Log what we popped and pushed
+    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>(values.top().begin(),
+                                                                 values.top().end())));
 }
 
 void
@@ -323,6 +406,11 @@ TokenNot::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
     } else {
         values.push("false");
     }
+
+    // Log what we popped and pushed
+    LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_NOT)
+        .arg('\'' + op + '\'')
+        .arg('\'' + values.top() + '\'');
 }
 
 void
@@ -345,6 +433,12 @@ TokenAnd::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
     } else {
         values.push("false");
     }
+
+    // Log what we popped and pushed
+    LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_AND)
+        .arg('\'' + op1 + '\'')
+        .arg('\'' + op2 + '\'')
+        .arg('\'' + values.top() + '\'');
 }
 
 void
@@ -367,6 +461,12 @@ TokenOr::evaluate(const Pkt& /*pkt*/, ValueStack& values) {
     } else {
         values.push("false");
     }
+
+    // Log what we popped and pushed
+    LOG_DEBUG(eval_logger, EVAL_DBG_STACK, EVAL_DEBUG_OR)
+        .arg('\'' + op1 + '\'')
+        .arg('\'' + op2 + '\'')
+        .arg('\'' + values.top() + '\'');
 }
 
 OptionPtr TokenRelay6Option::getOption(const Pkt& pkt) {
@@ -399,6 +499,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 +510,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 +522,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_STACK, EVAL_DEBUG_RELAY6_RANGE)
+              .arg(type_str)
+              .arg(unsigned(nest_level_))
+              .arg("0x");
             return;
         }
     } catch (const std::bad_cast&) {
@@ -431,12 +539,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_STACK, 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 +566,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 +576,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 +592,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_STACK, EVAL_DEBUG_PKT6)
+        .arg(type_str)
+        .arg("0x" + util::encode::encodeHex(std::vector<uint8_t>(value.begin(),
+                                                                 value.end())));
 }

src/lib/eval/token.h

@@ -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.
@@ -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)

src/lib/testutils/Makefile.am

@@ -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

src/lib/testutils/log_utils.cc

@@ -0,0 +1,74 @@
+// 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

src/lib/testutils/log_utils.h

@@ -0,0 +1,82 @@
+// 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