…or at least the best one I’ve managed to come up with.
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 —
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
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 “
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
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
"echo '[running] $@' && $@
2>&1"; and third,
"ts '%Y-%m-%d %H:%M:%S'".
mispipe is another helper from
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
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
"echo '[running] $@' &&
$@ 2>&1", is less complicated. It prints a header showing the command
being run, and then runs it, redirecting
stdout. This is so that both output streams will go through the
pipe to the next stage.
The second argument to
%H:%M:%S'", is another
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
Putting it all together, you could name the above file something like
log-output, and then use it in your
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
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
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
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!