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

NullPointerException from RollingFileAppender

    Details

      Description

      Having this logback configuration:

      <?xml version="1.0" encoding="UTF-8"?> 
      <configuration debug="true" scan="true" scanPeriod="60 minutes">
          <appender name="LOGOUTPUT" class="ch.qos.logback.core.rolling.RollingFileAppender">
              <file>${catalina.base}/logs/gateway_api.log</file>
              <encoder>
                  <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
              </encoder>
              <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                  <FileNamePattern>logFile.%d{yyyy-MM-dd}.log</FileNamePattern>
              </rollingPolicy>
          </appender>
      
          <appender name="STDOUTPUT" class="ch.qos.logback.core.ConsoleAppender">
              <encoder>
                  <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
              </encoder>
          </appender>
      
          <logger name="com.groupgti" level="DEBUG"/>
          <logger name="org.springframework" level="INFO"/>
          <logger name="org.apache.cxf" level="INFO"/>
          <root level="WARN">
              <appender-ref ref="LOGOUTPUT"/>
          </root>
      </configuration>
      

      And these dependencies in classpath:

              <dependency>
                  <groupId>org.slf4j</groupId>
                  <artifactId>slf4j-api</artifactId>
                  <version>1.7.10</version>
                  <scope>compile</scope>
              </dependency>
              <dependency>
                  <groupId>org.slf4j</groupId>
                  <artifactId>jcl-over-slf4j</artifactId>
                  <version>1.7.10</version>
                  <scope>compile</scope>
              </dependency>
              <dependency>
                  <groupId>ch.qos.logback</groupId>
                  <artifactId>logback-classic</artifactId>
                  <version>1.1.2</version>
                  <scope>compile</scope>
              </dependency>
      

      Getting a lot of these exceptions in log files.

      08:55:58,884 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Wed Feb 25 08:55:45 GMT 2015 
      08:55:58,889 |-INFO in c.q.l.co.rolling.helper.RenameUtil - Renaming file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] to [logFile.2015-02-25.log] 
      08:55:58,891 |-WARN in c.q.l.co.rolling.helper.RenameUtil - Failed to rename file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] as [logFile.2015-02-25.log]. 
      08:55:58,892 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[LOGOUTPUT] - Appender [LOGOUTPUT] failed to append. java.lang.NullPointerException 
              at java.lang.NullPointerException 
              at at ch.qos.logback.core.rolling.helper.FileStoreUtil.areOnSameFileStore(FileStoreUtil.java:44) 
              at at ch.qos.logback.core.rolling.helper.RenameUtil.areOnDifferentVolumes(RenameUtil.java:97) 
              at at ch.qos.logback.core.rolling.helper.RenameUtil.rename(RenameUtil.java:67) 
              at at ch.qos.logback.core.rolling.TimeBasedRollingPolicy.rollover(TimeBasedRollingPolicy.java:153) 
              at at ch.qos.logback.core.rolling.RollingFileAppender.attemptRollover(RollingFileAppender.java:158) 
              at at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:137) 
              at at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:178) 
              at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) 
              at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) 
              at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) 
              at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273) 
              at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260) 
              at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442) 
              at at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:414) 
              at at ch.qos.logback.classic.Logger.debug(Logger.java:507) 
              at at com.groupgti.saml.handler.AssertionHandler.purgeRecords(AssertionHandler.java:95) 
              at at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
              at at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
              at at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
              at at java.lang.reflect.Method.invoke(Method.java:483) 
              at at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) 
              at at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) 
              at at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) 
              at at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) 
              at at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) 
              at at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) 
              at at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) 
              at at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) 
              at at java.lang.Thread.run(Thread.java:745) 
      08:55:58,944 |-ERROR in c.q.l.c.recovery.ResilientFileOutputStream@1011140840 - IO failure while writing to file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] java.io.IOException: Stream Closed 
              at java.io.IOException: Stream Closed 
              at at java.io.FileOutputStream.writeBytes(Native Method) 
              at at java.io.FileOutputStream.write(FileOutputStream.java:315) 
              at at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) 
              at at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) 
              at at ch.qos.logback.core.recovery.ResilientOutputStreamBase.flush(ResilientOutputStreamBase.java:79) 
              at at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:137) 
              at at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194) 
              at at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:209) 
              at at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219) 
              at at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:182) 
              at at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) 
              at at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) 
              at at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) 
              at at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273) 
              at at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260) 
              at at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442) 
              at at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:414) 
              at at ch.qos.logback.classic.Logger.error(Logger.java:547) 
              at at com.groupgti.saml.handler.AssertionHandler.purgeRecords(AssertionHandler.java:103) 
              at at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
              at at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
              at at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
              at at java.lang.reflect.Method.invoke(Method.java:483) 
              at at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) 
              at at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) 
              at at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) 
              at at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) 
              at at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) 
              at at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) 
              at at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) 
              at at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) 
              at at java.lang.Thread.run(Thread.java:745) 
      10:07:37,098 |-INFO in c.q.l.c.recovery.ResilientFileOutputStream@1011140840 - Attempting to recover from IO failure on file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] 
      10:07:37,099 |-INFO in c.q.l.c.recovery.ResilientFileOutputStream@1011140840 - Recovered from IO failure on file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] 
      08:55:58,946 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Elapsed period: Thu Feb 26 08:55:58 GMT 2015 
      08:55:58,947 |-INFO in c.q.l.co.rolling.helper.RenameUtil - Renaming file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] to [logFile.2015-02-26.log] 
      08:55:58,947 |-WARN in c.q.l.co.rolling.helper.RenameUtil - Failed to rename file [/usr/share/apache-tomcat-8.0.18/logs/saml.log] as [logFile.2015-02-26.log]. 
      08:55:58,947 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[LOGOUTPUT] - Appender [LOGOUTPUT] failed to append. java.lang.NullPointerException 
      

      I have been adviced to raise a bug. Reference in a mailing list:

      http://logback.10977.n7.nabble.com/java-lang-NullPointerException-from-RollingFileAppender-td14082.html#a14087

        Activity

        Hide
        pmatulionis Paulius Matulionis added a comment - - edited

        Have anyone looked at this issue? It's still happening on 1.1.3 as well.

        Show
        pmatulionis Paulius Matulionis added a comment - - edited Have anyone looked at this issue? It's still happening on 1.1.3 as well.
        Hide
        palek Ferenc Palkovics added a comment -

        Appender configuration to reproduce the issue:

        	<appender name="MY"
        		class="ch.qos.logback.core.rolling.RollingFileAppender">
        		<file>my.log</file>
        		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        			<fileNamePattern>my.%d{yyyy-MM-dd}.log</fileNamePattern>
        		</rollingPolicy>
        		<encoder>
        			<pattern>%d{yyyy.MM.dd. HH:mm:ss.SSS} %-5level user:%X{userID} %logger{36} - %msg%n</pattern>
        		</encoder>
        	</appender>
        

        If file denotes an abstract path name on checking the second condition, the parentOfTarget will null

        Show
        palek Ferenc Palkovics added a comment - Appender configuration to reproduce the issue: <appender name= "MY" class= "ch.qos.logback.core.rolling.RollingFileAppender" > <file>my.log</file> <rollingPolicy class= "ch.qos.logback.core.rolling.TimeBasedRollingPolicy" > <fileNamePattern>my.%d{yyyy-MM-dd}.log</fileNamePattern> </rollingPolicy> <encoder> <pattern>%d{yyyy.MM.dd. HH:mm:ss.SSS} %-5level user:%X{userID} %logger{36} - %msg%n</pattern> </encoder> </appender> If file denotes an abstract path name on checking the second condition , the parentOfTarget will null
        Hide
        jgn Javier Gonzalez added a comment - - edited

        Hi,

        experiencing the same issue with logback-classic version 1.1.3. I was trying the configuration for RollingFileAppender with TimeBasedRollingPolicy. I had it set at 1-minute rolling intervals when this error occurred.

            <appender name="rollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${LOG_DIR}/app.log</file>
                <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
                    <Pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <fileNamePattern>app.%d{yyyyMMdd-HHmm}</fileNamePattern>
                    <maxHistory>15</maxHistory>
                </rollingPolicy>
            </appender>
        
        Show
        jgn Javier Gonzalez added a comment - - edited Hi, experiencing the same issue with logback-classic version 1.1.3 . I was trying the configuration for RollingFileAppender with TimeBasedRollingPolicy. I had it set at 1-minute rolling intervals when this error occurred. <appender name= "rollingFile" class= "ch.qos.logback.core.rolling.RollingFileAppender" > <file> ${LOG_DIR}/app.log </file> <encoder class= "ch.qos.logback.classic.encoder.PatternLayoutEncoder" > <Pattern> %d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n </Pattern> </encoder> <rollingPolicy class= "ch.qos.logback.core.rolling.TimeBasedRollingPolicy" > <fileNamePattern> app.%d{yyyyMMdd-HHmm} </fileNamePattern> <maxHistory> 15 </maxHistory> </rollingPolicy> </appender>
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        See PR 284

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited See PR 284
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        Fixed in commit 1f3a0080a8. Ferenc Palkovics Thank you for analyzing the issue and providing the relevant patch.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - Fixed in commit 1f3a0080a8 . Ferenc Palkovics Thank you for analyzing the issue and providing the relevant patch.

          People

          • Assignee:
            noreply.ceki@qos.ch Ceki Gulcu
            Reporter:
            pmatulionis Paulius Matulionis
          • Votes:
            2 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: