[boost] Re: Re: Re: Re: Logging Library -- Formal Review Request

From: Gennadiy Rozental (gennadiy.rozental_at_[hidden])
Date: 2005-05-02 13:17:30

>> I wonder what it's going to pring in more complicated cases:
>>
>> BOOST_LOG(..)  << "Print result of f(): " << f() << " and g()" << g();
>>
>> void f() {
>> BOOST_LOG(..)  << "Enter f()";
>>
>> BOOST_LOG(..)  << "f() inside uses m(): " << m();
>>
>> BOOST_LOG(..)  << "Exit f()";
>> }
>>
>> void g() {
>> BOOST_LOG(..)  << "Enter g()";
>>
>> BOOST_LOG(..)  << "g() inside uses m(): " << m();
>>
>> BOOST_LOG(..)  << "Exit g()";
>> }
>>
>> Gennadiy
>>
>> P.S. Could you explain a bit more how cashing and threading are involved
>> here
>
> Within any block (or a block nested within that block), writes to will
> appear in the proper order.  If my reading of the code is correct, the
> way the BOOST_LOG macro works when a log is enabled is to
> (oversimplifying) return a proxy stream object ("logger_keeper" which
> inherits from "enabled_logger") which will be the target of the
> operator<< calls.  When this proxy object is destroyed, the entire
> message gets written.
>
> So something like this:
>
> BOOST_LOG (x) << "Result of f: " << f ().
>
> Turns into something more like (expanding out the code inside the
> classes and greatly oversimplifying, but this iis the gist):
>
> if (!x.is_enabled ())
>    ;
> else
>    {
>    ostringstream s;
>    s << "Result of f: " << f ();
>    write_msg (logger::manager (), x, s.str ());
>    }
>
> So if there are nested logging calls inside of "f" that are destined
> for the logger "x", they will hit the output device *before* the
> caller's message does.

This means that in example like above Logs from m() calls will be printed 
before f() and g(). And nobody will be able to tell which one is from where. 
It's completely unacceptable IMO. Threading/no threading, cashing /no 
cashing Log is NOT allowed to change an order of events.

> You suggested something like this:
>
>> a.cpp:14: Print result of f():
>> b.cpp:75: Enter f()
>> b.cpp:95: Exit f()
>> a.cpp:14:  1234
>
> If I understand the behavior you desire, the string "Print result of
> f(): " would be logged either (1) immediately or (2) as soon as there
> were any logging calls from a different scope (e.g. the "Enter f()").

>From my standpoint there is only one possible strategy: log trace entries 
one after another the way program flow goes.

> The first option to me suggests no buffering between the loggers ("x"
> in this case) and the output devices (the things that write to files
> etc).  This would likely offer poor performance, and would lead to
> intermixing of output from multiple threads just like plain iostreams.

Now about bufferin/cashing. IMO is completely independent issue. It should 
be on a different level in hierarchy. Most probably somewhere on 
appender/sink level. Loggers just do the logging, sinks manage the device. 
As for threading, intermixing of output could be just what I want. In other 
case I could use independent sinks per thread.

> In other words, if multiple threads are writing to the same logger
> simultaneously, their messages would potentially be fragmented and
> mixed wherever they are separated by an <<.  Perhaps a thread-specific
> stream could be used to prevent this.

To prevent log entry fragmenting caused by multiple threads locks should be 
used.

> Am I totally off base here in terms of what you're suggesting and how
> it might be implemented?

My primary point is that log should reflect 1:1 everything that happened in 
program, without any order change. As a result some log entries my be 
fragmented (same thread fragmentation) and logger should be able to properly 
set up all prefixes.

Gennadiy