Opened 9 years ago

Closed 9 years ago

Last modified 9 years ago

#1071 closed task (complete)

introduce "null" output for logs

Reported by: jinmei Owned by: stephen
Priority: medium Milestone: Sprint-20110712
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: DNS Feature Depending on Ticket:
Estimated Difficulty: 3.0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

We need a special type of logging output (say "null") in addition to
more common syslog, local log file, stdout/stderr. If it's specified
as the logging output, log messages will be generated but won't actually
appear anywhere.

If you are familiar with BIND 9, it's like BIND 9's "null" logging
channel.

The primary purpose for this feature is to help #1024: so that we
won't spam test outputs due to the verbose log messages (note that
even without #1024, some log messages are currently dumped to
test outputs. So if we care about noise in test outputs, this feature
is useful anyway).

As agreed on jabber, I'm pushing this to the current sprint.

Subtickets

Change History (11)

comment:1 Changed 9 years ago by stephen

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

comment:2 Changed 9 years ago by stephen

As it is possible to set a severity of NONE, a comment as to the distinction between doing that and setting the output to /dev/null is offered by way of explanation for this ticket.

Logging is achieved using macros that effectively expand to something like:

if (logger.isDebugEnabled()) {
   logger.debug(...)
}

if (logger.isInfoEnabled()) {
   logger.info(...)
}

If we set the logging severity to INFO, isDebugEnabled() will return false and isInfoEnabled() will return true. Logging is disabled if the severity is set to NONE, as all the isXxxEnabled() methods return false and no methods on the logger that output text are called.

Another way of disabling logging is to ignore the logging severity and route all output to /dev/null. However, there is a difference between this and setting the severity to NONE. Consider the case where the logging statement is:

if (logger.isDebugEnabled()) {
   logger.debug(..., expensive())
}

... where the argument expensive() is a function that may take a long time to run or be expensive in some other way (e.g. it converts a complicated data structure into text, or perhaps it locks the database for the duration of the call).

If we set the logging severity to NONE, expensive() will never be executed. This is exactly what we want in production, as we keep needless work to a minimum.

On the other hand, setting the severity to DEBUG and the output to /dev/null is what is required in testing. Needless output is still discarded, but all code paths - including those in arguments to the logging functions, such as expensive() in the example above - are tested.

comment:3 Changed 9 years ago by stephen

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

comment:4 Changed 9 years ago by stephen

  • Owner changed from UnAssigned to stephen
  • Status changed from reviewing to accepted

comment:5 Changed 9 years ago by stephen

  • Owner changed from stephen to UnAssigned
  • Status changed from accepted to reviewing

Thought I had discovered a problem with the change, but it turns out that it was a problem in a test - see #1084.

comment:6 Changed 9 years ago by vorner

  • Owner changed from UnAssigned to vorner

comment:7 Changed 9 years ago by vorner

  • Owner changed from vorner to stephen

Hello

I don't know if I look correctly, but this seems to be more setting-up of logging options through environment variables. There seems to be no code regarding any null output. Do I look at a wrong branch or is it related in some way I don't see?

Anyway, the code looks useful, so here are comments to it:

  • This doesn't seem to be completely true (the part about „as is“, the %1, etc are replaced):
      * The rest of the line - from the first non-space character to the last non-
        space character - is taken exactly as-is for the text of the message. There
    
  • „The main program unit should include a call to isc.log.init()“ ‒ wouldn't „must“ be better?
  • Is this a typo or word I don't know? „Checks that the logger will limit the output of messages less _severy_ than“?
  • In the tests, when the output is routed to stdout or stderr, wouldn't it be better to use a single pipeline instead of (slower and more error prone) store-to-file and load again? Like this?:
    B10_LOGGER_SEVERITY=WARN ./init_logger_test 2>&1 | cut -d' ' -f3- | diff $tempfile -
    
  • Also, this looks really strange. Why is the „1“ there?
    ./init_logger_test 1> $destfile
    

With regards

comment:8 follow-up: Changed 9 years ago by stephen

  • Owner changed from stephen to vorner

I don't know if I look correctly, but this seems to be more setting-up of logging options through environment variables. There seems to be no code regarding any null output. Do I look at a wrong branch or is it related in some way I don't see?

It adds B10_LOGGER_DESTINATION. Setting that to /dev/null will route the output to the null device. I've added some text to LoggingCppApiDesign to describe this and will post a message to bind10-dev prior to committing #1024 to explain it.

This doesn't seem to be completely true (the part about "as is", the %1, etc are replaced): The rest of the line - from the first non-space character to the last non-space character - is taken exactly as-is for the text of the message.

I've combined this paragraph and the succeeding one (that talks about the replacement tokens); does this remove the ambiguity?

"The main program unit should include a call to isc.log.init()" ‒ wouldn't "must" be better?

Yes - changed.

Is this a typo or word I don't know? "Checks that the logger will limit the output of messages less _severy_ than"?

Typo - changed. (And updated test descriptions.)

In the tests, when the output is routed to stdout or stderr, wouldn't it be better to use a single pipeline instead of (slower and more error prone) store-to-file and load again? Like this?:
B10_LOGGER_SEVERITY=WARN ./init_logger_test 2>&1 | cut -d' ' -f3- | diff $tempfile -

Where appropriate the tests have been changed to use this construct.

Also, this looks really strange. Why is the "1" there?
./init_logger_test 1> $destfile

For symmetry: the following test a few lines down routes output to stderr (and so contains a "2>"). The "1>" is meant to emphasise the difference.

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

  • Owner changed from vorner to stephen

Hello

Replying to stephen:

I don't know if I look correctly, but this seems to be more setting-up of logging options through environment variables. There seems to be no code regarding any null output. Do I look at a wrong branch or is it related in some way I don't see?

It adds B10_LOGGER_DESTINATION. Setting that to /dev/null will route the output to the null device. I've added some text to LoggingCppApiDesign to describe this and will post a message to bind10-dev prior to committing #1024 to explain it.

Will it route them there by default or is it needed to specify manually? Would that make sense to be default? I don't really mind it this way, since I run distcheck from a script and putting it there isn't a problem for me.

This doesn't seem to be completely true (the part about "as is", the %1, etc are replaced): The rest of the line - from the first non-space character to the last non-space character - is taken exactly as-is for the text of the message.

I've combined this paragraph and the succeeding one (that talks about the replacement tokens); does this remove the ambiguity?

Well, I wasn't really worried about ambiguity, but about the sentence not being true (I understand „as-is“ to be completely unmodified, but the placeholders are modified). I tried to modify it a bit, is it OK for you this way?

Also, this looks really strange. Why is the "1" there?
./init_logger_test 1> $destfile

For symmetry: the following test a few lines down routes output to stderr (and so contains a "2>"). The "1>" is meant to emphasise the difference.

I find it surprising this way. But it is correct, so I don't really mind, it's just question if it is better to be symmetric or usual.

If you agree with my change of the text, it can probably be merged.

comment:10 Changed 9 years ago by stephen

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

Merged into master, commit e39dbc26a1aaecdff6809be620a91d4771e5af9b

comment:11 Changed 9 years ago by stephen

  • Estimated Difficulty changed from 0.0 to 3
Note: See TracTickets for help on using tickets.