3

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.

7
  • 1
    It would be helpful if you showed some lines from your /var/log/message that appeared to lack a program name.
    – John1024
    Feb 19 '14 at 1:12
  • @John1024 can't I just check systemcalls that write to /var/log/message?
    – Jidrick
    Feb 19 '14 at 1:16
  • Possibly. Is there a reason that you don't want to do it the easy way?
    – John1024
    Feb 19 '14 at 1:33
  • This question may help: find which process is modifying a file. But, it is likely the case that the program writing to /var/log/messages is the syslog daemon, which just relays other programs' log messages. Feb 19 '14 at 1:58
  • @John1024 sshd is one of the programs that is writting to /var/log/message but after checking the PID, it turns out that that process is using the BASH command to write it. I don't know where the command file is.
    – Jidrick
    Feb 19 '14 at 1:58
8

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

15
  • I get something like 'sshd(23718): O /var/log/messages' But I still don't know why sshd writes to /var/log/messages. Where's this '/var/log/messages' defined?
    – Jidrick
    Feb 19 '14 at 3:42
  • Check your /etc/ssh/sshd_config file, there is this line: SyslogFacility AUTHPRIV, this tells sshd to send its logs to rsyslogd.
    – slm
    Feb 19 '14 at 3:50
  • That line is commented out by putting a '#' in front of it, but it still sends logs to /var/log/message
    – Jidrick
    Feb 19 '14 at 3:55
  • @Jidrick - commenting it out just let's the default kick in, which that is. You need to change the level. Change LogLevel to QUIET and uncomment it.
    – slm
    Feb 19 '14 at 3:57
  • Can you also remove this line '*.info;mail.none;authpriv.none;cron.none /var/log/messages'?
    – Jidrick
    Feb 19 '14 at 4:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.