Logging APIs – Feature List
2010-02-01 | Filed Under Programming
Logging is not the world’s most interesting computing problem, but it is important, and it’s been on my mind lately because people have been pointing out that my company’s use of logging is currently a bit of a mess and ought to be cleaned up. Specifically, I’ve been thinking about the API that is used to invoke logging and also a little bit about the plumbing that is responsible for doing something with the log messages. What I would like to do here is a bit too big for one entry, so I will split it in two. In this, the first part, I will simply catalog some features that a logging API can have, then in the second part I will use that list to evaluate a few Java libraries. The catalog of features would apply to any language, but I will consistently use Java as an example.
The ultimate goal in logging is to write out some messages that are solely for use in debugging and managing a system — output that is a side effect rather than the primary goal of the program. The simplest version of logging has always been this:
SplineList splineList = reticulateSplines(rawSplines); System.out.println(splineList);
The simple “print” statement is a universal form of logging (I can name only a couple of languages that don’t have some basic syntax to support it) and I have used it far more times than I would choose to admit. Any logging framework should be evaluated in terms of what it adds to this capability. Here are the features I have been able to think of:
- Severity – the ability to mark some log messages as being more important than others. There is no need to go overboard: even the biggest systems I have seen have done quite well with 6 or seven different levels, but it is nice to distinguish between printing out the value of a variable for debugging and reporting a potentially fatal application error. Severity in logging looks like this:
logger.log(Level.WARNING, "Spline reticulation returned 0 results.");
- Tree of Log Topics – in large or medium-sized programs, no one is interested in every single log message (at least not all at the same time). The best solution that has been found is to group messages into “topics”, and the best solutions organize these topics into trees. So you may write some logs to the topic “security.login”, others to “validation.TransferMoney” and a library may write to “org.apache.comcat.util”. Logging levels can be set to view even DEBUG level messages within “security.*” but only FATAL messages in “org.apache.*”. Often a sensible default is to take the name of the log topic from the full package-and-class of the class that is writing the log message. Use of log topics looks like this:
private static Logger logger = new Logger("com.mcherm.sampleapp.ThisClass");
- Configurable – the choice of what to log, at what severity, and to what files (or other kinds of output) should not be embedded in code. It should be configurable, certainly at deploy time and perhaps at runtime as well. Configuration looks something like this:
log4j.appender.LOGFILE=org.apache.log4j.DailyRollingFileAppender log4j.appender.LOGFILE.layout=org.apache.log4j.PatternLayout log4j.appender.LOGFILE.layout.ConversionPattern=%d %p [%t] [%X{sesstag}] [%X{pmsessid}] [%c] - <%m>%n log4j.appender.LOGFILE.DatePattern='.'yyyy-MM-dd
- Rotating log files – When logs are written to a file (by far the most common approach), the files can very easily get too big to use. A useful feature is the ability to set a max size for the files. After the max size has been reached, subsequent writes go to a new file, and the old file is left in place until later. Rotating log files lead to directory listings like this:
12/10/2009 03:24 PM 1,710,360 loanapp.0.log 12/09/2009 11:41 AM 0 loanapp.0.log.lck 12/09/2009 11:40 AM 189,992 loanapp.1.log 12/08/2009 06:06 PM 1,366,039 loanapp.2.log 12/07/2009 03:08 PM 8,314,456 loanapp.3.log 11/24/2009 01:34 PM 410,931 loanapp.4.log 11/24/2009 11:34 AM 506,066 loanapp.5.log
The other kind of "Log Rolling"
- Configurable Log Line Format – The key content of a log message is typically some string that was provided when the call was made to the logger. But there is a lot of other information that may be available: the exact time the log call was made, the logger topic that was used, the place in the code the call was made from, the thread that was in use… and lots of others if you keep thinking about it. A useful feature of some loggers is the ability to configure just what information gets written out along with that basic message. Typical output from a logger may look like this:
* 2009-12-29T15:56:55.591-05:00 [22] com.company.util.security FINER (com.company.util.security.OneTimeCredential.validateCredential) clearCred = 00 00 01 25 DC 3A 23 8E 00 00 00 4E * 2009-12-29T15:56:55.591-05:00 [22] com.company.dg.util.OperatorImpl FINEST (com.company.dg.util.OperatorImpl.getOperator) Returning systemOperator = web * 2009-12-29T15:56:55.591-05:00 [22] com.company.util.ApplicationPropertiesImpl FINEST (com.company.util.ApplicationPropertiesImpl.getProperty) Property Name(AuthenHelper.custDatabase) has value (cust). * 2009-12-29T15:56:55.591-05:00 [22] com.company.util.ApplicationPropertiesImpl FINEST (com.company.util.ApplicationPropertiesImpl.getProperty) Property Name(AuthenHelper.getPartyId) has value (pkg_dg_party_login.sp_getPartyIdByString).
Each entry has a timestamp, the thread number in square brackets, the logger name, the severity, the function logging it, and then the log message string. There are various other pieces of metadata that could have been recorded instead of or in addition to the timestamp, thread number and so forth, and this can all be controlled from the logging config file.
- Logging of Exceptions – Most logging has been described in terms of the string to be logged, but there is no reason why it necessarily has to be a string. In theory, a logging framework could support producing sensible logs from other kinds of objects that are passed in to it. In practice, I have only seen one such object which is useful (but that one is quite helpful) – Exceptions. So it is useful if a logging framework allows the user to specify an exception, along with the string, when that is appropriate, and includes the stack trace from that exception in the data recorded for the log.
- Delayed String Construction – The content for a log message can be just a simple string:
logger.warn("Spline reticulation returned 0 results.");
but it is far more common for it to be a string constructed with data available at runtime:
logger.warn("Spline reticulation returned " + numResults + " results.");
Also, it is not at all unusual for there to be significant amounts of work in constructing the string:
logger.warn("Splines returned: " + splineList.toString());
Because Java does early binding of parameters (as do most languages other than Haskell), the work to generate the string to be logged will be done EACH AND EVERY TIME the log statement is encountered, EVEN IF LOGGING IS DISABLED. So even if the log levels are set to warnings and debug logs won’t be printed, the examples above would still perform all the work to construct the string. This overhead can be enormous: I personally worked on a project where we sped up the entire application by a factor of 3 just be avoiding the creation of log lines for statements that would not be logged.
There are three ways to avoid this overhead. One is specify the log level at compile time (lots of logging systems for C do this), but then it cannot be changed without recompiling. Another is to manually perform the (efficient) check of logging level before performing the work:
if (logger.isLoggable(Level.DEBUG) { logger.debug("Splines returned: " + splineList.toString()); }
but this requires burying each logging statement inside of an if. The final option is what I call “Delayed String Construction”, or sometimes “parameterized log messages” and that is to have library level support for delaying the construction:
logger.debug("Splines returned: {}", splineList);
- Log to Multiple Locations – Sometimes you want certain log entries to go to more than one file. For instance, you might want to send all logs to a single master log file, but also send logs about login errors to a separate security log which gets reviewed by a different group of people.
- Configure Where Logs are Directed – Usually you want logs to go to a file, but other times you want something more exotic like storing logs from multiple servers on a single remote location, sending logs to a messaging system, or writing logs to a database. This is particularly useful in conjunction with logging to multiple locations. So one useful feature, called “Appenders” in some systems, is the ability to provide a custom piece of code which processes the log entry: it could write it to a file OR do something else more exotic.
- Standard, or Widely Used – It is a big advantage if the logging system you use is widely used by others. One reason is the usual: standardized or widely used products tend to get improved over time while more obscure products tend to be forgotten and lose support. But in logging there is an additional advantage: if a library you are using or the server that is hosting your code also uses the same logging facility, then it may be possible (even easy) to comingle the log messages with your application log messages, which can be extremely useful when debugging issues which cross library boundaries.
- Sensible Fallbacks – As previous features have mentioned, logging can involve all kinds of complicated configuration and setup. In the real world, these will sometimes fail. Perhaps your logging configuration file cannot be found, or the log directory cannot be written to, or the logging database password fails — and the most common of these errors is to have no configuration at all. Different logging frameworks have different fallback behavior in the face of problems like this: some will disable all logging, others will fall back on a more primitive form of logging such as writing all logs to stdout if the logging is not configured. It is desirable for a logging system to have sensible fallback behavior.
- Logging Queued to Avoid Delays – In nearly all cases, logging is not the most important thing that your application is doing. The primary goal of the program is to reticulate splines, respond to user keystrokes, respond to web requests, or whatever it is that your application does; logging is a secondary concern. That being said, it is a real shame that writing logs slows down the application. It is quite common that the work done in response to a request can be quick and simple enough (retrieving some data that is already cached) that it is FAR less than the time required to open a file on disk and write even a single line of logging.One solution (with a few drawbacks) is that instead of actually writing the log immediately, logs that are to be written get put onto a queue, and they are written out by a background thread. The big advantage is performance: your program can quickly stash a few strings in memory and get on with its work faster; the log entry gets written later, when there are spare CPU cycles available. It can even save time overall by batching writes. There are a few disadvantages to be aware of: it will increase memory requirements (but typically by an insignificant amount); the queue typically needs a max size, and you need a policy for what to do when logs are being created faster than they can be written: typically the choices are either to discard some of the logs or to slow down the application. And it makes it difficult to debug issues that actually lead to crashes (because the logs don’t get written due to the crash). But significantly faster application performance is often worth these costs.
- Threadlocal Context Data – Imagine building a web application, which takes requests from logged-in users. And consider logs which are written from deep inside the spline reticulation code. For tracking down certain kinds of bugs, it would nice to know which user’s data contained the spline that was being reticulated. But we can’t just add that to the log message, because the spline reticulation code isn’t passed the name of the user. Some function 7 levels up the stack may have known it, but that doesn’t help to pass it into the log message.So a useful feature would be to have a command we could call at the point where we first identify the user submitting this request. This command could tell the logging system the name of the user and the logging system could store it in threadlocal storage. Then all future logs written from this thread could be annotated with “user=JSmith”, until this service call is completed.
Two versions of this feature are offered by Log4J: “Nested Diagnostic Context”, in which multiple pieces of data can be kept in a stack, and “Mapped Diagnostic Context” in which multiple pieces of data are kept in a map.
- Log Filtering – Not all applications will have this requirement, but at large institutions with a concern for security, there are some things which ought not be written into a log. For instance, there may be a policy that passwords are not recorded, or that customer social security numbers never be stored in an unencrypted fashion. A fairly rare, and often imperfect but still useful, feature is the ability to provide some sort of filter which will recognize these kinds of data and remove them before the log data is recorded to disk. The difficult part, of course, is in recognizing the data.
- Internationalization – Many loggers have support for writing messages in unicode (particularly in languages like Java where the fundamental String type supports unicode). But some go further and provide support for loading the messages from a language-specific file and may have features like localization of dates and other information appearing in log messages.
So that’s my list of features; see my next entry where I use this list of features to evaluate some Java logging libraries.
Post Links
Permalink | Trackback | 3 Comments
Comments
3 Responses to “Logging APIs – Feature List”
Leave a Reply
Two issues largely missed in logging
Uniqueness of message – “we had an error” that appears in multiple places… Which specific chunk of code with that message was the one that created it? I’ve seen function name and/or unique error number be most effective. But if you’ve got multiple functions with the same name (object overloading) then it can become complex. And tracking unique error numbers, especially with shared code/object libraries can become complex.
Message buffering. This one only really matters if the application crashes rather than being able to exit gracefully when an error is detected/handled. I’m a strong proponent of the C fflush(); it could be handled as part of the error logging code/objects (your logger.X example) with a frequency count (every N messages) or semi-explicitly (after a type of invocation), or even manually.
Granted, frequent fflushes slows processing (forcing physical I/O rather than buffered into larger writes), but provides more information on failure.
Your last “Delayed String Construction” example reminds me a lot of the C printf statement… Except you used {} instead of %s%s%s%s%s.
Oh, I particularly like your #1 “Uniqueness of Message”. A useful feature that I’ve seen is to automatically mark each log message with the line and file from which it was generated. This should be one of the criteria.
#2 I’m not so sure about. In the Java world, files flush when they are closed suddenly, unless the JVM itself crashes — and that is VERY rare these days; it essentially never happens with our files. Of course, this isn’t supposed to be a java-specific list, so given that I should probably list that one too.
The JVM may prevent #2 but that doesn’t help for O/S faults, or, as you mention, other languages. In the “old C days” the saying was “The world is not a VAX” (because the VAX would let you get away with things that would upset other systems – like dereferencing the NULL pointer). So you have to remember, “The world is not just Java” :-)