Showing posts with label exception. Show all posts
Showing posts with label exception. Show all posts

Thursday, October 17, 2013

Logging exception message in log event message

When exception happen and you want to log it and the right way to do it is

log.error("Processing is failed during phase {}", phase , e);

In log you will get something like this:
[main] ERROR test.Test - My message Error.
java.lang.RuntimeException:  Long long Message
 at test.Test.main(Test.java:10)

but this approach works fine for logging to output and file and have one problem with reporting to SysLog.
SysLog is not a java logger and it teat each line as separate event so printing stacktrace of exception will result into numerous event on SysLog level - so to resolve problem we use "throwableExcluded=true" , but we loose exception message in same time and it do contains useful information .
Exception message does not disclose reason of problem but it allow to quickly categorize problem and some time it is all that you need to fix a problem.

Example:
        <appender name="SYSLOG" class="ch.qos.logback.classic.net.SyslogAppender">
                <facility>LOCAL1</facility>
                <syslogHost>localhost</syslogHost>
                <suffixPattern>[%d${common.log.date.format}] [%t] [%c{0}] [%p]: %m%n</suffixPattern>
                <throwableExcluded>true</throwableExcluded>
                <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
                      <!-- deny all events with a level below ERROR -->
                      <level>ERROR</level>
                </filter>                                                                                                                            
        </appender>


Alternative way of logging - add Exception message to message of event.

logger.error("Handler execution resulted in exception: " + e.getMessage(), e);
log.error("Processing is failed during phase {} with exception message='{}' ", phase, e.getMessage(), e);

result in message duplicate(see bold text) in file and system output that complicate log reading. This example is not very representative but imagine long message like Spring give on exception.
Example:
[main] ERROR test.Test - My message Error: Long long Message
java.lang.RuntimeException:  Long long Message
 at test.Test.main(Test.java:10)

but this will resolve problem of SyslogAppender and with "throwableExcluded"=true Syslog will have informative message.
Second approach is highly NOT recommended, as it brake nature of log events in java and do duplication of error details.

Throwable class in Java have getMessage() method:  http://docs.oracle.com/javase/7/docs/api/java/lang/Throwable.html

Proposal:
So we need to update SyslogAppender to have "throwableMessageIncluded" or "throwableMessageAppended" parameter that will attach to Event message exception message.
Posted as - http://mailman.qos.ch/pipermail/logback-dev/2013-October/009240.html

Logback resources:
Discussion thread : http://mailman.qos.ch/pipermail/logback-dev/2013-October/009240.html,
or create issue: http://jira.qos.ch/browse
sources only: https://github.com/qos-ch/logback

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!