Yohan is a Senior Technical Lead specialising in Java and related technologies. His interests are in Software Architecture, API Design and Development, Enterprise Integration, Messaging, Distributed Computing and Parallel computing. Yohan is a DZone MVB and is not an employee of DZone and has posted 15 posts at DZone. You can read more from them at their website. View Full User Profile

The Dark Art of Logging

11.22.2010
| 9226 views |
  • submit to reddit

Logging is a mechanism of keeping track of the runtime behavior of an application, mainly for debugging / tracing purposes. In almost all of significantly complex / vital applications, maintaining a proper application log is a must; hence, almost all developers are quite familiar with the paradigm of logging. And it isn’t rocket science. You just have to call a simple method with whatever you want to log, and mess around with a simple configuration file, and that’s all. So what’s the big deal?

The problem is that though logging is a simple thing to do, doing it correctly needs a lot of practice, experience and understanding. That makes it more of an art than a science. In my personal experience, mastering the art of logging requires lots of patience, experience and forward thinking. It’s quite difficult to teach someone how to do it (sort of tacit knowledge), and most freshers tend to see the effort put into writing to log files as something additional. But all that effort pays up when you go through long nights trying to figure out what went wrong in a production system. But for that, it is important that proper logging is done through-out the system, which requires all of the team to master this dark art. Just one guy doing it right in a team is simply not enough.

First of all, it is important to understand the purpose of logging. The primary purpose of maintaining a log is to be able to trace the execution of the application. This can be used for debugging and also to ensure that application performs operations as expected. Also, in some cases, these log files are used for auditing purposes as well.

Therefore, when we write to a log file, it is important to keep in mind that whatever the content that we log is actually useful for the above mentioned purposes. Logging for the sake of doing it will not help. We have to envision a scenario in the future where we are going through log files, and plan ahead and log the message to be useful at such times.

Log about Context

One very important thing to keep in mind is to ensure that sufficient information about the context is written to the log file. Consider the following example method, which calls a complex business operation with two parameters passed in by the user.

public void invokeBusinessOperation(String param1, String param2) {

if (LOG.isTraceEnabled()) {
LOG.trace("Invoking the foo() business operation");
}

businessObject.foo(param1, param2);

}

This will write the following to our log output.

Invoking the foo() business operation

So far, so good. In the future, if need to ensure that this business operation is invoked as expected, we can monitor the log file and make sure that it gets called. This is way better than not having any log statements, in which case we have no way of tracking this. But is this good enough?

Think of a situation where this application is being used by multiple concurrent users. What we will see in the log file is something like this.

Some arbitary log message from another component.
Invoking the foo() business operation
Another log message
Another log message
Invoking the foo() business operation
Some arbitary log message from another component.
Another log message
Invoking the foo() business operation
Invoking the foo() business operation
Another log message

This is not very useful, since we have no way of identifying the exact invocation that we are interested in (due to concurrency and multiple invocations by various users). But, if we change our logging statement like this,

public void invokeBusinessOperation(String param1, String param2) {

if (LOG.isTraceEnabled()) {
LOG.trace("Invoking the foo() business operation with params : " + param1 + ", " + param2);
}

businessObject.foo(param1, param2);

}
Some arbitary log message from another component.
Invoking the foo() business operation with params : abc, def
Another log message
Another log message
Invoking the foo() business operation with params : xyz, ght
Some arbitary log message from another component.
Another log message
Invoking the foo() business operation with params : bar, tea
Invoking the foo() business operation with params : jkl, mno
Another log message

Below is a real life example of log outputs, which really shows the importance of contextual logging.

Reservation Validation Failed: Contract does not cover Meal Plan
Reservation Validation Failed (Reg.ID : 12) - No Contract Rate in Contract (33) covers the Meal Plan  (1 : FB)

As seen, the second approach would allow us to identify the problem easily, where as the first one leaves us no clue about which reservation or which contract.

With the context information, the log output is more meaningful, and would be much more helpful in future tracing / debugging activities. Therefore, it is important that we log useful context information when we do logging. Otherwise, it does not serve the purpose of maintaining a log file.

Log sufficiently – Not too much, not too less

It is important that we do a fair amount of logging in our applications. We should be able to go through the log file and ensure that application execution happens in expected path, and also to isolate errors and trace back to the actual cause, with minimal effort. Getting that done is not easy.

If we go ahead and log each and every method execution and parameters, our log files will grow, and it will contain unnecessary information which will make the debugging process a nightmare. On the other hand, if we don’t have sufficient logging, then it will be impossible to trace back, since we have no clue about what went wrong and where it went wrong. So it is important to strike a balance between these two ends.

One approach to achieve this is to log at least once when executing an important business function, in Information Level (logging levels will be discussed later on). This facilitates tracing execution of the application easily. Also, when an exceptional situation occurs (exceptions, errors and important validation failures) it should be logged in an appropriate level.

Log at the correct level

All of the logging frameworks out there support various log levels. These log levels exist to allow developers to control the output of log files using configurations, to filter out unnecessary messages. I will use the log levels supported by Apache Commons Logging API for this discussion, but counterparts exist in other log frameworks under various names (note that the priority of the log level increases downwards).

Level Description
TRACE This is the lowest logging level. This should be used for tracing activities such as method invocation and parameter logging, etc.
DEBUG This log level is commonly used for application debugging statements. This level should be used to log messages which are helpful in debugging, but which are too verbose to be written to the log under normal situations.
INFO This is the information log level. This should be used to log statements which are expected to be written to the log during the normal operations. For example, running a important business operation should be logged under this level.
WARN Warning Level. This should be used to log warnings, which are situations that are usually unexpected, but which does not significantly affect the business functionality.
ERROR Error level should be used to log all errors and exceptions which affect the business functionality of the application.
FATAL Fatal log level is used to write extreme situations where the entire application execution could be affected due to some cause.

Log before throwing exceptions

It is a good practice to log an error message before throwing an exception. This helps a lot when trying to identify the root cause of an exception. Although we cannot push in much detail to a normal exception (unless we add in attributes to keep those), we can log detailed contextual information to the application log, which will in turn pay off when we struggle in a late night trying to figure out what went wrong.

Usually, log statements for exception are written at ERROR level. However, if the exception that you are throwing is part of the business flow (which is a practice questioned by some), then it would be better to log such events in a lesser level, such as example WARN or INFO.

For example, in one of my past projects, we needed to do a complex validation sequence, and we used exceptions as the mechanism of notifying validation failures. However, we did not want to pollute the application log with ERROR statements for such cases, which are normally expected during execution of the application (ERROR statements should be used for real errors). So instead of ERROR level, we used the INFO level for those messages.

Avoid System.out / System.err

It is surprising to see that some developers of enterprise scale applications resort to System.out or System.err, while a proper logging framework is in use within the application. If we use System.out while rest of the application uses a logging framework, we lose the advantage of the logging framework. Logging frameworks can be configured to log at different levels and patterns, but System.out calls will be out of that configuration. Therefore, it is always better to use the same logging framework throughout the application.

One other thing is that automatic code generation for try-catch blocks in IDEs generate ex.printStackTrace() as the default catch block. The printStackTrace() method writes to System.err and this should be avoided in the presence of a logging framework. Instead of that, use the facilities provided by the logging framework for the task.

LOG.error("error description message here", ex);

Think of ‘Performance’ too

Although logging is really important for an application, it is not part of the actual business operation.  Although for many applications, overhead introduced by logging is negligible, there are situations where it should be seriously considered, especially since it involves writing to files (if the logger is configured so).

For example, consider a hypothetical application where for each business operation invocation (which takes less than a second to complete), we log 1KB of log output to a file. If that application is used heavily by concurrent users, say, 10000 business operations per second, then our application will need to write 1KB * 10000 = Approx. 10 MB of data per second. If we assume that the application logic needed to be executed can handle such a load without any issue, the bottleneck of the application will be the logging part, since it requires performing slow disk I/O.

Also, in most of the cases, writing context information to a log requires heavy string concatenations. String concatenations are pretty slow, and it will leave out garbage output in the Java’s String Constant Pool. However, we cannot avoid this as well (you can use a String Builder if there are many number of concatenations, but that will not be a good idea of the number of concatenations are less). One thing we could do is to use guard conditions for the logging statements, so that if the corresponding log level is disabled, we can skip the overhead of concatenation and running through the logging API code.

For example,

if (LOG.isDebugEnabled()) {
LOG.debug("Dispatching " + topic + " emails to : " + emailAddress);
}

With the ‘if’ condition, the log entry will be invoked only when the relevant log level is enabled. If it is not, the log statement will not be executed, and the string concatenation will not happen as well. If the ‘if’ condition was not there, then the concatenation will happen, and then the method will be executed. Within the method execution it will figure out that the logging for the level is disabled, and then it will discard the log message.  It is advised to use these guard blocks for lower log levels such as TRACE and DEBUG, which are normally disabled in production setup.

Get your IDE to do the hard work

Most of the IDEs out there supports coding templates, which are very useful when it comes to logging. These templates can generate the boilerplate code that is exhaustive to write. Then it’s just a matter of getting the template executed when you are writing your log statements, etc.

Following examples are for Eclipse, but similar approaches are there for other IDEs as well.

In Eclipse, you can create code templates through Window -> Preferences -> Java -> Editor ->Templates.

For generation of logger declaration (using Commons Logging), I use the following template which I have named as ‘getlog’.

${:import(org.apache.commons.logging.Log, org.apache.commons.logging.LogFactory)}
private static final Log LOG = LogFactory.getLog(${enclosing_type}.class);

So when I type in getlog and hit Ctrl+Space, Eclipse generates the following for me, with the proper class name filled.

private static final Log LOG = LogFactory.getLog(THE CLASS NAME.class);

Likewise, we can create templates for generating the if-blocks for DEBUG level as follows.

if (LOG.isDebugEnabled()) {
LOG.debug("${msg}");
}

With this, when you type in debug and hit Ctrl+Space and get the template executed, you will get the complete if-block, and your cursor placed inside the double quotes, ready to type the message.

One more thing to tweak the IDE is to change the standard code template for try-catch blocks, which contains the printStackTrace() method. This can be changed through Window -> Preferences -> Java -> Code Style -> Code Templates. Change the Code -> ‘Catch block body’ and  ‘Code in new catch blocks’  template to the following.

LOG.error("${msg}", ${exception_var});

And Finally,

As always, it’s easier said than done. It requires some practice to master this, but once you have, you will know instinctively when and how you should log, and when you shouldn’t.

 

From http://blog.yohanliyanage.com/2010/11/the-dark-art-of-logging/

Published at DZone with permission of Yohan Liyanage, author and DZone MVB.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Tags:

Comments

Eyal Golan replied on Mon, 2010/11/22 - 2:56am

Thanks for a really good article.

The eclipse tweeking is a very very good tip !

Chad Hahn replied on Mon, 2010/11/22 - 8:33am

Using SLF4J is a great way to get rid of all those nasty

if (LOG.isDebugEnabled()) {
}

blocks.  See http://www.slf4j.org/faq.html#logging_performance

Andrew Spencer replied on Mon, 2010/11/22 - 10:46am

Good summary.  I like the IDE macros suggestion.  I'm not very disciplined about logging, and maybe that will help me get into the habit.

An important part of logging, which is worth its own article, is how you configure and integrate your log framework(s).  It can be a surprisingly complex job, because you need to make sure statements are sent to the appropriate destination, at the appropriate level and in an appropriate format.  And you need to accomplish this, not only for your own log statements, but also for those coming from frameworks and libraries that you use (e.g. Hibernate, Spring).  And these frameworks and libraries may not use the same logging framework as you.

The slf4j framework helps with the last issue, but it's still a pain in the neck to set up, and I have to confess that on my current project it still isn't quite right.

 

Jonathan Fisher replied on Mon, 2010/11/22 - 10:49am

This is a good point to advertise SLF4J. I'm not a commit-er on the project, but there are two very important features of SLF4J that should have been included in JUL logging. SLF4J has a far better reputation that commons-logging, and is merely a shell around log4j, jul, simple or remote logging.

First is parameterized logging: In your example, these string concatenations and memory locations are allocated every time:
LOG.debug("Dispatching " + topic + " emails to : " + emailAddress);

To avoid the overhead, you did this:
if (LOG.isDebugEnabled()) {
LOG.debug("Dispatching " + topic + " emails to : " + emailAddress);
}

With SLF4J, you simple do this:
log.debug("Dispatching {} to emails to {}", topic,  emailAddress);

The braces{} are filled with the parameter. No concatenation is performed unless debug is enabled, and you remove a torrent of if->then statements in your code.

SLF4J log levels can be changed without restarting the app via JMX, it has HTML formatted output, and many other awesome features. It's far superior to commons-logging and waaay better than JUL logging. It's worth your time to use it.

Mike P(Okidoky) replied on Mon, 2010/11/22 - 1:51pm

How does SLF4J handle if (LOG.isDebugEnabled())?
Does it play with bytecodes at startup? Do any of the frameworks leverage asserts?
For instance, how about:
assert LOG("result is {}", test());

When "disabled" (upon startup, can't change at runtime from disabled to enabled, but can change from enabled to disabled - albeit then the code is always executed), the code in the assert is bypassed...

Roberto Lo Giacco replied on Mon, 2010/11/22 - 2:33pm in response to: Mike P(Okidoky)

Do you mind if I say that the statement assert LOG("result is {}", test()) is conceptually wrong?
Anyway, the concept behind the parameters replacement and the no more check needed for logging performance is quite easy: the exact same check is performed INSIDE the logging library so, qhen you call LOG("result is {}", x) the library performs (in pseudo code)
if (LOG level is enabled) {
  replace "{}" with value of x.toString()
  append log
}

That's all. This means if you WANT to use a method call instead of x you MUST agree with the fact the method could not be called if the log level is not enabled.

Now I think you have the reason regarding my sentence "your statement is conceptually wrong"...

Roberto Lo Giacco replied on Mon, 2010/11/22 - 2:35pm in response to: Jonathan Fisher

Neither am I (regarding project committer) and I love SLF4J too... and I loved commons-logging before. I go for SLF4J anytime I can... which means anytime I'm not thrown on a project with thousands of code lines already logging with some other logging framework

Hontvári József... replied on Mon, 2010/11/22 - 2:36pm

 

Mike, as Jonathan wrote, usually you don't have to use isDebugEnabled. If you don't concatenate Strings, and you don't have to with SLF4J, then isDebugEnabled actually makes logging a bit slower, because then you check the log level twice (if it is on).
It doesn't modify byte codes. It also doesn't use asserts, but nothing stops you from using them.

 

Josh Marotti replied on Mon, 2010/11/22 - 3:24pm in response to: Chad Hahn

Chad, slf4j only saves string concatenation, not processing needed to get to the string, so using the 'log.isDebugEnabled()' is still a necessary evil...

 

 

I absolutely abhor the use of trace logging.  You get that automatically with the stack trace.  But if you MUST have trace logging, use AOP (Spring has a built in trace logger aspect, you just have to turn it on!!).  The AOP trace logging doesn't require the check if the log level is on, and it is more elegant with a simple way to have it, turn it off/on, and not dirty your code all at once.

 

And, lastly, I would never use 'trace' logging, as it isn't used by all logging api's (like log4j doesn't use trace, anymore.  Debug is it's lowest level).  I'd stick with debug, warn, and error (maybe info) to make sure I can change logging apis/libraries without causing myself a major headache.

 

Chad Hahn replied on Mon, 2010/11/22 - 4:10pm in response to: Josh Marotti

 Chad, slf4j only saves string concatenation, not processing needed to get to the string, so using the 'log.isDebugEnabled()' is still a necessary evil...

 

I'm not sure what you're trying to say exactly, but I think it's along the lines of what Mike P asked above by putting a method inside the parameter list.  Roberto replied to him and basically said "don't do that".  So, I'll say that using 'log.isDebugEnabled()' is most certainly not a necessary evil.  I never write that line of ugly code.  Quoting the SLF4J FAQ on the fastest way of (not) logging:

 

The following two lines will yield the exact same output. However, the second form will outperform the first form by a factor of at least 30, in case of a disabled logging statement.

logger.debug("The new entry is "+entry+".");
logger.debug("The new entry is {}.", entry);

 

Tomasz Nurkiewicz replied on Mon, 2010/11/22 - 4:54pm in response to: Josh Marotti

Each logging level has its meaning (sometimes agreed by team members in advance), so that you can selectively enable or disable pieces of messages (also in runtime) with a fine grained control. Recently I wrote 10-part article about logging (covering pretty much the same aspect as this great article here), one part was specifically devoted to logging levels. 

Roberto Lo Giacco replied on Mon, 2010/11/22 - 5:12pm in response to: Josh Marotti

Josh, I think you misunderstood something.
First of all the article is not related to how you get those statements in place (through AOP or directly) but rather on what to log and how to log. I personally prefer to take out from direct coding every non businness aspect of the application using AOP for all the architectural choices (consequently ensuring they are applied uniformerly and correctly everywhere).
Second point is the log.isDebugEnabled() is not needed when using SLF4J with the replacement feature because SLF4J performs the necessary concatenations (substitutions to be more precise) on the message going to be logged only if the logging level is enabled on that particular logger (or category, if you prefer LOG4J terminology). This means the log level check is performed inside the log.debug() method before proceeding to substitute the brackets with the values and before eventually calling the toString() method on objects.
Third, and last, trace logging is very different from stack trace, simply because the first one is related to application execution, the second refer to the execution stack, which gives you information on the methods stack and no info on what method was called before or after... just the chain of calls which led the current execution pointer to the position you are right now... It is not a slight difference, it's a huge difference. You can call that level DEBUG, TRACE or MICKEY_MOUSE... but not confuse it with the stack trace, please =)

Mike P(Okidoky) replied on Mon, 2010/11/22 - 10:46pm in response to: Roberto Lo Giacco

Roberto, yes I missed the point that the toString's are only called after the logging level is determined to have to log it. It gets even better, with the JVM doing all sorts of voodoo magic like inlining generated machine code, possibly.

However, if it's not toString you're logging, but something like resultSet.getRow(), then getRow is called before the log level checking. Of course, one could run the app through a profiler, and have it report how much time is spent in logging and take it from there...

Bob Bobsmith replied on Tue, 2010/11/23 - 5:56am

Interestingly, I've recently read an article with a slightly different point of view. Logging Dos and Don'ts suggested not logging exceptions until you deal with them. IMO it makes a lot of sense, since you can repeatedly log the same thing at different levels, which may be unclear or which may result in unnecessary repetition. It's probably not something that we strictly follow in our code base at the moment, but it is definitely something that I'll look at in future. If you want the context of the error then you should get the stack trace. If the arguments are important and relevant then surely they should be available from the exception. If the exception is important enough for special handling, then surely it has its own catch block that can handle it appropriately.

Also, in general, I'm not sure that I agree with your context examples. Just like comments, that example is liable to get lost and separated from the call it logs. What happens if the business logic changes and a new call is used but the logging statement isn't updated? I think it is much better to put the logging within the method and have "entering X()" logging or "doing Y with parameters a and b" than it is to log about what you're going to do.

The only thing I'd add is that where you log is also important. The rule in our team is to not put logging in the API packages/plugins/projects. If it has an error that needs to be known about then the code should either throw exceptions or fire warning events that can be subscribed to. Why add an extra dependency of a logging framework to an API when a combination of sensible logging output formats and properly constructed exceptions can give you better flow control and an API that actually tells you when something happened?

P.S. The comment form is terrible. Making users put in the P tags just to get paragraph breaks is not friendly.

Andrew Spencer replied on Tue, 2010/11/23 - 9:54am in response to: Bob Bobsmith

Agreed that it's preferable to not log exceptions until you deal with them. Logging the same stacktrace five times in a row wastes time and causes confusion. However it is (psychologically) difficult to handle an exception without saying anything about it in the log, because you're never quite sure that the client code is going to log it properly. A good compromise may be to record an INFO statement when catching, wrapping and propagating exceptions.

Putting relevant arguments in the exception is another good practice that I'd love to see more often in real life.

Yohan Liyanage replied on Tue, 2010/11/23 - 11:10pm in response to: Bob Bobsmith

Hi Bob, Yes, if we log each and every exception then there is a issue. What I have said is to log before throwing any exception. That is, if we are throwing a exception, it would be better to log the full trace when we first detect it. Further down the line, we should not log the same exception again and again with full trace as it would pollute the log files with massive traces of the same exception. Usually what I do is, when I detect an exception, I log the full trace. Further down the line, when exceptions are wrapped (or translated) in various layer level exceptions (ex. PersistenceExceptions, ServiceExceptions, WebExceptions, etc), I would log those as debug statements indicating the translation, but without the trace. Thanks for bringing this up! It's a nice article to read.

Tire Works replied on Thu, 2011/08/04 - 10:03am

logging is something that needs takes a lot of practice to get right i agree with that. Working on a project now that is fairly good about it, but there are still some of those logging for the sake of logging comments, which is very useful. -Tire Works

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.