Opened 9 years ago

Closed 9 years ago

#555 closed enhancement (complete)

C++ Logging - multiple destinations and configuration

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

Description

The first pass of the C++ logging (ticket #438) only covers output to the console and limited configuration. The code needs to be expanded to:

  • Allow multiple destinations to be specified
  • Obtain configuration information from the configuration database

Subtickets

Change History (12)

comment:1 Changed 9 years ago by stephen

  • Milestone R-Team-Task-Backlog deleted

Milestone R-Team-Task-Backlog deleted

comment:2 Changed 9 years ago by stephen

  • Defect Severity set to N/A
  • Milestone set to Sprint-20110531
  • Sub-Project set to DNS

This may depend on ticket #899.

comment:3 Changed 9 years ago by stephen

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

comment:4 Changed 9 years ago by stephen

  • Estimated Difficulty changed from 0.0 to 8

comment:5 Changed 9 years ago by stephen

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

This ticket covers logging to two destinations: to a file and to a terminal. Output to syslog has been deferred to ticket #976.

The ticket was branched from #899 at 862e13c5c852b8ea55c1b53a67803105d473a342.

Broadly speaking, the changes have been:

  • Create a LoggerManager class (and an associated implementation class) to control logging initialization and the configuration of loggers. This has meant moving initialization out of the Logger and LoggerImpl classes.
  • Add code to create a file appender and a console appender (and associated unit tests)
  • Reorganise the sh-based tests around the (renamed) logger_example program. Each shell script now tests one aspect of the logger.

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 have some comments, but I believe none of them are serious, mostly details:

  • Is there any reason why the LoggerManagerImpl is in separate file? The class could be in the same C++ file as the LoggerManager class, which would mean that there's no public header file for the class and the calls to the class can be insined by the compiler if it sees it fit (which it should, as most of the methods in LoggerManager are only wrappers).
  • In several conversion functions, when it gets invalid input, it returns something anyway and logs a warning. Is there any reason for such behaviour? I believe it should rather throw an exception instead of silently ignoring invalid input (because one might do a typo, say „DEGUB“ and keep hunting down why the hell it doesn't log much). Generally I believe the BIND10 is written with the idiom „If you have to fail, fail loudly and fail as soon as possible“. Moreover, when it says the value must be one of "DEBUG", "INFO", ….
  • If we ignore the first point for a moment, why is void LoggerManagerImpl::processEnd() {} in logger_manager.cc? Shouldn't it be in logger_manager_impl.cc?
  • In LoggerManager::init, the comment „Log using the logging facility root logger“ isn't right. It logs using a logger with name "log".
  • I don't understand this comment: „There are - sort and remove any duplicates“ ‒ what does the „There are“ mean?
  • The comment and code don't match:
    +        // File successfully read, list the duplicates
    +        MessageReader::MessageIDCollection unknown = reader.getNotAdded();
    +        for (MessageReader::MessageIDCollection::const_iterator
    +            i = unknown.begin(); i != unknown.end(); ++i) {
    +            string message_id = boost::lexical_cast<string>(*i);
    +                logger.warn(MSG_IDNOTFND).arg(message_id);
    +        }
    
  • When logging the exception, you use a switch to specify number of arguments:
    switch (args.size()) {
        case 0:
            LOG_ERROR(logger, ident);
            break;
    
    The current implementation actually supports a cycle to provide arbitrary number of arguments. It should AFAIK work if you save the result of logger.error to variable and then call .arg on it as many times as needed (to be implementation detail agnostic, replacing the variable with it's result each time, but it would currently work without it as well).
  • This comment is probably true, but it's misleading (it says what happens inside, but sounds like there would be no more logging after this).
    +    /// Given a list of logger specifications, disables all current logging
    +    /// and resets the properties of each logger to that given.
    
    Would it be better to say something like it replaces configuration and sets it to the new one?
  • LoggerManager::init says This must be the first logging function called in the program. What happens if it isn't? Like if some object is statically initialized and uses a function in it's constructor which does some logging, therefore it's called before main starts, will it crash, or will it just log into some default destination?
  • And, it would be nice to say that the file parameter might be NULL.
  • What does the second sentence mean?
    /// Initializes the processing of a list of specifications by resetting all
    /// loggers to their defaults.  Note that loggers aren't removed as unless
    /// a previously-enabled logger is re-enabled, it becomes inactive.
    
  • logger_manager_impl.cc talks in two comments at the beginning of the file about reset, but there's no reset near it.
  • class UnknownLoggingDestination : public isc::Exception { ‒ shouldn't it be in some header file? How can someone catch it?
  • This isn't too extensible. Maybe we don't need to do anything about it now, but in future, we might want to add plugins or something to add logging destinations:
        switch (i->destination) {
            case OutputOption::DEST_CONSOLE:
    
  • Console test ‒ is there a need to use temporary files? Pipes could be enough. Or, alternatively, both stdout and stderr could be redirected at once, requiring only one run of each testcase instead of two.
  • This might be wrong, there's no setting of the sentinel char and no strncpy:
        // Get prefix.  Note that in all copies, strncpy does not guarantee
        // a null-terminated string, hence the explict setting of the last
        // character to NULL. ‒ kde?
    
  • Well, the compiler might warn because there's a race condition. Using more complicated code with the same problem to only silence the compiler seems wrong. Is it really needed to delete the file? Wouldn't closing be enough?
        // The compiler warns against tmpnam() and suggests mkstemp instead.
        // Unfortunately, this creates the filename and opens it.  So we need to
        // close and delete the file before returning the name.  Also, the name
        // is based on the template supplied and the name of the temporary
        // directory may vary between systems.  So translate TMPDIR and if that
        // does not exist, use /tmp.
    
  • What is the reason of this class? And even if you want to group tests together with TEST_F instead of TEST, what is the reason for the empty constructor and destructor?
    class LoggerSpecificationTest : public ::testing::Test {
    public:
        LoggerSpecificationTest()
        {}
        ~LoggerSpecificationTest()
        {}
    };
    
  • The same for OutputOptionTest.

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

  • Owner changed from stephen to vorner

Thanks for the very comprehensive review:

Is there any reason why the LoggerManagerImpl is in separate file?...

You are right about optimisation, but in this case the code has been put in a separate file because it very cleanly separates the underlying implementation from the interface. If we need to replace log4cplus, then (theoretically) we should only need to replaced the xxx_impl.* files and nothing else. The extra overhead caused by lack of optimisation should be negligible compared with the processing done by the various functions.

In several conversion functions, when it gets invalid input, it returns something anyway and logs a warning. Is there any reason for such behaviour?

It is for robustness - I didn't want BIND10 falling over if someone made a spelling mistake in the configuration file. (Also, it follows the Jon Postel dictum: "Be conservative in what you send and liberal in what you accept".) However, in some places no warning was logged and the error silently ignored. In these places I've logged a message before coercing the value. (Throwing an exception was an option, but is many cases is likely to result in program termination. Logging - at least to the console - is enabled early on in the program and so is used where possible.)

If we ignore the first point for a moment, why is void LoggerManagerImpl::processEnd() {} in logger_manager.cc? Shouldn't it be in logger_manager_impl.cc?

It should - it was put there temporarily during testing and never got moved. (In fact, being empty it has been moved to logger_manager_impl.h.)

In LoggerManager::init, the comment „Log using the logging facility root logger“ isn't right. It logs using a logger with name "log".

An example of where the code was updated but not the relevant comment. Removed the word "root" - it logs using the logging facility logger.

I don't understand this comment: „There are - sort and remove any duplicates“ ‒ what does the „There are“ mean?

It referred to the previous comment ("Check if there were any duplicate message IDs"), but the comment has been clarified.

The comment and code don't match:
// File successfully read, list the duplicates

Comment has been updated.

When logging the exception, you use a switch to specify number of arguments:
:
The current implementation actually supports a cycle to provide arbitrary number of arguments. It should AFAIK work if you save the result of logger.error to variable and then call .arg on it as many times as needed (to be implementation detail agnostic, replacing the variable with it's result each time, but it would currently work without it as well).

The original was a direct replacement for the time when a varadic argument list was used. The method you suggest works (although I had to add the assignment operator to the Formatter class) and has been implemented. In doing this I noticed that there is no check that a message is generated if there is a problem opening a local message file, so one was added. The test also checks that the above code formats the message correctly.

This comment is probably true, but it's misleading (it says what happens inside, but sounds like there would be no more logging after this)...
/// Given a list of logger specifications, disables all current logging
/// and resets the properties of each logger to that given.

Would it be better to say something like it replaces configuration and sets it to the new one?

Yes, and this has been done.

LoggerManager::init says This must be the first logging function called in the program. What happens if it isn't? Like if some object is statically initialized and uses a function in it's constructor which does some logging, therefore it's called before main starts, will it crash, or will it just log into some default destination?

The consequences have been noted in the header of the init() functions in LoggerManager and LoggerManagerImpl. There will be no crash, just messages written to stderr that log4cplus has not been initialized.

And, it would be nice to say that the file parameter might be NULL.

Done, although it is recommended that this not be the case.

What does the second sentence mean?

The comment has been updated.

logger_manager_impl.cc talks in two comments at the beginning of the file about reset, but there's no reset near it.

One of the comment blocks has been removed. The reset talked about at that point is in the call to log4cplus's getDefaultHierarchy().resetConfiguration()

class UnknownLoggingDestination : public isc::Exception { ‒ shouldn't it be in some header file? How can someone catch it?

Well noticed. The definition of the exception has been moved to the public header file logger_manager.h

This isn't too extensible. Maybe we don't need to do anything about it now, but in future, we might want to add plugins or something to add logging destinations:

Agreed, but I too think we should defer it.

Console test ‒ is there a need to use temporary files? Pipes could be enough. Or, alternatively, both stdout and stderr could be redirected at once, requiring only one run of each testcase instead of two.

I suggest leave it as is now it has been written. Each test checks one particular item and is very simple. I don't think the added complexity is worth changing it.

This might be wrong, there's no setting of the sentinel char and no strncpy:

It was - comment removed.

Well, the compiler might warn because there's a race condition. Using more complicated code with the same problem to only silence the compiler seems wrong. Is it really needed to delete the file? Wouldn't closing be enough

I think that the race condition is such that two calls to tmpnam at exactly the same time might generate the same name. By creating the file in the process, the condition is avoided. I'm not sure if deleting the file re-introduces the race condition, but I've taken that out of the SpecificationForFileLogger class. Deleting the file before the test now happens in just one place, where the ability to create the log file if it does not exist is checked. In other places I've followed your suggestion - the file is not deleted and messages are appended to it.

What is the reason of this class? And even if you want to group tests together with TEST_F instead of TEST, what is the reason for the empty constructor and destructor?
:
The same for OutputOptionTest.

They were just place holders. However, you are right - I've removed them and converted the TEST_Fs to TESTs

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

  • Owner changed from vorner to stephen

Hello

Replying to stephen:

In several conversion functions, when it gets invalid input, it returns something anyway and logs a warning. Is there any reason for such behaviour?

It is for robustness - I didn't want BIND10 falling over if someone made a spelling mistake in the configuration file. (Also, it follows the Jon Postel dictum: "Be conservative in what you send and liberal in what you accept".) However, in some places no warning was logged and the error silently ignored. In these places I've logged a message before coercing the value. (Throwing an exception was an option, but is many cases is likely to result in program termination. Logging - at least to the console - is enabled early on in the program and so is used where possible.)

Well, personally I don't like this kind of robustness, where something does something else than what I wanted (and what I think I asked it to do) and doesn't really tell me loudly what's wrong. But maybe it's better than kill the whole server, admins should have something to parse the logs for them and email them or so.

LoggerManager::init says This must be the first logging function called in the program. What happens if it isn't? Like if some object is statically initialized and uses a function in it's constructor which does some logging, therefore it's called before main starts, will it crash, or will it just log into some default destination?

The consequences have been noted in the header of the init() functions in LoggerManager and LoggerManagerImpl. There will be no crash, just messages written to stderr that log4cplus has not been initialized.

The thing that it's dependant on the underlying implementation doesn't sound any bit less scary O:-). I just wanted to point out that the possibility of logging before full initialization should not scare people into not logging.

And, it would be nice to say that the file parameter might be NULL.

Done, although it is recommended that this not be the case.

I didn't mean the name of the logger, I meant the filename of the replacement dictionary. I just wanted to make clear note that NULL means no dictionary (it's half-implicit in the description right now). It never occurred to me that the name of the root logger could be NULL and I don't think we want to document that O:-).

Anyway, do we need the impldef.{h,cc} files in git?

Thanks

comment:10 Changed 9 years ago by stephen

  • Owner changed from stephen to vorner

But maybe it's better than kill the whole server ...

I think so - better a degraded service than no service at all.

...admins should have something to parse the logs for them and email them or so.

In production environments, sysadmins usually have monitoring packages (such as Nagios) that warn them of trouble.

I didn't mean the name of the logger, I meant the filename of the replacement dictionary...

I've updated the header comments of LoggerManager::init() (in logger_manager.h) to reflect that.

Anyway, do we need the impldef.{h,cc} files in git?

For the present, yes. The files are created by the message compiler, which depends on the logging code, which in turn depends on these files. A longer-term goal could be to separate the files related to messages and the files related to logging and build the message-related code first. In that case, by the time the files are needed the message compiler would be built and they could be generated from the .mes file. But that is for another ticket.

comment:11 Changed 9 years ago by vorner

  • Owner changed from vorner to stephen

OK then. Please merge.

comment:12 Changed 9 years ago by stephen

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

Committed as change 38b3546867425bd64dbc5920111a843a3330646b

Note: See TracTickets for help on using tickets.