http://www.jboss.org runs mainly on Magnolia CMS. It is a web application, that runs on JBoss application server. Eng-ops (= the team responsible for maintaining infrastructure) reported, that logging does not work properly (the bug), because the logs are larger and larger and they are becomming huge. Jozef, the former colleague of mine, updated the configuration of the application server. We use log4j so the whole thing did not appear to be complicated. But the reality is sometimes quite interesting and so this issue remained unsolved for quite a long time.
Prequel - console.log is too long
First information I got was, that console.log is too long and everything from Java is logged into it. What I found in jboss-log4j.xml was very interesting:
<!-- ============================== -->
<!-- Append messages to the console -->
<!-- ============================== -->
<!-- appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
<param name="Target" value="System.out"/>
<param name="Threshold" value="INFO"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
</layout>
</appender -->
.............................
<!-- ======================= -->
<!-- Setup the Root category -->
<!-- ======================= -->
<root>
<!-- appender-ref ref="CONSOLE"/ -->
<appender-ref ref="FILE"/>
</root>
I knew little about log4j at start, but I knew what <!-- and --> does in xml. Just comment! So what the hell.... I asked Eng-ops to delete the old console.log file and to restart JBoss AS. The console.log was recreated and contained just a few lines of code. I also tried to raise some errors from applicaton, that might appear in this log (big thanks to Google for changing the API for getting Google analytics for giving me the error I needed). The error did not appear in the console.log, but in the log, that belonged to the specific web application responsible for rendering the web page instead. Nice! I asked again and was told, that the problem is actually server.log, not console.log. Aehmmm.....
The real fun - server.log too long
The configuration of the logger appeared to be valid:
<!-- A time/date based rolling appender -->
<appender name="FILE" class="org.jboss.logging.appender.DailyRollingFileAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
<param name="File" value="${jboss.server.log.dir}/server.log"/>
<param name="Append" value="true"/>
<param name="Threshold" value="INFO"/>
<!-- Rollover at midnight each day -->
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<!-- The default pattern: Date Priority [Category] Message\n -->
<param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
</layout>
</appender>
I copy pasted it on my local machine and it worked very well. When a new day came, the server.log was renamed to server.log.<date> and the logging to server.log started from the current day. Exactly as it should have been. But alas! You could see something like that on the staging:
......
2012-08-30 17:32:51,130 INFO [info.magnolia.cms.beans.config.PropertiesInitializer] Loading configuration at .................
2012-08-31 11:19:35,610 INFO [com.arjuna.ats.jbossatx.jta.TransactionManagerService] JBossTS Transaction Service (JTA version) - JBoss Inc.
......
So no roll over at all. What could possibly be wrong? Why on one machine it does work and on the other does not? A different version of log4j? Perhaps. A different locale and thus date-time format? Also possible. Thanks God log4j is the open source and thus the source code is available for everyone. I.e. here. If you check the code, you can find, that the content of the log is irrelevant. The only thing that matters is the modification date and time of the log file. It still does not answer why the roll over does not happen.
Unless you check the way, how the JBoss is started. We use a script for it, that has something like that inside:
for logfile in boot.log cluster.log console.log server.log; do
if [ -f /var/log/$NAME/$JBOSSCONF/$logfile ]; then
if [ "$JBOSSUS" != "RUNASIS" ]; then
$SU $JBOSSUS -s /bin/sh -c "touch /var/log/$NAME/$JBOSSCONF/$logfile >/dev/null 2>&1"
if [ ! $? -eq 0 ]; then
failure $"${NAME} startup"
echo -n -e "\nLogfile /var/log/$NAME/$JBOSSCONF/$logfile exists but not writable by $JBOSSUS."
echo -n -e "\n"
return 4
fi
else
if [ ! -w /var/log/$NAME/$JBOSSCONF/$logfile ]; then
failure $"${NAME} startup"
echo -n -e "\nLogfile /var/log/$NAME/$JBOSSCONF/$logfile exists but not writable."
echo -n -e "\n"
return 4
fi
fi
fi
done
And this is it. Touch changes the time, whe the server starts. And because there are logs to be written just when the application server starts, the date of the log file is always the current date and the roll over never happen.