[prev in list] [next in list] [prev in thread] [next in thread] 

List:       logback-user
Subject:    [logback-user] RollingFileAppender behaving weird
From:       Brecht Yperman <brecht.yperman () invenso ! com>
Date:       2016-02-01 11:05:48
Message-ID: DB4PR03MB3620DDC05267179C17A4AEC8BDE0 () DB4PR03MB362 ! eurprd03 ! prod ! outlook ! com
[Download RAW message or body]

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@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



_______________________________________________
logback-user mailing list
logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user


[prev in list] [next in list] [prev in thread] [next in thread]