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
[email protected]
http://mailman.qos.ch/mailman/listinfo/logback-user
