Is there an easy way to check which program wrote to /var/log/messages?

Question

Is there an easy way to check which program wrote to which file? I'd like to check which program wrote an error to /var/log/messages for example.

Answer 1

TL;DR

If you're only interestd in determining which process generated a given message in /var/log/messages then look at the first portion of each line. This shows the process name along with the PID of who generated a given line. In the examples below, fprintd, PID 444 and gnome-session, PID 8316 generated these lines in my messages log.

Feb 18 23:07:20 greeneggs fprintd[444]: ** Message: No devices in use, exit
Feb 18 23:08:53 greeneggs gnome-session[8316]: 23:08:53 | Git | personal_repo | Checking for remote changes...
Feb 18 23:08:53 greeneggs gnome-session[8316]: 23:08:53 | Cmd | personal_repo | git rev-parse HEAD

Analyzing writes

Processes don't write directly to /var/log/messages, rather they have to send their messages to rsyslogd which then managing writing messages to that log file. This is evident if you use the lsof command to see what files are opened in the /var/log directory by rsyslogd.

$ sudo lsof -p $(pgrep syslogd) | grep '/var/log'
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs
      Output information may be incomplete.
rsyslogd 733 root    5w   REG              253,1 11413306    1323777 /var/log/messages
rsyslogd 733 root    6w   REG              253,1    61714    1318348 /var/log/cron
rsyslogd 733 root    7w   REG              253,1    60103    1323778 /var/log/secure
rsyslogd 733 root    8w   REG              253,1    49725    1323776 /var/log/maillog

Can we see with strace?

So one approach would be to see what processes write to rsyslogd, rather then the log file messages directly. To do this we're going to first have to determine the PIDs of all the rsyslogd threads.

$ sudo ps -eLf | grep rsyslogd
root       733     1   733  0    4 Feb17 ?        00:00:00 /sbin/rsyslogd -n
root       733     1   795  0    4 Feb17 ?        00:00:01 /sbin/rsyslogd -n
root       733     1   796  0    4 Feb17 ?        00:00:00 /sbin/rsyslogd -n
root       733     1   798  0    4 Feb17 ?        00:00:01 /sbin/rsyslogd -n
root     27863 23659 27863  0    1 22:14 pts/2    00:00:00 grep --color=auto rsyslogd

With the PIDs in hand you can use strace to watch as logs are written to rsyslogd. This is a bit of trial and error, but I was able to strace this PID and then use logger to simulate activity on my /var/log/messages log file.

Example

$ sudo strace -p 795 -s 2000 -o rsyslogd.log

Now I write a message using logger:

$ logger hey

If we watch our strace log file, rsyslogd.log we'll see this type of messaging as a result:

$ sudo tail -f rsyslogd.log
select(4, [3], NULL, NULL, NULL)        = 1 (in [3])
recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"<13>Feb 18 22:15:49 saml: hey", 8096}], msg_controllen=0, msg_flags=MSG_CTRUNC}, MSG_DONTWAIT) = 29
futex(0x7f41ba963d14, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f41ba963d10, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f41ba963e70, FUTEX_WAKE_PRIVATE, 1) = 1
select(4, [3], NULL, NULL, NULL

If we strace all the rsyslogd PIDs, logging all their output to different log files (me*.log where * = 1-4) and then tail -f me*.log, we now get an expanded view from our logger hey command:

==> me1.log <==
)        = 1 (in [3])
recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"<13>Feb 18 22:23:23 saml: hey", 8096}], msg_controllen=0, msg_flags=MSG_CTRUNC}, MSG_DONTWAIT) = 29
futex(0x7f41ba963d14, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f41ba963d10, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1

==> me3.log <==
) = 0

==> me1.log <==
select(4, [3], NULL, NULL, NULL
==> me3.log <==
futex(0x7f41ba963e70, FUTEX_WAKE_PRIVATE, 1) = 0
write(5, "Feb 18 22:23:23 greeneggs saml: hey\n", 36) = 36
futex(0x7f41ba963d14, FUTEX_WAIT_PRIVATE, 67373, NULL

We can see a bit more of what's going on, but we still can't make out exactly what process generated the message to rsyslogd.

How about using fatrace?

This is a newer addition to the tracing suite of tools but it can prove very useful in situations such as yours. You can trace all file I/O access system wide using this tool, but we can narrow its focus to just the /var/log directory to see if we can't find out what process is throwing log messages to rsyslogd.

Example

For starters we'd run this command to watch just /var/log messages.

$ sudo fatrace | grep /var/log

Now as processes start to access /var/log we'll get a steady stream of which process is doing the accessing.

Here's the output when I ran this command, sudo -i:

systemd-journal(340): O /var/log/journal/0ee868f8b7da40f48013a281826b1b84
systemd-journal(340): C /var/log/journal/0ee868f8b7da40f48013a281826b1b84
rsyslogd(733): W /var/log/secure
rsyslogd(733): W /var/log/secure
auditd(546): W /var/log/audit/audit.log
auditd(546): W /var/log/audit/audit.log
auditd(546): W /var/log/audit/audit.log

Here's root ssh'ing into the box via localhost, ssh root@localhost:

auditd(546): W /var/log/audit/audit.log
auditd(546): W /var/log/audit/audit.log
rsyslogd(733): W /var/log/messages
rsyslogd(733): W /var/log/messages
rsyslogd(733): W /var/log/secure
sshd(23718): O /var/log/lastlog
rsyslogd(733): W /var/log/secure
sshd(23718): RC /var/log/lastlog
sshd(23718): RCO /var/log/btmp
auditd(546): W /var/log/audit/audit.log
sshd(23724): RCO /var/log/lastlog
sshd(23724): O /var/log/wtmp
sshd(23724): W /var/log/wtmp
sshd(23724): W /var/log/wtmp
sshd(23724): CW /var/log/wtmp
sshd(23724): CW /var/log/wtmp
sshd(23724): CWO /var/log/lastlog
sshd(23724): CW /var/log/lastlog

So using fatrace could help you to start to pinpoint what process is ultimately driving log messages to /var/log/messages.

How do messages get to /var/log/messages?

If you take something like SSH the daemon, sshd, is configured by this config file, /etc/ssh/sshd_config. There is this line in that file which specifies where sshd should send its log file messages.

# Logging
# obsoletes QuietMode and FascistLogging
#SyslogFacility AUTH
SyslogFacility AUTHPRIV
#LogLevel INFO

So this means that sshd is making use of the SyslogFacility, and its only sending messages that are AUTHPRIV or higher. So then how do the messages make their way to /var/log/messages?

Take a look at rsyslogd's config file, /etc/rsyslog.conf:

# Log anything (except mail) of level info or higher.
# Don't log private authentication messages!
*.info;mail.none;authpriv.none;cron.none                /var/log/messages

NOTE: Notice the authpriv on the left side there? That's what "routes" the messages from sshd to the file, /var/log/messages.

References

• Determining Specific File Responsible for High I/O