Details

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

      Java 1.7.0_25, Windows 7 64bit, IntelliJ IDEA 12 Ultimate

      Description

      Attempting to use FastRollingFile appender and configure log file rollover to occur monthly. When filePattern="logs/app-%d{yyyy-MM}.log.gz" is used, at application startup an archive file is created immediately (app-2013-01.log.gz) even if no log previously existed. A log file is created, but only a single entry is made into the log.

      1. LOG4J2-385.patch
        1 kB
        Porfirio Partida

        Activity

        Hide
        Porfirio Partida added a comment -

        Seems that it is triggering the rollover but it erases instead of back up the log as it does with daily backups.

        Show
        Porfirio Partida added a comment - Seems that it is triggering the rollover but it erases instead of back up the log as it does with daily backups.
        Hide
        Porfirio Partida added a comment - - edited

        org.apache.logging.log4j.core.appender.rolling.PatternProcessor
        Method: getNextTime(long, int, boolean)

        It has issues logging Monthly because it detects the next variables:

         
                final Calendar currentCal = Calendar.getInstance();
                currentCal.setTimeInMillis(current);
                final Calendar cal = Calendar.getInstance();
                cal.set(currentCal.get(Calendar.YEAR), 0, 1, 0, 0, 0);  // inits with current year
                cal.set(Calendar.MILLISECOND, 0);
        ....
        
                if (frequency == RolloverFrequency.MONTHLY) {
                    increment(cal, Calendar.MONTH, increment, modulus);
                    nextTime = cal.getTimeInMillis();
                    cal.add(Calendar.MONTH, -1);
                    nextFileTime = cal.getTimeInMillis();
                    // Running on September the 17th (it doesn't matter the date)
                    //   nextFileTime : 1357023600000 - Tue Jan 01 00:00:00 GMT-07:00 2013 //Only year is added
                    //   nextTime : 1359702000000 - Fri Feb 01 00:00:00 GMT-07:00 2013 //Moving from Jan to Feb
                    return nextTime;
                }
        ...
        
        //Why is daily working then? because right after Monthly we have weekly (it should be failing as well) and then daily comes as this:
        
        ...
                //Next line is going to point to current date to determine the very next lookup.
                cal.set(Calendar.DAY_OF_YEAR, currentCal.get(Calendar.DAY_OF_YEAR)); 
                if (frequency == RolloverFrequency.DAILY) {
                    increment(cal, Calendar.DAY_OF_YEAR, increment, modulus);
                    nextTime = cal.getTimeInMillis();
                    cal.add(Calendar.DAY_OF_YEAR, -1);
                    nextFileTime = cal.getTimeInMillis();
                    return nextTime;
                }
        ...
        

        In order to fix, we could move the line

            cal.set(Calendar.DAY_OF_YEAR, currentCal.get(Calendar.DAY_OF_YEAR)); 

        to the top (before Year) and remove the elements as needed inside each if statement, ie:

        • remove month, day, time inside year
        • remove day and time inside month
        • remove time inside daily
          etc..

        OR

        we can set current month at month level and add the week at week level, like this:

         
                if (frequency == RolloverFrequency.MONTHLY) {
        +           cal.set(Calendar.MONTH, currentCal.get(Calendar.MONTH)); //moves the date to today's month.
                    increment(cal, Calendar.MONTH, increment, modulus);
                    nextTime = cal.getTimeInMillis();
                    cal.add(Calendar.MONTH, -1);
                    nextFileTime = cal.getTimeInMillis();
                    return nextTime;
                }
                if (frequency == RolloverFrequency.WEEKLY) {
        +           cal.set(Calendar.WEEK_OF_YEAR, currentCal.get(Calendar.WEEK_OF_YEAR));//moves the week.
                    ....
        
        Show
        Porfirio Partida added a comment - - edited org.apache.logging.log4j.core.appender.rolling.PatternProcessor Method: getNextTime(long, int, boolean) It has issues logging Monthly because it detects the next variables: final Calendar currentCal = Calendar.getInstance(); currentCal.setTimeInMillis(current); final Calendar cal = Calendar.getInstance(); cal.set(currentCal.get(Calendar.YEAR), 0, 1, 0, 0, 0); // inits with current year cal.set(Calendar.MILLISECOND, 0); .... if (frequency == RolloverFrequency.MONTHLY) { increment(cal, Calendar.MONTH, increment, modulus); nextTime = cal.getTimeInMillis(); cal.add(Calendar.MONTH, -1); nextFileTime = cal.getTimeInMillis(); // Running on September the 17th (it doesn't matter the date) // nextFileTime : 1357023600000 - Tue Jan 01 00:00:00 GMT-07:00 2013 //Only year is added // nextTime : 1359702000000 - Fri Feb 01 00:00:00 GMT-07:00 2013 //Moving from Jan to Feb return nextTime; } ... //Why is daily working then? because right after Monthly we have weekly (it should be failing as well) and then daily comes as this : ... //Next line is going to point to current date to determine the very next lookup. cal.set(Calendar.DAY_OF_YEAR, currentCal.get(Calendar.DAY_OF_YEAR)); if (frequency == RolloverFrequency.DAILY) { increment(cal, Calendar.DAY_OF_YEAR, increment, modulus); nextTime = cal.getTimeInMillis(); cal.add(Calendar.DAY_OF_YEAR, -1); nextFileTime = cal.getTimeInMillis(); return nextTime; } ... In order to fix, we could move the line cal.set(Calendar.DAY_OF_YEAR, currentCal.get(Calendar.DAY_OF_YEAR)); to the top (before Year) and remove the elements as needed inside each if statement, ie: remove month, day, time inside year remove day and time inside month remove time inside daily etc.. OR we can set current month at month level and add the week at week level, like this: if (frequency == RolloverFrequency.MONTHLY) { + cal.set(Calendar.MONTH, currentCal.get(Calendar.MONTH)); //moves the date to today's month. increment(cal, Calendar.MONTH, increment, modulus); nextTime = cal.getTimeInMillis(); cal.add(Calendar.MONTH, -1); nextFileTime = cal.getTimeInMillis(); return nextTime; } if (frequency == RolloverFrequency.WEEKLY) { + cal.set(Calendar.WEEK_OF_YEAR, currentCal.get(Calendar.WEEK_OF_YEAR)); //moves the week. ....
        Hide
        Porfirio Partida added a comment -

        Attaching patch that fixes the issue, please review and check in, thanks.

        Show
        Porfirio Partida added a comment - Attaching patch that fixes the issue, please review and check in, thanks.
        Hide
        Remko Popma added a comment - - edited

        Team, what is the spec for rollover?

        • Starting Oct 15, given monthly rollover, do we expect Nov 15 (add 1 month), or Nov 1st (1st day of next month)? (And what time?)
        • Starting Tue March 4th, given weekly rollover, do we expect Tue March 11th (add 1 week)? (And what time?)
        • Starting Tue March 4th 10:31, given hourly rollover, do we expect Tue March 4th 11:31 (add 1 hour) or Tue March 4th 11:00 (1st minute of next hour)? (And do we truncate seconds/millis?)

        PatternProcessor.getNextTime() currently gives interesting answers to these questions (yyyy/MM/dd format):

        1. Monthly rollover from 2014/01/31 gives 2014/02/01
        2. Monthly rollover from 2014/10/15 gives 2014/02/01
        3. Weekly rollover from 2014/03/4 Tue gives 2014/01/08 Wed
        4. Hourly rollover from 2014/03/04 10:31 gives 2014/03/04 11:00

        Some JUnit tests:

        @Test
        public void testGetNextTimeMonthlyAddsOneMonthToSpecifiedTime() {
            PatternProcessor pp = new PatternProcessor("logs/app-%d{yyyy-MM}.log.gz");
            Calendar initial = Calendar.getInstance();
            initial.set(2014, 9, 15, 10, 31, 59); // Oct 15th
            long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
            
            // Do we expect 1st day of next month?
            // Or do we add 1 month, and expect Nov 15?
            Calendar expected = Calendar.getInstance();
            expected.set(2014, 10, 15, 0, 0, 00);
            expected.set(Calendar.MILLISECOND, 0);
            assertEquals(format(expected.getTimeInMillis()), format(actual));
        }
        
        @Test
        public void testGetNextTimeMonthlyAddsOneMonthOnLastDayOfMonth() {
            PatternProcessor pp = new PatternProcessor("logs/app-%d{yyyy-MM}.log.gz");
            Calendar initial = Calendar.getInstance();
            initial.set(2014, 0, 31, 10, 31, 59); // 2014 Jan 31st
            long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
            
            // Expect last day of next month: 2014 Feb 28th
            Calendar expected = Calendar.getInstance();
            expected.set(2014, 1, 28, 0, 0, 00);
            expected.set(Calendar.MILLISECOND, 0);
            assertEquals(format(expected.getTimeInMillis()), format(actual));
        }
        
        @Test
        public void testGetNextTimeWeeklyAddsOneWeekToSpecifiedTime() {
            PatternProcessor pp = new PatternProcessor("logs/app-%d{yyyy-MM-W}.log.gz");
            Calendar initial = Calendar.getInstance();
            initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014
            long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
            
            // expect Tue, March 11, 2014 (one week later)
            Calendar expected = Calendar.getInstance();
            expected.set(2014, 2, 11, 0, 0, 00);
            expected.set(Calendar.MILLISECOND, 0);
            assertEquals(format(expected.getTimeInMillis()), format(actual));
        }
        
        @Test
        public void testGetNextTimeHourlyAddsOneHourToSpecifiedTime() {
            PatternProcessor pp = new PatternProcessor("logs/app-%d{yyyy-MM-dd-HH}.log.gz");
            Calendar initial = Calendar.getInstance();
            initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014, 10:31
            long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
            
            // expect Wed, March 4, 2014, 11:31 (one hour later)
            Calendar expected = Calendar.getInstance();
            expected.set(2014, 2, 4, 11, 31, 00);
            expected.set(Calendar.MILLISECOND, 0);
            assertEquals(format(expected.getTimeInMillis()), format(actual));
        }
        
        private String format(long time) {
            String actualStr = new SimpleDateFormat("yyyy/MM/dd HH:mm:ss.SSS").format(new Date(time));
            return actualStr;
        }
        
        Show
        Remko Popma added a comment - - edited Team, what is the spec for rollover? Starting Oct 15, given monthly rollover, do we expect Nov 15 (add 1 month), or Nov 1st (1st day of next month)? (And what time?) Starting Tue March 4th, given weekly rollover, do we expect Tue March 11th (add 1 week)? (And what time?) Starting Tue March 4th 10:31, given hourly rollover, do we expect Tue March 4th 11:31 (add 1 hour) or Tue March 4th 11:00 (1st minute of next hour)? (And do we truncate seconds/millis?) PatternProcessor.getNextTime() currently gives interesting answers to these questions (yyyy/MM/dd format): Monthly rollover from 2014/01/31 gives 2014/02/ 01 Monthly rollover from 2014/10/15 gives 2014/ 02/01 Weekly rollover from 2014/03/4 Tue gives 2014/ 01/08 Wed Hourly rollover from 2014/03/04 10:31 gives 2014/03/04 11: 00 Some JUnit tests: @Test public void testGetNextTimeMonthlyAddsOneMonthToSpecifiedTime() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 9, 15, 10, 31, 59); // Oct 15th long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // Do we expect 1st day of next month? // Or do we add 1 month, and expect Nov 15? Calendar expected = Calendar.getInstance(); expected.set(2014, 10, 15, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } @Test public void testGetNextTimeMonthlyAddsOneMonthOnLastDayOfMonth() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 0, 31, 10, 31, 59); // 2014 Jan 31st long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // Expect last day of next month: 2014 Feb 28th Calendar expected = Calendar.getInstance(); expected.set(2014, 1, 28, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } @Test public void testGetNextTimeWeeklyAddsOneWeekToSpecifiedTime() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM-W}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014 long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // expect Tue, March 11, 2014 (one week later) Calendar expected = Calendar.getInstance(); expected.set(2014, 2, 11, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } @Test public void testGetNextTimeHourlyAddsOneHourToSpecifiedTime() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM-dd-HH}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014, 10:31 long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // expect Wed, March 4, 2014, 11:31 (one hour later) Calendar expected = Calendar.getInstance(); expected.set(2014, 2, 4, 11, 31, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } private String format( long time) { String actualStr = new SimpleDateFormat( "yyyy/MM/dd HH:mm:ss.SSS" ).format( new Date(time)); return actualStr; }
        Hide
        Gary Gregory added a comment - - edited

        I am wondering about following a standard like cron...

        Maybe even having a cron Quartz-based rollover policy as an additional (heavy) component.

        Show
        Gary Gregory added a comment - - edited I am wondering about following a standard like cron... Maybe even having a cron Quartz-based rollover policy as an additional (heavy) component.
        Hide
        Matt Sicker added a comment -

        Speaking of Quartz, another way to give that sort of feature is through the Jave EE Timer service for EJB as described in the tutorial. I also +1 the cron idea.

        Show
        Matt Sicker added a comment - Speaking of Quartz, another way to give that sort of feature is through the Jave EE Timer service for EJB as described in the tutorial . I also +1 the cron idea.
        Hide
        Remko Popma added a comment - - edited

        What do Log4j-1.2 and Logback do in the above scenarios? Considering easy migration, we probably want to follow them (unless they do something very strange...)

        Edit:
        To answer my own question:

        • Monthly rollover occurs at the beginning of each month.
        • Weekly rollover occurs at the first day of each week. The first day of the week depends on the locale.
        • Daily rollover occurs at midnight each day.
        • Log4J-1.2 also has an option to rollover both at midnight and at noon during the day, so twice each day.
        • Hourly rollover occurs at the beginning of each hour.
        • Minutely rollover occurs at the beginning of each minute.

        http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/DailyRollingFileAppender.html
        http://logback.qos.ch/manual/appenders.html#TimeBasedRollingPolicy

        Show
        Remko Popma added a comment - - edited What do Log4j-1.2 and Logback do in the above scenarios? Considering easy migration, we probably want to follow them (unless they do something very strange...) Edit: To answer my own question: Monthly rollover occurs at the beginning of each month. Weekly rollover occurs at the first day of each week. The first day of the week depends on the locale. Daily rollover occurs at midnight each day. Log4J-1.2 also has an option to rollover both at midnight and at noon during the day, so twice each day. Hourly rollover occurs at the beginning of each hour. Minutely rollover occurs at the beginning of each minute. http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/DailyRollingFileAppender.html http://logback.qos.ch/manual/appenders.html#TimeBasedRollingPolicy
        Hide
        Remko Popma added a comment -

        Cron... to be honest, I know it is a standard, but I really dislike the format... It "makes me think", every time I look at a crontab. I can't just "grok" what it says, I always have to think twice about it...

        However, the predefined values like @hourly, @weekly are very nice. I would like to be able to use those...

        At the moment the "${yyyy-W}" pattern does double duty: it determine the rollover frequency, and it also lets the user determine (to some limited degree) how the resulting file will be named after the rollover.

        Instead of asking the user to specify a pattern for the rename, we could use a fixed renaming rule:

        • filepattern="/logs/mylog_${@yearly}.log.gz" -> rollover once a year at midnight in the morning of January 1. Rename format is fixed "yyyy". E.g. on Jan 1, 2014, the old log file is renamed to /logs/mylog_2013.log.gz
        • filepattern="/logs/mylog_${@monthly}.log.gz" -> rollover once a month at midnight in the morning of the first day of the month. Rename format is fixed "yyyy-MM". E.g. on Feb 1, 2014, the old log file is renamed to /logs/mylog_2013-01.log.gz
        • filepattern="/logs/mylog_${@weekly}.log.gz" -> once a week at midnight the (locale-dependent) first day of the week. Rename format is fixed "yyyy-MM-dd". E.g. on Feb 2, 2014, the old log file is renamed to /logs/mylog_2013-01-26.log.gz
        • filepattern="/logs/mylog_${@daily}.log.gz" -> once a day at midnight. Rename format is fixed "yyyy-MM-dd". E.g. on Feb 1, 2014, the old log file is renamed to /logs/mylog_2013-01-31.log.gz
        • filepattern="/logs/mylog_${@hourly}.log.gz" -> once an hour at the beginning of the hour. Rename format is fixed "yyyy-MM-dd_HH". E.g. on Feb 1, 2014, 10:00 the old log file is renamed to /logs/mylog_2013-02-01_09.log.gz
        • filepattern="/logs/mylog_${@minutely}.log.gz" -> once a minute at the beginning of the minute. Rename format is fixed "yyyy-MM-dd_HH-mm". E.g. on Feb 1, 2014, 10:03 the old log file is renamed to /logs/mylog_2013-02-01_10-02.log.gz

        Thoughts?

        I would not like to ask users to use this type of cron format below:

         #  *  *  *  *  *  command to execute
         # ┬ ┬ ┬ ┬ ┬
         # │ │ │ │ │
         # │ │ │ │ │
         # │ │ │ │ └───── day of week (0 - 7) (0 to 6 are Sunday to Saturday, or use names; 7 is Sunday, the same as 0)
         # │ │ │ └────────── month (1 - 12)
         # │ │ └─────────────── day of month (1 - 31)
         # │ └──────────────────── hour (0 - 23)
         # └───────────────────────── min (0 - 59)
        
        Show
        Remko Popma added a comment - Cron... to be honest, I know it is a standard, but I really dislike the format... It "makes me think", every time I look at a crontab. I can't just "grok" what it says, I always have to think twice about it... However, the predefined values like @hourly , @weekly are very nice. I would like to be able to use those... At the moment the "${yyyy-W}" pattern does double duty: it determine the rollover frequency, and it also lets the user determine (to some limited degree) how the resulting file will be named after the rollover. Instead of asking the user to specify a pattern for the rename, we could use a fixed renaming rule: filepattern="/logs/mylog_${@yearly}.log.gz" -> rollover once a year at midnight in the morning of January 1. Rename format is fixed "yyyy" . E.g. on Jan 1, 2014, the old log file is renamed to /logs/mylog_2013.log.gz filepattern="/logs/mylog_${@monthly}.log.gz" -> rollover once a month at midnight in the morning of the first day of the month. Rename format is fixed "yyyy-MM" . E.g. on Feb 1, 2014, the old log file is renamed to /logs/mylog_2013-01.log.gz filepattern="/logs/mylog_${@weekly}.log.gz" -> once a week at midnight the (locale-dependent) first day of the week. Rename format is fixed "yyyy-MM-dd" . E.g. on Feb 2, 2014, the old log file is renamed to /logs/mylog_2013-01-26.log.gz filepattern="/logs/mylog_${@daily}.log.gz" -> once a day at midnight. Rename format is fixed "yyyy-MM-dd" . E.g. on Feb 1, 2014, the old log file is renamed to /logs/mylog_2013-01-31.log.gz filepattern="/logs/mylog_${@hourly}.log.gz" -> once an hour at the beginning of the hour. Rename format is fixed "yyyy-MM-dd_HH" . E.g. on Feb 1, 2014, 10:00 the old log file is renamed to /logs/mylog_2013-02-01_09.log.gz filepattern="/logs/mylog_${@minutely}.log.gz" -> once a minute at the beginning of the minute. Rename format is fixed "yyyy-MM-dd_HH-mm" . E.g. on Feb 1, 2014, 10:03 the old log file is renamed to /logs/mylog_2013-02-01_10-02.log.gz Thoughts? I would not like to ask users to use this type of cron format below: # * * * * * command to execute # ┬ ┬ ┬ ┬ ┬ # │ │ │ │ │ # │ │ │ │ │ # │ │ │ │ └───── day of week (0 - 7) (0 to 6 are Sunday to Saturday, or use names; 7 is Sunday, the same as 0) # │ │ │ └────────── month (1 - 12) # │ │ └─────────────── day of month (1 - 31) # │ └──────────────────── hour (0 - 23) # └───────────────────────── min (0 - 59)
        Hide
        Remko Popma added a comment -

        After checking the behaviour of Log4J-1.2 and Logback there seem to be a few bugs in the current PatternProcessor.getNextTime() logic.

        Current PatternProcessor.getNextTime() results (dates in yyyy/MM/dd format):

        1. Monthly rollover from 2014/01/31 gives 2014/02/01
        2. Monthly rollover from 2014/10/15 gives 2014/02/01 <-- BUG
        3. Weekly rollover from 2014/03/4 Tue gives 2014/01/08 Wed <-- BUG
        4. Hourly rollover from 2014/03/04 10:31 gives 2014/03/04 11:00 when run in the morning
        5. Hourly rollover from 2014/03/04 10:31 gives 2014/03/04 23:00 when run in the afternoon <-- BUG
        6. Minutely rollover from 2014/03/04 10:31 gives 2014/03/04 22:00 when run in the afternoon <-- BUG

        The following patch fixes the above issues:

        Index: src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java
        ===================================================================
        --- src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java	(revision 1563035)
        +++ src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java	(working copy)
        @@ -102,6 +102,7 @@
                     nextFileTime = cal.getTimeInMillis();
                     return nextTime;
                 }
        +        cal.set(Calendar.MONTH, currentCal.get(Calendar.MONTH));
                 if (frequency == RolloverFrequency.MONTHLY) {
                     increment(cal, Calendar.MONTH, increment, modulus);
                     nextTime = cal.getTimeInMillis();
        @@ -110,7 +111,9 @@
                     return nextTime;
                 }
                 if (frequency == RolloverFrequency.WEEKLY) {
        +            cal.set(Calendar.WEEK_OF_YEAR, currentCal.get(Calendar.WEEK_OF_YEAR));
                     increment(cal, Calendar.WEEK_OF_YEAR, increment, modulus);
        +            cal.set(Calendar.DAY_OF_WEEK, currentCal.getFirstDayOfWeek());
                     nextTime = cal.getTimeInMillis();
                     cal.add(Calendar.WEEK_OF_YEAR, -1);
                     nextFileTime = cal.getTimeInMillis();
        @@ -124,11 +127,11 @@
                     nextFileTime = cal.getTimeInMillis();
                     return nextTime;
                 }
        -        cal.set(Calendar.HOUR, currentCal.get(Calendar.HOUR));
        +        cal.set(Calendar.HOUR_OF_DAY, currentCal.get(Calendar.HOUR_OF_DAY));
                 if (frequency == RolloverFrequency.HOURLY) {
        -            increment(cal, Calendar.HOUR, increment, modulus);
        +            increment(cal, Calendar.HOUR_OF_DAY, increment, modulus);
                     nextTime = cal.getTimeInMillis();
        -            cal.add(Calendar.HOUR, -1);
        +            cal.add(Calendar.HOUR_OF_DAY, -1);
                     nextFileTime = cal.getTimeInMillis();
                     return nextTime;
                 }
        

        Updated JUnit tests:

            private String format(long time) {
                String actualStr = new SimpleDateFormat("yyyy/MM/dd HH:mm:ss.SSS")
                        .format(new Date(time));
                return actualStr;
            }
        
            @Test
            public void testGetNextTimeMonthlyReturnsFirstDayOfNextMonth() {
                PatternProcessor pp = new PatternProcessor(
                        "logs/app-%d{yyyy-MM}.log.gz");
                Calendar initial = Calendar.getInstance();
                initial.set(2014, 9, 15, 10, 31, 59); // Oct 15th
                long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
        
                // We expect 1st day of next month
                Calendar expected = Calendar.getInstance();
                expected.set(2014, 10, 1, 0, 0, 00);
                expected.set(Calendar.MILLISECOND, 0);
                assertEquals(format(expected.getTimeInMillis()), format(actual));
            }
        
            @Test
            public void testGetNextTimeMonthlyReturnsFirstDayOfNextMonth2() {
                PatternProcessor pp = new PatternProcessor(
                        "logs/app-%d{yyyy-MM}.log.gz");
                Calendar initial = Calendar.getInstance();
                initial.set(2014, 0, 31, 10, 31, 59); // 2014 Jan 31st
                long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
        
                // Expect 1st of next month: 2014 Feb 1st
                Calendar expected = Calendar.getInstance();
                expected.set(2014, 1, 1, 0, 0, 00);
                expected.set(Calendar.MILLISECOND, 0);
                assertEquals(format(expected.getTimeInMillis()), format(actual));
            }
        
            @Test
            public void testGetNextTimeWeeklyReturnsFirstDayOfNextWeek_US() {
                Locale old = Locale.getDefault();
                Locale.setDefault(Locale.US); // force 1st day to be Sunday
        
                try {
                    PatternProcessor pp = new PatternProcessor(
                            "logs/app-%d{yyyy-MM-W}.log.gz");
                    Calendar initial = Calendar.getInstance();
                    initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014
                    long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
        
                    // expect Sun, March 9, 2014
                    Calendar expected = Calendar.getInstance();
                    expected.set(2014, 2, 9, 0, 0, 00);
                    expected.set(Calendar.MILLISECOND, 0);
                    assertEquals(format(expected.getTimeInMillis()), format(actual));
                } finally {
                    Locale.setDefault(old);
                }
            }
        
            @Test
            public void testGetNextTimeWeeklyReturnsFirstDayOfNextWeek_FRANCE() {
                Locale old = Locale.getDefault();
                Locale.setDefault(Locale.FRANCE); // force 1st day to be Monday
        
                try {
                    PatternProcessor pp = new PatternProcessor(
                            "logs/app-%d{yyyy-MM-W}.log.gz");
                    Calendar initial = Calendar.getInstance();
                    initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014
                    long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
        
                    // expect Monday, March 10, 2014
                    Calendar expected = Calendar.getInstance();
                    expected.set(2014, 2, 10, 0, 0, 00);
                    expected.set(Calendar.MILLISECOND, 0);
                    assertEquals(format(expected.getTimeInMillis()), format(actual));
                } finally {
                    Locale.setDefault(old);
                }
            }
        
            @Test
            public void testGetNextTimeHourlyReturnsFirstMinuteOfNextHour() {
                PatternProcessor pp = new PatternProcessor(
                        "logs/app-%d{yyyy-MM-dd-HH}.log.gz");
                Calendar initial = Calendar.getInstance();
                initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014, 10:31
                long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
        
                // expect Wed, March 4, 2014, 11:00
                Calendar expected = Calendar.getInstance();
                expected.set(2014, 2, 4, 11, 00, 00);
                expected.set(Calendar.MILLISECOND, 0);
                assertEquals(format(expected.getTimeInMillis()), format(actual));
            }
        
            @Test
            public void testGetNextTimeMinutelyReturnsFirstSecondOfNextMinute() {
                PatternProcessor pp = new PatternProcessor(
                        "logs/app-%d{yyyy-MM-dd-HH-mm}.log.gz");
                Calendar initial = Calendar.getInstance();
                initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014, 10:31
                initial.set(Calendar.MILLISECOND, 0);
                assertEquals("2014/03/04 10:31:59.000", format(initial.getTimeInMillis()));
                long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false);
        
                // expect Tue, March 4, 2014, 10:32
                Calendar expected = Calendar.getInstance();
                expected.set(2014, 2, 4, 10, 32, 00);
                expected.set(Calendar.MILLISECOND, 0);
                assertEquals(format(expected.getTimeInMillis()), format(actual));
            }
        
        Show
        Remko Popma added a comment - After checking the behaviour of Log4J-1.2 and Logback there seem to be a few bugs in the current PatternProcessor.getNextTime() logic. Current PatternProcessor.getNextTime() results (dates in yyyy/MM/dd format): Monthly rollover from 2014/01/31 gives 2014/02/01 Monthly rollover from 2014/10/15 gives 2014/ 02/01 <-- BUG Weekly rollover from 2014/03/4 Tue gives 2014/ 01/08 Wed <-- BUG Hourly rollover from 2014/03/04 10:31 gives 2014/03/04 11:00 when run in the morning Hourly rollover from 2014/03/04 10:31 gives 2014/03/04 23 :00 when run in the afternoon <-- BUG Minutely rollover from 2014/03/04 10:31 gives 2014/03/04 22 :00 when run in the afternoon <-- BUG The following patch fixes the above issues: Index: src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java =================================================================== --- src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java (revision 1563035) +++ src/main/java/org/apache/logging/log4j/core/appender/rolling/PatternProcessor.java (working copy) @@ -102,6 +102,7 @@ nextFileTime = cal.getTimeInMillis(); return nextTime; } + cal.set(Calendar.MONTH, currentCal.get(Calendar.MONTH)); if (frequency == RolloverFrequency.MONTHLY) { increment(cal, Calendar.MONTH, increment, modulus); nextTime = cal.getTimeInMillis(); @@ -110,7 +111,9 @@ return nextTime; } if (frequency == RolloverFrequency.WEEKLY) { + cal.set(Calendar.WEEK_OF_YEAR, currentCal.get(Calendar.WEEK_OF_YEAR)); increment(cal, Calendar.WEEK_OF_YEAR, increment, modulus); + cal.set(Calendar.DAY_OF_WEEK, currentCal.getFirstDayOfWeek()); nextTime = cal.getTimeInMillis(); cal.add(Calendar.WEEK_OF_YEAR, -1); nextFileTime = cal.getTimeInMillis(); @@ -124,11 +127,11 @@ nextFileTime = cal.getTimeInMillis(); return nextTime; } - cal.set(Calendar.HOUR, currentCal.get(Calendar.HOUR)); + cal.set(Calendar.HOUR_OF_DAY, currentCal.get(Calendar.HOUR_OF_DAY)); if (frequency == RolloverFrequency.HOURLY) { - increment(cal, Calendar.HOUR, increment, modulus); + increment(cal, Calendar.HOUR_OF_DAY, increment, modulus); nextTime = cal.getTimeInMillis(); - cal.add(Calendar.HOUR, -1); + cal.add(Calendar.HOUR_OF_DAY, -1); nextFileTime = cal.getTimeInMillis(); return nextTime; } Updated JUnit tests: private String format( long time) { String actualStr = new SimpleDateFormat( "yyyy/MM/dd HH:mm:ss.SSS" ) .format( new Date(time)); return actualStr; } @Test public void testGetNextTimeMonthlyReturnsFirstDayOfNextMonth() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 9, 15, 10, 31, 59); // Oct 15th long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // We expect 1st day of next month Calendar expected = Calendar.getInstance(); expected.set(2014, 10, 1, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } @Test public void testGetNextTimeMonthlyReturnsFirstDayOfNextMonth2() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 0, 31, 10, 31, 59); // 2014 Jan 31st long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // Expect 1st of next month: 2014 Feb 1st Calendar expected = Calendar.getInstance(); expected.set(2014, 1, 1, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } @Test public void testGetNextTimeWeeklyReturnsFirstDayOfNextWeek_US() { Locale old = Locale.getDefault(); Locale.setDefault(Locale.US); // force 1st day to be Sunday try { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM-W}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014 long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // expect Sun, March 9, 2014 Calendar expected = Calendar.getInstance(); expected.set(2014, 2, 9, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } finally { Locale.setDefault(old); } } @Test public void testGetNextTimeWeeklyReturnsFirstDayOfNextWeek_FRANCE() { Locale old = Locale.getDefault(); Locale.setDefault(Locale.FRANCE); // force 1st day to be Monday try { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM-W}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014 long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // expect Monday, March 10, 2014 Calendar expected = Calendar.getInstance(); expected.set(2014, 2, 10, 0, 0, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } finally { Locale.setDefault(old); } } @Test public void testGetNextTimeHourlyReturnsFirstMinuteOfNextHour() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM-dd-HH}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014, 10:31 long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // expect Wed, March 4, 2014, 11:00 Calendar expected = Calendar.getInstance(); expected.set(2014, 2, 4, 11, 00, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); } @Test public void testGetNextTimeMinutelyReturnsFirstSecondOfNextMinute() { PatternProcessor pp = new PatternProcessor( "logs/app-%d{yyyy-MM-dd-HH-mm}.log.gz" ); Calendar initial = Calendar.getInstance(); initial.set(2014, 2, 4, 10, 31, 59); // Tue, March 4, 2014, 10:31 initial.set(Calendar.MILLISECOND, 0); assertEquals( "2014/03/04 10:31:59.000" , format(initial.getTimeInMillis())); long actual = pp.getNextTime(initial.getTimeInMillis(), 1, false ); // expect Tue, March 4, 2014, 10:32 Calendar expected = Calendar.getInstance(); expected.set(2014, 2, 4, 10, 32, 00); expected.set(Calendar.MILLISECOND, 0); assertEquals(format(expected.getTimeInMillis()), format(actual)); }
        Hide
        Remko Popma added a comment -

        Fixed the above issues with monthly, weekly, hourly and every-minute rollover in revision 1563132.

        Unfortunately, I was unable to reproduce the original issue reported in the description. I did not see a rollover zip file being created at application startup...

        Can you verify and close the issue if the problem no longer occurs with current trunk? (Please re-open if the issue still exists. In that case please also attach your log4j2.xml config to help me reproduce the issue.)

        Show
        Remko Popma added a comment - Fixed the above issues with monthly, weekly, hourly and every-minute rollover in revision 1563132. Unfortunately, I was unable to reproduce the original issue reported in the description. I did not see a rollover zip file being created at application startup... Can you verify and close the issue if the problem no longer occurs with current trunk? (Please re-open if the issue still exists. In that case please also attach your log4j2.xml config to help me reproduce the issue.)

          People

          • Assignee:
            Remko Popma
            Reporter:
            Ace Funk
          • Votes:
            2 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development