Logging Anti-Patterns, Part III

Recently I refactored a legacy application which based on a self-implemented logging-framework (I replaced the proprietary logging-code with slf4j). Along that I stumbled over a bunch of anti-patterns I want to discuss further on.

This is the third part of “Logging Anti-Patterns”.

9. Inherit your logger or expose it

If a class A can access a logger of a class B (by inheritance, public visibility or getter) class A can of course put it’s log events to this logger. As a result, the log events will show up in the log-files as related to class B. That decreases the readability and maintainability of your logs. Furthermore the calling class can potentially manipulate the logger and—as worst case scenario—set it’s log level to off.

So do not expose your logger. Especially do not offer a logger in abstract classes—nobody needs that when subclassing.

Anti-pattern

public class Foo {
	public final static Logger LOGGER = LoggerFactory.getLogger(Foo.class);
	...
}

public class Foo2 {
	private void foo() {
		Foo1.LOGGER.info("Logevent"); 
	}
}

Anti-pattern 2

public abstract class AbstractFoo {
	private final static Logger LOGGER = LoggerFactory.getLogger(AbstractFoo.class);

	protected Logger getLogger() {
		return LOGGER;
	}

	// or even worse:
	protected void logError(String msg) {
		LOGGER.error(msg);
	}
}
public class Foo extends AbstractFoo {
		
	public void bar() {
		getLogger().error("Logevent");
		// or: logError("Logevent");
	}
}

Pattern

public abstract class AbstractFoo {
}

public class Foo extends AbstractFoo {

	private final static Logger LOGGER = LoggerFactory.getLogger(Foo.class);	

	public void bar() {
		LOGGER.error("Logevent");
	}
}

10. Unnecessarily querying the Log-Level

The common logging-frameworks do a check inside their logging-methods (debug(..), info(..), etc.) on the current Log-Level. So most of the time when explicitly asking for the Log-Level like LOGGER.isDebugEnabled(), it’s just overhead—the logging-framework will does the same a few instructions later.

But be aware of generalising this rule—there are circumstances when using isDebugEnabled() (etc.) is mandatory: if (and only if) calculating the log-message will result in high performance costs. Then you should explicitly check the Log-Level before. Decide on your own whether a simple String-concatenation means to be a high performance cost or not…

Anti-pattern

public class Foo {

	public void bar() {
		...
		if (LOGGER.isDebugEnabled()) {
			LOGGER.debug("Message");
		}
		...
	}
}

Pattern

public class Foo {

	public void bar() {
		...
		LOGGER.debug("Message");
		...
	}

	// but:
	public void bar2() {
		...
		if (LOGGER.isDebugEnabled()) {
			LOGGER.debug(expensiveCalculation());
		}
		...
}

11. Naming the exception variables according to their types

Using the letter ‘e’ for exception variables in a try-catch-statement is very common—like using ‘i’ in for-loops (and yes—a clean-coder might frown at this point :-)). If you have multiple catch-clauses, it’s way more readable when using ‘e’ instead of the exception’s type as variable name.

Anti-pattern

try {
	...
} catch (NullPointerException nullPointerException) {
	LOGGER.error(nullPointerException.getMessage(), nullPointerException);
} catch (IllegalArgumentException illegalArgumentException) {
	LOGGER.error(illegalArgumentException.getMessage(), illegalArgumentException);
} catch (FooException fooException) {
	LOGGER.error(fooException.getMessage(), fooException);
}

Pattern

try {
	...
} catch (NullPointerException e) {
	LOGGER.error(e.getMessage(), e);
} catch (IllegalArgumentException e) {
	LOGGER.error(e.getMessage(), e);
} catch (FooException e) {
	LOGGER.error(e.getMessage(), e);
}

By the way—since Java 7 there exists the construct “multi catch” which will make this pattern implicitely superfluous. Because no one will write code like (at least I hope so):

try {
	...
} catch (NullPointerException | IllegalArgumentException nullpointerexception) { // bad!
	...
}

12. Including class- or method-names in the log-message

In general you should create your logger using the enclosing class as name (see [1]). Also most of the loggin frameworks allow to set the form of the logging outcome, for example using Logback [2]:

%d{HH:mm:ss.SSS} %-5level %logger{36} %msg%n

As a result, adding the class- and/or method-name is done by your logging framework, you don’t need to pollute your sourcecode with that information. Analogous you woudn’t add the current timestamp to your logmessage—this is also done by the framework itself. Respecting this pattern correlates with Separation of Concerns.

Anti-pattern

public class Foo {
	...
	LOGGER.info("Foo#bar():" + "My message");
	...
}

Pattern

public class Foo {
	...
	LOGGER.info("My message");
	...
}

// in your logging-configuration (here: Logback)
%logger{36} %msg%n

Rolf Engelhard

 

Comments (4) Write a comment

  1. Hi Rolf!

    I think logging anti patterns entries are very useful. They help me to make better applications and use better logging practices. First of all, thank you very much for sharing.

    But, reading your post, i have a doubt on 12 antipattern: “including class or method names in the log message”.

    I use slf4j with log4j to logging. Log4j layout patterns has M and C characters. M output the method name and C output the fully qualified class name. But reading the documentation, it says: ‘WARNING Generating the caller class information is slow’ and ‘WARNING Generating caller location information is extremely slow’.

    You say in your entry that is better use layout patterns, to write method and class information, than include that info in each log sentence. But, comments on slow execution in log4j’s documentation, worry me a little.

    You’ve had this in mind?

    Reply

    • Hi Eduardo,

      you’re welcome and thank you for your note!

      In my previous posts I encouraged to use the class name as logger name. In that case you can use %c (or %logger in Logback, as shown at the code snippet in pattern 12) and get the class name without an expensive calculation. I must admit that, when I was writing the post, I just focused on that scenario, rather than taking %C or %M into account. But correlating the logger name with the class name is a common practice. Any other logger name is a clue that the logger has another scope than the class (eg. a logger named “statistics”). And another scope often indicates that the class name isn’t important for the log message.

      If there are reasons why you can’t name a logger after the class (say, because of some corporate coding guidelines) then for sure you have to decide whether you ignore this pattern and spoil up your code (a bit) or you loose some performance. This depends on factors like the given requirements and the frequency of log events. But to be honest – I guess most of the time “performance” will succeed 🙂

      That leaves us with method names (or even line numbers) in log messages. I think that in most cases it is more than questionable whether they provide needed information. Often the messages are meaningful enough, even without method names. If not, try to refactor your code to make them meaningful. And if this doesn’t work for a specific situation, I would accept a certain loss of performance for calculating the caller data. Method names and line numbers are a very volatile aspect. And wrong (here: out-dated) information are often worse than missing information.

      Do you agree?

      BTW I also searched the Logback docs for caller data and found as well: “Generating the caller class information is not particularly fast. Thus, its use should be avoided unless execution speed is not an issue.” So this isn’t a log4j specific problem (which is somehow obvious if I think of it again :-).

      Reply

  2. private static final String CLASSNAME = MethodHandles.lookup().lookupClass().getSimpleName();
    private static final Logger LOGGER= Logger.getLogger(CLASSNAME);

    Reply

  3. Checking the DEBUG level is always a good pattern:

    if (LOGGER.isDebugEnabled()) LOGGER.debug(“Message”);

    unless you really, really need to save every instruction in the code (which is very very rare). Why? Because later someone may change the code

    if (LOGGER.isDebugEnabled()) LOGGER.debug(“Message: ” + msg);

    and you have useless string concatenation in case of DEBUG level is not enabled. I advocate the developers: for the DEBUG level, do isDebugEnabled() and you do not have to think about if it’s necessary or not. These a few CPU cycles are not worth your effort and avoid possible problems when code changes.

    Reply

Leave a Reply

Required fields are marked *.