[logback-user] RollingFileAppender with SizeBasedTriggeringPolicy keeps writing to rotated file

David Roussel nabble at diroussel.xsmail.com
Fri May 24 21:17:12 CEST 2013


Roland,

What version of logback are you using?

Can you debug and find what is causing the null pointer exception?

David

On 24 May 2013, at 19:35, Rolando Segura <rolandosegura at gmail.com> wrote:

> Hi Ceki,
> 
> I reproduced the problem in a dev environment (setting the maxfilesize to 1MB), There are several instances of a NullPointerException like the one shown below.
> Enabled debug in one of the pro machines but haven't seen the error yet, however I suspect the problem should be the same.
> 
> I believe is important to mention that we are logging very large strings sometimes larger than 40K.
> 
> Thanks,
> Rolando
> 
> 
> 5/24/13 11:01:20:636 CST] 00001e2a SystemOut     O 11:01:20,635 |-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[mop] - Appender [mop] failed to append. java.lang.NullPoi
> nterException
>         at java.lang.NullPointerException
>         at      at ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy.isTriggeringEvent(SizeBasedTriggeringPolicy.java:59)
>         at      at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:143)
>         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:280)
>         at      at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267)
>         at      at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449)
>         at      at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403)
>         at      at ch.qos.logback.classic.Logger.info(Logger.java:607)
>         at      at bizservices_notification.BizServicesReceiveStatusNotification20100310T231159EntityAbstractBase$JSE_10.execute(BizServicesReceiveStatusNotification20100310T231159E
> ntityAbstractBase.java:129)
>         at      at com.ibm.bpe.framework.ProcessBase6.executeJavaSnippet(ProcessBase6.java:330)
> 
> 
> 
> On Fri, May 24, 2013 at 10:26 AM, ceki <ceki at qos.ch> wrote:
>> Hi Rolando,
>> 
>> Thank you for posting your logback.xml file. I suspect that for some
>> reason logback is unable to rename some of the archives.
>> 
>> In any case, setting the debug attribute to true in <configuration>
>> element should provide helpful clues as to what is going on during
>> file rolling. Here is the modified <configuration> element:
>> 
>> <configuration debug="true" scan="true">
>>    ...
>> </configuration>
>> 
>> Please post the status messages on this list.
>> 
>> 
>> On 24.05.2013 17:53, Rolando Segura wrote:
>>> Hi David,
>>> Configuration is below. I'm also showing the sizes of the log files,
>>> you'll notice that some of them have sizes much larger to what is
>>> specified with the MaxFileSize parameter of the triggering policy.
>>> 
>>> Thanks,
>>> Rolando
>>> 
>>> 
>>> $ ls -l /opt/log/mop.log*
>>> -rw-r--r--    1 wps wps   13366643 May 24 09:47 /opt/log/mop.log
>>> -rw-r--r--    1 wps wps   67121376 May 24 09:16 /opt/log/mop.log.1
>>> -rw-r--r--    1 wps wps  849229334 May 24 09:47 /opt/log/mop.log.10
>>> -rw-r--r--    1 wps wps   67116193 May 23 23:16 /opt/log/mop.log.2
>>> -rw-r--r--    1 wps wps   67114690 May 23 19:54 /opt/log/mop.log.3
>>> -rw-r--r--    1 wps wps   31160111 May 24 09:47 /opt/log/mop.log.4
>>> -rw-r--r--    1 wps wps   67110076 May 23 17:09 /opt/log/mop.log.5
>>> -rw-r--r--    1 wps wps   67115644 May 23 11:38 /opt/log/mop.log.6
>>> -rw-r--r--    1 wps wps   67121760 May 23 00:31 /opt/log/mop.log.7
>>> -rw-r--r--    1 wps wps   29536505 May 23 17:09 /opt/log/mop.log.8
>>> -rw-r--r--    1 wps wps 2053363264 May 24 09:47 /opt/log/mop.log.9
>>> 
>>> $ ls -l /opt/log/mop.nocr*
>>> -rw-r--r--    1 wps wps   25664997 May 24 09:47 /opt/log/mop.nocrlf.log
>>> -rw-r--r--    1 wps wps  991283661 May 24 09:47 /opt/log/mop.nocrlf.log.1
>>> 
>>> 
>>> 
>>> $ cat logback.xml
>>> <?xml version="1.0" encoding="UTF-8"?>
>>> 
>>> <!-- For assistance related to logback-translator or configuration  -->
>>> <!-- files in general, please contact the logback user mailing list -->
>>> <!-- at http://www.qos.ch/mailman/listinfo/logback-user             -->
>>> <!--                                                                -->
>>> <!-- For professional support please see                            -->
>>> <!-- http://www.qos.ch/shop/products/professionalSupport         -->
>>> <!--                                                                -->
>>> <configuration scan="true">
>>>    <appender name="SYSLOG"
>>> class="ch.qos.logback.classic.net.SyslogAppender">
>>>      <syslogHost>localhost</syslogHost>
>>>      <facility>LOCAL7</facility>
>>>      <suffixPattern>%d{ISO8601} %5p [%t] \(%logger\) -
>>> %replace(%m){'\n',''}</suffixPattern>
>>>    </appender>
>>>    <appender name="mop"
>>> class="ch.qos.logback.core.rolling.RollingFileAppender">
>>>      <!--See also
>>> http://logback.qos.ch/manual/appenders.html#RollingFileAppender-->
>>>      <File>/opt/log/mop.log</File>
>>>      <encoder>
>>>        <pattern>%d{ISO8601} %5p [%t] \(%logger\) - %m%n</pattern>
>>>      </encoder>
>>>      <rollingPolicy
>>> class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
>>>        <maxIndex>10</maxIndex>
>>>        <FileNamePattern>/opt/log/mop.log.%i</FileNamePattern>
>>>      </rollingPolicy>
>>>      <triggeringPolicy
>>> class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
>>>        <MaxFileSize>64MB</MaxFileSize>
>>>      </triggeringPolicy>
>>>    </appender>
>>>    <appender name="mopnocrlf"
>>> class="ch.qos.logback.core.rolling.RollingFileAppender">
>>>      <File>/opt/log/mop.nocrlf.log</File>
>>>      <encoder>
>>>        <pattern>[%d{ISO8601}] %5p [%t] \(%logger\) -
>>> %replace(%m){'\r?\n',''}%n</pattern>
>>>      </encoder>
>>>      <rollingPolicy
>>> class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
>>>        <maxIndex>1</maxIndex>
>>>        <FileNamePattern>/opt/log/mop.nocrlf.log.%i</FileNamePattern>
>>>      </rollingPolicy>
>>>      <triggeringPolicy
>>> class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
>>>        <MaxFileSize>32MB</MaxFileSize>
>>>      </triggeringPolicy>
>>>    </appender>
>>>    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
>>>      <encoder>
>>>        <pattern>%5p [%t] \(%logger\) - %m%n</pattern>
>>>      </encoder>
>>>    </appender>
>>>    <logger name="mop" level="debug">
>>>      <appender-ref ref="mop"/>
>>>      <appender-ref ref="mopnocrlf"/>
>>>    </logger>
>>>    <root level="fatal">
>>>      <appender-ref ref="stdout"/>
>>>    </root>
>>> </configuration>
>>> 
>>> 
>>> 
>>> On Fri, May 24, 2013 at 7:21 AM, David Roussel
>>> <nabble at diroussel.xsmail.com <mailto:nabble at diroussel.xsmail.com>> wrote:
>>> 
>>>     Roland,
>>> 
>>>     That sounds strange. Can you post your logback.xml file?
>>> 
>>>     David
>>> 
>>>     On 23 May 2013, at 00:03, Rolando Segura <rolandosegura at gmail.com
>>>     <mailto:rolandosegura at gmail.com>> wrote:
>>> 
>>>      >  Hi I have an RollingFileAppender with a triggering policy of
>>>     rotating by size when the log reaches 32MB and a maxIndex of 1,
>>>     configuration below.
>>>      > It happens that after rotation logback keeps writing to both
>>>     files. Is this expected? My understanding from documentation is that
>>>     it will stop writing to the current log, rename it and starts
>>>     writing a to a new file with the name of the File parameter.
>>>      >
>>>      > I'd appreciate your clarification if I'm not understanding well
>>>     the RollingFileAppender and SizeBasedTriggering behavior.
>>>      >
>>>      > Thanks,
>>>      > Rolando
>>>      >
>>>      >
>>>      >
>>>      > <appender name="lognocrlf"
>>>     class="ch.qos.logback.core.rolling.RollingFileAppender">
>>>      >     <File>/opt/log/file.nocrlf.log</File>
>>>      >     <encoder>
>>>      >       <pattern>[%d{ISO8601}] %5p [%t] \(%logger\) -
>>>     %replace(%m){'\r?\n',''}%n</pattern>
>>>      >     </encoder>
>>>      >     <rollingPolicy
>>>     class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
>>>      >       <maxIndex>1</maxIndex>
>>>      >       <FileNamePattern>/opt/log/file.nocrlf.log.%i</FileNamePattern>
>>>      >     </rollingPolicy>
>>>      >     <triggeringPolicy
>>>     class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
>>>      >       <MaxFileSize>32MB</MaxFileSize>
>>>      >     </triggeringPolicy>
>>>      >   </appender>
>>>      >
>> 
>> 
>> 
>> -- 
>> Ceki
>> 65% of statistics are made up on the spot
>> 
>> _______________________________________________
>> Logback-user mailing list
>> Logback-user at qos.ch
>> http://mailman.qos.ch/mailman/listinfo/logback-user
> 
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20130524/92e95ebb/attachment-0001.html>


More information about the Logback-user mailing list