Async Log4j appender

Last week I was asked by a colleague what happens, if a log4j appender takes much time for doing its work. This actually was a good question as the appenders in log4j are all working synchronously. In case of my last example with a jdbc appender that means, if the insert statement takes much time, the application pauses for the logging time. And if the logdatabase is not available, the application itself even crashes due to errors in logging framework. This is ridiculous behaviour because normally the logging part should work beside the application in a separate thread. And exactly that is what the AsyncAppender feature of log4j is doing.

In the special case of the last example I modified the log4j config:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration>

	<appender name="DB" class="org.apache.log4j.jdbc.JDBCAppender">
		<param name="URL"
			value="jdbc:sqlite:C:/dev/eclipse-jee-luna-R-win32-x86_64-ws/log4jDbAppenderExample/database/testdb" />
		<param name="driver" value="org.sqlite.JDBC" />
		<!--param name="user" value="user_id"/ -->
		<!--param name="password" value="password"/ -->

		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern"
				value="
				INSERT 
					INTO logtable (DATED, LOGGER, LEVEL, MESSAGE, PROCESS, INTERNALRUNTIME, MESSAGE, TESTCOLUMN)
					VALUES ('%d','%C','%p','%m', '%X{process}', '%X{internalRuntime}', '%m')" />
		</layout>
	</appender>
	
	<logger name="req-resp.logger">
		<level value="INFO" />
		<appender-ref ref="DB" />
	</logger>

</log4j:configuration>

By setting intentionally an extra column with no value, the application will produce following error:

log4j:ERROR Failed to excute sql
java.sql.SQLException: 7 values for 8 columns
	at org.sqlite.NativeDB.throwex(NativeDB.java:210)
	at org.sqlite.NativeDB._exec(Native Method)
	at org.sqlite.Stmt.executeUpdate(Stmt.java:152)
	at org.apache.log4j.jdbc.JDBCAppender.execute(JDBCAppender.java:218)
	at org.apache.log4j.jdbc.JDBCAppender.flushBuffer(JDBCAppender.java:289)
	at org.apache.log4j.jdbc.JDBCAppender.append(JDBCAppender.java:186)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.info(Category.java:666)
	at eu.christophburmeister.logj4jdbcappender.Start.main(Start.java:19)

So if someone makes this simple mistake, the application will effectively crash. To prevent those crashes (or long appender runtimes having effects on the application itself), the configuration has to be modified this way:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration>

	<appender name="DB" class="org.apache.log4j.jdbc.JDBCAppender">
		<param name="URL"
			value="jdbc:sqlite:C:/dev/eclipse-jee-luna-R-win32-x86_64-ws/log4jDbAppenderExample/database/testdb" />
		<param name="driver" value="org.sqlite.JDBC" />
		<!--param name="user" value="user_id"/ -->
		<!--param name="password" value="password"/ -->

		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern"
				value="
				INSERT 
					INTO logtable (DATED, LOGGER, LEVEL, MESSAGE, PROCESS, INTERNALRUNTIME, MESSAGE, XTRACOLUMN)
					VALUES ('%d','%C','%p','%m', '%X{process}', '%X{internalRuntime}', '%m')" />
		</layout>
	</appender>

        <appender name="DB-async" class="org.apache.log4j.AsyncAppender">
             <param name="BufferSize" value="500"/>
             <appender-ref ref="DB"/>
        </appender>
	
	<logger name="req-resp.logger">
		<level value="INFO" />
		<!--appender-ref ref="DB" /-->
		<appender-ref ref="DB-async" />
	</logger>

</log4j:configuration>

This new appender „DB-async“ works as bridge between the logger and the original DB appender. In our case the application will push the log message to the async appender and will not produce errors anymore as the jdbc statement is executed in a separate thread 🙂 … but the application will also not produce any logfiles :-/
So in the end, one has to evaluate advantages and disadvantages from case to case and need a solid logging architecture/ concept.