So I've implemented my first logger based on the abstract logger class, (colorize stderr, convert strings to system locale for POSIX terminals and wstring on Windows consoles).

1. Yes, logging is slower than stderr.writeln("Hello, world!");
   It is a logging framework with timestamps, runtime
   reconfiguration, formatting etc. One has to accept that. :p

2. I noticed that as my logger implementation grew more complex
   and used functionality from other modules I wrote, that if
   these used logging as well I'd easily end up in a recursive
   logging situation.

   Can recursion checks be added somewhere
   before .writeLogMsg()?

3. Exceptions and loggin don't mix.
   Logging functions expect the file and line to be the one
   where the logging function is placed. When I work with C
   functions I tend to call them through a template that will
   check the error return code. See:
   http://dlang.org/phobos/std_exception.html#.errnoEnforce
   Such templates pick up file and line numbers from where
   they are instantiated and pass them on to the exception
   ctor as runtime values.
   Now when I use error(), I see no way to pass it runtime
   file and line variables to make the log file reflect the
   actual file and line where the error occured, instead of
   some line in the template or where ever I caught the
   exception.
   Not all errors/exceptions are fatal and we might just want
   to log an exception and continue with execution.

-- 
Marco

On Thursday, 11 September 2014 at 16:55:32 UTC, Marco Leise wrote:
> So I've implemented my first logger based on the abstract
> logger class, (colorize stderr, convert strings to system
> locale for POSIX terminals and wstring on Windows consoles).
>
> 1. Yes, logging is slower than stderr.writeln("Hello, world!");
>    It is a logging framework with timestamps, runtime
>    reconfiguration, formatting etc. One has to accept that. :p

what he said

>
> 2. I noticed that as my logger implementation grew more complex
>    and used functionality from other modules I wrote, that if
>    these used logging as well I'd easily end up in a recursive
>    logging situation.
>
>    Can recursion checks be added somewhere
>    before .writeLogMsg()?

I think I don't follow. Just to clear

foo() {
    log(); bar();
}

bar() {
    log(); foo();
}

?

>
> 3. Exceptions and loggin don't mix.
>    Logging functions expect the file and line to be the one
>    where the logging function is placed. When I work with C
>    functions I tend to call them through a template that will
>    check the error return code. See:
>    http://dlang.org/phobos/std_exception.html#.errnoEnforce
>    Such templates pick up file and line numbers from where
>    they are instantiated and pass them on to the exception
>    ctor as runtime values.
>    Now when I use error(), I see no way to pass it runtime
>    file and line variables to make the log file reflect the
>    actual file and line where the error occured, instead of
>    some line in the template or where ever I caught the
>    exception.
>    Not all errors/exceptions are fatal and we might just want
>    to log an exception and continue with execution.

hm, I think adding template function as requested by dicebot would solve that problem, as it would take line and friends as function parameters

Am Thu, 11 Sep 2014 21:32:44 +0000
schrieb "Robert burner Schadek" <rburners@gmail.com>:

> On Thursday, 11 September 2014 at 16:55:32 UTC, Marco Leise wrote:
> > 2. I noticed that as my logger implementation grew more complex
> >    and used functionality from other modules I wrote, that if
> >    these used logging as well I'd easily end up in a recursive
> >    logging situation.
> >
> >    Can recursion checks be added somewhere
> >    before .writeLogMsg()?
> 
> I think I don't follow. Just to clear
> 
> foo() {
>      log(); bar();
> }
> 
> bar() {
>      log(); foo();
> }

Let me clarify. Here is some code from 2015:

void main()
{
	stdlog = new MyLogger();
	// This call may overflow the stack if
	// 'somethingBadHappened in someFunc():
	error("ERROR!!!");
}

class MyLogger : Logger
{
	override void writeLogMsg(ref LogEntry payload)
	{
		auto bla = someFunc();
		useBlaToLog(bla, payload.msg);
	}
}

// This is just some helper function unrelated to logging
// but it uses the stdlog functionality from Phobos itself
// as that is good practice in 2015.
auto someFunc()
{
	...
	if (somethingBadHappened)
	{
		// Now I must not be used myself in a logger
		// implementation, or I overflow the stack!
		error("something bad in someFunc");
	}
	...
}

> > 3. Exceptions and loggin don't mix.
> >    Logging functions expect the file and line to be the one
> >    where the logging function is placed. When I work with C
> >    functions I tend to call them through a template that will
> >    check the error return code. See:
> >    http://dlang.org/phobos/std_exception.html#.errnoEnforce
> >    Such templates pick up file and line numbers from where
> >    they are instantiated and pass them on to the exception
> >    ctor as runtime values.
> >    Now when I use error(), I see no way to pass it runtime
> >    file and line variables to make the log file reflect the
> >    actual file and line where the error occured, instead of
> >    some line in the template or where ever I caught the
> >    exception.
> >    Not all errors/exceptions are fatal and we might just want
> >    to log an exception and continue with execution.
> 
> hm, I think adding template function as requested by dicebot would solve that problem, as it would take line and friends as function parameters

How do you log errors that also throw exceptions ?

-- 
Marco

On Thursday, 11 September 2014 at 22:10:01 UTC, Marco Leise wrote:
> Am Thu, 11 Sep 2014 21:32:44 +0000
> schrieb "Robert burner Schadek" <rburners@gmail.com>:
>
>> On Thursday, 11 September 2014 at 16:55:32 UTC, Marco Leise wrote:
>> > 2. I noticed that as my logger implementation grew more complex
>> >    and used functionality from other modules I wrote, that if
>> >    these used logging as well I'd easily end up in a recursive
>> >    logging situation.
>> >
>> >    Can recursion checks be added somewhere
>> >    before .writeLogMsg()?
>> 
>> I think I don't follow. Just to clear
>> 
>> foo() {
>>      log(); bar();
>> }
>> 
>> bar() {
>>      log(); foo();
>> }
>
> Let me clarify. Here is some code from 2015:
>
> void main()
> {
> 	stdlog = new MyLogger();
> 	// This call may overflow the stack if
> 	// 'somethingBadHappened in someFunc():
> 	error("ERROR!!!");
> }
>
> class MyLogger : Logger
> {
> 	override void writeLogMsg(ref LogEntry payload)
> 	{
> 		auto bla = someFunc();
> 		useBlaToLog(bla, payload.msg);
> 	}
> }
>
> // This is just some helper function unrelated to logging
> // but it uses the stdlog functionality from Phobos itself
> // as that is good practice in 2015.
> auto someFunc()
> {
> 	...
> 	if (somethingBadHappened)
> 	{
> 		// Now I must not be used myself in a logger
> 		// implementation, or I overflow the stack!
> 		error("something bad in someFunc");
> 	}
> 	...
> }

well you could set the LogLevel to off and reset it afterwards

>
>> > 3. Exceptions and loggin don't mix.

>> 
>> hm, I think adding template function as requested by dicebot would solve that problem, as it would take line and friends as function parameters
>
> How do you log errors that also throw exceptions ?

please elaborate. I think I misunderstand

Am Fri, 12 Sep 2014 09:46:18 +0000
schrieb "Robert burner Schadek" <rburners@gmail.com>:

> On Thursday, 11 September 2014 at 22:10:01 UTC, Marco Leise wrote:
> > Let me clarify. Here is some code from 2015:
> >
> > void main()
> > {
> > 	stdlog = new MyLogger();
> > 	// This call may overflow the stack if
> > 	// 'somethingBadHappened in someFunc():
> > 	error("ERROR!!!");
> > }
> >
> > class MyLogger : Logger
> > {
> > 	override void writeLogMsg(ref LogEntry payload)
> > 	{
> > 		auto bla = someFunc();
> > 		useBlaToLog(bla, payload.msg);
> > 	}
> > }
> >
> > // This is just some helper function unrelated to logging
> > // but it uses the stdlog functionality from Phobos itself
> > // as that is good practice in 2015.
> > auto someFunc()
> > {
> > 	...
> > 	if (somethingBadHappened)
> > 	{
> > 		// Now I must not be used myself in a logger
> > 		// implementation, or I overflow the stack!
> > 		error("something bad in someFunc");
> > 	}
> > 	...
> > }
> 
> well you could set the LogLevel to off and reset it afterwards

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.

> > 3. Exceptions and loggin don't mix.
> > How do you log errors that also throw exceptions ?
> 
> please elaborate. I think I misunderstand

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.

-- 
Marco

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.
>
>> > 3. Exceptions and loggin don't mix.
>> > How do you log errors that also throw exceptions ?
>> 
>> please elaborate. I think I misunderstand
>
> 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

Am Sat, 13 Sep 2014 14:34:16 +0000
schrieb "Robert burner Schadek" <rburners@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.

-- 
Marco

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

On Sun, Sep 14, 2014 at 10:30 AM, Cliff via Digitalmars-d < digitalmars-d@puremagic.com> wrote:

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

+1

Logging conceptually has two parts: firing off the log message, and later recording it.  These should be distinct, for many reasons (may want multiple sinks for each log message, different formatting per sink, sink handled by a different process, etc).

Ah, so you avoid recursion issues by separating the calls to error() et altera from the actual process of writing to disk or sending via the network.

Behind error() there would be a fixed implementation
controlled by the author of the logging library that just
appends the payloads to a list.
Another thread would pick items from that list and push them
into our Logger classes where we can happily use the logging
functionalities ourselves, because they would just get
appended to the list and wait for their time instead of
causing an immediate recursive call.

So basically your idea is message passing between the application and a physical (probably low priority) logging thread. This should also satisfy those who don't want to wait for the logging calls to finish while serving web requests. How do such systems handle a full inbox? In Phobos we have http://dlang.org/phobos/std_concurrency.html#.OnCrowding

-- 
Marco