30

On Ubuntu 12.04, I can find Upstart log messages in /var/log/syslog.

Commands:

# initctl log-priority info
# initctl emit hello

Log:

Apr  1 01:56:56 precise64 kernel: [ 8365.820425] init: Connection from private client
Apr  1 01:56:56 precise64 kernel: [ 8365.821130] init: Handling hello event

On Ubuntu 13.10, the messages do not appear in syslog or anywhere else under the /var/log directory, although commands like logger hello work as expected. Should I be looking for them somewhere else? Is there a configuration setting I need to change somewhere?

There’s a question on Server Fault from somebody who seems to be having the same problem on Ubuntu 13.04, and more here and here that may also be describing the same problem. Unfortunately, these questions offer no leads for the problem.

2 Answers 2

40

Edit 2016-06-02

If you're trying to find "Upstart log messages" in general, check /var/log/upstart/. That's where Upstart saves stdout and stderr from Upstart services. Thanks to leopd's answer for pointing this out.

If you're looking for log messages from Upstart itself, that are configured by initctl log-priority and emitted by initctl emit, read on!

Short version

The log entries should actually show up in dmesg. Despite that, they do not show up by default in /var/log.

If you want them in /var/log too, add $KLogPermitNonKernelFacility on to rsyslogd's config. I suggest creating a custom file like /etc/rsyslog.d/60-custom.conf to avoid editing /etc/rsyslog.conf, since that's managed by dpkg. Now Upstart messages should show up in /var/log/syslog, once you set Upstart's log-priority to info or so.

Long version

This took me days to track down, but apparently Upstart (1.5) does not log to syslog, that is, it doesn't call the glibc function syslog(). Instead, Upstart logs to the kernel ring buffer, which is what dmesg reads. Now, I didn't think it was possible for user space processes to write to that buffer, but apparently they can by writing to /dev/kmsg, and that's exactly what Upstart does. So that's the first part of the puzzle.

The second part is that there's a widely-held belief that messages written to the kernel ring buffer are automatically copied to syslog by the kernel (at least that's what I always thought). Turns out this is actually done by a user space daemon, traditionally klogd, which operates in tandem with syslogd. Obviously rsyslogd replaces syslogd but apparently it replaces klogd as well (sort of: see notes at the end).

The third part is that messages written to the kernel ring buffer from user space actually look different from messages written from kernel space: they have a different facility. dmesg has a few options that interact with this: -x will show the facility (and the priority), while -u and -k tell dmesg to show only user facility messages and kernel facility messages, respectively.

Now here's the clincher: by default, rsyslogd ignores messages with a non-kernel facility when it's reading messages from the kernel ring buffer. The relevant config option is $KLogPermitNonKernelFacility, which is off by default and needs to be turned on if you want rsyslogd to process these messages. Note that the rest of rsyslogd's config will treat all messages from the kernel ring buffer as having the kern facility, irrespective of the facility they had in the kernel ring buffer.

More information

syslog

Code can write to syslog by calling the glibc function syslog(), described in man 3 syslog. Apparently these functions write to /dev/log. Code can read from syslog by reading /dev/log, and this is what syslogd and its replacements do. rsyslogd reads /dev/log using its imuxsock input module.

Kernel ring buffer

Kernel space writes to this buffer by calling the kernel function printk(), so it's sometimes called the printk buffer. User space can write to it by writing to /dev/kmsg. User space can read from this buffer by several methods: it can read from /proc/kmsg (what dmesg does by default), or it can read from /dev/kmsg, or it can call the system call syslog(), which is described in man 2 syslog and is completely different from the glibc function syslog() described in man 3 syslog. glibc actually provides a wrapper to the system call syslog(), called klogctl(), to help alleviate this confusion.

Traditionally, klogd reads from one of these interfaces, then calls the glibc function syslog() to copy them to the syslog. rsyslogd reads one of these interfaces through its imklog input module but AFAIK doesn't bother calling the glibc syslog(), which is why it's not exactly like klogd; it just processes the output of imklog just like it processes output from any other input module. There is the added caveat that all imklog output has the kern facility irrespective of the facility messages had in the kernel ring buffer.

References

1
  • 4
    Thank you for the in-depth explanation of why this wasn’t working and how to fix it. One of the answers to the linked questions mentioned dmesg but it didn’t make any sense without the context given here. Jul 3, 2014 at 21:38
18

I found mine in /var/log/upstart/

2
  • I found mine in the file /var/log/upstart/job.log where job is the name of my job. Oct 9, 2015 at 1:25
  • AFAIK that's where stdout/stderr from jobs go. This question is about log messages from Upstart itself, that aren't associated with any particular job. Dec 1, 2015 at 22:37

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .