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):

 Replying to [comment:17 jelte]:

 '''About singleton'''

 > Come to think of it, flushing the logbuffer should to in processEnd().
 If we want to get rid of the singleton storage, what we *could* do is get
 all known loggers in processInit(), and do getAppender("buffer") on them,
 storing them in a vector of `SharedAppenderPtrs`, and flush those in
 processEnd() (instead of using the singleton like my last commit does).

 In that case the vector would have to be a singleton, so it wouldn't
 really be a "solution".  We could still have processInit() return the
 buffer to the caller, (the caller of) which would then pass it
 `processEnd()`, but that doesn't really seem to be clean anyway.  At
 this point I guess I have to give up "making it right" within this
 ticket.  So, let's keep the singleton buffer as is.

 Personally, I'd still like to clean up the singleton/global stuff in
 libb10-log as a future dream.  IMO there are too many global instances
 within this library, making it more difficult to understand/test and
 less predictable/robust.  What I'd envision is to unify all global
 stuff into a single instance of `LoggerManager` class (which will
 effectively be a singleton).  All other singleton/global instances of
 the current implementation, including the buffer added in this branch,
 will become part of the `LoggerManager` instance.  initLogger() will
 create the manager and return a pointer (or shared pointer) to it.
 This will be expected to be destroyed at the end of application's
 main(), at which necessary cleanups take place, including the
 last-resort log flush.  This happens before main() returns, minimizing
 the risk of having destruction fiasco.

 But that's obviously beyond the scope of this ticket, even if it makes
 sense.  And probably something we only dream but not actually work on.

 > > '''changelog'''
 > >
 > > I think we need a changelog entry for this task.
 >
 > ack, proposal:
 >
 > [bug/func?]   jelte
 > The system no longer prints initial log messages to stdout regardless of
 what logging configuration is present, but it temporarily stores any log
 messages until the configuration is processed. If there is no specific
 configuration, or if the configuration cannot be accessed, it will still
 fall back to stdout.
 > Note that there are still a few instances where output is printed, these
 shall be addressed separately.

 This looks okay.

 > > '''log_buffer.h'''

 > > - 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
 >
 > dunno, part of the reason this whole set of classes works in a non-
 obvious matter is because of the many pimpls there already :)
 [...]
 > Note, originally I had put both of these classes within an unnamed
 namespace in logger_manager_impl.cc, but then testing was a problem.

 By mentioning _impl.xx, I didn't mean the pimpl idiom, but clarifying that
 the `LogBuffer` class etc are part of internal helpers when we use
 log4cplus as the underlying log library.  e.g, so they won't be
 accidentally used by normal applications.  In that sense, my specific
 suggestion is to rename the files, and introduce a separate namespace
 like "detail", "internal", or "lgo4cplus_helper" under isc::log for
 these.

 > > '''log_buffer.cc'''

 > > - 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.
 >
 > hence the original potentially superfluous copies, and the only-dump-to-
 stdout instead of trying to still use the log4cplus system. But do the
 above changes (store shared ptrs to clones) alleviate your concern here?

 Actually, not fully so.  For example, I'd be afraid whether 'manager'
 refers to a valid object at this point:
 {{{#!cpp
     const log4cplus::LogLevelManager& manager =
         log4cplus::getLogLevelManager();
 }}}
 Maybe log4cplus guarantees it somehow, but it seems to be less
 reliable practice to rely on such subtle details of an external
 library.

 Since this method is expected to be called in a very special context
 (essentially after the program's lifetime), I'd be as conservative as
 possible: avoid using user-defined classes or other/std libraries as
 much as possible, e.g:
 {{{#!cpp
     for (it = stored_.begin(); it != stored_.end(); ++it) {
         printf("Severity=%d [%s]: %s\n", (*it)->getLogLevel(),
                (*it)->getLoggerName().c_str(),
 (*it)->getMessage().c_str());
     }
 }}}

 > > - `LogBuffer::flush`: what if it throws before clear()?
 > >
 >
 > then it is not cleared :) (I considered copying the vector, and removing
 items as they are flushed one by one, but tbh it did not seem worth the
 trouble)

 You could safely move the contents of stored_ to a different local
 vector using vector::swap, ensuring stored_ will be always cleared
 even if flush() throws in the middle of it:

 {{{#!cpp
     LoggerEventPtrList stored_copy;
     stored_.swap(stored_copy);

     LoggerEventPtrList::const_iterator it;
     for (it = stored_copy.begin(); it != stored_copy.end(); ++it) {
         log4cplus::Logger logger =
             log4cplus::Logger::getInstance((*it)->getLoggerName());

         logger.log((*it)->getLogLevel(), (*it)->getMessage());
     }
     flushed_ = true;
 }}}

 This requires a bit more additional code but I don't see any "trouble"
 in it.  See also the next topic.

 > > '''log_buffer_unittest.cc'''

 > > - 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.
 >
 > Added, it simply prevents the 'Foo' messages to be dumped to stdout
 (they need to go *somewhere*)

 Okay, but while trying to understand it, I found one minor and subtle
 issue: if we simply do flush here:
 {{{#!cpp
     ~LogBufferTest() {
         buffer1.flush();
         buffer2.flush();
     }
 }}}
 it would result in extending the vector while flush() iterating
 through that exact vector (because the logger still has the
 `BufferAppender`, which shares the same buffer), leading to a messy
 effect (crash in my case).  If flush() works on a swapped vector, we
 could avoid such disruption.

 > > - 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.
 >
 > I guess this other point ties in more to whether we should forcibly hide
 the type as deep as possible. (but in that case the tests would still need
 to create them somehow)

 I think in this case the issue is to separate things (rather than
 "hide") specific to a particular library, especially if it could be
 switched to something else (like the case for botan vs openssl).  If
 these are cleanly separated, it will be easier to build/test
 everything for a particular set of environment.  But for this ticket I
 don't necessarily insist that.

 > > '''buffer_manager_impl.cc'''

 - processSpecification: It now seems to be back to the original
   version, so it's probably better to make it a full copy of it.  At
   least I guess we should remove this comment:
 {{{#!cpp
     // If this is an 'empty' specification, just set the root logger
 }}}

 > > '''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.
 > >
 >
 > Added comments (we need to trigger the process() call to flush the
 buffers in case there is no explicit config)

 Okay, and if I understand it correctly, this means cfgmgr will use the
 default of log library, not the default given in logging.spec, right?
 Shouldn't it be the latter?  Even though they are likely to be the
 same, they can be different. (Although, technically this doesn't seem
 to be an issue of this branch, but already exists in the current
 implementation).

 > > '''python log.cc'''
 > >
 > > - supporting keyworded parameters is nice, but we should probably test
 > >   it.
 >
 > added, but only whether they are recognized (and fail on wrong types); I
 don't believe we have any provisioning for checking whether they got
 interpreted as expected...

 It's probably okay in practice.

 '''log/README'''

 - I'd reorder some sentences, like this:
 {{{
 ... Note that if this option is used,
 the program SHOULD call one of the LoggerManager's process() calls (if
 you are using the built-in logging configuration handling in
 ModuleCCSession, this is automatically handled.)  If the program exits
 before this is done, all log messages are dumped in a shortened format
 to stdout (so that no messages get lost).
 }}}

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