Details
-
Bug
-
Resolution: Fixed
-
Major
-
1.2.3
-
None
-
reconfiguration of logback during slf4j start
Description
12:28:28,924 |-ERROR in ch.qos.logback.core.ConsoleAppender[console] - Appender [console] failed to append. java.lang.NullPointerException at java.lang.NullPointerException at at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199) at at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231) at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at at ch.qos.logback.classic.Logger.log(Logger.java:775) at at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source) at at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at at java.lang.reflect.Method.invoke(Method.java:498) at at org.slf4j.helpers.SubstituteLogger.log(SubstituteLogger.java:374) at at org.slf4j.LoggerFactory.replaySingleEvent(LoggerFactory.java:229) at at org.slf4j.LoggerFactory.replayEvents(LoggerFactory.java:198) at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:142) at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124) at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:345) at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:290) at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:316)
In our environment sometimes we receive reconfiguration event of logback (via zookeeper) during sl4j initialization. During such reconfiguration we receieve such NPE.
I think this is happens because race-condition in OutputStreamAppender
thread1 subAppend() - call checkClosed() returns false
thread2 LoggerContext.reset() called, that translates to OutputStreamAppender.stop()
thread1 call writeBytes - throws NPE, becase appender already closed
possible unit test that reproduces NPE
package ch.qos.logback.core; import java.io.IOException; import java.io.OutputStream; import org.junit.Test; import ch.qos.logback.core.encoder.EncoderBase; public class TestAppender { @Test public void testAppender() throws InterruptedException { OutputStreamAppender<Object> appender = new OutputStreamAppender<Object>() { @Override public void addError(String msg, Throwable ex) { throw new RuntimeException(msg, ex); } }; appender.setEncoder(new EncoderBase<Object>() { @Override public byte[] headerBytes() { return null; } @Override public byte[] encode(Object event) { try { Thread.sleep(1000); } catch (InterruptedException e) { // TODO Auto-generated catch block e.printStackTrace(); } return new byte[] {'A'}; } @Override public byte[] footerBytes() { // TODO Auto-generated method stub return null; } }); appender.setOutputStream(new OutputStream() { @Override public void write(int b) throws IOException { throw new RuntimeException("not closed appender"); } }); appender.start(); Thread t = new Thread(new Runnable() { @Override public void run() { try { Thread.sleep(500); } catch (InterruptedException e) { // TODO Auto-generated catch block e.printStackTrace(); } appender.stop(); } }); t.start(); appender.doAppend(new Object()); t.join(); } }
Attachments
Issue Links
- links to