Bug 1556993 - logrotate appears miscalculating hours.
Summary: logrotate appears miscalculating hours.
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: logrotate
Version: 7.5
Hardware: All
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: Kamil Dudka
QA Contact: Frantisek Sumsal
URL:
Whiteboard:
Depends On:
Blocks: 1549689
TreeView+ depends on / blocked
 
Reported: 2018-03-15 17:39 UTC by Rupesh Patel
Modified: 2018-10-30 11:10 UTC (History)
4 users (show)

Fixed In Version: logrotate-3.8.6-16.el7
Doc Type: No Doc Update
Doc Text:
undefined
Clone Of:
Environment:
Last Closed: 2018-10-30 11:10:06 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:3202 None None None 2018-10-30 11:10:17 UTC

Description Rupesh Patel 2018-03-15 17:39:24 UTC
Latest logrotate with RHEL7.4


Monthly rotation is configured. By any chance (i mean customized configuration) if the rotation happened in first hour of the day, it would face issue with next rotation. 

[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 ~]# 

 monthly (4 rotations)
empty log files are rotated, old logs are removed
considering log /var/log/cron
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/maillog
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/messages
  log does not need rotating (log has been rotated at 2018-3-15 3:36, that is not month ago yet)
considering log /var/log/secure
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/spooler
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
not running postrotate script, since no logs were rotated


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

monthly (4 rotations)
empty log files are rotated, old logs are removed
considering log /var/log/cron
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/maillog
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/messages
  log needs rotating
considering log /var/log/secure
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/spooler
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
rotating log /var/log/messages, log->rotateCount is 4
dateext suffix '-20180315'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
destination /var/log/messages-20180315 already exists, skipping rotation


[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 ~]# 


 monthly (4 rotations)
empty log files are rotated, old logs are removed
considering log /var/log/cron
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/maillog
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/messages
  log needs rotating
considering log /var/log/secure
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/spooler
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
rotating log /var/log/messages, log->rotateCount is 4



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

 monthly (4 rotations)
empty log files are rotated, old logs are removed
considering log /var/log/cron
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/maillog
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/messages
  log needs rotating
considering log /var/log/secure
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
considering log /var/log/spooler
  log does not need rotating (log has been rotated at 2018-3-14 17:1, that is not month ago yet)
rotating log /var/log/messages, log->rotateCount is 4
dateext suffix '-20180315'


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

Customer who reported this behavior suspecting this is due to DST change. Here is what he said,

~~~
Here's what seems to be happening (based on behavior, not on examination of the code):

Every day when logrotate runs, it reads the status file, makes its decisions about rotation, etc, then writes a fresh copy of the status file.  Normally it works great - if no actions are done, the data stays pretty much the same.  However, on the two months out of the year where DAYLIGHT SAVINGS TIME occurs, there's a logic error that gets tickled:

The first few days of March it works normally.  But as soon as DST occurs, the program "compensates" for the 1-hour shift incorrectly.  As a result, every day after that, when it reads the status file, it subtracts an hour from the recorded time (of the entries which occur before the DST change).  The change gets written back to the status file, now 1-hour off.

This process repeats every day - all the recorded times "lose" an hour every day.  It eventually loses enough hours to roll back to the previous month.  And voilà, EVERYTHING suddenly needs to be rotated.

The same bug bites in reverse, in November, when DST ends, but it is harmless:  Every day after DST it *adds* an hour to the recorded times, but it doesn't stumble forward far enough to cause problems.
~~~

Comment 5 Kamil Dudka 2018-03-19 20:44:38 UTC
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.

Comment 6 Rupesh Patel 2018-03-19 20:46:15 UTC
(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.

Comment 8 Rupesh Patel 2018-03-19 20:52:37 UTC
(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.

Comment 9 Kamil Dudka 2018-03-20 14:19:08 UTC
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

Comment 10 Kamil Dudka 2018-03-20 14:33:02 UTC
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

Comment 18 Pavel Kankovsky 2018-04-10 16:20:20 UTC
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.

Comment 19 Kamil Dudka 2018-04-11 08:34:19 UTC
Thanks for confirmation, Pavel!

Comment 25 errata-xmlrpc 2018-10-30 11:10:06 UTC
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


Note You need to log in before you can comment on or make changes to this bug.