www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - std.experimental.logger: practical observations

reply Marco Leise <Marco.Leise gmx.de> writes:
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
Sep 11 2014
next sibling parent reply "Robert burner Schadek" <rburners gmail.com> writes:
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
Sep 11 2014
parent reply Marco Leise <Marco.Leise gmx.de> writes:
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
Sep 11 2014
parent reply "Robert burner Schadek" <rburners gmail.com> writes:
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
Sep 12 2014
parent reply Marco Leise <Marco.Leise gmx.de> writes:
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
Sep 12 2014
parent reply "Robert burner Schadek" <rburners gmail.com> writes:
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
Sep 13 2014
parent reply Marco Leise <Marco.Leise gmx.de> writes:
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
Sep 14 2014
parent reply "Cliff" <cliff.s.hudson gmail.com> writes:
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
Sep 14 2014
next sibling parent Jeremy Powers via Digitalmars-d <digitalmars-d puremagic.com> writes:
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).
Sep 15 2014
prev sibling parent reply Marco Leise <Marco.Leise gmx.de> writes:
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
Sep 15 2014
parent reply "Cliff" <cliff.s.hudson gmail.com> writes:
On Monday, 15 September 2014 at 18:24:07 UTC, Marco Leise wrote:
 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
In MSBuild (where we used a custom but extensible logging system) we had this exact issue with some of our larger customers who were logging to remote databases. Our solution in that case was to block the caller and force a flush down to a certain backlog level (we had a limit and hysteresis). This is not unlike garbage collector behavior. In fact, you almost certainly want to have a configuration of this sort so that users of your library can help ensure that the logging subsystem does not starve the rest of the application of memory. Another alternative (for completeness) is to drop the messages, but this is almost invariably NOT desirable.
Sep 15 2014
parent reply "Robert burner Schadek" <rburners gmail.com> writes:
On Monday, 15 September 2014 at 19:16:27 UTC, Cliff wrote:

and you can do all that with std.logger.

again, the idea of std.logger is not to give you everything, 
because nobody knows what that even is, the idea is to make it 
possible to do everything and have it understandable later and 
use transparently
Sep 15 2014
next sibling parent reply "David Nadlinger" <code klickverbot.at> writes:
On Monday, 15 September 2014 at 22:33:46 UTC, Robert burner 
Schadek wrote:
 and you can do all that with std.logger.

 again, the idea of std.logger is not to give you everything, 
 because nobody knows what that even is, the idea is to make it 
 possible to do everything and have it understandable later and 
 use transparently
Issues like threading behavior and (a)synchronicity guarantees are part of the API, though, and need to be clarified as part of the std.logger design. David
Sep 15 2014
next sibling parent "Cliff" <cliff.s.hudson gmail.com> writes:
On Monday, 15 September 2014 at 22:39:55 UTC, David Nadlinger
wrote:
 On Monday, 15 September 2014 at 22:33:46 UTC, Robert burner 
 Schadek wrote:
 and you can do all that with std.logger.

 again, the idea of std.logger is not to give you everything, 
 because nobody knows what that even is, the idea is to make it 
 possible to do everything and have it understandable later and 
 use transparently
Issues like threading behavior and (a)synchronicity guarantees are part of the API, though, and need to be clarified as part of the std.logger design. David
This is *really* what I am getting at. Even if not another line of code is written nor feature added, its important to state what is actually intended so people know where the limits are a priori, rather than finding an implicit contract and then running with it (leaving you with legacy behavior to potentially maintain later.)
Sep 15 2014
prev sibling parent reply "Robert burner Schadek" <rburners gmail.com> writes:
On Monday, 15 September 2014 at 22:39:55 UTC, David Nadlinger 
wrote:
 Issues like threading behavior and (a)synchronicity guarantees 
 are part of the API, though, and need to be clarified as part 
 of the std.logger design.
the threading behavior has been clarified in the api docs. the (a)synchronicity guarantees is part of the concrete Logger impl. the Logger api does not force synchronize or asynchronize behavior, it allows both to be implemented by every subclass of Logger.
Sep 15 2014
parent "Cliff" <cliff.s.hudson gmail.com> writes:
On Monday, 15 September 2014 at 22:47:57 UTC, Robert burner
Schadek wrote:
 On Monday, 15 September 2014 at 22:39:55 UTC, David Nadlinger 
 wrote:
 Issues like threading behavior and (a)synchronicity guarantees 
 are part of the API, though, and need to be clarified as part 
 of the std.logger design.
the threading behavior has been clarified in the api docs. the (a)synchronicity guarantees is part of the concrete Logger impl. the Logger api does not force synchronize or asynchronize behavior, it allows both to be implemented by every subclass of Logger.
Alright. BTW, thanks for undertaking this project - every app of reasonable size needs logging and I think having a standard logging library is just one more of those ecosystem improvements that gets people up and running quickly.
Sep 16 2014
prev sibling parent Marco Leise <Marco.Leise gmx.de> writes:
Please see the review thread for some looooong comment on
multi-threading issues with this design.

-- 
Marco
Sep 18 2014
prev sibling parent "Sean Kelly" <sean invisibleduck.org> writes:
On Thursday, 11 September 2014 at 16:55:32 UTC, Marco Leise wrote:
 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.
This is a tricky situation. Log files generally have a specific format for a given application, and I often don't want APIs I call writing lines to whatever log I have open. What I tend to like the best is for APIs that log data to log to an internal circular buffer, and provide me the option to request that log data. Then if I get an error while using that API and I want additional context, I can pull the internal logs and examine them or dump them in my own application's log file.
Sep 15 2014