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
'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
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 -
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"