www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - Feedback/Suggestions for std.log

reply Gary <gary.mcelroy gmail.com> writes:
1. Background

Hi all, first time posting.
This message is in response to Andrei's first call for feedback on the 
proposed std.log interface.

I'm piping up on the log topic because of recent experience using a 
logging library ("log4cxx") on a project at work.

I'll attempt to identify our teams' requirements of the logging library, 
and transition into suggestions for D's "std.log", and why D is a 
powerful language in which to implement a versatile log.

I also, in these suggestions, dare make the assumption that the goals of 
std.log include accommodating audiences and users similar to my humble 
team members and myself. If this assumption is incorrect or the scope of 
the suggestions is too large for std.log, by all means pull me back down 
to Earth.

2. Requirements (for our team's logging functionality), and features 
which accommodate them

- Must be scalable with respect to project size
-- Feature: Allow custom log destinations specified at compile or 
run-time, and log level options specified at logger instantiation 
(compile time) or at run-time.
-- Feature: Allow loggers to exist in a hierarchy, in which properties 
of parent loggers are shared with children.
--- Our team of 18 developers must make judgments about what to log and 
when. Depending on the diagnostic activity, it is necessary to 
enable/disable logging in specific domains of the application. The 
ability to shut off logging in certain parts of the program at run time 
is paramount to success in debugging certain issues, from our experiences.
--- The hierarchy helps in being able to shut off a large branch of 
loggers by specifying the level for just one ancestor. Also the 
hierarchy format (at least in our case) maps well to the organization of 
objects across our domains.

- Must be performant

- Log calls and interaction must be concise, readable code
-- Feature: Minimal setup code, minimal code at log call site
--- Our team has felt the pain of supporting and troubleshooting our 
products at customer sites, with irate customers present. Each 
illuminative log statement is worth it's weight in gold, but we're also 
cognizant of maintainability of software, and code with verbose comments 
becomes difficult to read.
--- I opine: the current interface for std.log currently achieves good 
readability! Awesome!
-- Feature: Allow code/logic to be run inside the conditional block of a 
log call.
--- An example of our need for this is the need to print specific data 
from each member of a list of objects. Rather than incur log call 
overhead on each iteration over a list (much less not being able to 
compile away that logic), the most efficient solution seems to be 
allowing logic in the log conditional block.
--- Of course, somebody somewhere will misuse this and put "business" 
logic in there, and compile out a small but necessary tidbit which made 
their program function.
--- From my very rough understanding after reading the Lazy Evaluation 
article on "d-programming-language.org", this can be possible with the 
current std.log interface:
                 Sample pseudo-code:
                 logInfo({
                 auto msg = "Video modes found: ";
                 foreach( mode, videoModes )
                 {
                 msg ~= to!string( mode.width ) ~ "x" ~ to!string( 
mode.height ) ~ ";";
                 }
                 return msg
                 });
--- log4cxx simply allows a query to the logger at run-time to find out 
the current log level.

I can provide success stories (well, success in finding and debugging 
issues) from having a few of these features in our logging library, but 
that could be boring so I'll hold back (available on request).

3. Suggestions
Well, the suggestions for std.log are basically the features described 
above :-) . It'd be an injustice to express a desire to recreate 
log4cxx/log4j in D, but certain features which log4cxx provides greatly 
enhance development on large teams.

I haven't thought through it, but I get the feeling D might accommodate 
creating the logger hierarchy at compile time, or rather avoid string 
(logger name) computations at run-time (log4cxx does all the string 
manipulation at run-time).

I hopefully have made a case for including these features. I believe 
they'd be helpful to larger teams and teams supporting somewhat complex 
commercial products.

I'm aware that it's very easy to ask for things when I'm not the one 
working to help provide them. Since I'd like to see this and other 
growth in the D language, I'll offer my help however I can.

Thanks,
Gary
May 18 2011
parent reply Jose Armando Garcia <jsancio gmail.com> writes:
Hi Gary.

You should take a look at the proposed logging module for phobos at
http://jsancio.github.com/phobos/phobos/std_log.html and
https://github.com/jsancio/phobos/blob/master/std/log.d. Please
comment.

I have some comments below.

Thanks for your input.


 - Must be scalable with respect to project size
 -- Feature: Allow custom log destinations specified at compile or run-tim=


e,

 and log level options specified at logger instantiation (compile time) or=


 at

 run-time.


This is not actually a requirement but more of an implementation
suggest. What are you trying to achieve? With std.log you can enable
and disable verbose logging in a module at run time with --vmodule.
You can also disable logging at a specific severity for the entire
process at compile time and run time.


 -- Feature: Allow loggers to exist in a hierarchy, in which properties of
 parent loggers are shared with children.


Again, this is a implementation detail and not a requirement. What do
you plan to do with a hierarchy? Look at vlog, it is much more
flexible than a tree of loggers.


 --- Our team of 18 developers must make judgments about what to log and
 when. Depending on the diagnostic activity, it is necessary to
 enable/disable logging in specific domains of the application. The abilit=


y

 to shut off logging in certain parts of the program at run time is paramo=


unt

 to success in debugging certain issues, from our experiences.


You can use verbose logging and the command line flag --vmodule.


 --- The hierarchy helps in being able to shut off a large branch of logge=


rs

 by specifying the level for just one ancestor. Also the hierarchy format =


(at

 least in our case) maps well to the organization of objects across our
 domains.
From my experience you never really know how to organize your loggers


at dev time. You realize you want to turn something only at debug time
which in many cases it is too late (E.g. you already shipped a binary
to QA or customer). std.log gives you the ability to enable and
disable logging based on glob match on the source file.


 - Must be performant

 - Log calls and interaction must be concise, readable code
 -- Feature: Minimal setup code, minimal code at log call site
 --- Our team has felt the pain of supporting and troubleshooting our
 products at customer sites, with irate customers present. Each illuminati=


ve

 log statement is worth it's weight in gold, but we're also cognizant of
 maintainability of software, and code with verbose comments becomes
 difficult to read.
 --- I opine: the current interface for std.log currently achieves good
 readability! Awesome!
 -- Feature: Allow code/logic to be run inside the conditional block of a =


log

 call.
 --- An example of our need for this is the need to print specific data fr=


om

 each member of a list of objects. Rather than incur log call overhead on
 each iteration over a list (much less not being able to compile away that
 logic), the most efficient solution seems to be allowing logic in the log
 conditional block.
 --- Of course, somebody somewhere will misuse this and put "business" log=


ic

 in there, and compile out a small but necessary tidbit which made their
 program function.
 --- From my very rough understanding after reading the Lazy Evaluation
 article on "d-programming-language.org", this can be possible with the
 current std.log interface:
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0Sample pseudo-code:
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0logInfo({
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0auto msg =3D "Video modes found: ";
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0foreach( mode, videoModes )
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0{
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0msg ~=3D to!string( mode.width ) ~ "x" ~ t=


o!string( mode.height

 ) ~ ";";
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0}
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0return msg
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0});


Yes! but your example has a small bug...


 --- log4cxx simply allows a query to the logger at run-time to find out t=


he

 current log level.


This currently not exposed but it is trivial to add support for it...


 I can provide success stories (well, success in finding and debugging
 issues) from having a few of these features in our logging library, but t=


hat

 could be boring so I'll hold back (available on request).

 3. Suggestions
 Well, the suggestions for std.log are basically the features described ab=


ove

 :-) . It'd be an injustice to express a desire to recreate log4cxx/log4j =


in

 D, but certain features which log4cxx provides greatly enhance developmen=


t

 on large teams.

 I haven't thought through it, but I get the feeling D might accommodate
 creating the logger hierarchy at compile time, or rather avoid string
 (logger name) computations at run-time (log4cxx does all the string
 manipulation at run-time).


We can talk about how to improve performance at a later point but it
should be possible to cache the results of vmodule filtering.

 I hopefully have made a case for including these features. I believe they=


'd

 be helpful to larger teams and teams supporting somewhat complex commerci=


al

 products.

 I'm aware that it's very easy to ask for things when I'm not the one work=


ing

 to help provide them. Since I'd like to see this and other growth in the =


D

 language, I'll offer my help however I can.

 Thanks,
 Gary
May 28 2011
next sibling parent Gary M <gary.mcelroy gmail.com> writes:
Hi Jose,

Thanks for your response! I imagine you're quite busy so I appreciate 
you spending the time to respond.


On 11-05-28 05:29 PM, Jose Armando Garcia wrote:

 Hi Gary.

 You should take a look at the proposed logging module for phobos at
 http://jsancio.github.com/phobos/phobos/std_log.html and
 https://github.com/jsancio/phobos/blob/master/std/log.d. Please
 comment.


I read the proposed interface and am impressed!

Comments:

* The write method signature uses the source file and line for the message:
"write(string file = __FILE__, int line = __LINE__, T...) ..."
I saw in an earlier newsgroup message you asked Walter if it was 
appropriate to include the __MODULE__ name.
I'd go further and suggest even optional inclusion of the function name!
 From our team's experience, any extra information while debugging or 
viewing logs means we troubleshoot issues that much quicker. If that 
info can be automatically included, we get a free boost in productivity!

* Love the moduleFilter thing. Hopefully I'm referring to it correctly. 
Comments below.

* I want to say this is in the C++ Coding Standards book: I think it's 
recommended to use nouns in names of classes. Perhaps it's consistent to 
use "VerbosityConfig" as opposed to "VerboseConfig"?

* Abstracting out the "LogFilter" from the Logger strikes me as a good 
design decision.

Responses to your responses:


 - Must be scalable with respect to project size
 -- Feature: Allow custom log destinations specified at compile or run-time,
 and log level options specified at logger instantiation (compile time) or at
 run-time.


 This is not actually a requirement but more of an implementation
 suggest. What are you trying to achieve? With std.log you can enable
 and disable verbose logging in a module at run time with --vmodule.
 You can also disable logging at a specific severity for the entire
 process at compile time and run time.


You must forgive my horrible attempt to organize these points. What I 
meant to convey was the high level requirements and possible features 
which achieve them as sub-bullets, and examples as sub-bullets of those.

Happily, I see std.log achieves the fine grained control of filtering 
log messages based on severity and verbosity level. Awesome.

The prior point is a suggestion for multiple log message destinations.
I see the "SharedLogger" in the current proposal sends messages to 
different files based on severity.
Do I perceive correctly that the "abstract interface Logger" can be 
extended by users of std.log? This is an excellent idea! It's also an 
effective way to manage feature requests. Can users choose to log to 
their own sub-types of loggers somehow?
This can be an effective way to allow folks to point their log messages 
at whichever different files they'd like, or to some email destination, 
all while keeping the std.log interface relatively simple.



 -- Feature: Allow loggers to exist in a hierarchy, in which properties of
 parent loggers are shared with children.


 Again, this is a implementation detail and not a requirement. What do
 you plan to do with a hierarchy? Look at vlog, it is much more
 flexible than a tree of loggers.


I believe the "moduleFilter" allows the core of functionality I was 
shooting for. Apologies for not just stating that.


 --- Our team of 18 developers must make judgments about what to log and
 when. Depending on the diagnostic activity, it is necessary to
 enable/disable logging in specific domains of the application. The ability
 to shut off logging in certain parts of the program at run time is paramount
 to success in debugging certain issues, from our experiences.


 You can use verbose logging and the command line flag --vmodule.


I see, agreed!

It seems the verbose level has similar behavior to the severity level. 
If this is true, could someone define their own spectrum of levels out 
of an enumeration set, if they find the 5 regular levels are too coarse 
grained?


 --- The hierarchy helps in being able to shut off a large branch of loggers
 by specifying the level for just one ancestor. Also the hierarchy format (at
 least in our case) maps well to the organization of objects across our
 domains.
 From my experience you never really know how to organize your loggers


 at dev time. You realize you want to turn something only at debug time
 which in many cases it is too late (E.g. you already shipped a binary
 to QA or customer). std.log gives you the ability to enable and
 disable logging based on glob match on the source file.


I believe I see this "glob" ability in the "moduleFilter" part of the 
VerboseConfig! Bravo! I was going to point out: the power of the 
hierarchy was in the efficient configuration of which parts of the 
program log and which do not. It appears the moduleFilter achieves this, 
though with more expressiveness!
Organization of loggers is definitely a brain exercise, I think partly 
because there's an implicit desire not to make a log message appear too 
alien if a customer must view it for any reason.
I've settled on roughly matching the logger organization to component 
organization.


 -- Feature: Allow code/logic to be run inside the conditional block of a log
 call.
 --- An example of our need for this is the need to print specific data from
 each member of a list of objects. Rather than incur log call overhead on
 each iteration over a list (much less not being able to compile away that
 logic), the most efficient solution seems to be allowing logic in the log
 conditional block.
 --- Of course, somebody somewhere will misuse this and put "business" logic
 in there, and compile out a small but necessary tidbit which made their
 program function.
 --- From my very rough understanding after reading the Lazy Evaluation
 article on "d-programming-language.org", this can be possible with the
 current std.log interface:
                 Sample pseudo-code:
                 logInfo({
                 auto msg = "Video modes found: ";
                 foreach( mode, videoModes )
                 {
                 msg ~= to!string( mode.width ) ~ "x" ~ to!string( mode.height
 ) ~ ";";
                 }
                 return msg
                 });


 Yes! but your example has a small bug...


Ha! I've been trying to achieve this "lazy implicit conversion of 
function literal to string" thing in my D "mini-test" suite. Haven't 
ironed it out just yet.


 --- log4cxx simply allows a query to the logger at run-time to find out the
 current log level.


 This currently not exposed but it is trivial to add support for it...


To start this point, I call upon the "Contract Programming" chapter of 
TDPL. Andrei notes that it is dangerous to place modifying code in code 
which should only be observing.
As it pertains to this case, I'd hope revealing the log level, or rather 
if the log filter will log, won't encourage putting "business logic" in 
a block meant only for logging.
To that end, all the same dangers exist for the method I described 
above. Hmmm, it may win if it can be stripped at compile time... I admit 
my ignorance regarding that stripping technique.



 I can provide success stories (well, success in finding and debugging
 issues) from having a few of these features in our logging library, but that
 could be boring so I'll hold back (available on request).

 3. Suggestions
 Well, the suggestions for std.log are basically the features described above
 :-) . It'd be an injustice to express a desire to recreate log4cxx/log4j in
 D, but certain features which log4cxx provides greatly enhance development
 on large teams.

 I haven't thought through it, but I get the feeling D might accommodate
 creating the logger hierarchy at compile time, or rather avoid string
 (logger name) computations at run-time (log4cxx does all the string
 manipulation at run-time).


 We can talk about how to improve performance at a later point but it
 should be possible to cache the results of vmodule filtering.


Right on!
May 31 2011
prev sibling parent Gary M <gary.mcelroy gmail.com> writes:
Hi Jose,

Thanks for your response! I imagine you're quite busy so I appreciate 
you spending the time to respond.


On 11-05-28 05:29 PM, Jose Armando Garcia wrote:

 Hi Gary.

 You should take a look at the proposed logging module for phobos at
 http://jsancio.github.com/phobos/phobos/std_log.html and
 https://github.com/jsancio/phobos/blob/master/std/log.d. Please
 comment.


I read the proposed interface and am impressed!

Comments:

* The write method signature uses the source file and line for the message:
"write(string file = __FILE__, int line = __LINE__, T...) ..."
I saw in an earlier newsgroup message you asked Walter if it was 
appropriate to include the __MODULE__ name.
I'd go further and suggest even optional inclusion of the function name!
 From our team's experience, any extra information while debugging or 
viewing logs means we troubleshoot issues that much quicker. If that 
info can be automatically included, we get a free boost in productivity!

* Love the moduleFilter thing. Hopefully I'm referring to it correctly. 
Comments below.

* I want to say this is in the C++ Coding Standards book: I think it's 
recommended to use nouns in names of classes. Perhaps it's consistent to 
use "VerbosityConfig" as opposed to "VerboseConfig"?

* Abstracting out the "LogFilter" from the Logger strikes me as a good 
design decision.

Responses to your responses:


 - Must be scalable with respect to project size
 -- Feature: Allow custom log destinations specified at compile or run-time,
 and log level options specified at logger instantiation (compile time) or at
 run-time.


 This is not actually a requirement but more of an implementation
 suggest. What are you trying to achieve? With std.log you can enable
 and disable verbose logging in a module at run time with --vmodule.
 You can also disable logging at a specific severity for the entire
 process at compile time and run time.


You must forgive my horrible attempt to organize these points. What I 
meant to convey was the high level requirements and possible features 
which achieve them as sub-bullets, and examples as sub-bullets of those.

Happily, I see std.log achieves the fine grained control of filtering 
log messages based on severity and verbosity level. Awesome.

The prior point is a suggestion for multiple log message destinations.
I see the "SharedLogger" in the current proposal sends messages to 
different files based on severity.
Do I perceive correctly that the "abstract interface Logger" can be 
extended by users of std.log? This is an excellent idea! It's also an 
effective way to manage feature requests. Can users choose to log to 
their own sub-types of loggers somehow?
This can be an effective way to allow folks to point their log messages 
at whichever different files they'd like, or to some email destination, 
all while keeping the std.log interface relatively simple.



 -- Feature: Allow loggers to exist in a hierarchy, in which properties of
 parent loggers are shared with children.


 Again, this is a implementation detail and not a requirement. What do
 you plan to do with a hierarchy? Look at vlog, it is much more
 flexible than a tree of loggers.


I believe the "moduleFilter" allows the core of functionality I was 
shooting for. Apologies for not just stating that.


 --- Our team of 18 developers must make judgments about what to log and
 when. Depending on the diagnostic activity, it is necessary to
 enable/disable logging in specific domains of the application. The ability
 to shut off logging in certain parts of the program at run time is paramount
 to success in debugging certain issues, from our experiences.


 You can use verbose logging and the command line flag --vmodule.


I see, agreed!

It seems the verbose level has similar behavior to the severity level. 
If this is true, could someone define their own spectrum of levels out 
of an enumeration set, if they find the 5 regular levels are too coarse 
grained?


 --- The hierarchy helps in being able to shut off a large branch of loggers
 by specifying the level for just one ancestor. Also the hierarchy format (at
 least in our case) maps well to the organization of objects across our
 domains.
 From my experience you never really know how to organize your loggers


 at dev time. You realize you want to turn something only at debug time
 which in many cases it is too late (E.g. you already shipped a binary
 to QA or customer). std.log gives you the ability to enable and
 disable logging based on glob match on the source file.


I believe I see this "glob" ability in the "moduleFilter" part of the 
VerboseConfig! Bravo! I was going to point out: the power of the 
hierarchy was in the efficient configuration of which parts of the 
program log and which do not. It appears the moduleFilter achieves this, 
though with more expressiveness!
Organization of loggers is definitely a brain exercise, I think partly 
because there's an implicit desire not to make a log message appear too 
alien if a customer must view it for any reason.
I've settled on roughly matching the logger organization to component 
organization.


 -- Feature: Allow code/logic to be run inside the conditional block of a log
 call.
 --- An example of our need for this is the need to print specific data from
 each member of a list of objects. Rather than incur log call overhead on
 each iteration over a list (much less not being able to compile away that
 logic), the most efficient solution seems to be allowing logic in the log
 conditional block.
 --- Of course, somebody somewhere will misuse this and put "business" logic
 in there, and compile out a small but necessary tidbit which made their
 program function.
 --- From my very rough understanding after reading the Lazy Evaluation
 article on "d-programming-language.org", this can be possible with the
 current std.log interface:
                 Sample pseudo-code:
                 logInfo({
                 auto msg = "Video modes found: ";
                 foreach( mode, videoModes )
                 {
                 msg ~= to!string( mode.width ) ~ "x" ~ to!string( mode.height
 ) ~ ";";
                 }
                 return msg
                 });


 Yes! but your example has a small bug...


Ha! I've been trying to achieve this "lazy implicit conversion of 
function literal to string" thing in my D "mini-test" suite. Haven't 
ironed it out just yet.


 --- log4cxx simply allows a query to the logger at run-time to find out the
 current log level.


 This currently not exposed but it is trivial to add support for it...


To start this point, I call upon the "Contract Programming" chapter of 
TDPL. Andrei notes that it is dangerous to place modifying code in code 
which should only be observing.
As it pertains to this case, I'd hope revealing the log level, or rather 
if the log filter will log, won't encourage putting "business logic" in 
a block meant only for logging.
To that end, all the same dangers exist for the method I described 
above. Hmmm, it may win if it can be stripped at compile time... I admit 
my ignorance regarding that stripping technique.



 I can provide success stories (well, success in finding and debugging
 issues) from having a few of these features in our logging library, but that
 could be boring so I'll hold back (available on request).

 3. Suggestions
 Well, the suggestions for std.log are basically the features described above
 :-) . It'd be an injustice to express a desire to recreate log4cxx/log4j in
 D, but certain features which log4cxx provides greatly enhance development
 on large teams.

 I haven't thought through it, but I get the feeling D might accommodate
 creating the logger hierarchy at compile time, or rather avoid string
 (logger name) computations at run-time (log4cxx does all the string
 manipulation at run-time).


 We can talk about how to improve performance at a later point but it
 should be possible to cache the results of vmodule filtering.


Right on!
May 31 2011