Job Logging in Upstart

Job Logging in Upstart

The big Upstart feature in Ubuntu Precise is "job logging" (in fact, it turned out to be a significantly bigger feature than we'd originally envisaged :-). This had been a wishlist item for some time and a lot of folk were very keen to see this implemented. All system jobs now have their stdout and stderr logged automatically by default to a text file in directory /var/log/upstart/.

Why did we make this the default? Surely daemons and services don't generally write any output? True, but when they do produce output, it is worth capturing since it has a very high chance of being an error message. And errors should not be ignored. For jobs that do not produce any output, there is minimal overhead and of course no log is written.

The logger actually uses pseudo-ptys just like script(1), xterm(1), expect(1), screen(1) et al. This is advantageous for a number of reasons, but from the logging perspective the biggie is "no buffering" so Upstart is able to slurp the jobs data as soon as it is generated. So even if a job produces only a single byte of output, this will be detected immediately.

Whilst developing this feature, we found a few services that had been generating warning and error messages for a looooong time but since the output was been discarded (implicit "console none"), we were not aware of them.

Job Debugging

The other great thing about job logging is that you don't need any special setup to use this feature as it's already enabled. All you need to do is add some calls to echo(1) and you are away.

To help with debugging script sections, you might like to add a "set -x" immediately after the script stanza. This is particularly helpful if you have tests in your code as you can see clearly which one is failing (recall that Upstart runs the script sections using "/bin/sh -e" so any errors are fatal.

$ cat <<EOT | sudo tee /etc/init/foo.conf
> task
> script
>   set -x
>   echo I am a job running with the following environment:
>   env
>   if [ 1 -gt 2 ]
>   then
>     echo impossible
>   else
>     echo sane
>   fi
> end script
> EOT
$ init-checkconf /etc/init/foo.conf && sudo start foo && sudo cat /var/log/upstart/foo.log
+ echo I am a job running with the following environment:
I am a job running with the following environment:
+ env
UPSTART_INSTANCE=
UPSTART_JOB=foo
TERM=linux
PATH=/usr/local/sbin:/usr/local/bin:/usr/bin:/usr/sbin:/sbin:/bin
PWD=/
+ [ 1 -gt 2 ]
+ echo sane
sane

Early Logging

Another neat feature of job logging is that it works from Upstart startup. What this means is that you can have a job that specifies "start on startup" (where startup is the first event Upstart emits at the point the disks are still read-only) and still have its output logged. Upstart handles this situation by writing the log as soon as the disk becomes writeable. This makes debugging very early system startup issues significantly easier. If you want the data "immediately" you could always use the  "--logdir" command-line option and arrange to have Upstart write job logs to a tmpfs filesystem.

Controlling Logging

Logging can be disabled entirely using the "--no-log" command-line option which gives you the old Upstart behaviour where all jobs implicitly defaulted to "console none".

You can of course disable logging for individual jobs by specifying an explicit "console none".

But you can also invert the logic and disable logging for all jobs except those you choose. To do this, add "console log" to all jobs you wish Upstart to log output for and then boot adding the following command-line option:  "--default-console=none". Now, Upstart will honour any job that specifies "console" explicitly, but if not, it will default to "console none", and discard all job output.

Further Reading

As usual, for further details, consult init(5) and the Upstart Cookbook, specifically:

• http://upstart.ubuntu.com/cookbook/#console-log
• http://upstart.ubuntu.com/cookbook/#command-line-options

If you haven't yet upgraded to precise, check out the release notes:

• https://wiki.ubuntu.com/PrecisePangolin/ReleaseNotes/TechnicalOverviewUpstart

Why not take a look in /var/log/upstart/ now and see what you can find?

JaMeS