Bug 1556993

Looking once again, I see that /var/log/messages is actually rotated (it was confused with /var/log/maillog in my head).  It is not clear when and how the debug output of logrotate was captured.  We would also need to see the full configuration of logrotate to make any conclusion out of this.

(In reply to Kamil Dudka from comment #4)
> Both /var/log/messages and /var/log/cron were rotated in March 2018.  So if
> they are configured to rotate monthly, none of them will rotate sooner than
> in April 2018.

That's correct but isn't that working in debug logs? 

When i have,

[root@vm251-148 ~]# cat /var/lib/logrotate/logrotate.status | egrep 'messages|cron'
"/var/log/messages" 2018-3-15-3:36:1 <<<<<< 
"/var/log/cron" 2018-3-14-17:1:37
[root@vm251-148 ~]# 

I correctly get message "log has been rotated at 2018-3-15 3:36, that is not month ago yet. 

However, if i just modify time of one of the file, 

[root@vm251-148 ~]# cat /var/lib/logrotate/logrotate.status | egrep 'messages|cron'
"/var/log/messages" 2018-1-1-0:36:1
"/var/log/cron" 2018-3-14-17:1:37
[root@vm251-148 ~]# 

Then logrotate consider it for rotating, isn't this unexpected? If it is just check month & year, it should treat both file same way.

(In reply to Kamil Dudka from comment #5)
> Looking once again, I see that /var/log/messages is actually rotated (it was
> confused with /var/log/maillog in my head).  It is not clear when and how
> the debug output of logrotate was captured.  We would also need to see the
> full configuration of logrotate to make any conclusion out of this.

As per customer he has already noticed this behavior in last year march as well.

Thank you for sharing the logs!  This is indeed a bug of logrotate.  I was able to reproduce it locally.  The following patch will fix it:

https://github.com/logrotate/logrotate/commit/r3-8-8~2#diff-c77f766704c11808480548296cdd6787

Minimal example:

# ln -fs /usr/share/zoneinfo/Europe/Prague /etc/localtime
# mkdir /tmp/test && cd /tmp/test
# echo test > /tmp/test/test.log
# cat > /tmp/test/lr.conf << EOF
/tmp/test/test.log {
    copytruncate
    rotate 4
    monthly
}
EOF


# date 0301003018 && logrotate -s lr.stat -f lr.conf
Thu Mar  1 00:30:00 CET 2018


# date 0325013018 && logrotate -s lr.stat -v lr.conf
Sun Mar 25 01:30:00 CET 2018
reading config file lr.conf
Allocating hash table for state file, size 15360 B

Handling 1 logs

rotating pattern: /tmp/test/test.log  monthly (4 rotations)
empty log files are rotated, old logs are removed
considering log /tmp/test/test.log
  log does not need rotating (log has been rotated at 2018-3-1 0:30, that is not month ago yet)
set default create context


# date 0325033018 && logrotate -s lr.stat -v lr.conf
Sun Mar 25 03:30:00 CEST 2018
reading config file lr.conf
Allocating hash table for state file, size 15360 B

Handling 1 logs

rotating pattern: /tmp/test/test.log  monthly (4 rotations)
empty log files are rotated, old logs are removed
considering log /tmp/test/test.log
  log needs rotating
rotating log /tmp/test/test.log, log->rotateCount is 4
dateext suffix '-20180325'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /tmp/test/test.log.4 to /tmp/test/test.log.5 (rotatecount 4, logstart 1, i 4), 
old log /tmp/test/test.log.4 does not exist
renaming /tmp/test/test.log.3 to /tmp/test/test.log.4 (rotatecount 4, logstart 1, i 3), 
old log /tmp/test/test.log.3 does not exist
renaming /tmp/test/test.log.2 to /tmp/test/test.log.3 (rotatecount 4, logstart 1, i 2), 
old log /tmp/test/test.log.2 does not exist
renaming /tmp/test/test.log.1 to /tmp/test/test.log.2 (rotatecount 4, logstart 1, i 1), 
renaming /tmp/test/test.log.0 to /tmp/test/test.log.1 (rotatecount 4, logstart 1, i 0), 
old log /tmp/test/test.log.0 does not exist
log /tmp/test/test.log.5 doesn't exist -- won't try to dispose of it
copying /tmp/test/test.log to /tmp/test/test.log.1
set default create context to unconfined_u:object_r:user_tmp_t:s0
truncating /tmp/test/test.log
set default create context

I would like to confirm the other issue mentioned in the discussion of bug #1465720 (comment 19) appears to be *this* bug.

I set up a testing logrotate config with one log rotated monthly and simulated daily invocations of logrotate from Jan 31 to Apr 5 (using dateshift). Here are abridged results of the suimulation:

...
==== 2018-03-24 03:23:01 ====
  log does not need rotating (log has been rotated at 2018-3-1 3:45, that is not month ago yet)
==== 2018-03-25 03:13:01 ====
  log does not need rotating (log has been rotated at 2018-3-1 2:45, that is not month ago yet)
==== 2018-03-26 03:07:01 ====
  log does not need rotating (log has been rotated at 2018-3-1 1:45, that is not month ago yet)
==== 2018-03-27 03:35:01 ====
  log does not need rotating (log has been rotated at 2018-3-1 0:45, that is not month ago yet)
==== 2018-03-28 03:37:01 ====
  log needs rotating
==== 2018-03-29 03:26:01 ====
  log does not need rotating (log has been rotated at 2018-3-28 3:37, that is not month ago yet)
...

You can see the time recorded in the state file kept slipping backward by one hour during every invocation of logrotate since the start of DST on Mar 25 until it slipped too far on Mar 28 and a spurious rotation was triggered.

I applied the tm_isdst patch mentioned in comment #9 to logrotate-3.8.6-14.el7.src.rpm, re-ran the simulation and there were no time slips or spurious rotations anymore.

Thanks for confirmation, Pavel!

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:3202