[logback-dev] [JIRA] (LOGBACK-1362) NullPointerException in OutputStreamAppender on logback reconfiguratiuon

[QOS.CH (JIRA)]

Alexander Kudrevatykh created LOGBACK-1362:
----------------------------------------------

             Summary: NullPointerException in OutputStreamAppender on logback reconfiguratiuon
                 Key: LOGBACK-1362
                 URL: https://jira.qos.ch/browse/LOGBACK-1362
             Project: logback
          Issue Type: Bug
          Components: logback-core
    Affects Versions: 1.2.3
         Environment: reconfiguration of logback during slf4j start
            Reporter: Alexander Kudrevatykh
            Assignee: Logback dev list


{noformat}
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){noformat}
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
{code:java}
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();
       }
 
}{code}
 

 



--
This message was sent by Atlassian JIRA
(v7.3.1#73012)