Re: [boost] Boost.Logging: formal review

From: John Torjo (john.lists_at_[hidden])
Date: 2005-11-13 18:02:51

> 
> I. Design Flaws
> ------------------
> 
> 1. Filtering support
> I understand that author strived to minimize the solution, but IMO it lead 
> to minimal value. IMO proper log system should support arbitrary user 
> defined filtering of log entries. At the bare minimum it should support:
> 
> entry level - levels set is ordered set of values indication importance of 
> information provided. Filtering is based on threshold. Examples: DEBUG, 
> INFO, MAJOR

How's this different from levels, in the library?

> 
> entry category - categories set is a set of unique values indicating kind of 
> information provided
> Filtering is based on masking. Examples: ARGS, RETURN_VALUE, ERROR_LOG, 
> DATA_FLOW, PROG_FLOW

What? I'm really curious how a line of code for logging would look, in 
your wishful lib?

> 
> entry keyword - keyword set is set of user defined keywords (most frequently 
> strings) identifying area of the program. Filtering is based on match of 
> keywords. Keywords usually are used to mark specific part of application. 
> Example: "NetworkLevel", "UI", "ABC" to mark class abc, "dfg.cpp"

In my lib, this is actually the log itself. You have a log, and can add 
appenders/modifiers to it.

> 
> 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;
}

> 
> The best solution would allow to plug-in at compile time any user defined 
> Filter (in a form of Policy). This way I could have a log that filter 
> nothing (no filters defined) or log that filter based on time of the day if 
> I want.

See above.

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

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

And besides, if you want to configure logging, you'll still need to 
identify each log, appender and manipulator by a string.

> 
> 3. Per output configuration.
> Log may have multiple appenders attached (BTW - I very much prefer term used 
> by iostreams library - sink). what if I want different entry 
> formatting/prefixing/filtering in different outputs. I may have 
> errors_output which contains only errors. I may have end_user_log that 
> contains only major information for end user with detailed time and date of 
> the entry. And I may have developer_output that contains performance 
> warnings with file and line information. Submitted library have no support 
> for this.

I don't recall anyone else asking for this, but anyway, if other people 
wish it, I can implement it.

And besides, you can implement it even now (not very efficiently), if 
you truly wish:

// this is an appender
struct modifiers_and_then_appender {
   modifiers_and_then_appender(appender_func a) : a(a) {}
   void operator()(const string&, const string& msg) {
      string copy(msg);
      .. // call each modifier
      a(copy);
   }
   modifiers_and_then_appender& add_modifier(
     modifier_func m) { modifiers.push_back(m); }
   std::vector<modifier_func> modifiers;
   appender_func a;
};

And you could have:

manipulate_logs("err").add_appender(
   modifiers_and_then_appender(write_to_file("errors_output"))
     .add_modifier(append_enter)
     .add_modifier(prepend_time) );

manipulate_logs("*").add_appender(
   modifiers_and_then_appender(write_to_file("end_user_log"))
     .add_modifier(append_enter)
     .add_modifier(prepend_time("..."))
     .add_modifier(whatever) ) );

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

> 5. File and line
> This solution completely ignores file and line number of trace entry. IMO 
> They are essential and should be collected for every entry (may not be 
> reported - depends on prefix format)

Yes, you're right. Added to my TODO list
> 
> 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?

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

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

> believe all the compile_tile machinery employed by library is unnecessary 
> and just complicate implementation

It was asked by users of the lib. I never use it, but they need it.

> 
> 9. Interface
> IMO primary interface advertised by library should be macro-less. 

Please provide such an implementation, so that the following works:

some_log << some_lengthy_function();

Which, if some_log is disabled, some_length_function() is not called -- 
without the use of macros.

> Documentation does need to cover how these macros needs to be written, but 
> with user defined filters user will need to do the job oneself. Also in my 
> experience I found that on some systems Even if( ... ) <actual log here> 
> could be unsatisfactory from performance standpoint. I employ one global 
> Boolean is_log_on flag to guard all my log entries. and it should be a part 
> of these macros

As I recall, noone else asked for this -- but it's not hard to implement.

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

>    b) I noticed some fishy construct (m_destroyed data member). It opens 
> some thread safety issues IMO.

It's used for the global logs (the ones defined with BOOST_DEFINE_LOG), 
which return a static reference to a boost::logging::logger - to know if 
the log is used after its destruction. I'm looking for better alternatives.

>    c) static manager_type & manager() doesn't look thread safe.

It's there only for function overloading -- the returned reference is 
never used

> 
> 3 . enabled_logger::m_stream
> For some reason enabled_logger allocates m_stream dynamically for each log 
> entry. I do not see why we need to do this. Even more: why not reuse a 
> single instance per thread?

Yes, in the future, I can re-implement it as a single instance per thread.

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

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

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

> 
> 6. Appenders copying.
>>From code it seems that each logger has its own copy of each appender. Why 
> would we need that?

Because if we had one appender for all loggers, we could run into 
thread-safety issues.

> If we do why all the appenders are so heavy?
> 

I don't understand what you mean.

> 7. #ifdef UNICODE
> #ifdef UNICODE are spread all over the code. It needs to be centralized

Yes, you're right.

> 
> 8. shared_memory.hpp
> This header refer to the library that is not part of boost yet. I don't 
> think it should be part of this submission.

Why not? First of all, you don't need to include it, if you don't use it.

> 
> 9. Time string cashing
> prepend_time and prepend_time_strf calls are not cashed. It's a lot of work 
> for nothing.

Please explain.

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

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!