Log4j 2
  1. Log4j 2
  2. LOG4J2-116

RollingFileAppender archives have wrong date values

    Details

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

      Description

      Suppose I have an appender configured like so:

      <RollingFile name="test"
      fileName="logs/test"
      filePattern="logs/test.%d

      {yyyy-MM-dd}

      ">
      <PatternLayout pattern="%d

      {yyyy-MM-dd HH:mm:ss.SSS}

      %-5level %message%n"/>
      <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
      </RollingFile>

      Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

      I create several logging events today, and as expected they end up in a file named "logs/test"

      Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

      What I expect to see after this is:
      logs/test
      logs/test.2012-11-13

      What I actually end up seeing is:
      logs/test
      logs/test.2012-11-14

      So the archived entries of the 13th are in a file name matching the 14th. That is quite confusing!

      I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always higher than expected.

      I traced through the code, and the culprit seems to be in PatternProcessor:

      protected final void formatFileName(final Object obj, final StringBuilder buf) {
      Object[] objects = new Object[]

      {new Date(System.currentTimeMillis()), obj}

      ;
      formatFileName(objects, buf);
      }

      So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

      In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th, which is what I'd get.

        Activity

        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        5d 4h 18m 1 Ralph Goers 19/Nov/12 03:24
        Hide
        Peter Pizza added a comment -

        This still seems to be an issue in 2.1, or am I getting something wrong here?

        <RollingFile name="ROLLING" ... fileName="test.log" filePattern="test.log.%d{yyyyMMdd-HHmm}.gz">
            <PatternLayout pattern="..." />
            <OnStartupTriggeringPolicy />
        </RollingFile>
        

        I'd expect rolled files retain their original timestamp in the pattern, i.e. a log file created originally on Nov 24 and rolled over the following day be named something like test.log.20141124-....gz instead of test.log.20141125-....gz.

        Show
        Peter Pizza added a comment - This still seems to be an issue in 2.1, or am I getting something wrong here? <RollingFile name= "ROLLING" ... fileName= "test.log" filePattern= "test.log.%d{yyyyMMdd-HHmm}.gz" > <PatternLayout pattern= "..." /> <OnStartupTriggeringPolicy /> </RollingFile> I'd expect rolled files retain their original timestamp in the pattern, i.e. a log file created originally on Nov 24 and rolled over the following day be named something like test.log.201411 24 -....gz instead of test.log.201411 25 -....gz .
        Ralph Goers made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Assignee Ralph Goers [ ralph.goers@dslextreme.com ]
        Fix Version/s 2.0-beta4 [ 12323477 ]
        Resolution Fixed [ 1 ]
        Hide
        Ralph Goers added a comment -

        Fixed in revision 1411052. Please verify and close.

        Show
        Ralph Goers added a comment - Fixed in revision 1411052. Please verify and close.
        Hide
        Ralph Goers added a comment -

        I've actually known about this one for a while and it bothered me to, just not enough to fix it yet. It is annoying so I do intend to fix it.

        Show
        Ralph Goers added a comment - I've actually known about this one for a while and it bothered me to, just not enough to fix it yet. It is annoying so I do intend to fix it.
        David Johle made changes -
        Description Suppose I have an appender configured like so:

        <RollingFile name="test"
                     fileName="logs/test"
                     filePattern="logs/test.%d{yyyy-MM-dd}">
          <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %message%n"/>
          <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </RollingFile>


        Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

        I create several logging events today, and as expected they end up in a file named "logs/test"

        Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

        What I expect to see after this is:
        logs/test
        logs/test.2012-11-13

        What I actually end up seeing is:
        logs/test
        logs/test.2012-11-14

        So the archived entries of the 13th are in a file name matching the 14th. That is quite confusing!


        I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always higher than expected.

        I traced through the code, and the culprit seems to be in PatternProcessor:

            protected final void formatFileName(final Object obj, final StringBuilder buf) {
                Object[] objects = new Object[] {new Date(System.currentTimeMillis()), obj};
                formatFileName(objects, buf);
            }


        So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

        In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th.
        Suppose I have an appender configured like so:

        <RollingFile name="test"
                     fileName="logs/test"
                     filePattern="logs/test.%d{yyyy-MM-dd}">
          <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %message%n"/>
          <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </RollingFile>


        Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

        I create several logging events today, and as expected they end up in a file named "logs/test"

        Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

        What I expect to see after this is:
        logs/test
        logs/test.2012-11-13

        What I actually end up seeing is:
        logs/test
        logs/test.2012-11-14

        So the archived entries of the 13th are in a file name matching the 14th. That is quite confusing!


        I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always higher than expected.

        I traced through the code, and the culprit seems to be in PatternProcessor:

            protected final void formatFileName(final Object obj, final StringBuilder buf) {
                Object[] objects = new Object[] {new Date(System.currentTimeMillis()), obj};
                formatFileName(objects, buf);
            }


        So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

        In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th, which is what I'd get.
        David Johle made changes -
        Description Suppose I have an appender configured like so:

        <RollingFile name="test"
                     fileName="logs/test"
                     filePattern="logs/test.%d{yyyy-MM-dd}">
          <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %message%n"/>
          <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </RollingFile>


        Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

        I create several logging events today, and as expected they end up in a file named "logs/test"

        Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

        What I expect to see after this is:
        logs/test
        logs/test.2012-11-13

        What I actually end up seeing is:
        logs/test
        logs/test.2012-11-14

        So the archived entries of the 13th are in a file name matching the 14th. That is quite confusing!


        I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always "1 higher" than expected.

        I traced through the code, and the culprit seems to be in PatternProcessor:

            protected final void formatFileName(final Object obj, final StringBuilder buf) {
                Object[] objects = new Object[] {new Date(System.currentTimeMillis()), obj};
                formatFileName(objects, buf);
            }


        So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

        In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th.
        Suppose I have an appender configured like so:

        <RollingFile name="test"
                     fileName="logs/test"
                     filePattern="logs/test.%d{yyyy-MM-dd}">
          <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %message%n"/>
          <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </RollingFile>


        Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

        I create several logging events today, and as expected they end up in a file named "logs/test"

        Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

        What I expect to see after this is:
        logs/test
        logs/test.2012-11-13

        What I actually end up seeing is:
        logs/test
        logs/test.2012-11-14

        So the archived entries of the 13th are in a file name matching the 14th. That is quite confusing!


        I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always higher than expected.

        I traced through the code, and the culprit seems to be in PatternProcessor:

            protected final void formatFileName(final Object obj, final StringBuilder buf) {
                Object[] objects = new Object[] {new Date(System.currentTimeMillis()), obj};
                formatFileName(objects, buf);
            }


        So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

        In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th.
        David Johle made changes -
        Field Original Value New Value
        Description Suppose I have an appender configured like so:

        <RollingFile name="test"
                     fileName="logs/test"
                     filePattern="logs/test.%d{yyyy-MM-dd}">
          <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %message%n"/>
          <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </RollingFile>


        Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

        I create several logging events today, and as expected they end up in a file named "logs/test"

        Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

        What I expect to see after this is:
        logs/test
        logs/test.2012-11-13

        What I actually end up seeing is:
        logs/test
        logs/test.2012-11-14

        So the archived entries of the 13th are in a file name maching the 14th. That is quite confusing!


        I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always "1 higher" than expected.

        I traced through the code, and the culprit seems to be in PatternProcessor:

            protected final void formatFileName(final Object obj, final StringBuilder buf) {
                Object[] objects = new Object[] {new Date(System.currentTimeMillis()), obj};
                formatFileName(objects, buf);
            }


        So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

        In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th.
        Suppose I have an appender configured like so:

        <RollingFile name="test"
                     fileName="logs/test"
                     filePattern="logs/test.%d{yyyy-MM-dd}">
          <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %message%n"/>
          <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </RollingFile>


        Supposed today is 2012-11-13, and thus tomorrow is 2012-11-14.

        I create several logging events today, and as expected they end up in a file named "logs/test"

        Midnight goes by, and it is now the 14th. Some more logging events occur around 12:01 am.

        What I expect to see after this is:
        logs/test
        logs/test.2012-11-13

        What I actually end up seeing is:
        logs/test
        logs/test.2012-11-14

        So the archived entries of the 13th are in a file name matching the 14th. That is quite confusing!


        I tested this with some other formats, and it seems that no matter what is the most specific (day, hour, minute, etc.) field, it is always "1 higher" than expected.

        I traced through the code, and the culprit seems to be in PatternProcessor:

            protected final void formatFileName(final Object obj, final StringBuilder buf) {
                Object[] objects = new Object[] {new Date(System.currentTimeMillis()), obj};
                formatFileName(objects, buf);
            }


        So the Date being used for the filename is the current time when the name is computed, which is guaranteed to be within an interval that is after the one of the file contents. If I went a copule of intervals (in this case days) without log events, then it could be stamped with a name that is several days after the contents.

        In the latter case, I'm not sure if I'd expect to see a filename with the 13th still, or maybe the 15th (assuming rollover happened during the 16th). But in either case, I definitely don't expect to see a filename with the 16th.
        David Johle created issue -

          People

          • Assignee:
            Ralph Goers
            Reporter:
            David Johle
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development