Putting logging in programs is a basic way to get the program to reveal what it is really doing. As I matured as a programmer, my strategy for logging evolved as follows:
Log4j/log4perl is complex, but it solves a lot of nagging problems. I use it in my own standardized way, which offers additional features. The list of things I find useful includes:
Log4perl/log4j implement some of the above, and some of it depends on using log4j/log4perl in a systematic way.
Log4perl/log4j implements the following "levels", in order of priority:
The above levels are hierarchical (except for "OFF"). For example, when "INFO" is set, all "INFO", "WARNING", "ERROR" and "FATAL" messages will be output.
The "default" logging level is "WARNING". In my code, I output messages that I unconditionally want the user to see with the "warn", "error" and "fatal" function calls. All messages are output this way - I don't use "print", "die" or "warn" in Perl, and I don't use "System.out.println" in Java. Thus, when I choose to output messages to a log file, the log file contains all the messages. This is good, but doesn't mean that stack-dump type error messages will show up in the file. Oh well.
In my code, the "INFO" and "DEBUG" levels are controlled by command-line arguments.
I want the user to control the amount of logging that a program generates. Command-line options control this. I offer the user 2 kinds of logging messages: "informational" and "debugging". Informational messages are used to let the user see the progress of the program. Debugging messages are more detailed, and are usually used only during development. Setting debugging turns on all informational levels.
The depth (verbosity) of messages is set with the "-i" and "-d" command-line options. For example, for a program that recursively walks a huge directory tree, modifying the URLs in some of the files, the command-line arguments might mean
-i
Show "informational" messages, for watching progress, like
-i 1 show directory opens
-i 2 show file opens
-i 3 show the files being changed
-i 4 show the URLs being changed
etc.
-dTo implement these depths, I use log4perl categories. For example, the category named "log1" corresponds to the "-i 1" and "-d 1" command-line options. In Log4Perl, DEBUG implies INFO, so turning on DEBUG also turns on INFO. A function that outputs "debugging" and "informational" messages has the general form
Show "debugging" messages, especially function entry/exit, like
-d 1 top-level functions
-d 2 second-level functions
-d 3 third-level functions
etc.
sub func1 () {
my $logger = get_logger("log1");
$logger->debug("called");
:
my $ifilename = 'abc.txt';
$logger->info("opening file abc.txt");
open IFILE $ifilename or do {
$logger->fatal("couldn't open file $ifilename");
exit;
};
:
$logger->debug("returning");
}
This approach uses the logging system to output fatal errors
regardless of the command-line options the user has chosen. The
default level of all loggers (including 'log1') is WARNING, so
in the above code, the call to $logger->fatal above will cause
output. By using logger calls to output fatal error messages,
the messages will appear with other logging messages in the same
logging destination, whether standard output or a file.
The function that parses command-line arguments sets the levels of the loggers. It calls InitializeLogging to do so. InitializeLogging sets the levels of all loggers to WARNING (the default), INFO or DEBUG.
To implement indenting in Log3perl, I use a "custom cspec" with a PatternLayout. See ~/bin/test-log4perl/test-caller.pl. I haven't yet implemented it in Java/log4j.