Skip to end of metadata
Go to start of metadata

About

Following these guidelines can help you make your logging output as consistent as possible across classes.

Declaring a Logger

For consistency, declare your logger as the first field (top of code) in your class and declare it as follows:

Notice that we have used the instance variable named "log" and not "logger". The term "log" (in lieu of "logger") is more efficient to type and makes for cleaner code while not reducing any developer's ability to understand the code. Follow this convention for both efficiency and consistency.

If you are declaring you logger to pipe through Apache Commons Logging, the declaration will be a little bit different:

Use TRACE only for tracing execution flow

In general, trace-level logging should be used only for tracing the flow of execution through a program and for flagging particular positions in a program (i.e. to ensure they have been reached). While you may want to trace every method of a class in early stages of development, you should ensure that you are only tracing key aspects of the flow when it is time to pass the code onto other developers. An overabundance of TRACE statements (especially in simple getter and setter methods) can hinder others rather than help them.

Entering a Method

  • Logging the entrance to a method should always be done with the level: TRACE
  • Use the abbreviated symbol for 'entering' which is '>>' followed by the method name. Use a parenthesis to help clarify that the item is a method. Example:

Exiting a Method

  • Logging the exit from a method should always be done with the level: TRACE
  • Use the abbreviated symbol for 'exiting' which is '<<' followed by the method name. Use a parenthesis to help clarify that the item is a method. Example:

Constructors

  • Logging the instantiation of an object (in the class constructor method) should always be done with the level: TRACE
  • Use the abbreviated symbol for 'instantiation' which is '**' followed by the constructor name. Use a parenthesis.

Prefix all logging statements with a method name

Assuming that you will set your logging configuration to print class names, it is then helpful to prefix the statements with the name of the method from which the statement is being executed.

For example:

Notice also that two hyphens are used before the method name. This helps to improve legibility in log files where trace may be also used with '>>' specifying the entry of a method and '<<' specifying exit. Adding '--' in the middle of methods provides a visual indication that the statement is executed somewhere in the middle after entry and before exit. So you get a clean visual pattern like this:

Use DEBUG to report results to yourself and other developers

Use INFO to report results to Administrators and Users

Use Guarded Logging

"Guarded logging" is a pattern that checks to see if a log statement will result in output before it is executed. Since the logger itself makes this check, it may seem redundant to do this for every call. However, as almost every logging call creates String objects, it is critical. The accumulation of these Strings causes memory fragmentation and unnecessary garbage collection. Garbage collection, while beneficial, also produces significant performance loss. To reduce this as much as possible, always guard logging statements with a severity less than SEVERE. Since SEVERE is always expressed by the logger, these do not need a guard. Here is an example:

Note that if you use SLF4J for logging, the necessity for guarded logging is reduced or eliminated as SLF4J has a nice pattern substitution mechanism that avoids the need for string concatenation and unnecessary evaluations and object instantiations.

SLF4J Parameter Substitution Example

Use StringBuffers and toString() or toPrint() to ease and improve logging

Sometimes, when you want to print all the values of an object, it is helpful to use a StringBuffer or StringBuilder. In this way, you can assemble all of the data into one clean output statement and avoid cluttering up your log file with redundant data (i.e. multiple lines with several time and level stamps for just one object). The snippet below shows an example of how to do this, but it is still not the best approach.

While the code above creates a clean logging statement without multiple lines containing redundant data, there is still a problem. Notice that we are printing the values of the object "cat" (of the class Category). What would be better is to move most of this code into a toString() method on the Category class itself. In this way, all developers can simply call the toString() method to get a print of all the object's current data. Sometimes, however, you might find that you'd rather use a toString() method for application functionality instead of for logging or because the toString() method is already being used in another way. In this case, you could create a method called toPrint() instead. Following is an example:

Notice also in the code snippet above that we have taken care to align all of the colons separating the key from value. This makes the toPrint() method's output much easier to read. Also notice that we've added a newline character to the beginning of each property statement that appends to the StringBuffer. If you get in the habit of adding a newline character to the end of the line, you might end up with something like this:

In the example above, since the newline must be merged into the String at runtime, your asking the JVM to do unnecessary work. By putting the newline in the beginning of the String instead, you'll need no addition operator and thus, your saving the JVM from having to do that operation. It all adds up!

Now, in any point of the code's execution, it is easy for a developer to inspect the object using just a few statements like this:

Use Delegates, Managers, or Service classes as a logging juncture

Typically Delegate or Manager classes act as junction or integration points. And the delegates often have very simple methods that act as proxies to actual implementations in other classes. You can take advantage of this delegate or manager class to act as a place to log the entry and exit of methods at the integration point including the data being passed in and the data returned. Here is an example of a simple method in a delegate class that logs entry, exit, and the data going in, and the data coming out:

The key here is that we have standardized on WHERE to do the primary logging so it is consistent. In this way, we don't have a random mix of primary logging code in the delegate and in the implementation classes.

 

Our Related Content

How to setup SLF4J and LOGBack in a web app - fast
This page provides a quick guide for setting up SLF4J and LOGBack in a Maven web project in five simple steps.

How to setup Log4i in a web app - fast
This page provides a quick guide for setting up Log4j in a web application. It is intended for those who are already familiar with Log4j and just need a rapid reminder.

 

Enterprise Solution Architecture
Cody Burleson is an Enterprise Web Architect, entrepreneur, and writer. He designs and builds solutions with his team at Base22 using IBM WebSphere Portal, IBM Web Content Manager, IBM Connections, and Java/J2EE. He is a tireless student of information technology who loves to invent things, improve things, and share what he learns. You can find more at his blog, codyburleson.com.

  1. Anonymous

    Thanks a lot to author.
    Article helped me a lot to understand the better way of logging.

  2. Anonymous

    good article.it helped.

    thanks

  3. Anonymous

    Excellent article! I have a few things to add...

    I dislike having to put code like this into every class:

    Not only is it verbose and distracting, sprinkling logging methods everywhere means that you're a prisoner to your logging abstraction because you'd have to change all of your code everywhere. (Although I heard there's a new logging abstraction library that takes care of that for you, so who knows, what follows might all "old hat" already.)

    So I've encapsulated it further as follows (this isn't quite how I do it as I'm doing it from memory, so there may be errors):

    You could elaborate on the Log class throughout, then you can log to your heart's content with just one line:

    Your Log.trace method could check to see if trace is enabled and only output it if was, so you wouldn't have to check it manually every time.

    Inside Log class:

    Then the code in other classes cleans up to:

    without a pesky "if" call everywhere.

    Your great formatting suggestions can be encapsulated in the methods themselves, meaning you don't need to remember to write the markers manually every time, and the code would read cleaner. So inside of the Log class you would have...

    Then you can just write a class as follows:

    ...and the log would still look like...

    You should check to see how much overhead there is getting a logger for the class each time before implementing this, so use this suggestion with caution (smile) I think we don't use a per-class logger, but my memory is fuzzy at the moment.

    1. Anonymous

      Post fail on my part, sorry about that. Just mentally skip the "Unknown macro" text and I think it still reads correctly

      1. No worries; I cleaned up your comment and it is legible now. In the future, when posting code blocks, use the following Confluence wiki syntax:

        {code:java}
        ...example code...
        {code}

    2. These are interesting suggestions. I am going to have to do some testing before coming to any conclusions, however. If I can find an even better approach based on these suggestions, I will update the article.

      I am not sure if it is true that you can pass a String into a method and have the guard within the method. I think just defining the String there instantiates it before it even reaches the guard, no? That's one of the things I need to test. I'm not sure.

    3. Anonymous

      The problem with Anonymous's suggest public static methods is if you have a complex log message, the JVM will construct the string and ignores the authors point, "Use StringBuffers and toString() or toPrint() to ease and improve logging" and "Use Guarded Logging"

      So if you use

      The string parameter will be constructed even if trace is not turned on. This could cause performance problems and other things the author mentioned in "Use Guarded Logging".

  4. Anonymous

    Hi,

    This is a bit yesterday's logging. SLF4J and/or logback have changed this. As they remove the guarded logging and simplify passing the parameters to the log.

    Also:
    static Logger log = Logger.getLogger(MyClassName.class.getName());

    Why not make it final?
    final static Logger log = Logger.getLogger(MyClassName.class.getName());

    Final would help the compiler and you do not want the Logger to be re-instantiated.

    Here is a better article: http://www.dzone.com/links/thoughts_on_java_logging_and_slf4j.html

    1. Your point about declaring the logger is good and I have corrected the code examples to reflect it. I have also provided a setup procedure for SLF4J and LOGBack in the related content panel (How to setup SLF4J and LOGBack in a web app - fast).

  5. Good point. I have corrected the code examples in the doc accordingly; thanks!

  6. Anonymous

    "I am not sure if it is true that you can pass a String into a method and have the guard within the method. I think just defining the String there instantiates it before it even reaches the guard, no? That's one of the things I need to test. I'm not sure."

    Yes, of course the strings are going to be instantiates before it reaches the guard. Still its nicer to use it in place when you do not need to worry about string creation overhead.

  7. Anonymous

    First, if you all realized how log4j, commons-logging and slf4j handle instances of loggers, you wouldn't bother making the LOG variables static or final.
    Read further the documentation of logger services. Making their variables static is not necessary, nor desirable.

    Second, don't put logs in the beggining and the end of each method, which is terribly error-prone (I've witnessed several methods logging wrong method names). Instead, log through an interceptor. All the decent frameworks offer this possibility, these days.

    1. Anonymous

      What do you mean by "log through an interceptor. All the decent frameworks offer this possibility, these days."?

      (Sorry, Couldn't find the answear with almighty google)

      1. Anonymous

        You are talking about trace logging inside of each method, logging at the entering and exiting of the method. I have implemented this using AOP so can only talk about my implementation. 

        The class requiring this trace logging is typically a Spring managed bean and the calls to its methods can be intercepted using Aspect Oriented Programming. This interceptor will typically be a BeforeAdvice (intercepting entry to method) and AfterReturningAdvice (intercepts exit of method).

        The interceptor implements the expected methods of these interfaces and looks at the Object to determine its class, looks at the Method to determine its name (and if required its argument types). It can then log the method being invoked. I implemented it by getting the logger for the Target object and adding "[AOP]" to the logged message to show that the logging statement would not be found in the target object.

        I've just finished working on legacy code that had its own Logger class with static methods. The code was awful. Lines of log statements logged using the Logger's classname and line numbers was incredibly frustrating. Logging the method name in each log statement seems a bit daft too to be honest. With access to the source code and uncorrupted logging (line numbers not hidden) you can see the method being invoked.

        isDebugEnabled() - lots of good people use it but I like my code to run through the same path regardless of the logging levels. Simply put - if you don't need your code to run through the same exact path in development as in production then put in the isDebugEnabled() and good luck!

  8. Anonymous

    Wow! Finally, the proverbial needle in the haystack! Thanks for a very instructive article.