Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1362

NullPointerException in OutputStreamAppender on logback reconfiguratiuon

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • 1.5.7
    • 1.2.3
    • logback-core
    • 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

        Activity

          People

            logback-dev Logback dev list
            kudrale Alexander Kudrevatykh
            Votes:
            7 Vote for this issue
            Watchers:
            10 Start watching this issue

            Dates

              Created:
              Updated: