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

From: Darryl Green (darryl.green_at_[hidden])
Date: 2005-05-03 22:38:44

Gennadiy Rozental <gennadiy.rozental <at> thomson.com> writes:
> 
> > 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.
> 

But the order hasn't been changed - it just isn't what you expected.
I'm not sure why you didn't expect it - it seems reasonable (to me) that
the result of evaluating the complete expression is logged. If some
subexpression has a side effect that writes to a log, its results will
be logged when the sub-expression is complete. That is "in order" afaiks.

What about this:

time_t slow_time()
{
   BOOST_LOG(x) << "going to sleep at " << time(0);
   sleep(1);
   time_t t;
   BOOST_LOG(x) << "waking up at " << t = time(0);
   return t;
}

void f()
{
  BOOST_LOG(x) << "slow_time returned " << slow_time() << " then " << slow_time();
}

Resulting in (I ran this test a long time ago, boot time isn't bad either :-) :

going to sleep at 0
waking up at 1
going to sleep at 1
waking up at 2
slow time returned 1 then 2

Looks in order to me. I'm still not sure what the alternative is?

Darryl.