Felix Crux

Technology & Miscellanea 

Tags: ,

...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!


blog comments powered by Disqus