Another post about logging? Yes!
Writing good
log statements is something hard to learn, in my honest opinion every log statement should follow these principles:
- contains complete information: in other words, there's no need to scroll to understand the meaning of the log or to read other related informations;
- log output is in a single line (see also logging in single line for grep);
- contains informations about where the log is placed (package and class).
About the latter point I'll share with you some bad techniques I've seen. Some people get tired about logging, so, in order to write less code, they do something like this:
package foo.bar;
import org.slf4j.*;
public class SharedClass {
protected final Logger log = LoggerFactory.getLogger(this.getClass());
public void doLog(int count) {
log.info("Called doLog with count = '{}'.", 1);
for (int i = 0; i < count; i++) {
callAnotherMethod(i);
}
}
public void callAnotherMethod(int i) {
log.info("Called method with i = '{}'.", i);
}
}
public class SubClass extends SharedClass {
@Override
public void callAnotherMethod(int i) {
log.info("Called method with i = '{}'.", i);
}
}
Where's the problem? Run this main and try to understand what happens:
public class Main {
public static void main(String[] args) {
SharedClass parent = new SharedClass();
SharedClass child = new SubClass();
child.doLog(10);
parent.doLog(10);
}
}
Pretend that you are reading the log output below without any knowledge of the application, and pretend that you are searching for a bug and the anomaly is on row one (e.g. because count is one but method is called five times):
13:21:40.261 [main] INFO foo.bar.SubClass - Called doLog with count = '1'.
13:21:40.264 [main] INFO foo.bar.SubClass - Called method with i = '0'.
13:21:40.264 [main] INFO foo.bar.SubClass - Called method with i = '1'.
13:21:40.264 [main] INFO foo.bar.SubClass - Called method with i = '2'.
13:21:40.264 [main] INFO foo.bar.SubClass - Called method with i = '3'.
13:21:40.264 [main] INFO foo.bar.SubClass - Called method with i = '4'.
13:21:40.264 [main] INFO foo.bar.SharedClass - Called doLog with count = '1'.
13:21:40.264 [main] INFO foo.bar.SharedClass - Called method with i = '0'.
13:21:40.264 [main] INFO foo.bar.SharedClass - Called method with i = '1'.
13:21:40.264 [main] INFO foo.bar.SharedClass - Called method with i = '2'.
13:21:40.264 [main] INFO foo.bar.SharedClass - Called method with i = '3'.
13:21:40.264 [main] INFO foo.bar.SharedClass - Called method with i = '4'.
Hence you start searching the class... but?! There is no log statement like that in SubClass! And now?! Do you try to search a string like
"Called doLog with count"? And what to do if the string doesn't exist because it's composed using concatenation?
Anybody could answer me: "It's simple! There should be a super class", but where? And if a method, somewhere around the code, is using the
Logger of another class?
Solution: declare
Logger as
private static final Logger log, initialized by the same class as where it's declared. Yes the
log fields is lower case because
it is not a constant, it is a final reference (see also
stackoverflow).
package foo.bar;
import org.slf4j.*;
public class SharedClass {
private static final Logger log = LoggerFactory.getLogger(SharedClass.class);
public void doLog(int count) {
log.info("Called doLog with count = '{}'.", 1);
for (int i = 0; i < count; i++) {
callAnotherMethod(i);
}
}
public void callAnotherMethod(int i) {
log.info("Called method with i = '{}'.", i);
}
}
public class SubClass extends SharedClass {
private static final Logger log = LoggerFactory.getLogger(SubClass.class);
@Override
public void callAnotherMethod(int i) {
log.info("Called method with i = '{}'.", i);
}
}
Eventually we can see a more debuggable log output, like the one below:
13:23:57.351 [main] INFO foo.bar.SharedClass - Called doLog with count = '1'.
13:23:57.354 [main] INFO foo.bar.SubClass - Called method with i = '0'.
13:23:57.354 [main] INFO foo.bar.SubClass - Called method with i = '1'.
13:23:57.354 [main] INFO foo.bar.SubClass - Called method with i = '2'.
13:23:57.354 [main] INFO foo.bar.SubClass - Called method with i = '3'.
13:23:57.354 [main] INFO foo.bar.SubClass - Called method with i = '4'.
13:23:57.354 [main] INFO foo.bar.SharedClass - Called doLog with count = '1'.
13:23:57.354 [main] INFO foo.bar.SharedClass - Called method with i = '0'.
13:23:57.354 [main] INFO foo.bar.SharedClass - Called method with i = '1'.
13:23:57.354 [main] INFO foo.bar.SharedClass - Called method with i = '2'.
13:23:57.354 [main] INFO foo.bar.SharedClass - Called method with i = '3'.
13:23:57.354 [main] INFO foo.bar.SharedClass - Called method with i = '4'.
Thank you everybody for your patience.
A question: what to do if you can't edit all the wrong
Logger declarations?
Wait for Go to my next post to have the answer! :-)
Related posts:
