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

No comments:

Post a Comment