Details
-
Bug
-
Resolution: Unresolved
-
Major
-
None
-
1.3.0-alpha0, 1.2.3
-
None
Description
When attempting to detach and stop all appenders (specifically SiftingAppender) associated with a logger, logback may throw a ConcurrentModificationException if another thread is currently logging.
java.util.ConcurrentModificationException: null
{{ at java.util.LinkedHashMap$LinkedHashIterator.nextNode(LinkedHashMap.java:719)}}
{{ at java.util.LinkedHashMap$LinkedValueIterator.next(LinkedHashMap.java:747)}}
{{ at ch.qos.logback.core.spi.AbstractComponentTracker.allComponents(AbstractComponentTracker.java:234)}}
{{ at ch.qos.logback.core.sift.SiftingAppenderBase.stop(SiftingAppenderBase.java:89)}}
{{ at ch.qos.logback.core.spi.AppenderAttachableImpl.detachAndStopAllAppenders(AppenderAttachableImpl.java:107)}}
{{ at ch.qos.logback.classic.Logger.detachAndStopAllAppenders(Logger.java:206)}}
{{ at automation.config.logging.LoggerGenerator.destroyLogger(LoggerGenerator.java:143)}}
{{ at processflow.ProcessHandler.destroyProcessContext(ProcessHandler.java:862)}}
{{ at automation.config.processflow.ProcessContextHandler.processConnection(ProcessContextHandler.java:636)}}
{{ at automation.config.processflow.DatabaseService$Processor.processConnection(DatabaseService.java:281)}}
{{ at appserversupport.sql.ConnectionProcessor$Processor.run(ConnectionProcessor.java:187)}}
{{ at java.lang.Thread.run(Thread.java:745)}}
The issue lies with the SiftingAppender where the underlying AppenderTracker objects "liveMap" and "lingerersMap" are being iterated over at the same time a "new" appender is being created. The creation is synchronized, but other methods that utilize these maps are not.
The only solution I see is to synchronize on the AppenderTracker object when attempting to access either map. Since the "getOrCreate" method is already synchronized, and is the method most predominantly called, I see little downside.
To test this, modify the allComponents method in AbstractComponentTracker as follows.
public Collection<C> allComponents() { List<C> allComponents = new ArrayList<C>(); Iterator<Entry<C>> i = liveMap.values().iterator(); while (i.hasNext()) { try {Thread.sleep(100);} catch (Exception e) {} allComponents.add(i.next().component); } //for (Entry<C> e : liveMap.values()) // allComponents.add(e.component); for (Entry<C> e : lingerersMap.values()) allComponents.add(e.component); return allComponents; }
Except for the delay, the above behaves the same.
Then create a class to test it.
package logbacktest; import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.encoder.PatternLayoutEncoder; import ch.qos.logback.classic.sift.MDCBasedDiscriminator; import ch.qos.logback.classic.sift.SiftingAppender; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.core.Appender; import ch.qos.logback.core.Context; import ch.qos.logback.core.OutputStreamAppender; import ch.qos.logback.core.sift.AppenderFactory; import ch.qos.logback.core.util.Duration; import java.util.HashMap; import java.util.Map; import org.apache.log4j.MDC; import org.slf4j.ILoggerFactory; import org.slf4j.LoggerFactory; public class TestSiftConcurrent implements AppenderFactory<ILoggingEvent> { public static void main(String[] args) throws Exception { final Logger logger = (Logger)LoggerFactory.getLogger("root"); ILoggerFactory factory = LoggerFactory.getILoggerFactory(); Context context = (Context)factory; SiftingAppender sift = new SiftingAppender(); sift.setContext(context); sift.setName("context"); MDCBasedDiscriminator discriminator = new MDCBasedDiscriminator(); discriminator.setContext(context); discriminator.setKey("logger-type"); discriminator.setDefaultValue("trace"); discriminator.start(); sift.setDiscriminator(discriminator); sift.setAppenderFactory(new TestSiftConcurrent()); sift.setTimeout(Duration.buildByDays(1)); sift.start(); logger.addAppender(sift); logger.error("Hello"); new Thread() { public void run() { MDC.put("logger-type", "foo"); logger.error("Hello"); } }.start(); logger.detachAndStopAllAppenders(); } public Appender<ILoggingEvent> buildAppender(Context context, String discriminatingValue) { OutputStreamAppender app = new OutputStreamAppender(); app.setContext(context); app.setName(discriminatingValue); app.setOutputStream(System.out); //Create pattern to use for logging statements PatternLayoutEncoder encoder = new PatternLayoutEncoder(); encoder.setContext(context); encoder.setPattern("%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{logger-type}] %-5level %logger{36} - %msg%n"); app.setEncoder(encoder); encoder.start(); app.start(); return app; } }
Invariably, the above should cause a ConcurrentModificationException to be thrown since the new "foo" appender will have been created while the "allComponents" method is executing within the iterator.
SImply synchronizing the methods endOfLife, allKeys, allComponents, CyclicBufferTracker.liveKeysAsOrderedList, and CyclicBufferTracker.lingererKeysAsOrderedList eliminates the issue. The getComponentCount method does not necessarily need to be synchronized as it does not modify or iterate.