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.

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.