#4480 closed defect (fixed)

Add debug/trace statements to client classification

Reported by: stephen Owned by: sar
Priority: medium Milestone: Kea1.1
Component: classification Version: git
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: DHCP Feature Depending on Ticket:
Estimated Difficulty: 24 Add Hours to Ticket: .5
Total Hours: 40.5 Internal?: no

Description

We need some way for users to find out why the classification code reaches a particular decision. For example why:

pkt4.giaddr == “a.b.c.d”

Where a.b.c.d is the correct IPv4 address for the gateway.

To do this, we should add a LOG_DEBUG statement to each evaluate method. This statement will print out the values that are being popped form or pushed to the value stack.So in the above example there would be three debug statements printed, one for the pkt4.giaddr token, one for the IPv4 string and one for the "==" expression.

This would be something like:

pkt4 pushing giaddr: 0xaabbccdd
string pushing string: “a.b.c.d”
equals evaluating: popping: “a.b.c.d” and 0xaabbccdd, pushing: false

It should be possible to enable these debug statements in the classification code without enabling others: either the statements should log to their own logger, or the debug level should be set very low.

Subtickets

Attachments (1)

logcontent_class.diff (3.2 KB) - added by tmark 18 months ago.
LogContentTest? class

Download all attachments as: .zip

Change History (11)

comment:1 Changed 20 months ago by sar

This ticket is a continuation of 4248 which was closed for administrative reasons.

Last edited 20 months ago by sar (previous) (diff)

comment:2 Changed 20 months ago by sar

  • Component changed from Unclassified to classification
  • Estimated Difficulty changed from 0 to 24
  • Milestone changed from Kea-proposed to Kea1.1
  • Owner set to sar
  • Status changed from new to assigned

Add to 1.1 as it replaces 4248, estimate of 24 hours

comment:3 Changed 18 months ago by sar

  • Owner changed from sar to unassigned
  • Status changed from assigned to reviewing
  • Total Hours changed from 0 to 32

Ready for review

comment:4 Changed 18 months ago by tmark

  • Owner changed from unassigned to tmark

Changed 18 months ago by tmark

comment:5 follow-up: Changed 18 months ago by tmark

You did a nice job with this.


ChangeLog? entry should mention the name of the new loggers, maybe something like:

 New debug level loggers, "kea-dhcp4.eval" and "kea-dhcp6.eval", were added
 that capture classification expression evalution details.

There's a doxygen error that needs to be fixed:

kea/src/lib/eval/token.h:571: warning: Found unknown command `\breif'


doc/guide/classify.xml

In the section on "Debugging Expressions" you mention use "token" and "value stack" without explaining our basic evaluation scheme. In other words, it seems to assume the reader knows how it works internally, which a user not going to know without reading the developer's guide. I think you need a basic description of the process.


doc/guide/classify.xml

You recommend that users "...debug only one set of expressions at a time to limit the log statements." but do not explain how this may be achieved. I don't see a way to do it, you're either logging all or none, right? Either clarify or remove the statement.


General:

Marcin had mentioned on the call he though single quotes would be better as they would match what one sees in the configuration. Having looked at your documentation example, I agree. I think you should use single quotes for enclosing strings rather than double quotes.

I don't recall Tomek's reasoning for preferring double quotes, but I think Marcin's argument is stronger.


src/lib/eval/eval_log.h

We have three constants defined in eval_log.h, only one of which is ever used. They are copy-paste renames from hooks_log.h and as such have their names do not reflect the actually context. I realize you did not create these.

I would suggest deleting EVAL_DBG_CALLS as it is not used at all, and renaming
EVAL_DBG_EXTENDED_CALLS to something more accurate such as EVAL_DBG_STACK.


eval_messages.mes

Your log message text and descriptions are good. HAH! You thought I was going to ding you!


src/lib/eval/tests/tokenunit_test.cc

1.I've attached a patch which creates a new base class LogContentTest? that embodies the log file setup and content checking, and from which TokenTest? is then derived. This new class should be moved to lib/util/testutils (and no the testutil classes do not require
their own unit tests ;) ).

  1. You could eliminate some reptitive steps from the tests by making the vector of expected strings a member of the test fixture class (LogContentClass?) and adding methods to add and/or clear it, checkFileContent() would then not require a parameter.
  1. Since the LogContentTest? class destructor calls remFile() that no longer would need to be called explicitly at the end of each test. Instead of this:
    vector<string> exp_strings;
    exp_strings.push_back("EVAL_DEBUG_STRING Pushing text string \"foo\"");
    EXPECT_TRUE(checkFile(exp_strings));
    remFile();

You'd have something like this:

    addExpectedString("EVAL_DEBUG_STRING Pushing text string \"foo\"");
    EXPECT_TRUE(checkFile());

Note that items 2 and 3 could be done, even if you don't extract the base
class, though I think you should. This is a very handy thing.


General:

In many of the evaluate methods you have added locals and assignments of the locals to preserve the result pushed for logging. What this means of course is these extra variables are created and assigned all the time. As an alternative, you could instead use the values.top() within the log arguments:

        .arg('"' + result + '"');

vs

        .arg('"' + values.top() + '"');

At least for some of the simpler cases, such as TokenAnd?, you might consider this.

comment:6 Changed 18 months ago by tmark

  • Add Hours to Ticket changed from 0 to 4
  • Owner changed from tmark to sar
  • Total Hours changed from 32 to 36

Make distcheck passes under OS-X too.

comment:7 in reply to: ↑ 5 Changed 18 months ago by sar

Replying to tmark:

You did a nice job with this.

thank you


ChangeLog? entry should mention the name of the new loggers, maybe something like:

 New debug level loggers, "kea-dhcp4.eval" and "kea-dhcp6.eval", were added
 that capture classification expression evalution details.

The loggers already existed so I don't want to say they were added. I've changed the above to say that those loggers are being used which I think covers things well enough.


There's a doxygen error that needs to be fixed:

kea/src/lib/eval/token.h:571: warning: Found unknown command `\breif'

done


doc/guide/classify.xml

In the section on "Debugging Expressions" you mention use "token" and "value stack" without explaining our basic evaluation scheme. In other words, it seems to assume the reader knows how it works internally, which a user not going to know without reading the developer's guide. I think you need a basic description of the process.

I've added one, possibly it should move but it's a start at least.


doc/guide/classify.xml

You recommend that users "...debug only one set of expressions at a time to limit the log statements." but do not explain how this may be achieved. I don't see a way to do it, you're either logging all or none, right? Either clarify or remove the statement.

I was thinking of having only one set of expressions in the configuration file. I've updated the comment to be clearer.


General:

Marcin had mentioned on the call he though single quotes would be better as they would match what one sees in the configuration. Having looked at your documentation example, I agree. I think you should use single quotes for enclosing strings rather than double quotes.

I don't recall Tomek's reasoning for preferring double quotes, but I think Marcin's argument is stronger.

Done, we may want to update some of the text in the user guide as it seems to be using "true" and "false", though that may simply be for emphasis rather than as a specific text.


src/lib/eval/eval_log.h

We have three constants defined in eval_log.h, only one of which is ever used. They are copy-paste renames from hooks_log.h and as such have their names do not reflect the actually context. I realize you did not create these.

I would suggest deleting EVAL_DBG_CALLS as it is not used at all, and renaming
EVAL_DBG_EXTENDED_CALLS to something more accurate such as EVAL_DBG_STACK.

Done


src/lib/eval/tests/tokenunit_test.cc

1.I've attached a patch which creates a new base class LogContentTest? that embodies the log file setup and content checking, and from which TokenTest? is then derived. This new class should be moved to lib/util/testutils (and no the testutil classes do not require
their own unit tests ;) ).

  1. You could eliminate some reptitive steps from the tests by making the vector of expected strings a member of the test fixture class (LogContentClass?) and adding methods to add and/or clear it, checkFileContent() would then not require a parameter.
  1. Since the LogContentTest? class destructor calls remFile() that no longer would need to be called explicitly at the end of each test. Instead of this:
    vector<string> exp_strings;
    exp_strings.push_back("EVAL_DEBUG_STRING Pushing text string \"foo\"");
    EXPECT_TRUE(checkFile(exp_strings));
    remFile();

You'd have something like this:

    addExpectedString("EVAL_DEBUG_STRING Pushing text string \"foo\"");
    EXPECT_TRUE(checkFile());

Note that items 2 and 3 could be done, even if you don't extract the base
class, though I think you should. This is a very handy thing.

This seems reasonable and I shall get to it tomorrow.


General:

In many of the evaluate methods you have added locals and assignments of the locals to preserve the result pushed for logging. What this means of course is these extra variables are created and assigned all the time. As an alternative, you could instead use the values.top() within the log arguments:

        .arg('"' + result + '"');

vs

        .arg('"' + values.top() + '"');

At least for some of the simpler cases, such as TokenAnd?, you might consider this.

I've changed to using values.top() for all the cases where I had added extra code. I was thinking of doing it for everything as that would ensure we get what is actually on the top of the stack but decided that wasn't necessary if we just pushed a variable to the stack.

comment:8 Changed 18 months ago by sar

  • Owner changed from sar to tmark
  • Total Hours changed from 36 to 40

I've now updated the code to add the LogContentTest? class and moved it to testutils. In the future I think it would be useful to update that code to allow the caller to set the severity and debug levels as well as the output file but that can be deferred until somebody needs those options.

Ready for re-review

comment:9 Changed 18 months ago by tmark

  • Add Hours to Ticket changed from 4 to .5
  • Owner changed from tmark to sar
  • Total Hours changed from 40 to 40.5

I made a couple of minor typo fixes in the doc, so be sure to pull them.
Beyond that the changes look fine, please merge them in.

comment:10 Changed 18 months ago by sar

  • Resolution set to fixed
  • Status changed from reviewing to closed

merged to master
cf14d0d21c69879f21733457a97a6ac0bdb1dae2

Note: See TracTickets for help on using tickets.