On Thu, Mar 1, 2012 at 6:38 AM, H. S. Teoh <hsteoh@quickfur.ath.cx> wrote:
> On Thu, Mar 01, 2012 at 10:09:28AM +0100, Mikael Lindsten wrote:
>> On Monday, 27 February 2012 at 18:10:15 UTC, Kalle Svensson wrote:
>> >* I agree that it is a good idea just to use few log levels.
> [...]
>> I second what Kalle Svensson is saying.
>>
>> My belief is that when there are many log levels, people don't use them as intended or only use a subset of them, often a combination.
> [...]
>
> I used to think that the more log levels, the better. But later, based on what I observe in real-life projects, I see that most people don't bother trying to figure out what each log level means (they are too lazy / busy to read the docs) so they just randomly pick one that "sounds right" (which usually is equal to "totally wrong"). Let this happen for a few iterations of the software, and you end up with so many wrong level messages that the whole log level system basically becomes useless. This problem gets worse proportionally to the number of people on the project.
>

Agreed. I have recently extended this to hierarchy. Most of the time you don't want to deal with the complexity of using and configuring a hierarchical logger. Most programs/system want to enable logging across the board. From my experience is only in very critical areas where you want to increase and decrease logging for that component.

An example that comes to mind are inputs and outputs to a system/program. Which may be expensive to log in production but which you want to record during testing. This is why the library includes vlog. To allow the developer and system admin to increase logging for a specific module.

Thanks,
-Jose

>
> T
>
> --
> What's a "hot crossed bun"? An angry rabbit.

On Thu, Mar 1, 2012 at 4:59 PM, Sean Kelly <sean@invisibleduck.org> wrote:
> On Feb 29, 2012, at 4:13 PM, Richard van Scheijen wrote:
>
>> When logging the severity level should convey a certain insight that the developer has about the code. This can be done with a 3 bit field. These are: known-cause, known-effect and breaks-flow.
>>
>> This creates the following matrix:
>>
>> KC KE BF Severity
>> =================
>> 1  1  0  Trace
>> 0  1  0  Info
>> 1  0  0  Notice
>> 0  0  0  Warning
>> 1  1  1  Error
>> 0  1  1  Critical
>> 1  0  1  Severe
>> 0  0  1  Fatal
>>
>> A known cause is when the developer knows why a log event is made. e.g.: if you cannot open a file, you do not know why. A known effect is when he/she knows what happens after. Basically, you can tell if it is a catch-all by this flag.
>>
>> When a severity should only be handled by a debugger, the normal debug statement should be used. This is in essence a 4th bit.
>
> This is a really great breakdown of the log levels.  I've never seen it explained so clearly.  As a counterpoint, the important distinction I've found is primarily regarding what person should see a particular log line, and then only differentiated between INFO and ERROR messages.  Roughly:
>
> * Developer-Trace
> * Developer-Info
> * Developer-Error
> * Admin-Info
> * Admin-Error
> * All-Fatal
>
> Typically, the Developer and Admin logs go to different locations, in which case the Admin log lines may be duplicated in the Developer logs to provide added context.  In any case, what I've found is that with more than a few log levels, people typically don't know how to classify things, severity becomes arbitrary, and log-levels are rendered largely useless.  So from the above, we have four severities: Trace, Info, Error, and Fatal, with flags to indicate what type of message is being logged: Developer or Admin (aka. User).

I liked Richard analysis but the truth is that I never needed that may knobs for my logging needs. My thought process goes as follow:

I observed a interesting state:
1. Is the program observing external input for which the program can
execute around. E.g. parsing error with known default. If this is the
case the log warning.
2. Is the program observing a state that can do harm to the
system/computer/user. Log error and abort (std.log's fatal level) or
throw (std.log's critical level)
3. Is the program observing a state that would be interesting to
record for forensic. Log at info.

Think of a compiler parsing and generating CPU instructions for a piece of code. If the compiler encounters an error in the code for which it has no way to recover (missing symbol, etc), it logs an error and aborts (exception or assert). If the compiler encounters a type mismatch for which it can implicitly convert then maybe the compiler will log a warning and continue. If the compiler wants to document that it generated objects x, y and z then it can log at info.

Thanks,
-Jose

On Tue, 06 Mar 2012 11:01:19 -0600, Jose Armando Garcia <jsancio@gmail.com> wrote:

> On Wed, Feb 29, 2012 at 4:13 PM, Richard van Scheijen <dlang@mesadu.net> wrote:
>> When logging the severity level should convey a certain insight that the
>> developer has about the code. This can be done with a 3 bit field. These
>> are: known-cause, known-effect and breaks-flow.
>>
>> This creates the following matrix:
>>
>> KC KE BF Severity
>> =================
>> 1  1  0  Trace
>> 0  1  0  Info
>> 1  0  0  Notice
>> 0  0  0  Warning
>> 1  1  1  Error
>> 0  1  1  Critical
>> 1  0  1  Severe
>> 0  0  1  Fatal
>>
>> A known cause is when the developer knows why a log event is made. e.g.: if
>> you cannot open a file, you do not know why.
>> A known effect is when he/she knows what happens after. Basically, you can
>> tell if it is a catch-all by this flag.
>>
>> When a severity should only be handled by a debugger, the normal debug
>> statement should be used. This is in essence a 4th bit.
>>
>> I hope this helpful in the search for a good level system.
>>
>
> Interesting observation on logging. I like your theoretical
> observation and explanation. To me the most important thing is
> usability and unfortunately people are used to log levels as a order
> concept. Meaning error is higher severity than info so if I am logging
> info events I should probably also log error events.
>
> If we go with a mechanism like the one you describe above there is no
> order so the configuration is a little more complicated or verbose I
> should say. Instead of saying we should log everything "greater" than
> warning the user needs to say that they want to log known-cause,
> known-effect, breaks-flow events. This mean that there are 27 (= 3^3)
> configuration combinations. To implement this we need 3 configuration
> nobs with 3 values (on, off, both).
>
> Thoughts?
> -Jose

There are only 8 possible configurations and they are nicely ordered in terms of severity. So I don't see this as a problem. Also, if you went with a combinatorial approach, shouldn't it be 2^8 = 256, not 3^3 = 27 values?

On Thu, Mar 1, 2012 at 6:24 PM, Robert Jacques <sandford@jhu.edu> wrote:
> On Wed, 29 Feb 2012 18:13:30 -0600, Richard van Scheijen <dlang@mesadu.net> wrote:
>
>> When logging the severity level should convey a certain insight that the developer has about the code. This can be done with a 3 bit field. These are: known-cause, known-effect and breaks-flow.
>>
>> This creates the following matrix:
>>
>> KC KE BF Severity
>> =================
>> 1  1  0  Trace
>> 0  1  0  Info
>> 1  0  0  Notice
>> 0  0  0  Warning
>> 1  1  1  Error
>> 0  1  1  Critical
>> 1  0  1  Severe
>> 0  0  1  Fatal
>>
>> A known cause is when the developer knows why a log event is made. e.g.: if you cannot open a file, you do not know why. A known effect is when he/she knows what happens after. Basically, you can tell if it is a catch-all by this flag.
>>
>> When a severity should only be handled by a debugger, the normal debug statement should be used. This is in essence a 4th bit.
>>
>> I hope this helpful in the search for a good level system.
>>
>
> vote++
>
> I think establishing a good guideline as to log usage should be part of std.log's documentation. Making the bitflags a part of Severity might help cement this concept. It would also allow self documenting code, like:
>
> log!(knownCause|unknownEffect|breaksFlow)("This is a severe message.");

Alluded to this before. My concern with this is that order is not clear from the usage. And if we want to configure logging with a mechanism that doesn't support ordering that means that the user will need 3 knobs to configure each with 3 possible values.

Thanks,
-Jose

On Tue, Mar 6, 2012 at 9:32 AM, Robert Jacques <sandford@jhu.edu> wrote:
> On Tue, 06 Mar 2012 11:01:19 -0600, Jose Armando Garcia <jsancio@gmail.com> wrote:
>
>> On Wed, Feb 29, 2012 at 4:13 PM, Richard van Scheijen <dlang@mesadu.net> wrote:
>>>
>>> When logging the severity level should convey a certain insight that the developer has about the code. This can be done with a 3 bit field. These are: known-cause, known-effect and breaks-flow.
>>>
>>> This creates the following matrix:
>>>
>>> KC KE BF Severity
>>> =================
>>> 1  1  0  Trace
>>> 0  1  0  Info
>>> 1  0  0  Notice
>>> 0  0  0  Warning
>>> 1  1  1  Error
>>> 0  1  1  Critical
>>> 1  0  1  Severe
>>> 0  0  1  Fatal
>>>
>>> A known cause is when the developer knows why a log event is made. e.g.:
>>> if
>>> you cannot open a file, you do not know why.
>>> A known effect is when he/she knows what happens after. Basically, you
>>> can
>>> tell if it is a catch-all by this flag.
>>>
>>> When a severity should only be handled by a debugger, the normal debug statement should be used. This is in essence a 4th bit.
>>>
>>> I hope this helpful in the search for a good level system.
>>>
>>
>> Interesting observation on logging. I like your theoretical observation and explanation. To me the most important thing is usability and unfortunately people are used to log levels as a order concept. Meaning error is higher severity than info so if I am logging info events I should probably also log error events.
>>
>> If we go with a mechanism like the one you describe above there is no order so the configuration is a little more complicated or verbose I should say. Instead of saying we should log everything "greater" than warning the user needs to say that they want to log known-cause, known-effect, breaks-flow events. This mean that there are 27 (= 3^3) configuration combinations. To implement this we need 3 configuration nobs with 3 values (on, off, both).
>>
>> Thoughts?
>> -Jose
>
>
> There are only 8 possible configurations and they are nicely ordered in terms of severity. So I don't see this as a problem. Also, if you went with a combinatorial approach, shouldn't it be 2^8 = 256, not 3^3 = 27 values?

Yes. If you want to enable and disable each individual "level" then you need 8 configuration options which leads to 2^8.

I suggested 3^3 as a more reasonable options that matches how the developer is logging but doesn't give you as much expressiveness as the 2^8 option.

On Tue, 06 Mar 2012 11:44:13 -0600, Jose Armando Garcia <jsancio@gmail.com> wrote:
> On Tue, Mar 6, 2012 at 9:32 AM, Robert Jacques <sandford@jhu.edu> wrote:
>> On Tue, 06 Mar 2012 11:01:19 -0600, Jose Armando Garcia <jsancio@gmail.com>
>> wrote:
>>
>>> On Wed, Feb 29, 2012 at 4:13 PM, Richard van Scheijen <dlang@mesadu.net>
>>> wrote:
>>>>
>>>> When logging the severity level should convey a certain insight that the
>>>> developer has about the code. This can be done with a 3 bit field. These
>>>> are: known-cause, known-effect and breaks-flow.
>>>>
>>>> This creates the following matrix:
>>>>
>>>> KC KE BF Severity
>>>> =================
>>>> 1  1  0  Trace
>>>> 0  1  0  Info
>>>> 1  0  0  Notice
>>>> 0  0  0  Warning
>>>> 1  1  1  Error
>>>> 0  1  1  Critical
>>>> 1  0  1  Severe
>>>> 0  0  1  Fatal
>>>>
>>>> A known cause is when the developer knows why a log event is made. e.g.:
>>>> if
>>>> you cannot open a file, you do not know why.
>>>> A known effect is when he/she knows what happens after. Basically, you
>>>> can
>>>> tell if it is a catch-all by this flag.
>>>>
>>>> When a severity should only be handled by a debugger, the normal debug
>>>> statement should be used. This is in essence a 4th bit.
>>>>
>>>> I hope this helpful in the search for a good level system.
>>>>
>>>
>>> Interesting observation on logging. I like your theoretical
>>> observation and explanation. To me the most important thing is
>>> usability and unfortunately people are used to log levels as a order
>>> concept. Meaning error is higher severity than info so if I am logging
>>> info events I should probably also log error events.
>>>
>>> If we go with a mechanism like the one you describe above there is no
>>> order so the configuration is a little more complicated or verbose I
>>> should say. Instead of saying we should log everything "greater" than
>>> warning the user needs to say that they want to log known-cause,
>>> known-effect, breaks-flow events. This mean that there are 27 (= 3^3)
>>> configuration combinations. To implement this we need 3 configuration
>>> nobs with 3 values (on, off, both).
>>>
>>> Thoughts?
>>> -Jose
>>
>>
>> There are only 8 possible configurations and they are nicely ordered in
>> terms of severity. So I don't see this as a problem. Also, if you went with
>> a combinatorial approach, shouldn't it be 2^8 = 256, not 3^3 = 27 values?
>
> Yes. If you want to enable and disable each individual "level" then
> you need 8 configuration options which leads to 2^8.
>
> I suggested 3^3 as a more reasonable options that matches how the
> developer is logging but doesn't give you as much expressiveness as
> the 2^8 option.

In practice, all you'd need to take is a flag with the desired levels. i.e.

// Automatically set logging levels using the standard severity ordering
config.minSeverity(Severity.Warning);

// Manually set the logging levels
config.setSeverities(Severity.Warning|
		     Severity.Error|
		     Severity.Critical|
		     Severity.Severe|
		     Severity.Fatal);

I don't see the problem with including both methods and a large advantage to having a standardized severity framework.

On Tue, 06 Mar 2012 11:34:21 -0600, Jose Armando Garcia <jsancio@gmail.com> wrote:
> On Thu, Mar 1, 2012 at 6:24 PM, Robert Jacques <sandford@jhu.edu> wrote:
>> On Wed, 29 Feb 2012 18:13:30 -0600, Richard van Scheijen <dlang@mesadu.net>
>> wrote:
>>
>>> When logging the severity level should convey a certain insight
>>> that the developer has about the code. This can be done with a 3
>>> bit field. These are: known-cause, known-effect and breaks-flow.
>>>
>>> This creates the following matrix:
>>>
>>> KC KE BF Severity
>>> =================
>>> 1  1  0  Trace
>>> 0  1  0  Info
>>> 1  0  0  Notice
>>> 0  0  0  Warning
>>> 1  1  1  Error
>>> 0  1  1  Critical
>>> 1  0  1  Severe
>>> 0  0  1  Fatal
>>>
>>> A known cause is when the developer knows why a log event is
>>> made. e.g.: if you cannot open a file, you do not know why.
>>> A known effect is when he/she knows what happens after.
>>> Basically, you can tell if it is a catch-all by this flag.
>>>
>>> When a severity should only be handled by a debugger, the normal
>>> debug statement should be used. This is in essence a 4th bit.
>>>
>>> I hope this helpful in the search for a good level system.
>>>
>>
>> vote++
>>
>> I think establishing a good guideline as to log usage should be part of
>> std.log's documentation. Making the bitflags a part of Severity might help
>> cement this concept. It would also allow self documenting code, like:
>>
>> log!(knownCause|unknownEffect|breaksFlow)("This is a severe message.");
>
> Alluded to this before. My concern with this is that order is not
> clear from the usage. And if we want to configure logging with a
> mechanism that doesn't support ordering that means that the user will
> need 3 knobs to configure each with 3 possible values.
>
> Thanks,
> -Jose

The corollary to this is that causation is not clear from order. As I posted in the other thread, I don't see a conflict between standardized descriptive flags and a total ordering; in fact I think the flags help to define the total ordering and improve logging consistency.

On Fri, Mar 2, 2012 at 12:56 AM, Brad Roberts <braddr@puremagic.com> wrote:
> On 2/13/2012 7:50 AM, David Nadlinger wrote:
>> There are several modules in the review queue right now, and to get things going, I have volunteered to manage the review of Jose's std.log proposal. Barring any objections, the review period starts now and ends in three weeks, on March 6th, followed by a week of voting.
>>
>> ---
>> Code: https://github.com/jsancio/phobos/commit/d114420e0791c704f6899d81a0293cbd3cc8e6f5 Docs: http://jsancio.github.com/phobos/phobos/std_log.html
>>
>> Known remaining issues:
>>  - Proof-reading of the docs is required.
>>  - Not yet fully tested on Windows.
>>
>> Depends on: https://github.com/D-Programming-Language/druntime/pull/141 (will be part of 2.058)
>> ---
>>
>> Earlier drafts of this library were discussed last year, just search the NG and ML archives for "std.log".
>>
>> I think getting this right is vitally important so that we can avoid an abundance of partly incompatible logging libraries like in Java. Thus, I'd warmly encourage everyone to actively try out the module or compare it with any logging solution you might already be using in your project.
>>
>> Please post all feedback in this thread, and remember: Although comprehensive reviews are obviously appreciated, short comments are very welcome as well!
>>
>> David
>
> My 2 cents from a fairly quick scan of the docs:
>
Thanks for looking at the documentation.

> 1) I'm of the opinion that it should be possible to strip all log code from an app without changing it's behavior. Having log levels that change execution flow is evil.  It's it the same class of bad practices as assert expressions having side effects, imho.
>
I think this depends on your point of view. One way to look at critical("critical") is as a replacement to enforce() that logs. We could extends critical in a way similar to enforce where you can specify the exception that should be thrown. David, would this help with the issues you express earlier?

> 2) Apps over a certain size (that tends to not be all that big, a few 10's of thousands of lines) tend to start to need module based logging.  This proposal includes a set of log levels that have no concept of modularity and another separate set that do.  The distinction seems arbitrary and limiting.
>

This distinction is not a limitation of the logger API. It is a limitation of the configuration API. In the future we can add the option to enable error, warning, info at the module level without breaking existing code.

> 3) The conditional stuff seems cute, but I can't recall ever wanting it in anything I've done before.
>
> 4) I don't see an obvious facility for changing log parameters at runtime, unless the intent is to build a paramstring
> array as if it came from command line parameters and calling parseCommandLine again.  use case: long running application
> that has a configuration api or notices a config file has been updated or whatever.  Fairly common behavior.
>

If you want to change the log level at runtime you can just:

std.log.config.minSeverity = Severity.info;

No need to call parseCommandLine. Everything that parseCommandLine does can be implemented by a client user. Really parseCommandLine doesn't need to be part of the Configuration class. It is just there for grouping and documentation.

> 5) The logger severity symbols part should allow more than single character tokens.  IMHO, the default should be the full name of the severity, not just the first character.
>

My motivation for using one char is that it is easier to parse by both computers and humans. It is also makes the framework faster since it writes less bytes. I think we can extends this and fix this once we have custom line formatted.

> 6) Is the log system thread safe?  I see that it's at least thread aware, but what guarantees are about log entry atomicity?
>

Yes, it is. It is probably to conservative in this regard. I need to go back and do a lot performances improvements.

> 7) The logger setter docs says it's an error to change the logger after a log message has been emitted.  That's going to
> hurt.  It's not at all uncommon for an app to want to log some set of errors before it's potentially had enough time to
> execute the code that configures the logger.  use case: reading a config file to get the logger configuration, but can't
> process the config file properly.
>
This was brought up before. There is no technical reason for this and I will remove it.

Thanks!

> Later,
> Brad

On Mon, Mar 5, 2012 at 1:55 PM, Steven Schveighoffer <schveiguy@yahoo.com> wrote:
> On Mon, 13 Feb 2012 10:50:04 -0500, David Nadlinger <see@klickverbot.at> wrote:
>
>> There are several modules in the review queue right now, and to get things going, I have volunteered to manage the review of Jose's std.log proposal. Barring any objections, the review period starts now and ends in three weeks, on March 6th, followed by a week of voting.
>
>
>
> Some notes:
>
> I dislike that logging affects function execution.  In particular, I don't think the logging library should have any business throwing exceptions or errors.  It should be invisible to the application.  The equivalent function can be had by giving a wrapper function (i.e. log this message at the fatal level, and then throw an error).  A use case I can see is printing several fatal log messages before exiting.
>
Then don't use std.log.fatal. It is not like you are forced to use it. You can implement the above by using std.log.error

> The log aliases use names that are too common.  I think log.info is a better symbol for logging than just 'info', which could be a symbol in a myriad of places.  Given that D's symbol lookup rules allow shadowing of global symbols, this does not work out very well.
>
This is a tough one. Should we be relying on D's module abstraction. It is not scalable as a module designer and implementer to think about other modules. This is why a lot of programming languages implement the concept of namespaces.

import log = std.log;
log.info("hello world");

> Like others have stated, I think vlog is a) confusing, and b) unnecessary.  Even reading the docs, I can't understand what it's used for, and why it has such different syntax than the normal logging stuff.
>
I have tried to explain this before but it looks like I have failed. I find it useful. If you are interested on a different explaination: http://google-glog.googlecode.com/svn/trunk/doc/glog.html

> I really like the every function, that's a great idea, one that I've manually implemented (at least the once every N times) many times.
>

Great!

> Do we have to make the logger a singleton?  I'd like to see cases where I can have different log instances.  For example, an instance I can enable/disable per class type, or an instance that logs to a diffferent backend.  Or a non-shared instance which does not need to handle threading issues (i.e. a per-thread file log). Does this help with the vlog issue?
>
My point of view here is that as a developer I never know how I want to categorize my log during development. Some people use class name as a hack for doing this. What about functional programs that don't use class/objects? What about logical component/classes that span multiple classes? I always found class based grouping for logging as a hack. D made the observation that classes are not always the best abstraction unit so it introduced modules. std.log filters based on modules (actually source files to be exact but if D had __MODULE__, std.log would use that instead.)

> -Steve

On Mon, Mar 5, 2012 at 3:51 PM, Steven Schveighoffer <schveiguy@yahoo.com> wrote:
> On Mon, 05 Mar 2012 18:30:03 -0500, David Nadlinger <see@klickverbot.at> wrote:
>
>> On Monday, 5 March 2012 at 21:55:08 UTC, Steven Schveighoffer wrote:
>>>
>>> The log aliases use names that are too common.  I think log.info is a better symbol for logging than just 'info', which could be a symbol in a myriad of places.  Given that D's symbol lookup rules allow shadowing of global symbols, this does not work out very well.
>>
>>
>> Originally, the code used log!info and so on, but it was changed to the current design right after review begin, the rationale being that you could always use »import log = std.log« if you want the extra namespace.
>
>
> That doesn't help.  Software isn't static.
>
> import std.log;
import log = std.log;
> import other; // defines B
>
> class A : B
> {
>   void foo()
>   {
>      info("some info message"); // error! int isn't a function!
       log.info("some info message");
>   }
> }
>
> other.d:
>
> class B
> {
>   int info; // added later
>
> }
>
>>
>>> Like others have stated, I think vlog is a) confusing, and b)
>>> unnecessary.  Even reading the docs, I can't understand what it's used for,
>>> and why it has such different syntax than the normal logging stuff.
>>
>>
>> I think this been modelled after glog's verbose logging support [1], just like much of the rest of the design (by the way, I think a note about this should added somewhere in the module docs). Does the feature as described in the glog docs make sense to you?
>
>
> It's good to know the root of where this comes from.  The docs in glog do make more sense than the vlog docs.
>
> This may be a doc issue.  I'll have to think about it some more.
>
> -Steve