Log4j 2
  1. Log4j 2
  2. LOG4J2-535

Rolled log files end up in the wrong directory

    Details

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

      Ubuntu 12.04 and 13.04, java version "1.7.0_51"

      Description

      Follow-up for issue LOG4J2-531: the main issue (rolled over archives were overwritten) was resolved but the solution brought to light another issue that is tracked here:

      The distribution of the log files into the folders is odd and it feels like there might be a flaw in the timestamp logic in there somewhere still.

      Test program to reproduce the issue:

      import org.apache.logging.log4j.LogManager;
      import org.apache.logging.log4j.Logger;
      
      public class LogTest {
          private static final Logger logger = LogManager.getLogger("TestLogger");
      
          public static void main(String[] args) throws Exception {
              for (long i=0; ; i+=1) {
                  logger.debug("Sequence: " + i);
                  Thread.sleep(250);
              }
          }
      }
      

      Sample configuration for LOG4J2-531:

      <?xml version="1.0" encoding="UTF-8"?>
      <Configuration>
          <Appenders>
              <RollingFile name="Test" fileName="logs/test.log" filePattern="logs/test/$${date:yyyyMMddHHmm}/TEST-%d{yyyyMMddHHmm}-%i.log.gz">
                  <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
                  <Policies>
                      <TimeBasedTriggeringPolicy />
                      <SizeBasedTriggeringPolicy size="1 KB"/>
                  </Policies>
                  <DefaultRolloverStrategy max="999999"/>
              </RollingFile>
          </Appenders>
          <Loggers>
              <Root level="debug">
                  <AppenderRef ref="Test"/>
              </Root>
          </Loggers>
      </Configuration>
      

      I kicked off the test run at 14:29:11 using my example setup from the first post above more or less as is - but with a more sensible max=99.

      The initial folder created was 201402101429 and contained 27 numbered files prefixed TEST-201402101429-. Numbers 1-12 contained 16 log lines each with timestamps 14:29:11,667 to 14:29:59,649, number 13 a single log line with timestamp 14:29:59,899, and numbers 14-27 again contain 16 lines each with timestamps 14:30:00,164 to 14:30:56,155.

      The second folder created was 201402101430 and contained 15 numbered files. The first file contained 15 log lines with timestamps 14:30:56,405 to 14:30:59,919. The subsequent files contained 16 log lines each with timestamps 14:31:00,170 to 14:31:56,123.

      The third folder created was 201402101431. The first file contained 15 log lines with timestamps 14:31:56,373 to 14:31:59,886. The subsequent files contained 16 log lines each with timestamps from 14:32:00,136 onwards.

      So in summary after the first minute the majority of log lines from minute X end up in the folder for minute X-1. The exception are the last file of lines which end up in the correct folder.


      This happens with longer rollover periods as well:


      Sample configuration based on that for LOG4J2-531, adjusted to roll every hour and every 64kb (i.e. expect similar number of files per folder):

      <?xml version="1.0" encoding="UTF-8"?>
      <Configuration>
          <Appenders>
              <RollingFile name="Test" fileName="logs/test.log" filePattern="logs/test/$${date:yyyyMMddHH}/TEST-%d{yyyyMMddHH}-%i.log.gz">
                  <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
                  <Policies>
                      <TimeBasedTriggeringPolicy />
                      <SizeBasedTriggeringPolicy size="64 KB"/>
                  </Policies>
                  <DefaultRolloverStrategy max="99"/>
              </RollingFile>
          </Appenders>
          <Loggers>
              <Root level="debug">
                  <AppenderRef ref="Test"/>
              </Root>
          </Loggers>
      </Configuration>
      

      Running this overnight gave a similar pattern, e.g. the folder for 2014021100 contains one file with timestamps 00:59:42,836 to 00:59:59,851, and then 15 others covering timestamps 01:00:00,101 to 01:59:24,196. Only the last file's worth for each hour (the one rotated based on time) is in the correct folder, and the rest (rotated based on size) are in the previous hour's folder.

        Issue Links

          Activity

          Remko Popma created issue -
          Remko Popma made changes -
          Field Original Value New Value
          Link This issue is related to LOG4J2-531 [ LOG4J2-531 ]
          Remko Popma made changes -
          Description Follow-up for issue LOG4J2-531: the main issue (rolled over archives were overwritten) was resolved but the solution brought to light another issue that is tracked here.

          Sample configuration based on that for LOG4J2-531, adjusted to roll every hour and every 64kb (i.e. expect similar number of files per folder):

          {code:xml}
          <?xml version="1.0" encoding="UTF-8"?>
          <Configuration>
              <Appenders>
                  <RollingFile name="Test" fileName="logs/test.log" filePattern="logs/test/$${date:yyyyMMddHH}/TEST-%d{yyyyMMddHH}-%i.log.gz">
                      <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
                      <Policies>
                          <TimeBasedTriggeringPolicy />
                          <SizeBasedTriggeringPolicy size="64 KB"/>
                      </Policies>
                      <DefaultRolloverStrategy max="99"/>
                  </RollingFile>
              </Appenders>
              <Loggers>
                  <Root level="debug">
                      <AppenderRef ref="Test"/>
                  </Root>
              </Loggers>
          </Configuration>
          {code}

          Running this overnight gave a similar pattern, e.g. the folder for {{2014021100}} contains one file with timestamps {{00:59:42,836}} to {{00:59:59,851}}, and then 15 others covering timestamps {{01:00:00,101}} to {{01:59:24,196}}. Only the last file's worth for each hour (the one rotated based on time) is in the correct folder, and the rest (rotated based on size) are in the previous hour's folder.
          Follow-up for issue LOG4J2-531: the main issue (rolled over archives were overwritten) was resolved but the solution brought to light another issue that is tracked here:

          The distribution of the log files into the folders is odd and it feels like there might be a flaw in the timestamp logic in there somewhere still.

          Test program to reproduce the issue:
          {code}
          import org.apache.logging.log4j.LogManager;
          import org.apache.logging.log4j.Logger;

          public class LogTest {
              private static final Logger logger = LogManager.getLogger("TestLogger");

              public static void main(String[] args) throws Exception {
                  for (long i=0; ; i+=1) {
                      logger.debug("Sequence: " + i);
                      Thread.sleep(250);
                  }
              }
          }
          {code}

          Sample configuration for LOG4J2-531:
          {code}
          <?xml version="1.0" encoding="UTF-8"?>
          <Configuration>
              <Appenders>
                  <RollingFile name="Test" fileName="logs/test.log" filePattern="logs/test/$${date:yyyyMMddHHmm}/TEST-%d{yyyyMMddHHmm}-%i.log.gz">
                      <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
                      <Policies>
                          <TimeBasedTriggeringPolicy />
                          <SizeBasedTriggeringPolicy size="1 KB"/>
                      </Policies>
                      <DefaultRolloverStrategy max="999999"/>
                  </RollingFile>
              </Appenders>
              <Loggers>
                  <Root level="debug">
                      <AppenderRef ref="Test"/>
                  </Root>
              </Loggers>
          </Configuration>
          {code}

          I kicked off the test run at {{14:29:11}} using my example setup from the first post above more or less as is - but with a more sensible {{max=99}}.

          The initial folder created was {{201402101429}} and contained 27 numbered files prefixed {{TEST-201402101429-}}. Numbers 1-12 contained 16 log lines each with timestamps {{14:29:11,667}} to {{14:29:59,649}}, number 13 a single log line with timestamp {{14:29:59,899}}, and numbers 14-27 again contain 16 lines each with timestamps {{14:30:00,164}} to {{14:30:56,155}}.

          The second folder created was {{201402101430}} and contained 15 numbered files. The first file contained 15 log lines with timestamps {{14:30:56,405}} to {{14:30:59,919}}. The subsequent files contained 16 log lines each with timestamps {{14:31:00,170}} to {{14:31:56,123}}.

          The third folder created was {{201402101431}}. The first file contained 15 log lines with timestamps {{14:31:56,373}} to {{14:31:59,886}}. The subsequent files contained 16 log lines each with timestamps from {{14:32:00,136}} onwards.

          So in summary after the first minute the majority of log lines from minute X end up in the folder for minute X-1. The exception are the last file of lines which end up in the correct folder.
          ----
          This happens with longer rollover periods as well:
          ----
          Sample configuration based on that for LOG4J2-531, adjusted to roll every hour and every 64kb (i.e. expect similar number of files per folder):

          {code:xml}
          <?xml version="1.0" encoding="UTF-8"?>
          <Configuration>
              <Appenders>
                  <RollingFile name="Test" fileName="logs/test.log" filePattern="logs/test/$${date:yyyyMMddHH}/TEST-%d{yyyyMMddHH}-%i.log.gz">
                      <PatternLayout pattern="%d %p (%t) [%c] - %m%n"/>
                      <Policies>
                          <TimeBasedTriggeringPolicy />
                          <SizeBasedTriggeringPolicy size="64 KB"/>
                      </Policies>
                      <DefaultRolloverStrategy max="99"/>
                  </RollingFile>
              </Appenders>
              <Loggers>
                  <Root level="debug">
                      <AppenderRef ref="Test"/>
                  </Root>
              </Loggers>
          </Configuration>
          {code}

          Running this overnight gave a similar pattern, e.g. the folder for {{2014021100}} contains one file with timestamps {{00:59:42,836}} to {{00:59:59,851}}, and then 15 others covering timestamps {{01:00:00,101}} to {{01:59:24,196}}. Only the last file's worth for each hour (the one rotated based on time) is in the correct folder, and the rest (rotated based on size) are in the previous hour's folder.
          Ralph Goers made changes -
          Assignee Ralph Goers [ ralph.goers@dslextreme.com ]
          Ralph Goers made changes -
          Status Open [ 1 ] In Progress [ 3 ]
          Hide
          Ralph Goers added a comment -

          I have run your test and it definitely is not behaving as you would like.

          Show
          Ralph Goers added a comment - I have run your test and it definitely is not behaving as you would like.
          Hide
          Ralph Goers added a comment -

          When a time based rollover occurs the time is supposed to be for the previous time unit (in this case a second) since all the data would be for that time frame. from what I can tell this is working properly.

          When a size based rollover occurs it just takes the current filename and increments the counter. This causes a file to be created with a name containing the previous time unit and the counter incremented. This is really incorrect as the data is for the current time period.

          Show
          Ralph Goers added a comment - When a time based rollover occurs the time is supposed to be for the previous time unit (in this case a second) since all the data would be for that time frame. from what I can tell this is working properly. When a size based rollover occurs it just takes the current filename and increments the counter. This causes a file to be created with a name containing the previous time unit and the counter incremented. This is really incorrect as the data is for the current time period.
          Hide
          Ralph Goers added a comment -

          The size based triggering policy now causes the file time to update which now seems to have the test program behaving correctly. Please verify and close.

          Show
          Ralph Goers added a comment - The size based triggering policy now causes the file time to update which now seems to have the test program behaving correctly. Please verify and close.
          Ralph Goers made changes -
          Status In Progress [ 3 ] Resolved [ 5 ]
          Fix Version/s 2.0-rc2 [ 12326292 ]
          Resolution Fixed [ 1 ]
          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open In Progress In Progress
          18d 9h 12m 1 Ralph Goers 01/Mar/14 19:59
          In Progress In Progress Resolved Resolved
          98d 2h 45m 1 Ralph Goers 07/Jun/14 23:45

            People

            • Assignee:
              Ralph Goers
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development