Recently I got nullmailer working on my home server - and along with it working CRON logs filling my inbox. Tracking these issues down will often leave you in unexpected territory. I'll write up each journey one at a time.
First up is a very brief email from logrotate that greets me every morning.
Subject: Cron <root@vault> test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
run-parts: /etc/cron.daily/logrotate exited with return code 1
Daily cron scrips are typically found in /etc/cron.daily. This particular one does some funky things with its own log file but our concern is:
/usr/sbin/logrotate /etc/logrotate.conf 2>&1 | grep -v 'sized changed'
The last command grep -v 'sized changed'
indicates failure with exit code 1.
So to see what is failing I ran the script:
/usr/sbin/logrotate --verbose /etc/logrotate.conf && echo $?
[... snip ...]
rotating pattern: /var/log/btmp monthly (1 rotations)
empty log files are rotated, old logs are removed
switching euid to 0 and egid to 103
considering log /var/log/btmp
Now: 2019-05-27 10:33
Last rotated at 2019-05-01 06:25
log does not need rotating (log has been rotated at 2019-5-1 6:25, that is not month ago yet)
switching euid to 0 and egid to 0
0
The actual logrotate command returns success with code 0. Then why did the
CRON report failure? Because we are getting the return code from grep -v
'sized changed'
not the logrotate
command itself. What's up with sized
changed? Let's do some grepping ourselves:
# /usr/sbin/logrotate --verbose /etc/logrotate.conf >/tmp/wtf.log 2>&1
# cd /tmp
# wc -l wtf.log
336 wtf.log
# grep 'sized changed' wtf.log && echo $?
0
# grep -v 'sized changed' wtf.log >/dev/null; echo $?
0
# /usr/sbin/logrotate /etc/logrotate.conf 2>&1 | grep -v 'sized changed'
1
# echo "wtf?"
wtf?
OK - time to check some assertions. grep -v
searches for lines that do not
match the string sized changed
. But that doesn't negate its return value.
It seems to return 0 with or without the -v
. Time for some tests
$ echo '' | grep -v 'sized changed'; echo $?
0
$ echo 'sldkjflsdkfj' | grep -v 'sized changed'; echo $?
sldkjflsdkfj
0
$ echo 'sldkjflsdkfj' 2>&1 | grep -v 'sized changed'; echo $?
sldkjflsdkfj
0
$ echo '' 2>&1 | grep -v 'sized changed'; echo $?
0
$ echo -e '' 2>&1 | grep -v 'sized changed'; echo $?
0
$ echo -v '' 2>&1 | grep -v 'sized changed'; echo $?
-v
0
dan@vault:/etc/cron.daily
$ echo -n '' 2>&1 | grep -v 'sized changed'; echo $?
1
Ah Hah! grep will return 1 if it's input doesn't container a line ending. Even echo '' will pass, echo -n '' will fail. The man page has this to say about it:
Normally the exit status is 0 if a line is selected, 1 if no lines were selected, and 2 if an error occurred.
That makes twisted sense. An empty line is still a line, and -v
can
successfully not match on it. No line means nothing to not match against.
So here is my remedy:
(echo; /usr/sbin/logrotate /etc/logrotate.conf;) 2>&1 | grep -v 'sized changed'
Sub shells for the win. No more false negative results. But now I get an
email with just a single line of text - /etc/cron.daily/logrotate:
Time to wrap the script for errors. Here is the final script after ShellCheck
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 | #!/bin/sh
# Clean non existent log file entries from status file
cd /var/lib/logrotate || exit 1
test -e status || touch status
head -1 status > status.clean
sed 's/"//g' status | while read -r logfile date
do
[ -e "$logfile" ] && echo "\"$logfile\" $date"
done >> status.clean
mv status.clean status
test -x /usr/sbin/logrotate || exit 0
tempfile=$(mktemp -p /var/lib/logrotate)
date > "$tempfile" || exit 1
/usr/sbin/logrotate /etc/logrotate.conf > "$tempfile" 2>&1
if grep -qE 'sized? changed' "$tempfile"; then
echo "Error in daily logrotate - a log file changed while rotating"
echo "============================================================"
cat "$tempfile"
fi
rm "$tempfile"
|