Re: [boost] Boost.Logging: formal review

From: John Torjo (john.lists_at_[hidden])
Date: 2005-11-14 09:42:22

Gennadiy Rozental wrote:

> BTW before I start, I recalled couple more issues I forgot to mention in 
> original post:
> 
> 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?

> I need to use the library in header. IMO log needs to support/implement some 
> lightweight debug abstract interface Something like:
> 
> struct DebugLog {
>     virtual void log( string const& ) = 0;
>     virtual void log( int ) = 0;
> };
> 
> struct Log : DebugLog { ... };
> 
> Now I could use DebugLog interface without need to know an implementation. 
> It comes with the price of virtual call. I primarily use this for debug only 
> logging.

Anybody else wants this?

> 
> 2. Design: Enter/Exit function scope support
> I believe it's required for log library to provide some kind of support for 
> scope tracking. It could be an addon to core functionality to it needs to be 
> configurable.

Added to my TODO list.

> 
> 3. Design: hexdump
> I believe log library needs to provide support for dumping memory in hex 
> format on log file. It could be an addon to core functionality.
> 

I can add this, even though I'm not sure why you'd want this.

> 4. Design: logged assert
> I believe log library needs to provide support for custom assert. Such 
> assert would log into log file and invoke system assert depends in assert 
> level. It could be an addon to core functionality.
> 

Well, I want to adapt SMART_ASSERT to allow for this functionality.

> 5. Implementation/Design: log entry data copying.
> Modifiers implemented by applying modifier for string that represent entry 
> data. This model is inefficient in following regards:
>   a) you need to make a copy of original entry data for every output.
>   b) you need to prepend the strings in most cases - which is inefficient 
> operation.
>   c) you couldn't share the work for different outputs - you need to repeat 
> it for every string
> 
> 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.

> 
> 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 woudn't use it in 
real-life apps.

>>>Also multithreaded application should support filtering based on thread 
>>>id.
>>
>>And what's stopping you from making an appender that does just this?
>>
>>// 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;
>>}
> 
> 
> You must be kidding, right? I want filtering on log level. So that entry 
> appear or not appear in all outputs.

Please read what you just wrote a couple of lines above: "filtering 
based on thread id."

> 
>>>2. Configuration support
>>>Submitted solution supports configuration in a form of arbitrary 
>>>modifiers
>>>that user could register in log. While this looks like very inflexible 
>>>it's
>>>also as very inconvenient. In most cases I prefer log to be configured at
>>>run time from within configuration file. his would be very cumbersome 
>>>with
>>>modifiers model. Not only each modifier needs to be added separately. I 
>>>also
>>
>>Did you take a look at Darryl's proposal?
>>http://torjo.com/code/lib/alternate_manipulating.html)
> 
> 
> And how that has anything to do with what I am talking about? It's just a 
> twist of the same unacceptable interface.

Unacceptable to you, yes.

> 
> 
>>>need to keep track of it's name to be able to remove it and it's index to
>>>know how modifiers are ordered. This ability to configure log remotely in
>>>many locations makes it impossible to really know what and how is written
>>>into log.
>>>   My preferred way to configure the log is with use of configuration
>>>string. First of all it's simplify an interface and you immediately see 
>>>how
>>>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.

> 
> 
>>And besides, if you want to configure logging, you'll still need to
>>identify each log, appender and manipulator by a string.
> 
> 
> Why is that? I do not want or need to know log name to configure it. I have 
> an instance.

Because when you have some setting in the configuration file, you need 
whom it refers to. Therefore, you need to have some log-to-string 
correspondence.

> 
>>>4. Internationalization support
>>>I do see some vague traces in code that indicate that author new this 
>>>needs
>>>to be supported. But since documentation have exactly zero information 
>>>and I
>>>couldn't figure out how to do it myself, I assume that library doesn't
>>>support this. IMO it's required for industrial strength solution.
>>
>>How many times have you needed internationalization support logging?
> 
> 
> Me, personally - never. But may be the fact that I work in domestic 
> department of American company could be accounted for that. But for the 
> boost level library this is a showstopper. Internationalization is not an 
> afterthought.

Still what do you understand by internationalization?
It can deal with Unicode, if this is what you want...

> 
> 
>>>6. Misfeature: pre-init cashing
>>>Library starts with cashing turned on to support pre-init logging. IMO 
>>>this
>>>is too dangerous. Now developer needs to remember how many log entries 
>>>are
>>>printed. Otherwise some of them will just start disappearing (could be
>>>different in every run). And it may start happening only at the user 
>>>site.
>>>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.

> 
> 
>>And lets face it -- when one starts using a logging lib, will at least
>>trace one call to the debug lib. If he sees the line doesn't show up
>>anywhere, he'll most likely read the docs. If you take a look at the
> 
> 
> I don't see how reading the docs will help. Solution is dangerous in it's 
> nature.

When you'll come up with something better, I'll use it. Until then...

> 
> 
>>Basic Usage, you'll see the 'flush_log_cache()' call.
>>
>>Besides, even if you don't call it and you write 256 messages to a log,
>>the caching will automatically turn itself off and flush. The same
> 
> 
> And what if log is not configured yet? What will happened? We will loose all 
> those 256 messages or program will crash?

Ok, I have not handled this case yet. I need to handle it -- have a 
"safe log", where I will write if program exists with cache still turned 
on, and logs have not been initialized yet.

> 
> 
>>happens if the application ends, and caching was still on.
>>
>>
>>>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.

> different output comparing timestamps? (*if* they are printed). I do 
> *rarely* use more than additional logs for information dedicated to 
> different target audience (operation departments, end users). But this is 
> not driven by module/submodule hierarchy. To mark the modules I use much 
> better idiom - keyword (all within bounds of same log).
> 

I'm not even gonna ask why yours is such a better idiom...

> 
>>>8. Misfeature: compile-time log support
>>>As it clear from above IMO log is (almost) never always enabled (and in 
>>>any
>>>case there is a way to implement this without any additional support). 
>>>And
>>>always disabled log could be implemented on macro level. Based on this I
>>
>>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...
You can turn on/off ***all*** logging... Wow!

And to think that BOOST_LOG allows you to turn on/off certain logs -- 
allowing for some information to be logged while what's not important is 
turned off... Your solution is indeed much better...

Not to say that if you write something like:

LOG << some_lengthy_function();

some_lengthy_function() will still be executed, even though logging is 
disabled...

> 
> 
>>>II. Implementation flaws
>>>------------------
>>>
>>>2. Multithreading support implementation
>>>  a) For some unclear reason author chose to reimplement some of
>>>Boost.Threads functionality in some places (and in some places 
>>>Boost.Thread
>>>is used always). I believe log library shouldn't do this.
>>
>>It was requested -- some users wanted to remove dependency on 
>>Boost.Thread.
> 
> 
> Well it still wrong. You couldn't justify that by user's request. BTW you do 
> depend on Boost.Threads still.

???
If you use ts_appender(), yes.
Otherwise, not.

> 
> 
>>>4. collection in use
>>>appender_array and modifier_array are better be implemented using lists
>>
>>Have you done some tests, or is this just a gut feeling?
> 
> 
> I did not provide any tests, did you? And it's not a gut feeling. In places 
> where it's important you never need random access.

It's not about random access. It's about so many tests have shown that 
std::vector is faster than std::list, especially when the vectors are 
small - in the case of logger_impl.

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

> 
> 
>>>5. appender_array
>>>appender_array seems to be defined in 2 placed
>>
>>Yes, once in the log_impl's class definition, and once in
>>namespace boost { namespace logging { namespace {
> 
> 
> Why would you give the same name to 2 different things?
> 
It's about context. Why not?

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

> 
> 
>>>9. Time string cashing
>>>prepend_time and prepend_time_strf calls are not cashed. It's a lot of 
>>>work
>>>for nothing.
>>
>>Please explain.
> 
> 
> You may have 1000 messages per second. And you format time string for every 
> single one.
> 

Ok, you're right. I can improve on that.

> 
>>>10. write_msg locking
>>>write_msg shouldn't lock on appenders writing. Each appender should be
>>>locked independently instead.
>>
>>It's because appenders/modifiers could be added/deleted while someone is
>>writing a message to the log. Thus, it needs to be thread-safe.
> 
> 
> You need to find an alternative solution. Every output has to be locked 
> independently. This is one of the "premature pessimization" you force on the 
> user.
> 

I'll think about it.

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!