JBoss log4j rotation

JBoss has a related log4j file rotation bug. This is similar to the Log4j file rotation bug I've talked about, but it caused by the right combination of bugs in JDK 1.5 and log4j.

The stack trace usually looks something like this: <geshi> Caused by: java.lang.IllegalStateException: Current state = FLUSHED, new state = CODING

       at java.nio.charset.CharsetEncoder.throwIllegalStateException(CharsetEncoder.java:941)
       at java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:537)
       at sun.nio.cs.StreamEncoder$CharsetSE.implWrite(StreamEncoder.java:384)
       at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:136)
       at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:146)
       at java.io.OutputStreamWriter.write(OutputStreamWriter.java:204)
       at java.io.Writer.write(Writer.java:126)
       at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:47)
       at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
       at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:358)
       at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
       at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
       at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
       at org.apache.log4j.Category.callAppenders(Category.java:203)
       at org.apache.log4j.Category.forcedLog(Category.java:388)
       at org.apache.log4j.Category.log(Category.java:853)
       at org.jboss.logging.Log4jLoggerPlugin.info(Log4jLoggerPlugin.java:161)
       at org.jboss.logging.Logger.info(Logger.java:189)
       at org.jboss.system.server.ServerImpl.shutdown(ServerImpl.java:654)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
       ... 45 more

</geshi>

For this to fail, the rename call must fail in the DailyRollingFileAppender. This code looks like:

<geshi lang="java"> boolean result = file.renameTo(target);

   if(result) {
     LogLog.debug(fileName +" - > "+ scheduledFilename);
   } else {
     LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");
   }

</geshi>

This code by itself is fine. Log4j will log any errors it has to standard err. Unfortunately, JBoss by default redirects standard err and standout into log4j. See https://jira.jboss.org/jira/browse/JBAS-845.

turn off stdout / stderr redirection

You can turn this feature off with:

<geshi lang="bash"> JAVA_OPTS="$JAVA_OPTS -Dorg.jboss.logging.Log4jService.catchSystemOut=false -Dorg.jboss.logging.Log4jService.catchSystemErr=false" </geshi>

This is probably good to turn off anyway. It'll highlight modules that aren't using log4j, and really serious stuff will go to your boot.log.

Use the DatedFileAppender

The DatedFileAppender is a drop in replacement for the DailyRollingFileAppender. The difference is is starts with the dated filename, so no rename is necessary. You can download the DatedFileAppender here. Thanks Ted!

Other fixes

On Unix, moving the logs to a NetApp, local disk, or temp folder also fixes this problem. One other idea is to attempt to kill any processes doing a tail/less on the file before it rotates.