#504333 logrotate ignores files with date 1904-1-1 in /var/lib/logrotate/status

Package:
logrotate
Source:
logrotate
Description:
Log rotation utility
Submitter:
Vincent Lefevre
Date:
2019-09-21 00:45:03 UTC
Severity:
normal
#504333#5
Date:
2008-11-02 22:04:23 UTC
From:
To:
When /var/lib/logrotate/status has files with date 1904-1-1 (e.g.
/var/log/wtmp), these files are no longer rotated. I don't even
get any error message.

Note: the 1904-1-1 is due to the fact that on the PowerBook G4,
when the battery is empty, the date is reset to 1904-01-01.

#504333#10
Date:
2008-11-03 04:04:50 UTC
From:
To:
That shouldn't be possible without getting an error:

        if ((year != 1900) && (year < 1970 || year > 2100)) {
            message(MESS_ERROR, "bad year %d for file %s in state file %s\n",
                    year, argv[0], stateFilename);
            fclose(f);
            return 1;
        }

Could you attach your /var/lib/logrotate/status, please?

#504333#15
Date:
2008-11-03 09:29:49 UTC
From:
To:
Sorry, I've tried and I get an error (in fact, after checking in the
shell history, it seems that I hadn't tested logrotate with these 1904
dates: when I noticed all these 1904 dates, I just removed the status
file as I thought it would have been simpler than fixing all these
dates, then ran logrotate, and I didn't get an error for this missing
status file, but this may be expected).

BTW, I should have seen this error in the anacron messages (a bit
hidden amongst other spurious error messages, unfortunately).

Now, the fact that 1904 is ignored is quite annoying. Well, the best
solution would be that logrotate should never put such an old date in
/var/lib/logrotate/status.

#504333#20
Date:
2018-08-22 21:44:05 UTC
From:
To:
Hi,
I tested logrotate version 3.14.0-2 with an ancient logfile from 1904
and it got rotated. Also no such date should show up in the state file
(only rotation times, not file mtimes).
Can you reproduce this issue with logrotate 3.14.0-2 or newer?
Please post a logrotate state file with such ancient dates.

Best regards
        Christian Göttsche

#504333#27
Date:
2018-08-23 10:52:28 UTC
From:
To:
This is old, and I'm not sure that the issue is the same.
And I no longer have the old machine to test under the
same conditions. But...

/var/lib/logrotate/status contains:

"/var/log/lpr.log" 2018-1-23-12:00:00

(i.e. a date sufficiently old to trigger a rotate).

# ls -l /var/log/lpr.log*
-rw-r----- 1 root adm  5 1904-01-01 00:00:00 /var/log/lpr.log
-rw-r----- 1 root adm  4 1904-01-01 00:00:00 /var/log/lpr.log.1
-rw-r----- 1 root adm 60 2015-06-18 18:41:13 /var/log/lpr.log.2.gz
# /usr/sbin/logrotate /etc/logrotate.conf
error: Compressing program wrote following message to stderr when compressing log /var/log/lpr.log.1:
gzip: stdin: warning: file timestamp out of range for gzip format
error: failed to compress log /var/log/lpr.log.1
# ls -l /var/log/lpr.log*
-rw-r----- 1 root adm  5 1904-01-01 00:00:00 /var/log/lpr.log
-rw-r----- 1 root adm  4 1904-01-01 00:00:00 /var/log/lpr.log.1
-rw-r----- 1 root adm 60 2015-06-18 18:41:13 /var/log/lpr.log.2.gz
# /usr/sbin/logrotate /etc/logrotate.conf
# ls -l /var/log/lpr.log*
-rw-r----- 1 root adm  5 1904-01-01 00:00:00 /var/log/lpr.log
-rw-r----- 1 root adm  4 1904-01-01 00:00:00 /var/log/lpr.log.1
-rw-r----- 1 root adm 60 2015-06-18 18:41:13 /var/log/lpr.log.2.gz

I don't know whether this was the cause of the failure of the
rotations in the past. But the error has disappeared and the
logs files are no longer rotated. This is inconsistent.

In case of gzip error, logrotate should either ignore it and rotate
the files, or it should keep the old date in /var/lib/logrotate/status
(I assume that the user should see the repeating error in cron
e-mails).

#504333#42
Date:
2019-09-08 15:22:15 UTC
From:
To:
The timestamp in the state file stands for the last attempt to rotate
the file (see https://github.com/logrotate/logrotate/issues/223), so
an update of it is fine.

In message #27 logrotate probably did not show any error cause the
option 'daily' was used; when forcing a rotation (--force) an error
message is also shown in subsequently runs.

#504333#49
Date:
2019-09-10 16:16:28 UTC
From:
To:
Control: tags -1 - fixed-upstream

This time also sending to the submitter...

#504333#54
Date:
2019-09-10 16:16:28 UTC
From:
To:
Control: tags -1 - fixed-upstream

This time also sending to the submitter...

#504333#59
Date:
2019-09-17 13:32:10 UTC
From:
To:
OK, I understand the reason with the upstream discussion. I think
that the best thing is to try to reproduce the issue under the
usual conditions (i.e. via cron and without trying to change the
status file). So, on some machine, I've set in /var/log/apache2

  touch -d 19040101 error.log error.log.1

so that I now have

#504333#64
Date:
2019-09-18 08:32:24 UTC
From:
To:
It seems really broken, worse than expected. First, I did not get
any error via cron, and the error logs did not change:

#504333#71
Date:
2019-09-18 10:52:32 UTC
From:
To:
Please share your current setup:
Debian version: (old-stable | stable | testing | unstable)
Logrotate version: (logrotate --version)
Please share your cronjob config '/etc/cron.daily/logrotate'
Are you using systemd?
    If yes, please share 'systemctl status logrotate.timer' and
'journalctl -u logrotate' (the most recent part of it).

That the logs do not change is expected, as gzip failed;
if you using systemd you should see some error messages in the journal.

This is indeed unexpected, in my tests logrotate continues to rotate
other logs. (see https://paste.debian.net/1101399/)


p.s.:
To avoid these timestamps you can use the configuration option 'prerotate'.
Otherwise it's on gzip.

#504333#76
Date:
2019-09-19 09:03:36 UTC
From:
To:
unstable

logrotate 3.15.1

    Default mail command:       /usr/bin/mail
    Default compress command:   /bin/gzip
    Default uncompress command: /bin/gunzip
    Default compress extension: .gz
    Default state file path:    /var/lib/logrotate/status
    ACL support:                yes
    SELinux support:            yes

#!/bin/sh

# skip in favour of systemd timer
if [ -d /run/systemd/system ]; then
    exit 0
fi

# this cronjob persists removals (but not purges)
if [ ! -x /usr/sbin/logrotate ]; then
    exit 0
fi

/usr/sbin/logrotate /etc/logrotate.conf
EXITVALUE=$?
if [ $EXITVALUE != 0 ]; then
    /usr/bin/logger -t logrotate "ALERT exited abnormally with [$EXITVALUE]"
fi
exit $EXITVALUE

(This is the default one.)

Yes, this machine does.
   Loaded: loaded (/lib/systemd/system/logrotate.timer; enabled; vendor preset: enabled)
   Active: active (waiting) since Thu 2019-09-19 10:25:10 CEST; 32min ago
  Trigger: Fri 2019-09-20 00:00:00 CEST; 13h left
     Docs: man:logrotate(8)
           man:logrotate.conf(5)

Sep 19 10:25:10 cventin systemd[1]: Started Daily rotation of log files.

[...]
Sep 16 00:00:01 cventin systemd[1]: Starting Rotate log files...
Sep 16 00:00:02 cventin systemd[1]: logrotate.service: Succeeded.
Sep 16 00:00:02 cventin systemd[1]: Started Rotate log files.
Sep 17 00:00:01 cventin systemd[1]: Starting Rotate log files...
Sep 17 00:00:03 cventin systemd[1]: logrotate.service: Succeeded.
Sep 17 00:00:03 cventin systemd[1]: Started Rotate log files.
Sep 18 00:00:01 cventin systemd[1]: Starting Rotate log files...
Sep 18 00:00:01 cventin logrotate[16206]: error: Compressing program wrote following message to stderr when compressing log /var/log/apache2/error.log.1:
Sep 18 00:00:01 cventin logrotate[16206]: gzip: stdin: warning: file timestamp out of range for gzip format
Sep 18 00:00:01 cventin logrotate[16206]: error: failed to compress log /var/log/apache2/error.log.1
Sep 18 00:00:02 cventin systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Sep 18 00:00:02 cventin systemd[1]: logrotate.service: Failed with result 'exit-code'.
Sep 18 00:00:02 cventin systemd[1]: Failed to start Rotate log files.
Sep 19 00:00:01 cventin systemd[1]: Starting Rotate log files...
Sep 19 00:00:02 cventin logrotate[19728]: error: Compressing program wrote following message to stderr when compressing log /var/log/apache2/error.log.1:
Sep 19 00:00:02 cventin logrotate[19728]: gzip: stdin: warning: file timestamp out of range for gzip format
Sep 19 00:00:02 cventin logrotate[19728]: error: failed to compress log /var/log/apache2/error.log.1
Sep 19 00:00:02 cventin systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Sep 19 00:00:02 cventin systemd[1]: logrotate.service: Failed with result 'exit-code'.
Sep 19 00:00:02 cventin systemd[1]: Failed to start Rotate log files.

Yes, this is the case. But cron should have sent a mail with these
error messages, and I haven't received such a mail.

It is only access.log that it doesn't rotate. After last night:

#504333#81
Date:
2019-09-19 09:27:37 UTC
From:
To:
So, the rotation occurs at midnight, according to the systemd timer.
This conflicts with the crontab configuration.

#504333#86
Date:
2019-09-19 10:54:59 UTC
From:
To:
Hmm... I see that /etc/cron.daily/logrotate disables the rotation
by cron in case of systemd. So, the issue with the missing mail is
due to the systemd timer, which just outputs the error message in
the logs (not sufficient as a manual intervention is needed). In
any case, this is different from the original bug. I've reported
a new bug for this particular problem.

Now, I still don't understand why the logs are not rotated since
gzip is actually fine with the date 1904-01-01: this is just a
warning. Test:

cventin% rm -f test.txt*
cventin% echo blah > test.txt
cventin% touch -d 1904-01-01 test.txt
cventin% ls -l test.txt*
-rw-r--r-- 1 vlefevre vlefevre 5 1904-01-01 00:00:00 test.txt
cventin% gzip test.txt
gzip: test.txt: warning: file timestamp out of range for gzip format
cventin% ls -l test.txt*
-rw-r--r-- 1 vlefevre vlefevre 34 1904-01-01 00:00:00 test.txt.gz

i.e. the file got compressed as expected.

Really, this warning does not matter, in particular for log files.
Thus logrotate should ignore it.

BTW, even if the file could not be compressed, I think that the best
solution would be to rotate anyway.

#504333#91
Date:
2019-09-20 17:36:02 UTC
From:
To:
Can you please run 'logrotate --debug /etc/logrotate.conf' and search
for output regarding to access.log

gzip may say warning, but it exits with a value of 2, and prints to stderr.
So logrotate has every reason to think somethings wrong and leave this
file as it is.
I do not think that should be changed.

#504333#96
Date:
2019-09-21 00:41:23 UTC
From:
To:
rotating pattern: /var/log/apache2/*.log  after 1 days (14 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/apache2/access.log
  Now: 2019-09-21 02:35
  Last rotated at 2019-09-21 00:00
  log does not need rotating (log has been rotated at 2019-9-21 0:0, that is not day ago yet)
considering log /var/log/apache2/error.log
  Now: 2019-09-21 02:35
  Last rotated at 2019-09-21 00:00
  log does not need rotating (log has been rotated at 2019-9-21 0:0, that is not day ago yet)
considering log /var/log/apache2/other_vhosts_access.log
  Now: 2019-09-21 02:35
  Last rotated at 2019-02-19 00:00
  log does not need rotating (log is empty)
not running prerotate script, since no logs will be rotated
not running postrotate script, since no logs were rotated

No, a warning is a warning. This is not an error. FYI, from the
gzip(1) man page:

  Exit status is normally 0; if an error occurs, exit status is 1.
  If a warning occurs, exit status is 2.

logrotate should regard 0 and 2 as OK.