Log4j 2
  1. Log4j 2
  2. LOG4J2-642

Mismatch in Rollover date and log entry date in the log file

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0-rc1
    • Component/s: None
    • Labels:
      None
    • Environment:

      Java 7

      Description

      This is an issue with the rollbacking of the log file. The file is rollbacked as inst4-out-2014-05-16.log. But the log entry is created on 2014-05-19. So many log files are rollbacked like this. The configuration is as follows. Can you please advise why this is happening?

      <?xml version="1.0" encoding="UTF-8"?>
      <configuration>
      	<properties>
      		<property name="logPattern">log_type_%c|%K{sessionId}|%t|%d{MM/dd/yyyy HH:mm:ss.SSS}|%p|%C|%M|%L|%K{msg}%n</property>
      		<property name="filePattern">${sys:logfilepath}//$${date:yyyy-MM}//${sys:oft.appserver}-out-%d{yyyy-MM-dd}.log</property>
      		<property name="fileName">${sys:logfilepath}//${sys:oft.appserver}-out.log</property>
      	</properties>
      	<appenders>
      		<Console name="Console" target="SYSTEM_OUT">
      			<PatternLayout pattern="logPattern"/>
      		</Console>
      		<RollingFile name="RollingFile" fileName="${fileName}" filePattern="${filePattern}">
      			<PatternLayout>
      				<pattern>${logPattern}</pattern>
      			</PatternLayout>
      			<Policies>
      				<TimeBasedTriggeringPolicy />
      				<SizeBasedTriggeringPolicy />
      			</Policies>
      			<DefaultRolloverStrategy compressionLevel="0" max="3"/>
      		</RollingFile>	
      	</appenders>
      	<loggers>					
      		<AsyncLogger name="sso" level="info" includeLocation="true" additivity="false">
      			<AppenderRef ref="RollingFile"/>
      		</AsyncLogger>
      		<AsyncLogger name="webservice" level="info" includeLocation="true" additivity="false">
      			<AppenderRef ref="RollingFile"/>
      		</AsyncLogger>
      		<root level="info">
      			<AppenderRef ref="Console"/>
      		</root>
      	</loggers>
      </configuration>
      

      Below is the Log Entry from log file.

      log_type_webservice|job-945|ump-standard-jobType-203-sessKey-job-945|05/19/2014 15:29:29.374|INFO|com.mmp.webservice.wsFactory|factory|109|Service#FirmSTP#$$#Starts creating the ws client: FirmSTP
      
      1. logFolder.png
        6 kB
        sivan
      2. rolledLogFile.png
        17 kB
        sivan
      3. rolloverFile.png
        3 kB
        sivan

        Activity

        sivan created issue -
        Remko Popma made changes -
        Field Original Value New Value
        Description This is an issue with the rollbacking of the log file. The file is rollbacked as inst4-out-2014-05-16.log. But the log entry is created on 2014-05-19. So many log files are rollbacked like this. The configuration is as follows. Can you please advise why this is happening?

        <?xml version="1.0" encoding="UTF-8"?>
        <configuration>
        <properties>
        <property name="logPattern">log_type_%c|%K{sessionId}|%t|%d{MM/dd/yyyy HH:mm:ss.SSS}|%p|%C|%M|%L|%K{msg}%n</property>
        <property name="filePattern">${sys:logfilepath}//$${date:yyyy-MM}//${sys:oft.appserver}-out-%d{yyyy-MM-dd}.log</property>
        <property name="fileName">${sys:logfilepath}//${sys:oft.appserver}-out.log</property>
        </properties>
        <appenders>
        <Console name="Console" target="SYSTEM_OUT">
        <PatternLayout pattern="logPattern"/>
        </Console>
        <RollingFile name="RollingFile" fileName="${fileName}" filePattern="${filePattern}">
        <PatternLayout>
        <pattern>${logPattern}</pattern>
        </PatternLayout>
        <Policies>
        <TimeBasedTriggeringPolicy />
        <SizeBasedTriggeringPolicy />
        </Policies>
        <DefaultRolloverStrategy compressionLevel="0" max="3"/>
        </RollingFile>
        </appenders>
        <loggers>
        <AsyncLogger name="sso" level="info" includeLocation="true" additivity="false">
        <AppenderRef ref="RollingFile"/>
        </AsyncLogger>
        <AsyncLogger name="webservice" level="info" includeLocation="true" additivity="false">
        <AppenderRef ref="RollingFile"/>
        </AsyncLogger>
        <root level="info">
        <AppenderRef ref="Console"/>
        </root>
        </loggers>
        </configuration>


        Below is the Log Entry from log file.
        log_type_webservice|job-945|ump-standard-jobType-203-sessKey-job-945|05/19/2014 15:29:29.374|INFO|com.mmp.webservice.wsFactory|factory|109|Service#FirmSTP#$$#Starts creating the ws client: FirmSTP
        This is an issue with the rollbacking of the log file. The file is rollbacked as inst4-out-2014-05-16.log. But the log entry is created on 2014-05-19. So many log files are rollbacked like this. The configuration is as follows. Can you please advise why this is happening?

        {code}
        <?xml version="1.0" encoding="UTF-8"?>
        <configuration>
        <properties>
        <property name="logPattern">log_type_%c|%K{sessionId}|%t|%d{MM/dd/yyyy HH:mm:ss.SSS}|%p|%C|%M|%L|%K{msg}%n</property>
        <property name="filePattern">${sys:logfilepath}//$${date:yyyy-MM}//${sys:oft.appserver}-out-%d{yyyy-MM-dd}.log</property>
        <property name="fileName">${sys:logfilepath}//${sys:oft.appserver}-out.log</property>
        </properties>
        <appenders>
        <Console name="Console" target="SYSTEM_OUT">
        <PatternLayout pattern="logPattern"/>
        </Console>
        <RollingFile name="RollingFile" fileName="${fileName}" filePattern="${filePattern}">
        <PatternLayout>
        <pattern>${logPattern}</pattern>
        </PatternLayout>
        <Policies>
        <TimeBasedTriggeringPolicy />
        <SizeBasedTriggeringPolicy />
        </Policies>
        <DefaultRolloverStrategy compressionLevel="0" max="3"/>
        </RollingFile>
        </appenders>
        <loggers>
        <AsyncLogger name="sso" level="info" includeLocation="true" additivity="false">
        <AppenderRef ref="RollingFile"/>
        </AsyncLogger>
        <AsyncLogger name="webservice" level="info" includeLocation="true" additivity="false">
        <AppenderRef ref="RollingFile"/>
        </AsyncLogger>
        <root level="info">
        <AppenderRef ref="Console"/>
        </root>
        </loggers>
        </configuration>
        {code}


        Below is the Log Entry from log file.
        {code}
        log_type_webservice|job-945|ump-standard-jobType-203-sessKey-job-945|05/19/2014 15:29:29.374|INFO|com.mmp.webservice.wsFactory|factory|109|Service#FirmSTP#$$#Starts creating the ws client: FirmSTP
        {code}
        Hide
        Remko Popma added a comment -

        Quick thing to try: replace your filePattern property with

        ${sys:logfilepath}//$${date:yyyy-MM}//${sys:oft.appserver}-out-$${date:yyyy-MM-dd}.log
        
        Show
        Remko Popma added a comment - Quick thing to try: replace your filePattern property with ${sys:logfilepath} //$${date:yyyy-MM}//${sys:oft.appserver}-out-$${date:yyyy-MM-dd}.log
        Hide
        Ralph Goers added a comment -

        Remko, that won't work. There has to be a %date for the TimeBasedTriggeringPolicy to know when to rollover.

        I'd like to know how many log records are in the file with dates after 05-19. If there are less than 15 then this is "normal"

        Show
        Ralph Goers added a comment - Remko, that won't work. There has to be a %date for the TimeBasedTriggeringPolicy to know when to rollover. I'd like to know how many log records are in the file with dates after 05-19. If there are less than 15 then this is "normal"
        Hide
        sivan added a comment - - edited

        For example out-2014-05-18 file contains full of log entries with 19th date. The requirement is one file for each day and the file should contain only the log entries on that day.

        Today is 05/20. But files created on 05/16 and 05/19 are still there and they haven't roll backed to the folder 2014-05.

        How can we specify when to rollover in the TimeBasedTriggeringPolicy for each day?

        Show
        sivan added a comment - - edited For example out-2014-05-18 file contains full of log entries with 19th date. The requirement is one file for each day and the file should contain only the log entries on that day. Today is 05/20. But files created on 05/16 and 05/19 are still there and they haven't roll backed to the folder 2014-05. How can we specify when to rollover in the TimeBasedTriggeringPolicy for each day?
        Hide
        sivan added a comment -

        Today is 05/20. But files created on 05/16 and 05/19 are still there and they haven't roll backed to the folder 2014-05.

        Show
        sivan added a comment - Today is 05/20. But files created on 05/16 and 05/19 are still there and they haven't roll backed to the folder 2014-05.
        sivan made changes -
        Attachment logFolder.png [ 12645753 ]
        Hide
        Ralph Goers added a comment -

        I don't know what you mean by "roll backed" but I am guessing you mean "rolled over".

        If I understand you correctly you are complaining about 2 things:
        1. A file dated 2014-05-18 has logs for 2014-05-19.
        2. Log files are not being placed in the correct directory during rollover. I am not clear where the files on 05/16 and 05/19 ended up and what their names were.

        You also don't state what version you are using and whether you have tried the latest in trunk.

        Your configuration looks correct for a daily rollover so this would seem to be a bug, unless other things are going on that you haven't mentioned,

        Show
        Ralph Goers added a comment - I don't know what you mean by "roll backed" but I am guessing you mean "rolled over". If I understand you correctly you are complaining about 2 things: 1. A file dated 2014-05-18 has logs for 2014-05-19. 2. Log files are not being placed in the correct directory during rollover. I am not clear where the files on 05/16 and 05/19 ended up and what their names were. You also don't state what version you are using and whether you have tried the latest in trunk. Your configuration looks correct for a daily rollover so this would seem to be a bug, unless other things are going on that you haven't mentioned,
        Ralph Goers made changes -
        Summary Mismatch in Rollback date and log entry date in the log file Mismatch in Rollover date and log entry date in the log file
        Hide
        sivan added a comment - - edited

        Yes i meant Rolled Over.

        I am complaining on the first point only. Second point is working fine.

        Today is 05/20. But files created on 05/16 and 05/19 are still there and they haven't rolled over to the folder 2014-05.

        Can you please look at the attached image?

        I am using log4j-api-2.0-rc1.jar and log4j-core-2.0-rc1.jar files.

        Please advise how can we specify when to rollover in the TimeBasedTriggeringPolicy for each day?

        Show
        sivan added a comment - - edited Yes i meant Rolled Over. I am complaining on the first point only. Second point is working fine. Today is 05/20. But files created on 05/16 and 05/19 are still there and they haven't rolled over to the folder 2014-05. Can you please look at the attached image? I am using log4j-api-2.0-rc1.jar and log4j-core-2.0-rc1.jar files. Please advise how can we specify when to rollover in the TimeBasedTriggeringPolicy for each day?
        Hide
        Ralph Goers added a comment -

        Inst1-out has no log events as it's file size is zero. Rollover is only checked every 16 log events so that will only happen when your application logs something.

        Is the listing showing the create date or last modified time (which is what is normally displayed). If it is the last modified time then the other file is also waiting for log events to trigger a rollover.

        Show
        Ralph Goers added a comment - Inst1-out has no log events as it's file size is zero. Rollover is only checked every 16 log events so that will only happen when your application logs something. Is the listing showing the create date or last modified time (which is what is normally displayed). If it is the last modified time then the other file is also waiting for log events to trigger a rollover.
        Hide
        sivan added a comment -

        How the rolled log file on 05/18 contains the entries of 05/19?

        Show
        sivan added a comment - How the rolled log file on 05/18 contains the entries of 05/19?
        sivan made changes -
        Attachment rolledLogFile.png [ 12645794 ]
        Hide
        sivan added a comment - - edited

        Yes, the list is showing the last modified date and the other files are waiting for the rollover.

        But how the rolled log file on 05/18 contains the entries of 05/19?

        Please take a look on the attached image.

        05/18 is Sunday and on that day I think there is no log entries and the file size was 0 bytes. 05/19 is Monday and starts logging in the same file for some time and rolled over as 'ape1-out-2014-05-18' and creates a new file for 05/19. This new file contains the entries for only 05/19 and rolled over as 'ape1-out-2014-05-19'.

        Also the application has been restarted two times after the patch build has been deployed. Is anything we need to do for log4j2 in such situations like calling any clear method or stop method etc..

        Can you please go through this scenarios and advise me on this issue?

        Show
        sivan added a comment - - edited Yes, the list is showing the last modified date and the other files are waiting for the rollover. But how the rolled log file on 05/18 contains the entries of 05/19? Please take a look on the attached image. 05/18 is Sunday and on that day I think there is no log entries and the file size was 0 bytes. 05/19 is Monday and starts logging in the same file for some time and rolled over as 'ape1-out-2014-05-18' and creates a new file for 05/19. This new file contains the entries for only 05/19 and rolled over as 'ape1-out-2014-05-19'. Also the application has been restarted two times after the patch build has been deployed. Is anything we need to do for log4j2 in such situations like calling any clear method or stop method etc.. Can you please go through this scenarios and advise me on this issue?
        Hide
        sivan added a comment - - edited

        This issue is happening on daily basis.
        Can any body give assistance on this issue?
        Please find the attachment.

        Show
        sivan added a comment - - edited This issue is happening on daily basis. Can any body give assistance on this issue? Please find the attachment.
        Hide
        sivan added a comment -

        This is happening on daily basis. Please find the attachment.

        Show
        sivan added a comment - This is happening on daily basis. Please find the attachment.
        sivan made changes -
        Attachment rolloverFile.png [ 12646276 ]
        Hide
        sivan added a comment -

        This issue seems resolved. I removed the <SizeBasedTriggeringPolicy /> from the configuration.

        Show
        sivan added a comment - This issue seems resolved. I removed the <SizeBasedTriggeringPolicy /> from the configuration.
        Hide
        sivan added a comment -

        This issue seems resolved. I removed the <SizeBasedTriggeringPolicy /> from the configuration.

        Show
        sivan added a comment - This issue seems resolved. I removed the <SizeBasedTriggeringPolicy /> from the configuration.
        sivan made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s 2.0-rc1 [ 12325011 ]
        Resolution Fixed [ 1 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        7d 29m 1 sivan 27/May/14 06:58

          People

          • Assignee:
            Unassigned
            Reporter:
            sivan
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development