Re: [boost] Boost.Logging: formal review

From: John Torjo (john.lists_at_[hidden])
Date: 2005-11-14 13:28:58

Gennadiy Rozental wrote:

>>>1. Design: Lightweight interface
>>>Log library brings a lot of dependencies. In some case I do not want this 
>>>if
>>
>>Care to exemplify? What are the dependencies?
> 
> 
> <iostream>

Had you taken the time to look, this is included only in the source files.

> <sstream>

Needed for buffering the messages.
I've measured the effects of including or not including this, and at 
least for VC7.1, including <sstream> is compile-time wise virtually same 
as not including it.

In fact, the only headers I include, in log.hpp, are <sstream> and <string>.

So, I did minimize the dependencies.

> <vector>
> <fstream>
> <cstdlib>
> <ctime>
> <boost/function.hpp>
> ....

They're only used when you need to manipulate the logs (add 
appenders/modifiers, set the level). This will most likely happen in 
very few places, so you pay compile-wise only when you do advanced stuff.

>>>IMO better model would be to apply modifiers to outputs instead.
>>>
>>
>>Yes, I will consider this. IMO, is better to have a working model, which
>>can be optimized later.
> 
> 
> You couldn't change an API post review and introduce completely new 
> modifiers model. It's a different library that needs different review
> 

I was only talking about changing (optimizing) the implementation.

> 
>>>Actually since macros are not primary interface in different subsystems 
>>>log
>>>may look different. Couple examples:
>>>
>>>1. LOG( INFO, PROG_FLOW, "SocketLib" ) << "Connection esteblished to: " 
>>><<
>>>address;
>>>2. LOG( DEBUG, RETURN_VALUE ) << "Fetched value: " << v;
>>>Here a LOG macro refer to some keyword by name. Usually I have keyword 
>>>per
>>>file, per library or per class.
>>>3. DEBUG_LOG( DATA_FLOW ) << "Input msg: " < msg;
>>>Here DEBUG_LOG automatically apply DEBUG level and refer to keyword by 
>>>name
>>>
>>
>>This IMO is too much to type, and I personally wouldn't use it in
>>real-life apps.
> 
> 
> How DLOG( DATA_FLOW) is more to type then BOOST_LOG( DEBUG )? Depends on 

First of all, you'd have to prefix it with BOOST_:

So lets see:
BOOST_LOG(DEBUG)

BOOST_DLOG(DATA_FLOW)
BOOST_LOG(DEBUG, RETURN_VALUE)
BOOST_LOG(INFO, PROG_FLOW, "SocketLib")

> 
>>>>// trivial example
>>>>struct only_for_thread_id {
>>>> only_for_thread_id(int tid, appender_func forward_to)
>>>>   : tid(tid), forward_to(forward_to) {}
>>>> void operator()(const std::string&,const std::string & msg) {
>>>>   if ( ::GetCurrentThreadId() == tid) forward_to(msg);
>>>> }
>>>> int tid;
>>>> appender_func forward_to;
>>>
> 
> Sorry typo. I want filtering on thread id. So that entry appear or not 
> appear in all outputs based on which is current thread id.

Using the only_for_thread_id, combined with other appenders (for 
instance, appender_array), you can accomplish that:

manipulate_logs("*").add_appender(
   only_for_thread_id(1552,appender_array()
     .add(write_to_cout)
     .add(write_to_file("out.txt") )
     .add(write_to_dbg_wnd) ) );

>>>>>your log entries going to look like. Here is an example:
>>>>>"keyword=*,-ACD;categ=prog_flow,return
>>>>>value,-details;l=debug;track=on;roll=10000;prefix=file ( line ) - time
>>>>>:;timeformat=%s:%m".
>>>>
>>>>You can implement Configuration Support on top of the current library.
>>>
>>>
>>>I do not see how it possible and why should I do this on top of useless 
>>>API.
>>
>>Funny, but I think your last statement is quite useless.
> 
> 
> Ok Useless is wrong word. I meant to say that I would never use it since 
> single configure string is so much more clear and convenient.
> 

Yes, it is. But as you app grows bigger and bigger, I think that single 
string could get pretty complex.

Basically, on top of the lib, you can build your Configuration Support, 
or what I envisioned -- using multiple lines. It's a matter of choice.

> 
> I don't see how log name comes into play here (it could but only if end user 
> will choose to). I may have single log that doesn't care about the name at 
> all. Or I may have 2 different named config parameters:
> 
> config.get( "system_log_config" )
> config.get( "admin_log_config" )
> 
> But this strings has nothing to do with log names either.
> 

How do you set the log's settings, when you read them from the 
Configuration file?

> 
>>>>>Much more reliable solution is to use some kind of startup log that does
>>>>>not
>>>>>require configuration.
>>>>>
>>>>
>>>>And where would that log write to? What if it's very important data?
>>>>To console? What if you don't have console?
>>>
>>>
>>>I think I covered that in my last statement.
>>
>>Well, I don't think it's covered.
> 
> 
> Let me repeat: Much more reliable solution is to use some kind of startup 
> log.
> IOW we use dedicated log that only used during startup.
> 

Well, I will allow for a startup log to be used in case the application 
ends, and the logs have not been initialized yet.

> 
> 
>>>>>7. Misfeature: log hierarchies
>>>>>I personally never have a need for that and have some difficulties to
>>>>>imagine why would anyone have. You could probably have it on top of
>>>>>existent
>>>>>solution as add-on. If it doesn't require any new interfaces (or some
>>>>
>>>>Have you heard of modules, and sub-modules? What if each
>>>>module/sub-module was to have a log to write to?
>>>
>>>
>>>I primarily use one file for everything. Why would I want 10 different
>>>files? So to figure out what happened I will need to jump through 10
>>
>>You can have multiple logs that output to the same file.
> 
> 
> And how about thread safety: Don't you lock on log level?

Ok, you're right. I guess it's better to have locking on the 
modifier/appenders.

> And what if I want to filter out specific subsystem? Do I need to 
> register/unregister outputs?  But this will still cause log statement to be 
> executed.

If you want to filter out a specific subsystem, you will disable the 
logs corresponding to that subsystem.

When a message is about to be written to the log, if the log is 
disabled, the whole message is ignored.

// assume x is disabled
BOOST_LOG(x) << even << if << this is costly << it will not be executed;

> 
> Why would I do that instead of common filtering mechanism with multiple 
> filters?

Efficiency, for starters.

> 
> Because I have single idiom "filters", why you propose numerous different 
> ways to do this task. And filters are less prone to be misused.

What you call filters, can in my case be logs, and again, you can 
enable/disable them in an efficient manner.

> 
> 
>>>>Please enlighten me: how can you implement a disabled log at macro level?
>>>
>>>Numerous ways. Here is from top of my head:
>>>
>>>struct nil_stream {}
>>>
>>>template<typename T>
>>>nil_stream const& operator<<( nil_stream const& ns, T const&) { return 
>>>ns; }
>>>
>>>#define LOG( .... ) if(true) {} else nil_stream() <<
>>
>>Amazing...
>>
>>LOG << some_lengthy_function();
>>
>>some_lengthy_function() will still be executed, even though logging is
>>disabled...
> 
> How did you case to such conclusion? Since when false branch gets executed?

When the false branch gets executed, it will look like:

nil_stream() << some_lengthy_function();

While operator<< can be considered a nop, compilers will not necessary 
optimize away the some_lengthy_function() call.

> 
> 
>>>>>5. exception support
>>>>>
>>>>>try {
>>>>>   LOG << "aaa" << foo()
>>>>>}
>>>>>catch(...) {
>>>>>   LOG << "exception"
>>>>>}
>>>>>
>>>>>This construct doesn't seems generate what is expected if foo() throws 
>>>>>an
>>>>>exception
>>>>
>>>>What is expected?
>>>
>>>
>>>Try to run this and you will see.
>>
>>It tries to print as much as possible from the original "LOG << "aaa" <<
>> foo()" expression, and then it prints "exception".
>>
>>What do you expect?
> 
> 
> First of all in my test (VC7.1) it did not print aaa and it printed second 
> statement on the same line

The second statement was printed on the same line, because you did not 
add the append_enter to the appenders for LOG.

Finally, I'd really love to see a construct that will work in the way 
you expect.

Because, as you probably know, foo() is executed first, and only 
afterwards is "LOG << "aaa" << results_of_calling_foo" executed.

> 
> 
>>>>>If we do why all the appenders are so heavy?
>>>>>
>>>>
>>>>I don't understand what you mean.
>>>
>>>
>>>So costly to copy.
>>
>>How would you know?
> 
> 
> Just do sizeof(logger). Keep in mind that your design assumes that may copy 
> logger for *every* log entry.

sizeof(logger) is 12

And BOOST_LOG uses a reference to a logger, so the logger is never copied.

Best,
John

-- 
John Torjo,    Contributing editor, C/C++ Users Journal
-- "Win32 GUI Generics" -- generics & GUI do mix, after all
-- http://www.torjo.com/win32gui/surfaces.html - Sky's the limit!
-- http://www.torjo.com/cb/ - Click, Build, Run!