Search This Blog

Clean code, clean logs: do you know what you are logging? (3/10)

Every time you issue a logging statement, take a moment and have a look what exactly will land in your log file. Read your logs afterwards and spot malformed sentences. First of all, avoid NPEs like this:

log.debug("Processing request with id: {}", request.getId());

Are you absolutely sure that request is not null here? Another pitfall is logging collections. If you fetched collection of domain objects from the database using Hibernate and carelessly log them like here:

log.debug("Returning users: {}", users);

SLF4J will call toString() only when the statement is actually printed, which is quite nice. But if it does... Out of memory error, N+1 select problem, thread starvation (logging is synchronous!), lazy initialization exception, logs storage filled completely – each of these might occur.

It is a much better idea to log, for example, only ids of domain objects (or even only size of the collection). But making a collection of ids when having a collection of objects having getId() method is unbelievably difficult and cumbersome in Java. Groovy has a great spread operator (users*.id), in Java we can emulate it using Commons Beanutils library:

Unfortunately the method above is not yet part of Commons Beanutils framework, but I have already filed up the request to make our lives easier (BEANUTILS-375).

The last thing is improper implementation or usage of toString(). First, create toString() for each class that appears anywhere in logging statements, preferably using ToStringBuilder (but not its reflective counterpart). Secondly, watch out for arrays and non-typical collections. Arrays and some strange collections might not have toString() implemented calling toString() of each item. Use Arrays #deepToString JDK utility method. And read your logs often to spot incorrectly formatted messages.

The best answer is: "it depends". Sometimes having only id is sufficient, but the semantics of toString() and many programmers expectations suggest, that it should return full object description.

Take, for example, User object. In some cases having only id of int type in toString() is enough, but what if I would like to log full user description (including its name and set of lazy-loaded roles)?

I prefer having toString() printing almost everything about the object (but always take extra caution, especially with lazy-loaded properties) and if I really need just an id, I can always get it explicitly.

BTW I really like calling getId() instead of accessing id field directly in your example. In general, it will cause lazy loaded fields to be fetched instead of printing zeros or nulls in toString(). I forgot to mention about it.