Saturday, August 31, 2013

Exception logging: 'log and rethrow' vs 'wrap and throw' vs 'log context and re-throw'

If Exception happen during any SQL call to DB server - Where it is good to catch and log it and how to do it?

There is no exact answer, but there are few ways to do it, and some of them have problems that you need to consider.

Case "log and re-throw":
} catch (SQLException e) {
               log.error("Exception occurred ,for sql [" + sql + ]", e);
               throw e;
}

Case "wrap and throw":
} catch (SQLException e) {
           throw new XXXXXDataAccessException("Exception occurred ,for sql [" + sql + ]", e) ;
}

Case "log context and rethrow":

} catch (SQLException e) {
               log.warn("Exception is appear, stack-trace see further in logs, failed sql is [" + sql + ]");
               throw e;
}

Case "log and re-throw":
In log and throw - log with Error or with Warning ?
If we do it with ERROR level - you will brake good pattern "one event - one ERROR message in logs", link to read.
If you will log with WARN - you will spoil logs with duplicated print of stacktrace. On moment of logs review it will not be clear (without review of sources) either exception happen twice or it was logged twice or ....   

General rules for logging and re-throwing:
 - if you develop Library - never log with ERROR level - library does not know how it is used so he have to return all to application and application decide how and when to log it, or even ignore it. Such problem existed in Hibernate, Hibernate, Hibernate, Hibernate, and looks like resolved in Hibernate 4.X only.
- if you are in Application - do logging on level that do know how to treat/translate/process that exception and make exception part of business logic(your algorithm).

Case "wrap and throw":
If you do not log sql and trow exception up, upper level does not have information what sql was in call. You can not log sql with ERROR level at place where you have SQL as is SQL is not an ERROR , exception is a ERROR event - log and rethrow is also bad practice (link to read). Wrapping to your exception make you have custom exception objects and ask yourself and Google why there is no such standard exception - it is so obvious (ones you end up in creation set of custom exceptions in each application).

if you so like to follow "big brothers" - non of these exceptions classes store SQL:
for 15 year off massive SQL usage in java non of them wanted to have it in class as member, because SQL is only one part of problem not a exact reason. 
Non of them have sql as member in class:
http://docs.oracle.com/javase/6/docs/api/java/sql/SQLException.html
https://github.com/hibernate/hibernate-orm/tree/master/hibernate-core/src/main/java/org/hibernate/exception


Case "log context and rethrow":
So logging with WARN is ok, but smb could yell "Error should encapsulate all details of it", and here is nuance - you will never put in Exception object all context, even previous events in logs is a context as you need to see what application did before ERROR. So I recommend to log context of SQL and parameters if any with WARN level and do rethrow exception without wrap.

Main idea is - as you got exception and that level can not log it or process it properly - just print context of exception with WARN level an re-throw it further. Context could be anything: all set of class members, any local variables, whatever will be useful to know state of class when exception happen.

Make a rule for yourself to search for exception in logs and then view events before ERROR event to see a context of problem not only be cause you did logging of exception context but due to the fact that previous events are also context , and they could be even more informational and helpful than smth that you did.

Attention: You can not fix a problem by just looking at exception stacktrace and its message - you need wide context of what happen in application before!

No comments:

Post a Comment