std.experimental.logger: practical observations

[Cliff via Digitalmars-d]

On Sunday, 14 September 2014 at 07:22:52 UTC, Marco Leise wrote:
> Am Sat, 13 Sep 2014 14:34:16 +0000
> schrieb "Robert burner Schadek" <rburners at gmail.com>:
>
>> On Friday, 12 September 2014 at 16:08:42 UTC, Marco Leise 
>> wrote:
>> >
>> > Remember that the stdlog is __gshared? Imagine we set the
>> > LogLevel to off and while executing writeLogMsg ...
>> >
>> > * a different thread wants to log a warning to stdlog
>> > * a different thread wants to inspect/set the log level
>> >
>> > It is your design to have loggers shared between threads.
>> > You should go all the way to make them thread safe.
>> >
>> > * catch recursive calls from within the same thread,
>> >   while not affecting other threads' logging
>> > * make Logger a shared class and work with atomicLoad/Store,
>> >   a synchronized class or use the built-in monitor field
>> >   through synchronized(this) blocks.
>> 
>> hm, I don't know of any magic pill for that. I guess this 
>> would require some dataflow analysis.
>
> Why so complicated? In general - not specific to std.logger -
> I'd wrap those calls in some function that acquires a mutex
> and then check a recursion flag to abort the logging if this
> thread has already been here.
>
> synchronized(loggingMutex) {
>   if (isRecursion) return;
>   isRecursion = true;
>   scope(exit) isRecursion = false;
>   logger.writeLogMsg(...);
> }
>
>> > I know when to throw an exception, but I never used logging
>> > much. If some function throws, would I also log the same
>> > message with error() one line before the throw statement?
>> > Or would I log at the place where I catch the exception?
>> > What to do about the stack trace when I only have one line 
>> > per
>> > log entry?
>> > You see, I am a total newbie when it comes to logging and 
>> > from
>> > the question that arose in my head I figured exceptions and
>> > logging don't really mix. Maybe only info() and debug() 
>> > should
>> > be used and actual problems left to exception handling alone.
>> 
>> that is depended on what your program requires. You can write 
>> more than one line, just indent it by a tab or two. again no 
>> magic pill as far as I know
>
> Ok, I'll experiment a bit and see what works best.

I'd like to throw my oar in here:

On the subject of recursion, this is only a problem if the 
logging contract is that log methods are fully synchronous - was 
this an explicit design choice?

Loggers are not *necessarily* also debuggers.  When used for 
post-mortem analysis (the typical case), it is not generally 
important that log data has been written by the time any given 
log method has returned - if the caller *intends* that, the 
logging system can have a sync/flush method similar to I/O 
behavior, or a configuration option to force fully synchronized 
behavior.

Personally I am not a huge fan of any potential I/O calls being 
by-default synchronous - particularly when those calls may easily 
result in long-running operations e.g. a network call, wait on a 
contended resource, etc.  Coming from the .NET world and having 
seen far too many large programs with user-facing components, 
blocking I/O by-default leads to poor user experiences as their 
program starts to stutter or be subject to timeouts the original 
author did not test for or intend.  With an extensible logging 
system, the same can - I mean *will* - come about.  Logging to my 
mind is usually a fire-and-forget utility - I want to see what 
happened (past tense) not what is happening now (that's what a 
debugger is for).

A way to solve this is to make the (or some) logging methods 
asynchronous.  logger.writeLogAsync(...) which returns 
immediately.  As an implementation detail, the log request gets 
posted to an internal queue serviced by a logging thread (thread 
pool thread is probably fine for this).  Since requests are 
*conceptually* independent from each other, this breaks the 
unintentional semantic dependence which occurs when recursion is 
introduced within the logging system itself.  I think this is 
*generally* the behavior you want, and specialized methods can be 
used to enforce synchronized semantics on top of this.  This 
system also guarantees log message ordering within a given thread.

If this queue is serviced by a threadpool thread, then the next 
logical problem then is to ensure that thread does not get tied 
up by one of the endpoints. There are several ways to solve this 
as well.

- Cliff