DM Server simultaneously logging to all historical logs after rollover

[estrnod]

Has anyone else seen this problem? Intermittently under dm server, one of our application’s bundles’ logs will roll over (using sifted rolling file appender) and then start logging simultaneously to all the historical log files for that application (log_1.log, log_2.log, etc.) as well as the current one (log.log). Once this happens, application performance is severely degraded.

We are using dm server 2.0.0.RELEASE running under either Windows XP or Windows 7 (problem has been seen on both). All of the application code has been updated to use slf4j logging and all references to log4j and apache commons logging have been removed from the bundle builds. (Third-party libraries it is using using may still be using log4j.)

The only logging configuration for the app is the serviceability.xml file in the dm server config directory. There are 4 active bundles deployed - a war file and 3 bundle jar files. To make these log into their own logs, they are currently deployed as separate plans, one of which is not scoped since it is shared (so logs into the default log).

Here is the serviceability.xml file contents: (The logging levels are currently as high as possible without preventing dm server from starting, to cause rollovers to occur quickly.)

<configuration>

<appender name="SIFTED_LOG_FILE" class="ch.qos.logback.classic.sift.SiftingAppender ">
<discriminator>
<Key>applicationName</Key>
<DefaultValue>dm-server</DefaultValue>
</discriminator>
<sift>
<appender name="${applicationName}_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppe nder">
<file>serviceability/logs/${applicationName}/log.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRoll ingPolicy">
<FileNamePattern>serviceability/logs/${applicationName}/log_%i.log</FileNamePattern>
<MinIndex>1</MinIndex>
<MaxIndex>4</MaxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTrigge ringPolicy">
<MaxFileSize>10MB</MaxFileSize>
</triggeringPolicy>
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|%t|%p|%c{35}.%M:%L|%msg %ex%n</Pattern>
</layout>
</appender>
</sift>
</appender>


<appender name="EVENT_LOG_STDOUT" class="com.springsource.osgi.medic.log.logback.Rer outingAwareConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|%t|%p|%c{35}.%M:%L|&lt;%X{medic.even tCode}&gt; %msg %ex%n</Pattern>
</layout>
</appender>

<appender name="EVENT_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppe nder">
<file>serviceability/eventlogs/eventlog.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRoll ingPolicy">
<FileNamePattern>serviceability/eventlogs/eventlog_%i.log</FileNamePattern>
<MinIndex>1</MinIndex>
<MaxIndex>4</MaxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTrigge ringPolicy">
<MaxFileSize>10MB</MaxFileSize>
</triggeringPolicy>
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|%t|%p|%c{35}.%M:%L|&lt;%X{medic.even tCode}&gt; %msg %ex%n</Pattern>
</layout>
</appender>

<logger level="info" additivity="false" name="com.springsource.osgi.medic.eventlog.localiz ed">
<appender-ref ref="EVENT_LOG_STDOUT" />
<appender-ref ref="EVENT_LOG_FILE" />
</logger>
<logger level="warn" additivity="false" name="com.springsource.osgi.medic.eventlog.default ">
<appender-ref ref="SIFTED_LOG_FILE" />
</logger>

<!-- … project packages at debug level using SIFTED_LOG_FILE appender elided -->

<logger level="debug" additivity="false" name="org.springframework.security">
<appender-ref ref="SIFTED_LOG_FILE" />
</logger>
<logger level="debug" additivity="false" name="springframework.security">
<appender-ref ref="SIFTED_LOG_FILE" />
</logger>
<logger level="debug" additivity="false" name="org.hibernate.type">
<appender-ref ref="SIFTED_LOG_FILE" />
</logger>
<logger level="warn" additivity="false" name="com.springsource">
<appender-ref ref="SIFTED_LOG_FILE" />
</logger>

<root level="info" additivity="false">
<appender-ref ref="SIFTED_LOG_FILE" />
</root>

</configuration>

[Glyn Normington]

This is the first time I've heard of such behaviour. Sounds like a bug in LogBack, so you might try searching there.

[estrnod]

Right you are. I have an independent test case outside of dm server that shows it happens when multiple threads are logging to the same file.

[estrnod]

http://jira.qos.ch/browse/LBCLASSIC-203

[Glyn Normington]

Great work! Let's see if the Logback guys can deliver a fix which we can pick up in due course.

[estrnod]

... requires use of new slf4j api version 1.6.0 as well.