BIND 10 #2445: suppress initial log

[BIND 10 Development]

#2445: suppress initial log
-------------------------------------+-------------------------------------
            Reporter:  jinmei        |                        Owner:
                Type:  defect        |  jinmei
            Priority:  medium        |                       Status:
           Component:  Boss of BIND  |  reviewing
            Keywords:                |                    Milestone:
           Sensitive:  0             |  Sprint-20121218
         Sub-Project:  Core          |                   Resolution:
Estimated Difficulty:  4             |                 CVSS Scoring:
         Total Hours:  0             |              Defect Severity:  N/A
                                     |  Feature Depending on Ticket:
                                     |          Add Hours to Ticket:  0
                                     |                    Internal?:  0
-------------------------------------+-------------------------------------

Comment (by jinmei):

 Basic approach looks good.  I have several points to discuss in detail
 though.

 '''changelog'''

 I think we need a changelog entry for this task.

 '''design'''

 - In general I'd like to avoid relying on singleton whenever possible
   (for many reasons, but most notably because it's very unfriendly
   with tests).  In this case it seems we can avoid making the buffer
   object a singleton: let createBufferAppender() make a new one for
   the given logger, and maintain it in the appender.  In
   `LoggerManagerImpl::processSpecification` we retrieve it from
   the logger using getAppender() (we need RTTI here though), and get
   access to the internal buffer and flush it.

 '''log_buffer.h'''

 - If I understand it correctly, I think `friend` is too strong a tool
   in this case:
 {{{#!cpp
     friend class LogBufferTest;
 }}}
   AFAICS (and also as commented in the code) the only purpose for the
   `friend` is to give `LogBufferTest` read-only access to `stored_`.
   In that case I'd rather provide a read-only getter for the vector,
   noting it's only for testing and it's possible we'll remove/change
   the interface (so normal apps shouldn't use it).  Also AFAIC, we
   could even hide the fact that it's a vector: all we need for the
   test seems to be an interface to return the number of stored
   messages.
 - flush() isn't documented.
 - `flush_stdout` should be renamed `flushStdout` (or something) per naming
 convention.
 - it directly depends on log4cplus internal.  My first question is
   whether it's a good idea or we should introduce a higher level
   interface for the concept of buffering.  If the answer to the first
   question is yes, maybe it's better to clarify the intent by renaming
   log_buffer.h to log_buffer_impl.h.  Same for .cc
 - is it okay to store `InternalLoggingEvent` objects in a vector?
   This class seems to be inheritable according to the log4cplus doc,
   so in general there can be a risk of slicing due to the inevitable
   copy in the vector.  To be really safe, I guess we should make a
   pointer-based copy by `InternalLoggingEvent::clone()`, release it
   from auto_ptr, move it to shared_ptr, and then store it in a vector.

 '''log_buffer.cc'''

 - I'd include `<iostream>` if we keep using std::cout etc (but see below
 too)
 - with this implementation, the singleton `LogBuffer` object will be
   destoryed at an unpredictable timing, and its `stored_` member could
   be a non empty (though which may be less likely in practice) vector
   of a third-party type (`InternalLoggingEvent`).  I'm afraid it's
   quite fragile in terms of "static destruction" fiasco.

 - `LogBuffer` constructor: a minor point in this case, but I'd initialize
   `flushed_` in the initialization list.

 - `LogBuffer` destructor: flush_stdout() seems to do non trivial task,
   and it can throw.  If the dumping behavior isn't crucial, I'm simply
   releasing the stuff here; if it's necessary, I'd at least ensure no
   exception (if any) leaks from the destructor:
 {{{#!cpp
 LogBuffer::~LogBuffer() {
     try {
         flush_stdout();
     } catch (...) {}
 }
 }}}

 - `LogBuffer::flush`: why is `event` copied?
 {{{#!cpp
         const log4cplus::spi::InternalLoggingEvent event(stored_.at(i));
 }}}
   I guess a reference should suffice here.  See also discussion about
   copying event objects and slicing above.
 - `LogBuffer::flush`: what if it throws before clear()?

 '''log_buffer_unittest.cc'''

 - Isn't it better to use a mock appender to inspect what happens
   on flush()?
 - I don't understand why we need this trick (or what exactly it does):
 {{{#!cpp
         // If any log messages are left, we don't care, get rid of them,
         // by flushing them to a null appender
         log4cplus::SharedAppenderPtr null_appender(
             new log4cplus::NullAppender());
         logger.removeAllAppenders();
         logger.addAppender(null_appender);
         buffer1.flush();
         buffer2.flush();
 }}}
   Maybe some more comments are needed.
 - `LogBuffer::add()` doesn't seem to be directly tested.
 - `BufferAppender::append()` doesn't seem to be directly tested.
 - Related to the point of directly relying on log4cplus API, I wonder
   whether the original intent is to exclude tests directly depending
   on log4cplus from the unittests.  I think direct unit tests are a
   good practice anyway, but maybe you want to ask Stephen about the
   original plan.

 '''buffer_logger_test.cc'''

 - I'd hide usage() in an unnamed namespace.

 '''buffer_manager_impl.h'''

 - `createBufferAppender`: has a non existent parameter description:
 {{{#!cpp
     /// \param opt Output options for this appender.
 }}}

 '''buffer_manager_impl.cc'''

 - why is scoped_ptr.hpp included?

 - `processSpecification`: due to the complexity I cannot be 100% sure,
   but if I understand it correctly this change breaks existing
   behavior.  Consider the case only severity level is set without any
   output option.  Previously existing appenders are preserved, but
   they are now cleaned up and replaced with a single default appender.

 - `processSpecification`: this change also seems to be fragile:
 {{{#!diff
 -    log4cplus::Logger logger = log4cplus::Logger::getInstance(
 +    log4cplus::Logger logger;
 +    // If this is an 'empty' specification, just set the root logger
 +    if (spec.getName() == "") {
 +        logger = log4cplus::Logger::getInstance(getRootLoggerName());
 +    } else {
 +        logger = log4cplus::Logger::getInstance(
                                     expandLoggerName(spec.getName()));
 +    }
 }}}
   I guess it's intended to be called via `LoggerManager::process()`,
   but what if a spec whose name is "" is explicitly given?  In the
   previous code it result in
 {{{#!cpp
         logger = log4cplus::Logger::getInstance(expandLoggerName(""));
 }}}
   but now it results in
 {{{#!cpp
         logger = log4cplus::Logger::getInstance(getRootLoggerName());
 }}}

 - Considering these, I guess we should handle cases with buffering
   more explicitly, instead of abusing existing states of the class.
   For example, introduce a member variable to indicate whether any
   spec has been given, and flush-buffer-and-remove-it only for the
   first time it's configured.

 '''logger_manager.h'''

 - what's the purpose of the change?
 {{{#!diff
 -        for (T i = start; i != finish; ++i) {
 -            processSpecification(*i);
 +        if (start == finish) {
 +            process();
 +        } else {
 +            for (T i = start; i != finish; ++i) {
 +                processSpecification(*i);
 +            }
 }}}
   hmm, okay, after seeing everything I think I understand it, but it
   doesn't seem to be tested, and in any case I think we should revisit
   the interface (see the previous points).
 - "empty iterator" should be "empty specification"?
 {{{#!cpp
     void process() {
         // empty iterator; set defaults
         const LoggerSpecification spec;
         processSpecification(spec);
     }
 }}}
   also, we don't need a temporary object in this case:
 {{{#!cpp
         processSpecification(LoggerSpecification());
 }}}
   and, like the previous case, I guess it's better to clearly separate
   the interface for buffer flushing.

 '''cfgmgr.py'''

 - I don't understand the purpose of the changes (and there's no test
   for these changes).  Please explain and/or add comments.

 '''log/README'''

 - I'd also note that process() is normally called from
   `ModuleCCSession` if the program uses the config framework (so it
   doesn't do it explicitly in its program code).
 {{{
 be flushed according to the specification. Note that if this option is
 used,
 the program SHOULD call one of the LoggerManager's process() calls. If the
 }}}

 '''python log.cc'''

 - supporting keyworded parameters is nice, but we should probably test
   it.
 - there's an unbalanced parenthesis
 {{{
         "severity (optional): one of 'DEBUG', 'INFO', 'WARN', 'ERROR' or "
         "'FATAL')\n"
 }}}
 - s/pointed/point/?
 {{{
         "to be stored internally until log_config_update is called, at "
         "which pointed they shall be logged."},
 }}}

-- 
Ticket URL: <http://bind10.isc.org/ticket/2445#comment:12>
BIND 10 Development <http://bind10.isc.org>
BIND 10 Development