Opened 8 years ago

Closed 8 years ago

#1892 closed task (fixed)

Check mode of logger

Reported by: vorner Owned by: muks
Priority: medium Milestone: Sprint-20120515
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 5 Add Hours to Ticket: 0
Total Hours: 0.67 Internal?: no

Description

I think this or something similar is somewhere, but I can't find it anywhere.

It would be nice if we had a mode in the logger where we could say to throw if
there's a missing or extra placeholder, so we can check in the tests we don't
have these problems. It should probably be enabled by some configure/compile
flag, so we don't degrade the performance. I (once again) made a typo in the
message, this should be caught automatically to eliminate stupid bugs and show
problems sooner.

Subtickets

Change History (15)

comment:1 Changed 8 years ago by jelte

i don't think we considered a mode for it; but we have had the discussion whether it should be more strict or more lenient. Some wanted more strictness because of issues like this :) (the argument for more lenience being more flexibility, and would include removing the missing/extra placeholder messages)

comment:2 Changed 8 years ago by jelte

  • Milestone changed from Next-Sprint-Proposed to Sprint-20120501

comment:3 Changed 8 years ago by muks

  • Owner set to muks
  • Status changed from new to assigned

Currently the placeholders are replaced in this manner:

LOG_DEBUG(...,"$1 $2").arg("foo").arg("bar")

Will:

  1. call arg() with "$1 $2", returning "foo $2"
  2. call arg() with "foo $2" which returns "foo bar"

We can check if there are fewer $ placeholders than the number of arg() [there is already such a check], but we can't check if there are more $ placeholders as arg() only knows about replacing one argument and returns a Formatter on which arg() can be called again.

Comments?

comment:4 Changed 8 years ago by muks

Nevermind. The destructor is the place to check.

comment:5 Changed 8 years ago by muks

  • Owner changed from muks to UnAssigned
  • Status changed from assigned to reviewing

Up for review.

Note that make check at toplevel will fail when --enable-logger-checks is used, due to various issues all around the codebase. The fix in this bug catches those problems.

We discussed this on Jabber:

(2012-05-01 16:04:37) muks: there are log messages like this:
(2012-05-01 16:04:43) muks: % DATASRC_DATABASE_WILDCARD_MATCH search in datasource %1 resulted in wildcard match at %5 with RRset %6
(2012-05-01 16:05:21) muks: logged by a helper function that takes %1, %2, %3, %4, %5, %6
(2012-05-01 16:05:31) vorner: Yes, that one is a problem
(2012-05-01 16:05:40) vorner: but I think there'll be more that are different than this one
(2012-05-01 16:06:10) muks: the code that calls the helper function passes the DATASRC_DATABASE_WILDCARD_MATCH which only logs what it wants to use
(2012-05-01 16:06:21) muks: i suppose we can accomodate this?
(2012-05-01 16:06:34) muks: by only checking if there are args left at the end?
(2012-05-01 16:06:56) muks: i.e., there's %6 left and we don't call .arg() for that
(2012-05-01 16:06:58) vorner: muks: I think the check should be strict and used only to check when producing new code, not run by users.
(2012-05-01 16:07:11) vorner: I want to have the other option checked as well
(2012-05-01 16:07:20) muks: vorner: right now it's disabled by default
(2012-05-01 16:07:31) vorner: anyway, we might want to get rid of the helper in long term
(2012-05-01 16:07:31) muks: but if we use --enable-option, make check will fail for these caes
(2012-05-01 16:07:32) muks: cases
(2012-05-01 16:07:43) vorner: yes, that's OK for now I think

comment:6 Changed 8 years ago by vorner

  • Owner changed from UnAssigned to vorner

comment:7 follow-up: Changed 8 years ago by vorner

  • Owner changed from vorner to muks

Hello

Two small things. First, if the strict mode is not there, we may want to preserve the original behaviour with the @@Missing placeholder, because it at least shows the value, even if it is not obvious where exactly the value should be.

Also, I think it is better not to call the checkExcessPlaceholders at all if the ENABLE_LOGGER_CHECKS is not enabled, to save the call of empty function (eg. adding the #ifdef to the header file too).

Thanks

comment:8 in reply to: ↑ 7 ; follow-up: Changed 8 years ago by muks

  • Owner changed from muks to vorner

Hi vorner

Thank you for reviewing my bugs.

Replying to vorner:

Hello

Two small things. First, if the strict mode is not there, we may want to preserve the original behaviour with the @@Missing placeholder, because it at least shows the value, even if it is not obvious where exactly the value should be.

I've added it back. :)

Also, I think it is better not to call the checkExcessPlaceholders at all if the ENABLE_LOGGER_CHECKS is not enabled, to save the call of empty function (eg. adding the #ifdef to the header file too).

It did occur to me, but that'd involve including config.h into the header file which would become a problem if the header is ever installed. This single function call isn't a performance blocker for where it's used. I think it's fine the way it is.

Last edited 8 years ago by muks (previous) (diff)

comment:9 in reply to: ↑ 8 ; follow-up: Changed 8 years ago by vorner

  • Owner changed from vorner to muks
  • Total Hours changed from 0 to 0.67

Hello

Replying to muks:

Also, I think it is better not to call the checkExcessPlaceholders at all if the ENABLE_LOGGER_CHECKS is not enabled, to save the call of empty function (eg. adding the #ifdef to the header file too).

It did occur to me, but that'd involve including config.h into the header file which would become a problem if the header is ever installed. This single function call isn't a performance blocker for where it's used. I think it's fine the way it is.

Yes, right. OK, then it looks ready for merge. I just updated the test for the latest change (so pull first, please).

Will you create a ticket for running everything through the check and fixing the problems?

Thank you

comment:10 Changed 8 years ago by muks

Check if #1880 is merged before this one, as this bug contains abort tests.

comment:11 Changed 8 years ago by muks

Pushed to master:

* 5fb1859 [1892] Return the placeholders to tests too
* dfaf971 [1892] Put back the @@Missing placeholder warning when logger checks are off
* f894ef7 [1892] Conditionally throw an exception if logger placeholders are not matched

comment:12 in reply to: ↑ 9 Changed 8 years ago by muks

Replying to vorner:

Will you create a ticket for running everything through the check and fixing the problems?

#1944 was filed for it.

comment:13 Changed 8 years ago by muks

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

Resolving this bug as fixed.

comment:14 Changed 8 years ago by jreed

  • Resolution fixed deleted
  • Status changed from closed to reopened

Here is an example. It doesn't show the message but maybe the pointer.

[ RUN      ] DatabaseClientTest/0.iterator
*** Exception derived from isc::exception thrown:
    file: log_formatter.cc
    line: 40
    what: Missing logger placeholder in message: 0xe403a0
/bin/sh: line 1: 36308 Abort trap              (core dumped) ${dir}$tst
FAIL: run_unittests

comment:15 Changed 8 years ago by muks

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

Added a hotfix patch to address this issue:

--- a/src/lib/log/log_formatter.cc
+++ b/src/lib/log/log_formatter.cc
@@ -37,7 +37,7 @@ replacePlaceholder(string* message, const string& arg,
     else {
         // We're missing the placeholder, so throw an exception
         isc_throw(MismatchedPlaceholders,
-                 "Missing logger placeholder in message: " << message);
+                 "Missing logger placeholder in message: " << *message);
     }
 #else
     else {
@@ -56,7 +56,7 @@ checkExcessPlaceholders(string* message, unsigned int placeholder)
     if (pos != string::npos) {
         // Excess placeholders were found, so throw an exception
         isc_throw(MismatchedPlaceholders,
-                 "Excess logger placeholders still exist in message: " << message);
+                 "Excess logger placeholders still exist in message: " << *message);
     }
 #endif /* ENABLE_LOGGER_CHECKS */
 }

As this is a trivial patch, I'm just pushing it to master:

* 1c88a49 [1892] Fix the message string in MismatchedPlaceholders exceptions

Resolving the bug as fixed.

Note: See TracTickets for help on using tickets.