Skip to main content

Clean code, clean logs: avoid side effects (4/10)

Logging statements should have no or little impact on application behavior. Recently a friend of mine gave an example of a system that threw Hibernates' LazyInitializationException only on some particular environment. As you’ve probably guessed from the context, some logging statement caused lazy initialized collection to be loaded when session was attached. On this environment the logging levels were increased and collection was no longer initialized. Think how long would it take you to find a bug without knowing this context?

Another side effect is slowing the application down. Quick answer: if you log too much or improperly use toString()/string concatenation, logging has a performance side effect. How big? Well, I have seen server restarting every 15 minutes because of a thread starvation caused by excessive logging. Now this is a side effect! From my experience, few hundreds of MiB is probably the upper limit of how much you can log onto disk per hour.

Of course if logging statement itself fails and causes business process to terminate due to exception, this is also a huge side effect. I have seen such a construct to avoid this:

try {
log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

This is a real code, but please make the world a bit better place and don’t do it, ever. Anyway, I have already warned you about NPEs.