Opened 7 years ago

Closed 7 years ago

Last modified 7 years ago

#2445 closed defect (fixed)

suppress initial log

Reported by: jinmei Owned by: jelte
Priority: medium Milestone: Sprint-20121218
Component: ~Boss of BIND (obsolete) Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 4 Add Hours to Ticket: 11.6
Total Hours: 0 Internal?: no

Description

I think we need to have some (even not very clean) way to suppress
the amount of initial log messages dumped to stdout. No specific
idea right now, though.

Subtickets

Change History (32)

comment:1 follow-up: Changed 7 years ago by jreed

This may be a duplicate of #1898.

comment:2 in reply to: ↑ 1 ; follow-up: Changed 7 years ago by vorner

Hello

Replying to jreed:

This may be a duplicate of #1898.

I think it is.

Anyway, if we only want to suppress it (and not put anywhere at startup, for
which we'll need to do the ring buffer for messages, as we discussed), it could
be just a simple change of default severity. The output goes to stderr, because
we didn't read the configuration yet and we don't know where else to log.

comment:3 in reply to: ↑ 2 Changed 7 years ago by jinmei

Replying to vorner:

This may be a duplicate of #1898.

I think it is.

In some sense, yes (and I actually didn't check pre-existing one in
this case). But my intent of opening this ticket is that based on the
observation that we won't have time to have a clean fix to this we
should provide some workaround solution by the beta release.

Anyway, if we only want to suppress it (and not put anywhere at startup, for
which we'll need to do the ring buffer for messages, as we discussed), it could
be just a simple change of default severity. The output goes to stderr, because
we didn't read the configuration yet and we don't know where else to log.

Currently it dumps INFO level logs, which are still noisy at least to
me. But increasing the default level to something higher than INFO do
not seem to be a good idea to me either.

I guess some of these initial INFO logs should actually be categorized
as DEBUG, but that's probably a subject of a different ticket.

Considering these, my suggestion for this ticket is:

  • introduce a way to specify the "destination" of initial logs. it can be specified via a command line option of bind10
  • set the default destination to a file, something like ${prefix}/var/bind10-devel/bind10-init.log
  • on the startup of bind10, it only produces a few lines of messages saying (in addition to some "hello") where the initial logs go.

comment:4 Changed 7 years ago by jinmei

  • Milestone set to Next-Sprint-Proposed

comment:5 Changed 7 years ago by jelte

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

comment:6 follow-up: Changed 7 years ago by jelte

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

tbh, I think logging to some file given in the command line is really just moving the problem sideways a little, and not really constructive.

But I did some quick experiments, and I think temporarily storing the logs isn't that hard

comment:7 in reply to: ↑ 6 Changed 7 years ago by jinmei

Replying to jelte:

tbh, I think logging to some file given in the command line is really just moving the problem sideways a little, [...]

True, but...

[...] and not really constructive.

...it may depend on the definition of "constructive", but I personally
think it's worth working around (assuming a complete solution is much
harder) in terms of enticing people to actually use it.

comment:8 Changed 7 years ago by shane

See also ticket #1898.

comment:9 Changed 7 years ago by jelte

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

it was doable :)

So here is a version that optionally creates a new specialized logger appender (instead of the default stdout), during initialization of the logging system. It stores all logging events until an actual specification is processed, at which time all stored events are replayed to the now fully configured logger. Should this for some reason never happen (say, it can't connect to msgq), everything that is not replayed (i called it flushed) is dumped to stdout.

It does not use a ring buffer but a simple vector of logging events, and it is only usable once (after it has been flushed it will refuse to accept new events).

I've updated the components to enable this, and any output that still goes to stdout or stderr is because the offending program is writing directly there, which should be addressed separately. But apart from that, this should also solve #1898.

comment:10 Changed 7 years ago by jinmei

  • Owner changed from UnAssigned to jinmei

comment:11 Changed 7 years ago by jinmei

I'm in the middle of review, but one possibly important point first:
unit test for dhcp6 failed for me:

Running command: ../b10-dhcp6 -v -s -p 10547
Process finished, return code=-15, stdout=173 bytes, stderr=568 bytes
.
======================================================================
FAIL: test_alive (__main__.TestDhcpv6Daemon)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/jinmei/src/isc/git/bind10-2445/src/bin/dhcp6/tests/dhcp6_test.py", line 167, in test_alive
    self.assertEqual(output_text.count("DHCP6_STARTING"), 1)
AssertionError: 0 != 1

I didn't look into it further, so I don't know if it's dhcp6 specific
regression or the interaction with this branch (it doesn't fail on
master).

comment:12 Changed 7 years ago 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:
        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:
    LogBuffer::~LogBuffer() {
        try {
            flush_stdout();
        } catch (...) {}
    }
    
  • LogBuffer::flush: why is event copied?
            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):
            // 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:
        /// \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:
    -    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
            logger = log4cplus::Logger::getInstance(expandLoggerName(""));
    
    but now it results in
            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?
    -        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"?
        void process() {
            // empty iterator; set defaults
            const LoggerSpecification spec;
            processSpecification(spec);
        }
    
    also, we don't need a temporary object in this case:
            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."},
    

comment:13 Changed 7 years ago by jinmei

  • Owner changed from jinmei to jelte

comment:14 follow-up: Changed 7 years ago by jelte

While I work on the smaller points, let me first comment on two of your larger points, since they are somewhat related, and chosen for a reason:

  1. Singleton buffer
  2. Replacing appenders on specification with empty output options list

Currently, behaviour does change on the Impl class level (see below, i'm changing that back), but not on the public API, because (and this is kind of obfuscated by the pimpl implementation; the outer calls contain extra lines of code), in logger_manager.[h|cc]'s existing processSpecfication() calls, the entire logging system is reset; all appenders are destroyed, and new defaults are created (for the root logger). And then it starts working through the specification(s) for the actual logger(s).

So the reason I put it in a singleton was to not have to collect all possible bufferappenders and keep them around before the call to processInit() in loggermanager.h's process() calls; otherwise either processInit() would need to change; and in that case behaviour would change, since it would no longer automatically support *removing* loggers from your specification (they'd remain unchanged), or alternatively, it would have to make lists of loggers and bufferappenders before and after the change and then go through them, which I suspect would be more brittle than this is :)

(note I do agree about the if name="" getRootLogger, but that's not a very difficult change)

Regarding 2, now that I look at it again, it's not even necessary (but due to a mistake in the process() method without arguments it looked like it did. The appenders are reset and replaced by defaults anyway, so removing them and readding a default stdout one did not actually change behaviour (but it was unnecessary).

I hope I'm making sense here :)

comment:15 in reply to: ↑ 14 Changed 7 years ago by jinmei

Replying to jelte:

Okay, I realize I didn't fully understand how the logging
initialization and reconfiguration work. Now I've taken a closer look
at the implementation, and with my revised understanding I'm still not
convinced a singleton must be inevitably used (meaning other
alternatives would rather be considered much worse).

While I work on the smaller points, let me first comment on two of your larger points, since they are somewhat related, and chosen for a reason:

  1. Singleton buffer
  2. Replacing appenders on specification with empty output options list

Currently, behaviour does change on the Impl class level (see below,
i'm changing that back), but not on the public API, because (and
this is kind of obfuscated by the pimpl implementation; the outer
calls contain extra lines of code), in logger_manager.[h|cc]'s
existing processSpecfication() calls, the entire logging system is
reset; all appenders are destroyed, and new defaults are created
(for the root logger). And then it starts working through the
specification(s) for the actual logger(s).

I'd like to clarify a few things here.

First, by "existing processSpecfication() calls" I guess you actually
meant LoggerManager::process() calls (except for the one you added
in this branch), which call processInit(), which calls
LoggerManagerImpl::processInit(), which calls
LoggerManagerImpl::initRootLogger(), where some default values for
b10root logger object are reset. But, in my understanding,
initRootLogger() shouldn't destroy existing appenders in b10root
at this point. Note that log4cplus::Logger::getInstance() returns
an existing logger if one exists.

Secondly, in LoggerManagerImpl::processSpecfication(), existing
appenders for the specified name of logger can be destroyed, but (in
the original version before this branch) it seems to happen only if
output options are given.

So the reason I put it in a singleton was to not have to collect all possible bufferappenders and keep them around before the call to processInit() in loggermanager.h's process() calls; otherwise either processInit() would need to change; and in that case behaviour would change, since it would no longer automatically support *removing* loggers from your specification (they'd remain unchanged), or alternatively, it would have to make lists of loggers and bufferappenders before and after the change and then go through them, which I suspect would be more brittle than this is :)

Here I'm afraid I don't understand...what do you mean by "no longer
automatically support removing loggers"? In my understanding (as I
said above), there's no current behavior of "automatically removing
loggers", either in processInit() (which actually doesn't touch
existing ones except for the default log level etc on the root) or in
LoggerManagerImpl::processSpecfication() (unless output options are
specified).

With my revised understanding, our goal seems to be reasonably
achievable by extending processInit():

void
LoggerManagerImpl::processInit() {
    // b10root should exist in the context where this method is called
    log4cplus::Logger b10root = log4cplus::Logger::getInstance(
                                                    getRootLoggerName());
    SharedAppenderPtr buffer_appender = b10root.getAppender("buffer");
    if (buffer_appender) {
        // BufferAppender::flush() is an extension, which would flush the
        // internal buffer
        dynamic_cast<BufferAppender&>(*buffer_appender).flush();
    }

    log4cplus::Logger::getDefaultHierarchy().resetConfiguration();
    initRootLogger();
}

comment:16 Changed 7 years ago by jelte

In the original code (and the now revised process(), see below); it's not initRootLogger that destroys anything, it is getDefaultHierarchy().resetConfiguration(), from http://log4cplus.sourceforge.net/docs/html/classlog4cplus_1_1Hierarchy.html#aa85b45cef82941012cd1d0f4a8ac89b8 :

Reset all values contained in this hierarchy instance to their default.

This removes all appenders from all loggers, sets the LogLevel of all
non-root loggers to NOT_SET_LOG_LEVEL, sets their additivity flag to
true and sets the LogLevel of the root logger to DEBUG_LOG_LEVEL.
Moreover, message disabling is set its default "off" value.

Existing loggers are not removed. They are just reset.

After that, initRootLogger readds a new stdout to the root logger.

The problem with calling flush in processInit() is that there is nothing to flush to yet :)

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

Anyway, I've addressed all the other comments, (commits 1 and 2, except for the iostream which is in 3), and did this in the third commit; there is still an empty process(), but it simply calls processInit() followed by processEnd() (it is no more than a convenience form of the iterator one with an empty iterator). The actual processSpecification() implementation now no longer needs to do the fragily getRootLogger thing and it also no longer needs to care about flushing.

comment:17 follow-up: Changed 7 years ago by jelte

  • Owner changed from jelte to jinmei

And here are the comments about the other comments:

Replying to 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.

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.

log_buffer.h

  • If I understand it correctly, I think friend is too strong a tool in this case:
        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.

Yeah, I can just add a getBufferSize(), done.

  • flush() isn't documented.

done

  • 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

dunno, part of the reason this whole set of classes works in a non-obvious matter is because of the many pimpls there already :)

Of course a related question is whether some of the things we do would even be possible if we'd change the logging system (and whether it would require rewriting the public side as well anyway).

Also, there is the problem that this internal event type is simply is what we get (in the sublass of log4cplus::Appender). We could of course move *that* to some file with a hint in its name, and then wrap it in our own extra super/subclass pair, with its own replay() call. But at some point I think we need to stop adding classes tbh.

Note, originally I had put both of these classes within an unnamed namespace in logger_manager_impl.cc, but then testing was a problem.

  • 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.

oh right, of course.

log_buffer.cc

  • I'd include <iostream> if we keep using std::cout etc (but see below too)

added (in the third commit about the other change, forgot about this one)

  • 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?

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

done

  • 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:
    LogBuffer::~LogBuffer() {
        try {
            flush_stdout();
        } catch (...) {}
    }
    

Ok

  • LogBuffer::flush: why is event copied?
            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.

Yeah, i changed this to a normal iterator when doing the above

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

log_buffer_unittest.cc

  • Isn't it better to use a mock appender to inspect what happens on flush()?

I originally had one, but it was really the same as the existing one. Apart from testing that it is empty after flush, and that the events have been passed on to whatever appender is now in the logger, I'm not sure what else it should test anyway (actual output it tested through the other script test)

  • I don't understand why we need this trick (or what exactly it does):
            // 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*)

  • LogBuffer::add() doesn't seem to be directly tested.

added

  • BufferAppender::append() doesn't seem to be directly tested.

i just made it protected (to reflect the original, a property I had missed), so unless we want to reintroduce a friend again (or yet another subclass), this would be quite hard :)

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

buffer_logger_test.cc

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

ok

buffer_manager_impl.h

  • createBufferAppender: has a non existent parameter description:
        /// \param opt Output options for this appender.
    

oops :) removed

buffer_manager_impl.cc

  • why is scoped_ptr.hpp included?

because i forgot to remove it, done now

  • 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.

see other comment

  • processSpecification: this change also seems to be fragile:
    -    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
            logger = log4cplus::Logger::getInstance(expandLoggerName(""));
    
    but now it results in
            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.

partly see other comment, but i did pull it out and change the 'no-specification' process version.

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)

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
    

added

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...

  • there's an unbalanced parenthesis
            "severity (optional): one of 'DEBUG', 'INFO', 'WARN', 'ERROR' or "
            "'FATAL')\n"
    

removed :)

  • s/pointed/point/?
            "to be stored internally until log_config_update is called, at "
            "which pointed they shall be logged."},
    

fixed

comment:18 in reply to: ↑ 17 ; follow-up: Changed 7 years ago by jinmei

Replying to 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:

    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:

    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:

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

    ~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:
        // 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).
    

comment:19 Changed 7 years ago by jinmei

  • Owner changed from jinmei to jelte

comment:20 in reply to: ↑ 18 ; follow-up: Changed 7 years ago by jelte

  • Owner changed from jelte to jinmei

Note: I have made 3 commits; the first is the name and namespace change, the second is the rest of the comments, and the third is a proposal to get rid of the logbuffer singleton (we can still decide not to include that one), but see below :)

Replying to jinmei:

Replying to 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.

perhaps not really that much more clean, but i was imagining it'd be stored in the LoggerManagerImpl instance. In fact, I don't understand why everything in LoggerManagerImpl was made static; it makes sense for a few of the things there, but most calls are made on an instance anyway.

So in the third commit, (which we can leave out if this is too much of a change), I've applied this idea; each BufferAppender? does keep its own logbuffer; LoggerManagerImpl walks through all loggers and collects them in the (no longer static) processInit(), and flushes them all in the (also no longer static) processEnd(), and the singleton LogBuffer? is removed.

Personally, I'd still like to clean up the singleton/global stuff in

<snip>

I have no problems with that approach, but:

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.

yeah...

log_buffer.h

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.

ah, like that, ok, done

log_buffer.cc

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:

    for (it = stored_.begin(); it != stored_.end(); ++it) {
        printf("Severity=%d [%s]: %s\n", (*it)->getLogLevel(),
               (*it)->getLoggerName().c_str(), (*it)->getMessage().c_str());
    }

Right, at the very initial version it only printed message and logger name, and I didn't really like printing severity as a number, which is why i pulled in the manager again. But ok, using the above now.

  • LogBuffer::flush: what if it throws before clear()?
    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.

ok, using this as well.

log_buffer_unittest.cc

Okay, but while trying to understand it, I found one minor and subtle
issue: if we simply do flush here:

    ~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.

that's done now :)

  • 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.

Ok

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:
        // If this is an 'empty' specification, just set the root logger
    

doh, of course

cfgmgr.py

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

yes, and yes

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

done

comment:21 in reply to: ↑ 20 Changed 7 years ago by jinmei

Replying to jelte:

About singleton

perhaps not really that much more clean, but i was imagining it'd be stored in the LoggerManagerImpl instance. In fact, I don't understand why everything in LoggerManagerImpl was made static; it makes sense for a few of the things there, but most calls are made on an instance anyway.

So in the third commit, (which we can leave out if this is too much of a change), I've applied this idea; each BufferAppender? does keep its own logbuffer; LoggerManagerImpl walks through all loggers and collects them in the (no longer static) processInit(), and flushes them all in the (also no longer static) processEnd(), and the singleton LogBuffer? is removed.

I think I like it. At least it seems to be one step closer to the
"right design". And, to this end, I'd rather unify LogBuffer
into BufferAppender. In fact, methods of BufferAppender are now
trivial wrappers to corresponding methods of LogBuffer (flush to
flush, append to LogBuffer::add()), and the LogBuffer itself is
basically a simple encapsulation of a vector. So the revised
BufferAppender would look like:

class BufferAppender : public log4cplus::Appender {
public:
    void flush(); // this does what LogBuffer::flush did
protected:
    // this does what LogBuffer::add() did
    virtual void append(const log4cplus::spi::InternalLoggingEvent& event);
private:
    void flushStdout();
    LoggerEventPtrList stored_;
    bool flushed_;
};

And we won't need getLogBuffer(); A new
BufferAppender::getBufferSize() would suffice (and, in any event,
I'd like to avoid providing non-const method unless it's related to
the core responsibility of the class because it can be abused to break
class integrity unnecessarily).

log_buffer.cc

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:

    for (it = stored_.begin(); it != stored_.end(); ++it) {
        printf("Severity=%d [%s]: %s\n", (*it)->getLogLevel(),
               (*it)->getLoggerName().c_str(), (*it)->getMessage().c_str());
    }

Right, at the very initial version it only printed message and logger name, and I didn't really like printing severity as a number, which is why i pulled in the manager again. But ok, using the above now.

I've come up with an idea to improve it a bit: convert the integer
levels to string versions at the time of BufferAppender::append()
and store the result in the buffer. In flushStdout() we sue the
stored string.

log_buffer_impl.cc

  • In flush(), you shouldn't need explicit clear() after swap:
        LoggerEventPtrList stored_copy;
        stored_.swap(stored_copy);
    ...
        stored_.clear();
    

logger_manager_impl.cc

  • in flushBufferAppenders, I suspect making a local copy is not (necessarily) needed. In this case, there's no risk of disruption I mentioned in my previous comment, and if flushBufferAppenders() throws in the middle of it, remaining appenders in buffer_appender_store_ will be cleaned up in the manager's destructor (which will soon take place in practice). But if you want to guarantee that buffer_appender_store_ will always be cleared within flushBufferAppenders(), I don't oppose to making a copy here, too.

comment:22 Changed 7 years ago by jinmei

  • Owner changed from jinmei to jelte

comment:23 Changed 7 years ago by jinmei

One more thing: in LoggerManagerImpl::flushBufferAppenders(),
I'd make sure dynamic_cast succeeds:

        internal::BufferAppender* app =
            dynamic_cast<internal::BufferAppender*>(it->get());
        assert(app != NULL); // <= add this line
        app->flush();

comment:24 follow-up: Changed 7 years ago by jinmei

Yet another thing: I guess we can simply remove these:

    //LogBuffer buffer_appender1->getLogBuffer().
    //LogBuffer buffer_appender2->getLogBuffer().

comment:25 in reply to: ↑ 24 ; follow-up: Changed 7 years ago by jelte

  • Owner changed from jelte to jinmei

Replying to jinmei:

Replying to jelte:

I think I like it. At least it seems to be one step closer to the
"right design". And, to this end, I'd rather unify LogBuffer
into BufferAppender. In fact, methods of BufferAppender are now
trivial wrappers to corresponding methods of LogBuffer (flush to
flush, append to LogBuffer::add()), and the LogBuffer itself is
basically a simple encapsulation of a vector. So the revised
BufferAppender would look like:

<snip>

OK, good point :) Done. Renamed some files (again), to match the contents (i.e. log_buffer_impl -> buffer_appender_impl)

Right, at the very initial version it only printed message and logger name, and I didn't really like printing severity as a number, which is why i pulled in the manager again. But ok, using the above now.

I've come up with an idea to improve it a bit: convert the integer
levels to string versions at the time of BufferAppender::append()
and store the result in the buffer. In flushStdout() we sue the
stored string.

ah, good idea :) Done too, added and changed some typedefs in an attempt to keep it readable; log level strings are now converted to string in append. Does result in a few more copies, but I do not think this is a problem (from the point of view of performance).

log_buffer_impl.cc

  • In flush(), you shouldn't need explicit clear() after swap:
        LoggerEventPtrList stored_copy;
        stored_.swap(stored_copy);
    ...
        stored_.clear();
    

removed

logger_manager_impl.cc

  • in flushBufferAppenders, I suspect making a local copy is not (necessarily) needed. In this case, there's no risk of disruption I mentioned in my previous comment, and if flushBufferAppenders() throws in the middle of it, remaining appenders in buffer_appender_store_ will be cleaned up in the manager's destructor (which will soon take place in practice). But if you want to guarantee that buffer_appender_store_ will always be cleared within flushBufferAppenders(), I don't oppose to making a copy here, too.

I know, however, I indeed did it so that it was always cleared.

Replying to jinmei:

One more thing: in LoggerManagerImpl::flushBufferAppenders(),
I'd make sure dynamic_cast succeeds:

        internal::BufferAppender* app =
            dynamic_cast<internal::BufferAppender*>(it->get());
        assert(app != NULL); // <= add this line
        app->flush();

done

Replying to jinmei:

Yet another thing: I guess we can simply remove these:

    //LogBuffer buffer_appender1->getLogBuffer().
    //LogBuffer buffer_appender2->getLogBuffer().

yeah removed (along with some other cleanups)

comment:26 in reply to: ↑ 25 Changed 7 years ago by jinmei

I made a couple of small changes. I believe these are okay, but please
check.

And, one final question. If I start bind10 with a broken config
and see buffered logs in stdtout at the end, the logs include DEBUG
messages.

% ./src/bin/bind10/run_bind10.sh 
INFO [b10-cfgmgr.cfgmgr]: CFGMGR_CONFIG_FILE Configuration manager starting with configuration file: /Users/jinmei/src/isc/git/bind10-2445/b10-config.db
FATAL [b10-cfgmgr.cfgmgr]: CFGMGR_DATA_READ_ERROR error reading configuration database from disk: Configuration file out of date or corrupt, please update or remove /Users/jinmei/src/isc/git/bind10-2445/b10-config.db
INFO [b10-boss.boss]: BIND10_STARTING starting BIND10: bind10 20110223 (BIND 10 20120817)
DEBUG [b10-boss.boss]: BIND10_CHECK_MSGQ_ALREADY_RUNNING checking if msgq is already running
...

I didn't figure out how this happened, but shouldn't these be only
shown when we start bind 10 with -v?

comment:27 Changed 7 years ago by jinmei

  • Owner changed from jinmei to jelte

comment:28 follow-up: Changed 7 years ago by jelte

  • Owner changed from jelte to jinmei

Hmm, that's actually slightly tricky, and we have a little bit of a trade-off here.

in createBufferAppender(), I set the logger level to log anything. If this isn't done, any level past INFO won't be logged, even if the later config says DEBUG (since it has been filtered out already and did not even get to the appender).

But this causes everything to be dumped in case it gets to flushStdout().

I just considered another approach; storing the initial log level, and checking it in flushStdout (normal flush should use the log level of the spec it just applied). But then for at least bind10-boss, the DEBUG messages wouldn't show up in flushStdout even if -v was given, because boss sets the log level of the logger manually, and right now I can't think of any way to do this 'right';

  • these two approaches either show too much or too little
  • removing setLogLevel(TRACE) causes debug messages to be dropped in the case where -v is *not* given, but the config says DEBUG (that is, the messages until process() on the config is first called)
  • storing the *current* loglevel of the logger during append() would also not work, since we'd still need to set it to TRACE initially then, which would mean the same result as what it originally did (dump too much).

For now I'm removing the setLogLevel(TRACE), so it will dump DEBUG on -v, and not dump them in normal mode, but then, in the -v is not given, and working configuration that sets it to DEBUG, some initial DEBUG messages get lost....

Maybe some idea will come to me after some rest, but for now I think we'll have to live with that.

comment:29 in reply to: ↑ 28 Changed 7 years ago by jinmei

Replying to jelte:

Hmm, that's actually slightly tricky, and we have a little bit of a trade-off here.

[...]

For now I'm removing the setLogLevel(TRACE), so it will dump DEBUG on -v, and not dump them in normal mode, but then, in the -v is not given, and working configuration that sets it to DEBUG, some initial DEBUG messages get lost....

In that case I'd rather suggest the previous behavior. When something
goes wrong in initial setup and the loggers fall back to the last
resort, we'll probably want to see verbose messages.

A more possible solution I can think of is to somehow delay the log
initialization (or reinitialize it) after parsing the command line
options, and initialize it with corresponding log level (by extending
the interface further to make it possible). But I think we should
complete the ticket now and defer any solution to this problem to a
separate task - actually we originally intended to just do a
lightweight "hack" in this ticket, but spent much larger time than
we'd have needed for it (I'm much more happier with the resulting more
complete solution, though).

So, I suggest resetting to 0a9dafb and merge it (and open a new ticket
for the remaining issue).

comment:30 Changed 7 years ago by jinmei

  • Owner changed from jinmei to jelte

comment:31 Changed 7 years ago by jelte

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

OK, merged, created ticket #2550, and added the current behaviour to the changelog entry. Closing ticket!

comment:32 Changed 7 years ago by jinmei

  • Add Hours to Ticket changed from 0 to 11.6
Note: See TracTickets for help on using tickets.