diff --git a/ChangeLog b/ChangeLog index c7d75619fb..e717051be8 100644 --- a/ChangeLog +++ b/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. diff --git a/doc/guide/classify.xml b/doc/guide/classify.xml index ba746272f5..ec640f8d2d 100644 --- a/doc/guide/classify.xml +++ b/doc/guide/classify.xml @@ -625,4 +625,96 @@ +
+ Debugging Expressions + + While you are constructing your classification expressions you may + find it useful to enable logging see for + a more complete description of the logging facility. + + + + 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". + + + + 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 . + 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. + + + + 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: + + "test": "substring(option[61].hex,0,3) == 'foo'", + + This will result in the following tokens: + + option, number (0), number (3), substring, text ('foo'), equals + + 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. + + + + 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. + + + + 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. + + + + 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. + + "test": "substring(option[61].hex,0,3) == 'foo'", + + The logging might then resemble this: + + 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" + + + + + 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. + +
+ diff --git a/src/lib/eval/eval_log.h b/src/lib/eval/eval_log.h index a85e459f1f..c7fa5001fd 100644 --- a/src/lib/eval/eval_log.h +++ b/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 /// diff --git a/src/lib/eval/eval_messages.mes b/src/lib/eval/eval_messages.mes index 9d23293581..3ee2da1306 100644 --- a/src/lib/eval/eval_messages.mes +++ b/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 diff --git a/src/lib/eval/tests/Makefile.am b/src/lib/eval/tests/Makefile.am index ec42f1d992..a492686eff 100644 --- a/src/lib/eval/tests/Makefile.am +++ b/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) diff --git a/src/lib/eval/tests/token_unittest.cc b/src/lib/eval/tests/token_unittest.cc index 80af7c3c12..c4cbec6003 100644 --- a/src/lib/eval/tests/token_unittest.cc +++ b/src/lib/eval/tests/token_unittest.cc @@ -5,12 +5,17 @@ // file, You can obtain one at http://mozilla.org/MPL/2.0/. #include +#include #include #include #include #include #include #include +#include +#include +#include +#include #include #include @@ -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()); } +}; diff --git a/src/lib/eval/token.cc b/src/lib/eval/token.cc index 7fbe6f2d22..f0e74a04d5 100644 --- a/src/lib/eval/token.cc +++ b/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(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(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(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 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(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(op1.begin(), + op1.end()))) + .arg("0x" + util::encode::encodeHex(std::vector(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(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(string_str.begin(), + string_str.end()))) + .arg("0x" + util::encode::encodeHex(std::vector(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(op1.begin(), + op1.end()))) + .arg("0x" + util::encode::encodeHex(std::vector(op2.begin(), + op2.end()))) + .arg("0x" + util::encode::encodeHex(std::vector(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 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(value.begin(), + value.end()))); } void TokenPkt6::evaluate(const Pkt& pkt, ValueStack& values) { vector 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(value.begin(), + value.end()))); } diff --git a/src/lib/eval/token.h b/src/lib/eval/token.h index 316106e43e..d51ed6d1ec 100644 --- a/src/lib/eval/token.h +++ b/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) diff --git a/src/lib/testutils/Makefile.am b/src/lib/testutils/Makefile.am index 3d4d8d56ad..8aa2cc2c71 100644 --- a/src/lib/testutils/Makefile.am +++ b/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 diff --git a/src/lib/testutils/log_utils.cc b/src/lib/testutils/log_utils.cc new file mode 100644 index 0000000000..2bfcc78843 --- /dev/null +++ b/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 + +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(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 diff --git a/src/lib/testutils/log_utils.h b/src/lib/testutils/log_utils.h new file mode 100644 index 0000000000..fbfd24cb33 --- /dev/null +++ b/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 +#include + +//#include + +#include +#include +#include + +//#include +//#include +#include + +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 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