Logging Anti-Patterns, Part I

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.

1. Logger-instantiation inside a method

In general there should be only one logger per class. Most of the common logging-frameworks are caching their loggers after instantiation. So calling a LoggerFactory inside a method is simply an unnecessary code and a (slight) performance waste. Just instantiate a static final logger in the class and use that one on every logging event.

Anti-pattern

public void foo() {
	...
	Logger logger = LoggerFactory.getLogger(Foo.class);
	logger.info("bar!");
	...
}

Pattern

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

public void foo() {
	...
	LOGGER.info("Bar");
	...
}

2. Logger-instantiation using the exception message

This is one of my favorites: on each exception a new logger is created using the exception message as logger name. That neither makes sense nor does it help when analyzing the log-files. It also wastes resources: if the exception messages differ, every factory-call will create a new logger instance (instead of returning a cached one) and additionally adds the new logger to the factory’s cache. As a result the cache will be blown up with multiple logger instances—which won’t be used furthermore.

Anti-pattern

public void foo() {
	try {
	...
	} catch (Exception e) {
		Logger logger = LoggerFactory.getLogger(e.getMessage());
		logger.error(e.getMessage(), e);
	}
}

Pattern

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

public void foo() {
	try {
		...
	} catch (Exception e) {
		LOGGER.error(e.getMessage(), e);
	}
}

3. Logger-instantiation using the enclosing class’ name as string

For ordinary loggers the factory-method of LoggerFactory should be called passing the enclosing class. Avoid to pass a class’ name as string. If you use the enclosing class, your favorite IDE will automatically suit that occurrence on a change of the class’ name (if you’re using vi or something similar to scourge yourself—at last your compiler tells you about it). Your logger will always be related to the current class’ name, a string will not give you that guarantee.

Anti-pattern

privat final static Logger LOGGER = LoggerFactory.getLogger("de.bar.Foo");

Pattern

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

4. Logger-instantiation somewhere in between

A specialization of a common basic: define your class constants and attributes at the beginning of a class, not somewhere in between [1]. That significantly increases the readability and maintainability of your code. Apparently that also holds for loggers.

Anti-pattern

public class Foo {
	// ... code ...
	private final static Logger LOGGER = LoggerFactory.getLogger(Foo.class);
	// ... even more code ...
}

Pattern

public class Foo {

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

	// ... code
}

Reference

  1. [1] Martin, Robert C. 2008. Clean Code. Prentice Hall International

Rolf Engelhard

 

Comments (5) Write a comment

  1. I find your posts about logging anti-patterns valuable, however there is one point that I can’t agree with. It’s #3 ” Logger-instantiation using the enclosing class’ name as string”. What I have problem with is something that seems to be pretty common in the Java world: using fully qualified name of the class as the logger name. While using a string with class name is really braindead (no argument here), using class is not that much better.
    What happens is that one is exposing implementation details as a contract to the user (as the user is the one who can provide logging configuration file describing which logs should be written where and what logging levels should be discarded, etc.). If later class structure changes (e.g. due to refactor) the user has to update his logging configuration accordingly. The better way here is to use explicit logger hierarchy and names that refer to the logical structure of the application, that mostly should remain stable throughout evolution of the software.

    Reply

    • Hi Jarek,

      you made a good point. And wearing my dogmatic glasses I would totally agree :-).

      But I think in most of all cases the log config just routes a minority of “special” log events to some “special” places and the rest of all log events are pushed equally to the same destinations. Does this really justify a meta model?

      Obviously building a meta model isn’t for free: you have another model in your application to maintain and hold consistent. Especially it has to be unambiguous – if you can’t find the class which emitted a log event by having only the information of a log event, you got a problem. And if it is unambiguous

      Also when tracing the occurence of a log event you first have to find the class instead of just seeing it in the log message. Additionally you make creating a logger less simple and fast, because you first need to look up the name to use or – even slower – need to commit with your team about the name. Worst case scenario: some devs would prefer to not use a logger instead of being slowed down by such a “non-relevant part of the application” (not my opinion, but some devs are different :-). Last but not least – your application already has a logical structure – why not use it?

      For sure there are always some loggers which are special (e.g. an “audit-log”) and THOSE have to be handled special by using a “meta-name”.

      And finally I won’t omit that there are still situations where a meta model perfectly makes sense – like you’re selling a web app to a company and the company admins want to monitor the log events. I guess changing the logger names with every refactoring doesn’t make your customer feel happy. But just to give a counterexample: in my company the logging configurations are included in the application and maintained by the developers (in conjunction with the ops). This works nicely and we really don’t need a meta model. If we do a refactoring we also change the log config too. And for sure we’re using the class name as logger name.

      Maybe a light abstraction for the underling logging framework would be a compromise: it wraps or transforms the class names to the logical structure of a meta model (e.g. your own LoggingFactory which wraps the “original” LoggerFactory). So you can stick with instantiating loggers by class names and – as a bonus – concentrate the knowledge about the logical structure of your meta model at one (or just a few) single point in your application.

      So let me conclude with a re-formulation of pattern #3: “In case you’re using the class name as logger name, don’t use the enclosing class’ name as String. Anything other is braindead (BTW I like that last word ;-)”

      Reply

  2. I guess you missed antipattern about debugging without logger.isDegugEnabled() check

    Reply

  3. I find mixing logging code and feature code to be an anti-pattern. Except for warnings (something in between “no problem” and “problem”) I try to do all logging from a specialized aspect, and determine what and how gets logged from configuration – i.e. I don’t have to recompile and redeploy in order to add new log statements, I just have to configure the logging infrastructure to log some additional calls, in a more or less detailed way, to obtain all the info I need. I can also add additional aspects, if I want to log specialized logging, such as audit logging.

    Reply

Leave a Reply

Required fields are marked *.