Suppressing An Appender For A Log4J Logger

Occasionally, a third-party library will balk the log-or-throw exception handling convention. Most recently, I came across this issue with Hibernate's Work API: an org.hibernate.exception.ConstraintViolationException was being logged and thrown when a unique key constraint was violated. To be exact, Hibernate's JDBCExceptionHelper logged exceptions through JDBCExceptionReporter. The flow was similar to the following:

WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 0, SQLState: 23505
ERROR org.hibernate.util.JDBCExceptionReporter - ERROR: duplicate key value violates unique constraint "order_number_uk"
WARN  com.acme.order.application.impl.OrderServiceImpl - Order 'xyz' already exists. Using existing order.
org.hibernate.exception.ConstraintViolationException: error executing work
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:96)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52)
    at org.hibernate.impl.SessionImpl.doWork(SessionImpl.java:2001)
    ...
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "order_number_uk"
 Detail: Key (order_number)=(xyz) already exists.
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
    ...

While this exact problem could have been avoided by a specific infrastructure pattern (sticky load balancing and/or replicated session state), significant overhead and complexity would have to be added to an existing and completely stateless system. Further, this was a fringe (<0.01%) scenario. Indeed, handling the ConstraintViolationException was the simplest (and lowest risk)solution given the time constraints.

As most any production system, error logs were broadcast over several channels to alert the on-call technical support team. Unfortunately, Hibernate's log-and-throw approach resulted in numerous false positives. Being aware that false positives set a risky precedent, you, the diligent reader, may ask how this was tamed.

The Solution

Being a typical Log4J configuration, assume two appenders are configured: a RollingFileAppender, rolling, and an SMTPAppender, mail:

log4j.rootLogger=INFO, rolling, mail

log4j.appender.rolling=org.apache.log4j.DailyRollingFileAppender
log4j.appender.rolling.File=${log.rolling.file}
log4j.appender.rolling.DatePattern=.yyyy-MM-dd
log4j.appender.rolling.layout=org.apache.log4j.PatternLayout
log4j.appender.rolling.layout.ConversionPattern=%d %-5p %c~%t::%M(%X) - %m%n

log4j.appender.mail=org.apache.log4j.net.SMTPAppender
log4j.appender.mail.Threshold=ERROR
log4j.appender.mail.To=${log.mail.to}
log4j.appender.mail.From=${log.mail.from}
log4j.appender.mail.SMTPHost=${log.mail.host}
log4j.appender.mail.Subject=${log.mail.subject}
log4j.appender.mail.BufferSize=1024
log4j.appender.mail.layout=org.apache.log4j.PatternLayout
log4j.appender.mail.layout.ConversionPattern=%d %-5p %c~%t::%M(%X) - %m%n

Simply, all loggers will append to rolling and mail. Further, the mail appender has a threshold of ERROR. That is, only ERROR (or above) entries will be logged.

Log4J's loggers are hierarchal: logger.com.acme is a child of logger.com, which is a child of rootLogger. By default, appenders are inherited from a logger's parent. In the above configuration, all loggers will append to rolling and mail.

This inheritance can be disabled using the additivity property (true, by default). Looking back to the stack trace, we can determine that the org.hibernate.util.JDBCExceptionReporter logger is appending to the mail appender through the logger's inheritance from its parents.

Ideally, we do not want to suppress all logging for the JDBCExceptionReporter logger: we simply want to disable the SMTP appender. Setting the additivity property to false and explicitly configuring the logger threshold/appenders will solve this problem:

log4j.additivity.org.hibernate.util.JDBCExceptionReporter=false
log4j.logger.org.hibernate.util.JDBCExceptionReporter=INFO, rolling

These changes will cause the org.hibernate.util.JDBCExceptionReporter logger to append to the rolling appender at an INFO threshold.

Considerations

Assumptions

Any time you make assumptions, you run the risk of being incorrect. Further, you risk becoming incorrect when situations change. This solution assumes that the Hibernate Work API will always throw/rethrow an exception. While this is a reasonable assumption based on the historical implementation, no guarantees are made.

Complexity

Also, disabling additivity increases complexity. By being more specific, you lose the ability to configure things in a more general way. For example, if we added a new appender to the example above, we may have to make changes in multiple places. More deviations will reduce orthogonality.