Skip to main content

Clean code, clean logs: watch out for external systems (8/10)

This is the special case of the previous tip: if you communicate with any external system, consider logging every piece of data that comes out from your application and gets in. Period. Integration is a tough job and diagnosing problems between two applications (think two different vendors, environments, technology stacks and teams) is particularly hard. Recently, for example, we've discovered that logging full messages contents, including SOAP and HTTP headers in Apache CXF web services is extremely useful during integration and system testing.

This is a big overhead and if performance is an issue, you can always disable logging. But what is the point of having fast, but broken application, that no one can fix? Be extra careful when integrating with external systems and prepare to pay that cost. If you are lucky and all your integration is handled by ESB, bus is probably the best place to log every incoming request and response. See for example Mules' <log-component/>.

Sometimes the amount of information exchanged with external systems makes it unacceptable to log everything. On the other hand during testing and for short period of time on production (for example when something wrong is happening) we would like to have everything saved in logs and are ready to pay performance cost. This can be achieved by carefully using logging levels. Just take a look at the following idiom:

Collection<Integer> requestIds = //...

if(log.isDebugEnabled())
log.debug("Processing ids: {}", requestIds);
else
log.info("Processing ids size: {}", requestIds.size());


If this particular logger is configured to log DEBUG messages, it will print the whole requestIds collection contents. But if it is configured to print INFO messages, only the size of collection will be outputted. If you are wondering why I forgot about isInfoEnabled() condition, go back to this tip. One thing worth mentioning is that requestIds collection should not be null in this case. Although it will be logged correctly as null if DEBUG is enabled, but big fat NullPointerException will be thrown if logger is configured to INFO. Remember my lesson about side effects?


Comments