Re: [boost] [log] Boost.Log Review...

Subject: Re: [boost] [log] Boost.Log Review...
From: Sean Chittenden (sean_at_[hidden])
Date: 2010-03-13 21:36:59

>> The above wasn't explicitly distilled in the documentation in a
>> single place, but I think future developers would find it very useful
>> to see that spelled out explicitly.  Given the extremely modular
>> design of the library, I understand why the docs are the way they are
>> and know that some of this is touched on in the Design Overview, but
>> until I became very competent with the library, the documentation
>> seemed too abstract.  Despite the importance of logging, becoming a
>> logging expert was tangential to the problem I was trying to solve
>> and I would have personally found the above summary very useful.
> 
> Well, that summary may describe your use case very well, but it is by no 
> means complete with regard to Boost.Log as a whole. I would even say 
> it's misleading in some parts - in particular: "Loggers are collections 
> of Sinks" and "Think of channels as a Sink-level observer".

Fair response.  I think a more general way for me to classify my response/concern (instead of providing a loosely worded example) would be:

"Which class does what and how do the classes relate to each other?"

Right now answering that question results in a decent exploration of Boost.Log's code and documentation.  It would have been useful to me, and likely future developers, to have the classes that comprise Boost.Log summarized so that conceptual map could have been more easily formed without having to dig in to the actual headers.  Something similar to the contents of the Definitions page, but with architectural clues.

http://boost-log.sourceforge.net/libs/log/doc/html/log/defs.html

As an example, expanding on the Sinks definition from above:

> Log Sink: A target, to which all log records are fed after being collected from user's application. It is sink's nature that defines where and how the log records are going to be stored.

Maybe include something as brief as:

> With a Log Sink, developers can modify the filtering and add additional backends.

I consider myself a modestly competent user of boost, but still am getting parts of this wrong after over three months of using/digging in to Boost.Log.

>> A hindsight 20/20 architecture and terminology for Boost.Log could be
>> simplified in terms of:
> 
> What is "20/20"? I'll continue my answers assuming that the following 
> was your understanding of the current Boost.Log architecture.

Correct.  The contents of this email has evolved from sometime around mid-January or whenever I learned that Boost.Log was going to be reviewed and accepted.  It also crudely mirrors my understanding of the library as I went through the development process of utilizing the library.

>> *) Log Record pre-conditions.  Sinks control whether or not a Log
>> Record is to be generated
> 
> Looks like you're confusing sinks with filters. Also, don't forget about 
> the global filter.

I became sloppy with my terminology.  Filters are stored in Sinks and the Global core.

Speaking of filters, yesterday I stumbled across a feature request:

> Program received signal SIGABRT, Aborted.
> 0x00007fff81de2fe6 in __kill ()
> (gdb) bt
> #0  0x00007fff81de2fe6 in __kill ()
> #1  0x00007fff81e83e32 in abort ()
> #2  0x00007fff81e03de2 in _Unwind_Resume ()
> #3  0x00000001000a3b1c in main (argc=1, argv=0x7fff5fbff338) at /tmp/foo.cc:267

If I wrap everything in a boost exception, I get:

> exception: /usr/local/include/boost/log/filters/attr.hpp(134): Throw in function (unknown)
> Dynamic exception type: N5boost16exception_detail10clone_implINS0_19error_info_injectorINS_12log_mt_posix13missing_valueEEEEE
> std::exception::what: Requested attribute value not found

It'd be nice if the error message were able to somehow include the string representation of the value (attribute) it wasn't able to find.  Turns out it was a type-o so I had an unregistered attribute, but the type-o would've been very easy to identify if it were included in the error message someplace (instead it took a fair amount of manual investigation and backtracking to figure out it was a filter searching for an attribute that didn't exist).

[snip useful responses/corrections ]

>> Observers could then be placed on Sinks that would stamp Log Records
>> with Severities, or Channels, or in whatever hodge-podge
>> configuration the developer wanted and such examples would be very
>> cookbook.
> 
> Now that you presented a code snippet, your suggestion makes more sense 
> to me. Let me express my thoughts on it in two parts:
> 
> 1. Custom log records. Yes, the model of "mandatory" attributes look 
> promising. It could, at least, partially solve the problem of possible 
> library misconfiguration that was highlighted in another review. I 
> imagine that some kind of log record prototype (or factory) should be 
> defined by the user in order to be able to construct log records with 
> the specific set of attribute values. Filters and formatters could then 
> request these mandatory attribute values without having to worry about 
> their absence. Lookup performance may also be higher, but I doubt it 
> will be compile-time. The idea is quite vague now but after some 
> thinking over it might become a good addition to the library.
> 
> 2. Designing sinks (and the core, I presume) after the log records. No, 
> that looks unacceptable to me, at least for what Boost.Log tries to 
> achieve. This would introduce too much coupling between the logging side 
> of the library (which tends to be exposed to many parts of the 
> application) and the consuming side (which tends to be configured in a 
> single place of the application). To my mind, these sides of the library 
> should be maximally decoupled. Also, it's not clear how to support 
> multiple log record types in such a design.

>> *) Global loggers vs. per-object references to singletons
> 
> Not sure I understand.

Is it better to have global objects that reference singletons:

> typedef boost::log::sources::severity_channel_logger_mt<levels::severity_level> logger_t;
> 
> BOOST_LOG_DECLARE_GLOBAL_LOGGER(default_log, logger_t);
> BOOST_LOG_DECLARE_GLOBAL_LOGGER_CTOR_ARGS(stats_log, logger_t, (boost::log::keywords::channel = "stats"));

or per object references to logging singletons:

> typedef boost::shared_ptr< boost::log::sinks::synchronous_sink< boost::log::sinks::text_ostream_backend > > console_sink_t;
> typedef boost::shared_ptr< boost::log::core > logger_core_t;
> 
> struct my_obj {
>   my_obj(logger_core_t& logger) : lg(logger) {}
>   void foo() { BOOST_LOG(lg) << "log msg"; }
>   logger_core_t& lg;
> }
> 
> int main() {
>   console_sink_t cerr_sink;
>   cerr_sink = boost::log::init_log_to_console(
>     std::cerr,
>     boost::log::keywords::filter = boost::log::filters::attr< int >("Severity") >= warning,
>     boost::log::keywords::format = "%TimeStamp%: %_%",
>     boost::log::keywords::auto_flush = true);
>   my_obj o(boost::log::core::get());
>   o.foo();
> }

... I think that example's right.

>> *) Channel severity loggers example
> 
> That example wouldn't be much different from the ones in sections about 
> severity_logger or channel_logger. But I'll add a code sample.

Where I spent time with this was figuring out how multiple chan severity loggers interacted with the core and how my app was supposed to interact with the distinct loggers, which were linked in to the core, behind the scenes.

> typedef boost::log::sources::severity_channel_logger_mt<levels::severity_level> logger_t;
> BOOST_LOG_DECLARE_GLOBAL_LOGGER(default_log, logger_t);
> BOOST_LOG_DECLARE_GLOBAL_LOGGER_CTOR_ARGS(lg1, logger_t, (boost::log::keywords::channel = "chan1"));
> BOOST_LOG_DECLARE_GLOBAL_LOGGER_CTOR_ARGS(lg2, logger_t, (boost::log::keywords::channel = "chan2"));
> #define LG1_WARN BOOST_LOG_SEV(lg1::get(), log_severities::warn)
> #define LG1_INFO BOOST_LOG_SEV(lg1::get(), log_severities::info)
> ...
> LG1_INFO << "info msg";

>> *) Setting up an initial console logger as
>> line one in main()
> 
> Hmm. Ok, I'll add something about that to the tutorial.

Easy to do (see above), but I didn't see anything that said, "it would be wise to do this first and then remove your console sink after you setup your logging environment."  Initially I disregarded the init_to_console() convenience functions while reading the docs, and it wasn't until I started dealing with error messages that weren't being logged to a file because my logging setup routines hadn't been completed (or had failed for some reason due to FS perms), that I suddenly took note of needing to get console logging working first.

>> *) Changing a backend filter at a later date
> 
> Just call set_filter on the backend, that's all.

This was one of the areas where there were lots of ways that I could do it, but I couldn't tell which was the right way.  libs/log didn't suggest a preferred mechanism or right way to do it.

>> *) Using async logging for INFO level logs, but switching to sync for
>> CRIT errors.
> 
> You can register two sinks - one synchronous and one asynchronous, and 
> set their filters accordingly.

Ah, clever way of handling that.

>> *) Obtaining the severity of a particular logger
> 
> You mean, the default severity? There's no public API for this, but 
> there's a protected function default_severity in the logger feature. Why 
> would you need it?

Internally you're using spirit for log record filtering, so it's impossible from what I can tell to do that inside of Boost.Log.  Having a way of poking at a sink to obtain information about its runtime status.  Using the above console sink as an example:

>   typedef boost::shared_ptr< boost::log::sinks::synchronous_sink< boost::log::sinks::text_ostream_backend > > console_sink_t;

>   console_sink_t cerr_sink;
>   cerr_sink = boost::log::init_log_to_console(
>     std::cerr,
>     boost::log::keywords::filter = boost::log::filters::attr< int >("Severity") >= warning,
>     boost::log::keywords::format = "%TimeStamp%: %_%",
>     boost::log::keywords::auto_flush = true);

> 
>   std::cout << "Current Severity Level: " << /* or something like this */ cerr_sink->filter_severity() << std::endl;

I ended up adding this to my application's surrounding code.

>> *) How do you remove log events given a severity level at compile
>> time.  Currently this isn't explicit defined in the documentation
>> like it is in Google's glog library:
>> 
>> http://google-glog.googlecode.com/svn/trunk/doc/glog.html#strip
> 
> The library has no direct means for that. Users can conditionally define 
> their logging macros, based on BOOST_LOG_SEV or pure C++ interface and 
> then enable or disable the particular logging statements from the source.

*nods*  I just didn't see anything in the docs to do this, which is why I ended up with the practice:

> #ifdef RELEASE

> # define LG1_WARN BOOST_LOG(null_log::get())
> #else
> # define LG1_WARN BOOST_LOG_SEV(lg1::get(), log_severities::warn)
> #endif

null_log always filters everything sent to it.  Probably less than ideal, but I couldn't think of a better way to handle this.

>> *) Is there a way to set a bit in a Log Record that overrides a
>> Sink's filter?  For instance, there are certain events that I want to
>> make sure go to the console 100% of the time without changing the
>> severity of the log message.  Do I just log twice?  It'd be keen if
>> Log Records could have a bit that could be set and would override a
>> filter.
>> 
>> bool log_to_console = true; BOOST_LOG_SEV_CONS(lg, warning,
>> log_to_console)<<  "my message";
> 
> You can set an attribute (say, "Emergency") for that record, and setup 
> filters so that whenever this attribute is present, the record is passed 
> on to the console backend.

You mean a scope attribute?

> boost::shared_ptr< attrs::mutable_constant< bool > > console_attr(new attrs::mutable_constant< bool >(false));
> lg.add_attribute("Console", console_attr);
> BOOST_LOG(lg) << "Console is false by default";
> 
> {
>   BOOST_LOG_SCOPED_THREAD_ATTR(lg, "Console", true);
>   BOOST_LOG(lg) << "Console is true";
> }
> 
> BOOST_LOG(lg) << "Console is false again";

Like that?

>> *) It should be noted that the internal async log message queuing
>> mechanism uses a vector and during very bursty logging activity that
>> the vector can grow large in size and doesn't ever reduce in size.
>> This is a known limitation and the use of a vector was chosen to
>> facilitate atomic append operations for log records.  Using a
>> std::deque would be preferred for bursty applications that way space
>> could be reclaimed easier, but as Andrey pointed out, it would
>> require a full mutex which would reduce the performance of the
>> library.
> 
> There is no vector in the async frontends. The problem with the current 
> queuing mechanism is not the storage strategy but the lack of queue 
> boundaries. But I agree, I should have drawn attention to this aspect in 
> the docs. Will do.

*nods*  I brought this up in a private email w/ you and was satisfied with your answer, but thought it worth noting for others.

As for the frontends having their own queue, with the way that async frontends work and their feed_records() call, I'd assumed the backend used a time-based mechanism to come by and pick up the log records stored in per-frontend TSS queues.  Something where frontends atomically pushed records on, and the backend would atomically swap() the list of records off for sorting and processing by the backend.  Just a point of confusion after reading:

http://boost-log.sourceforge.net/libs/log/doc/html/log/detailed/sink_frontends.html#log.detailed.sink_frontends.async

and I never dove in to the source to investigate further.

>> *) I find the argument against Lazy Streaming of attributes to be
>> weak.
>> 
>> Current BOOST_LOG() expands to a for() loop where the contents of
>> the for() loop aren't executed unless a Sink in a Logger accepts the
>> record.
>> 
>> So why can't Log Records have compile-time attributes that can be
>> populated with typed attributes in a stream?
>> 
>> And then be able to extract the compile-time attribute in a backend:
> 
> Just as it is said in the rationale - the streaming expression is _not_ 
> executed until _after_ the filtering is done. And filtering already 
> involves attribute values, so there's no way to use these attribute 
> values you specified in the streaming expression. Besides, after the 
> view of attribute values is constructed, it is immutable, so nothing can 
> be added after the filtering is done.

That's why I make the distinction between "log record preconditions," attributes that can be used in a filter, and "attributes," which is a catch-al term for data stored in a Log Record.  I agree that it is impossible for streamed attributes to be used as preconditions, but streamed attributes act as an extremely convenient (from a syntax perspective) way of passing data to a backend for processing.

>> *) Dovetailing on the above two points, a flush bit for a given Log
>> Record would be very nice as well.  99.999% of the time async logging
>> is desired, but in the 0.001% of the time when a Log Record must get
>> out to disk, chances are that one Log Record every blue moon is
>> disproportionally valuable compared to the normal Log Record.  Having
>> a flush() that doesn't return until the backend has fsync(2)'ed data
>> would be really spiffy.
>> 
>> BOOST_LOG_SEV(lg, warning)<<  "My message"<<  lg::flush;
> 
> As I already noted, your mileage is too biased, at least. I, personally, 
> tend to use synchronous logging. But I do recognize that some kind of 
> flushing ability would be nice in case of async logging.

I like the idea of using both async and sync sinks.  It leaves me with a few questions, however:

How does that work if they're both using the same text file backend?  Will log entries still be ordered?

> typedef boost::log::sinks::text_file_backend backend_t;
> typedef boost::log::sinks::ordering_asynchronous_sink< backend_t > sink_t;
> boost::shared_ptr<sink_t> sink(new sink_t(
>     boost::make_shared< backend_t >(),
>     keywords::order = logging::make_attr_ordering("LineId", std::less< unsigned int >()),
>     keywords::ordering_window = boost::posix_time::seconds(1)));

Thanks again in advance.  -sc

--
Sean Chittenden
sean_at_[hidden]