[logback-user] RollingFileAppender behaving weird

[Brecht Yperman]

Hi everyone,

We recently had an issue on one of our production servers.
We never had this problem before, so unfortunately it's not something I can reproduce.

The symptom was that the server continuously used 1 CPU. We took some thread dumps and saw one thread was rolling the files.

"Server Thread: /81.82.251.166:53103" - Thread t at 35951
   java.lang.Thread.State: RUNNABLE
	at java.util.zip.Deflater.deflateBytes(Native Method)
	at java.util.zip.Deflater.deflate(Deflater.java:442)
	- locked <29369617> (a java.util.zip.ZStreamRef)
	at java.util.zip.Deflater.deflate(Deflater.java:364)
	at java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:251)
	at java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:211)
	at java.util.zip.ZipOutputStream.write(ZipOutputStream.java:331)
	- locked <528548da> (a java.util.zip.ZipOutputStream)
	at ch.qos.logback.core.rolling.helper.Compressor.zipCompress(Compressor.java:110)
	at ch.qos.logback.core.rolling.helper.Compressor.compress(Compressor.java:58)
	at ch.qos.logback.core.rolling.FixedWindowRollingPolicy.rollover(FixedWindowRollingPolicy.java:157)
	at ch.qos.logback.core.rolling.RollingFileAppender.attemptRollover(RollingFileAppender.java:158)
	at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:137)
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:178)
	- locked <38d457ec> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
	at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:433)
	at ch.qos.logback.classic.Logger.debug(Logger.java:511)
	...

A thread dump from a few minutes later showed a different thread with more or less the exact same stack trace.

The appender looks like this:

	<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>E:\Invenso\Logging\xbiadmin.log.txt</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
			<fileNamePattern>E:\Invenso\Logging\xbiadmin.%i.log.zip</fileNamePattern>
			<minIndex>1</minIndex>
			<maxIndex>5</maxIndex>
		</rollingPolicy>
		<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
			<maxFileSize>25MB</maxFileSize>
		</triggeringPolicy>
		<encoder>
			<pattern>%d{"dd-MM-yy HH:mm:ss,SSS"} - [%t] %-5p - %m%n</pattern>
		</encoder>
	</appender>

(Unfortunately, this configuration is recreated on restart, and we did not think to copy the configuration.
It is possible that this configuration looked somewhat different when the issue occurred)

When we took a look at the log files, we immediately saw all log files being equal in size.
If we took a look inside the zip files, we saw all files being equal, and the same as the actual log files.

So we had 6 files:
- 5 zip files (16,076 KB)
- 1 txt file (32,554 KB)

The log file is bigger than the maxFileSize configured and the contents of the six files are identical.

I noticed that one of the lines logged was over 6Mb, and if I remove this line and all the subsequent lines, the file is 24,906 KB.

Any help on what went wrong here, or what we can do to better investigate this should this occur another time would be much appreciated.

Thanks,
Brecht