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"