…or at least the best one I’ve managed to come up with.
The venerable cron utility has some well-known shortcomings,
chief among which is how difficult it is to monitor the health and output of
scheduled tasks. The default setup tries to email output, but on a typical
laptop, desktop workstation, or even on many servers, it’s common to not have
a working system-wide mailer configuration. Many users therefore set up
“wrapper” scripts that handle logging, timestamping, and so forth. This
is the best one I’ve managed to come up with.
There are a few properties we’d like our wrapper script to have:
- It should produce no output whatsoever on success.
- It should log standard output and standard error to a file on failure.
- It should still print its output on error, in case we do have a working mailer.
- It should accurately timestamp all lines of output.
This was a persistent annoyance for me until I learned of the moreutils collection of tools —
in particular chronic, mispipe, and ts.
Using those, we can put together the following wrapper:
#!/bin/sh
chronic mispipe "echo '[running] $@' && $@ 2>&1" "ts '%Y-%m-%d %H:%M:%S'" \
| tee --append /var/log/cron.log
Breakdown
What’s going on here? Let’s look at the pieces one at a time, starting from the outside and working our way in.
The easiest part is the bit after the pipe, on the second line. The
tee utility takes its input and writes it to the given file while
also outputting it on stdout. The “--append” option
makes it so it adds to the file, rather than overwriting it.
The effect of this is that if the command before the pipe produces any
output, it will be added to /var/log/cron.log, as well as
printed. You may want to set up logrotate for that file, if it
isn’t configured already (on my Debian system, it was already covered by
/etc/logrotate.d/rsyslog and I didn’t have to change anything).
This satisfies our second and third bullet-point requirements from above.
Next, let’s jump to the start: What does chronic do? This tool
from the moreutils collection simply runs whatever command you
put after it, but suppresses all of its output unless it errors or
crashes. This gives us the behaviour we want in the first requirement bullet
point: silence on success, output on error. That means we can be extra-verbose
in our actual cron task, for example inserting lots of detailed logging, or
running with “set -x”, since all that extraneous output will not
show up anywhere unless there is a problem and we want it for debugging.
Now for the trickier bit: mispipe "echo '[running] $@' && $@ 2>&1"
"ts '%Y-%m-%d %H:%M:%S'" — what does all this do? There are three
parts: First, mispipe; second, "echo '[running] $@' && $@
2>&1"; and third, "ts '%Y-%m-%d %H:%M:%S'".
mispipe is another helper from moreutils that
does something very simple: it takes two commands, and pipes the output of the
first into the input of the second, while setting the overall exit code of the
pipeline to be whatever the first command exited with. This is
similar (but not identical) to bash’s “pipefail”
option, but works in any shell. So, in short, “mispipe foo bar”
is equivalent to “foo | bar” but exits with whatever status
foo exits with.
The first argument to mispipe, "echo '[running] $@' &&
$@ 2>&1", is less complicated. It prints a header showing the command
being run, and then runs it, redirecting stderr to
stdout. This is so that both output streams will go through the
pipe to the next stage.
The second argument to mispipe, namely "ts '%Y-%m-%d
%H:%M:%S'", is another moreutils tool: ts.
This little helper simply adds a timestamp to each line of input it receives
and prints it out. The default timestamp format isn’t my favourite, so I’ve
added a custom format specifier to change it from “Nov 25 10:49:42” to
“2018-11-25 10:49:42”.
Usage
Putting it all together, you could name the above file something like
log-output, and then use it in your crontab or
anacrontab like so:
* * * * * log-ouput 'actual-scheduled-task.sh arg1 arg2'
If your wrapped task succeeds, you should see nothing at all in your logfile or in cron’s output, but if it fails, everything it printed should be there, with timestamps!
For example, a wrapped task like this:
#!/bin/sh
echo "starting..."
sleep 2
echo "continuing..."
sleep 2
echo "failing..."
exit 1
…causes the following to appear in /var/log/cron.log:
2018-11-25 10:49:01 [running] ~/bin/test-cron-output.sh
2018-11-25 10:49:01 starting...
2018-11-25 10:49:03 continuing...
2018-11-25 10:49:05 failing...
If, on the other hand, the command succeeded, nothing would be logged or output at all.
Limitations & Improvements
There are a few things about this wrapper I’m not happy with but haven’t spent the time to figure out.
First, it erases the distinction between stdout and
stderr on output. In the innermost invocation of the actual
wrapped task, we redirect “2>&1”, and after that both output
streams are just interleaved. It would be nice to be able to distinguish them
in some way in the logs, and to have them emitted at the top level as separate
outputs.
Second, the wrapped task and any arguments to it have to be quoted when
invoked (i.e. “log-output 'foo bar'” rather than
“log-output foo bar”). It’s a minor thing but the script doesn’t
fail gracefully if you forget it.
If you know of relatively clean and straightforward fixes to these issues, please let me know!
