Friday, 25 May 2012

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:


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

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

JaMeS



5 comments:

  1. Can I retain the default log dir of upstart to /var/log/upstart, while changing
    it, only for some of my services ?, i.e a subset of my services logging to
    /var/log/upstart/myservices.
    Is there any stanza/config to specify this, per service ?

    ReplyDelete
  2. Placement Requirement for Unix , Linux Solaris , Windows , Storage , Oracle for 3+ years of experience , please send your resume with Passport number and Date of birth to Info@linuxpune.com -- Interview on SAT 25th Jan..

    Rahul , LinuxPune ,

    1st Floor,Sai Shankar Apartment,Sigma HR Solutions,Opp Columbia Asia Hospital,Kharadi

    Mobile : +91 808 717171 0 , Website : http://www.linuxpune.com , info@linuxpune.com

    Google Map | Google Plus | Facebook | Twitter | LinkedIN | WordPress | SlideShare | JustDial

    ReplyDelete
  3. Really bad job. I'm ordinary user with xubuntu 14.04 and SSD. And I see permanently writing unnecessary big-big log in ~/.cache/upstart. How do I disable it? I don't need this. And where is determined $XDG_CACHE_HOME/upstart? I move $XDG_CACHE_HOME to /tmp, but $XDG_CACHE_HOME/upstart I can't move. And I think ordinary user like me does not require such obsessive logging. Bad job.

    ReplyDelete
  4. Nice Post, Thanks for your very useful information... I will bookmark for next reference.

    ReplyDelete
  5. So fortunes to run over your incredible online journal. Your online journal presents to me a lot of fun.. Good fortunes with the site.
    see this

    ReplyDelete