Log every command typed in any shell: output (from logger function to syslog-ng/journald) contains duplicate entries for commands

auditsyslog-ngsystemdsystemd-journald

I installed syslog-ng to use on my desktop (Gentoo 64bit, upgraded to systemd i.e. was OpenRC before, with Openbox and Slim only) with my normal user to log all commands I type in the shell (bash first, then eventually zsh). I've explored different solutions, and different ways of setting this up, old and new and often this is achieved using the .bash_history file. I'm trying to implement this solution from a few years ago, with reliance on the companion trap. First I've modified .bashrc and set some history variables because the solution relies on formatting the history data, then making sure it is saved to its file, then pushing it to the log messaging system with logger in a function called in the shell environment. So first the variables:

export HISTCONTROL=
export HISTFILE=$HOME/.bash_history
export HISTFILESIZE=2000
export HISTIGNORE=
export HISTSIZE=1000
export HISTTIMEFORMAT="%a %b %Y %T %z "

typeset -r HISTCONTROL
typeset -r HISTFILE
typeset -r HISTFILESIZE
typeset -r HISTIGNORE
typeset -r HISTSIZE
typeset -r HISTTIMEFORMAT

shopt -s cmdhist
shopt -s histappend

PROMPT_COMMAND="history -a"
typeset -r PROMPT_COMMAND

ex. history command output with timestamps
860  Tue Jan 2014 10:33:50 -0900 exit
861  Tue Jan 2014 10:33:56 -0900 ls
862  Tue Jan 2014 10:33:58 -0900 history

Then, as explained in the linked article, you must add this trap which uses logger in .bashrc (there is reference to /etc/profile, but here I want this for my regular user only and ~/.profile is not sourced by something like lxterminal):

function log2syslog
{
   declare command
   command=$(fc -ln -0)
   logger -p local1.notice -t bash -i -- $USER : $command
}
trap log2syslog DEBUG

A single long hyphen was (mistakenly?) used in the original doc, followed by a space and $USER.

I've replaced my original syslog-ng configuration file. I've tried the suggested config from Arch, but after some warnings, I've configured it like so explained for Gentoo which is what the Arch doc is based on anyway:

@version: 3.4
options {
        chain_hostnames(no);

        # The default action of syslog-ng is to log a STATS line
        # to the file every 10 minutes.  That's pretty ugly after a while.
        # Change it to every 12 hours so you get a nice daily update of
        # how many messages syslog-ng missed (0).
        stats_freq(43200);
};

source src {
    unix-dgram("/dev/log" max-connections(256));
    internal();
};

source kernsrc { file("/proc/kmsg"); };

# define destinations
destination authlog { file("/var/log/auth.log"); };
destination syslog { file("/var/log/syslog"); };
destination cron { file("/var/log/cron.log"); };
destination daemon { file("/var/log/daemon.log"); };
destination kern { file("/var/log/kern.log"); };
destination lpr { file("/var/log/lpr.log"); };
destination user { file("/var/log/user.log"); };
destination mail { file("/var/log/mail.log"); };

destination mailinfo { file("/var/log/mail.info"); };
destination mailwarn { file("/var/log/mail.warn"); };
destination mailerr { file("/var/log/mail.err"); };

destination newscrit { file("/var/log/news/news.crit"); };
destination newserr { file("/var/log/news/news.err"); };
destination newsnotice { file("/var/log/news/news.notice"); };

destination debug { file("/var/log/debug"); };
destination messages { file("/var/log/messages"); };
destination console { usertty("root"); };

# By default messages are logged to tty12...
destination console_all { file("/dev/tty12"); };

# ...if you intend to use /dev/console for programs like xconsole
# you can comment out the destination line above that references /dev/tty12
# and uncomment the line below.
#destination console_all { file("/dev/console"); };

# create filters
filter f_authpriv { facility(auth, authpriv); };
filter f_syslog { not facility(authpriv, mail); };
filter f_cron { facility(cron); };
filter f_daemon { facility(daemon); };
filter f_kern { facility(kern); };
filter f_lpr { facility(lpr); };
filter f_mail { facility(mail); };
filter f_user { facility(user); };
filter f_debug { not facility(auth, authpriv, news, mail); };
filter f_messages { level(info..warn)
        and not facility(auth, authpriv, mail, news); };
filter f_emergency { level(emerg); };

filter f_info { level(info); };
filter f_notice { level(notice); };
filter f_warn { level(warn); };
filter f_crit { level(crit); };
filter f_err { level(err); };
filter f_failed { message("failed"); };
filter f_denied { message("denied"); };

# connect filter and destination
log { source(src); filter(f_authpriv); destination(authlog); };
log { source(src); filter(f_syslog); destination(syslog); };
log { source(src); filter(f_cron); destination(cron); };
log { source(src); filter(f_daemon); destination(daemon); };
log { source(kernsrc); filter(f_kern); destination(kern); };
log { source(src); filter(f_lpr); destination(lpr); };
log { source(src); filter(f_mail); destination(mail); };
log { source(src); filter(f_user); destination(user); };
log { source(src); filter(f_mail); filter(f_info); destination(mailinfo); };
log { source(src); filter(f_mail); filter(f_warn); destination(mailwarn); };
log { source(src); filter(f_mail); filter(f_err); destination(mailerr); };

log { source(src); filter(f_debug); destination(debug); };
log { source(src); filter(f_messages); destination(messages); };
log { source(src); filter(f_emergency); destination(console); };

# default log
log { source(src); destination(console_all); };

Of note is the comment from Arch wiki about the unix-stream reference misbehaving and prohibiting loading syslog-ng at startup. Changing the reference to unix-dgram takes care of that is basically the only change from the model used, except for providing a version number on the first line. After that you can do systemctl enable syslog-ng to have that available at boot.

So it is up and running manually here:

# systemctl status syslog-ng
syslog-ng.service - System Logger Daemon
   Loaded: loaded (/usr/lib64/systemd/system/syslog-ng.service; disabled)
   Active: active (running) since Tue 2014-01-28 20:23:36 EST; 1s ago
     Docs: man:syslog-ng(8)
 Main PID: 9238 (syslog-ng)
   CGroup: /system.slice/syslog-ng.service
           \u2514\u25009238 /usr/sbin/syslog-ng -F

Jan 28 20:23:36 gentoouser3x86_64 systemd[1]: Starting System Logger Daemon...
Jan 28 20:23:36 gentoouser3x86_64 systemd[1]: Started System Logger Daemon.

And I get the desired basic ouput in /var/log/messages:

Jan 28 20:42:00 gentoouser3x86_64 bash[9878]: myuser : shopt
Jan 28 20:42:04 gentoouser3x86_64 bash[9880]: myuser : su -
...
Jan 29 03:30:58 gentoouser3x86_64 bash[4386]: myuser : ls
Jan 29 03:30:58 gentoouser3x86_64 bash[4389]: myuser : ls  <--- duplicate
Jan 29 03:30:58 gentoouser3x86_64 bash[4391]: myuser : ls  <--- entries
Jan 29 04:36:31 gentoouser3x86_64 bash[4491]: myuser : cat .bashrc
Jan 29 04:37:14 gentoouser3x86_64 bash[4495]: myuser : cat .bashrc  <---
Jan 29 04:37:14 gentoouser3x86_64 bash[4497]: myuser : cat .bashrc  <---
Jan 29 04:37:35 gentoouser3x86_64 bash[4500]: myuser : nedit .bashrc
Jan 29 04:37:35 gentoouser3x86_64 bash[4503]: myuser : nedit .bashrc  <---
Jan 29 04:37:35 gentoouser3x86_64 bash[4505]: myuser : nedit .bashrc  <---

Or, if I disable syslog-ng with systemctl stop syslog-ng, I get the very same output from the journald binary log using journalctl -f (or journalctl -f -o verbose for the details) because systemd "takes over" in that case. Restarting syslog-ng and/or its socket reclaims the output immediately and sends it to its assorted files specified in its configuration.

Questions

  • Whether I use syslog-ng or journald, I get many duplicate lines in the logs whereas the commands were only executed once. Listing the contents of a directory for instance may show ls 2-3 times in the logs when I use many terminal windows. In particular, pressing enter in the CLI seems to echo the the last command in the log. Why? (Is it because the variable in the trap is still set to the last line of the history file? If so how can this be remedied?)

The main source link indicates that since version 4.1, bash can write to syslog directly… the changelog says:

"There is a new configuration option (in config-top.h) that forces
bash to forward all history entries to syslog."

  • So is the trap function used here still useful or is it obsolete? Is the a more modern/elegant way of doing this? Is that >4.1 option exposed somewhere or do you need to recompile bash to do that? What is it?
  • Aside from built-in options that are native to bash, can we expect implementing a similar solution for zsh? Or again, is there a better and more integrated way of doing this?
  • Is there lots of overhead generated from sending all the commands to the logs, and are journald and syslog-ng equal in this respect?

Best Answer

You have a lot going on there..... My best answer to this is to explain simply how I have seen session logging done in the past. Hopefully that will give you some options to explore.

  1. As you have already mentioned, pulling the bash history from the user accounts. This only works after the session has ended. Not really the best option but it's easy and reliable.
  2. Using a virtual terminal such as the screen command in Linux. This is not very robust as it starts on the user login however if they know it's being logged you can still kill the service. This works well in an end-user scenario. End users generally are trapped in a specified area anyway and don't have the knowledge to get around this.
  3. Pam_tty_audit module & aureport --tty This is a tool that allows you to specify which users get logged and allow you to specify the storage location of said logs... as always keep the logs off of the host server. I have the session logs on our SFTP server being copied off to a central logging server and a local cronjob moving them to a non shared location for archive.

This is built in for RedHat and Fedora however you can install it on Debian and Ubuntu. It's part of the auditd package I believe. Here is some documentation on auditd and the required configuration changes to pam (in /etc/pam.d/system-auth), specifying a single user here(root):

session required pam_tty_audit.so disable=* enable=root

Example output of aureport --tty:

TTY Report
===============================================
# date time event auid term sess comm data
===============================================
1. 1/29/2014 00:08:52 122249 0000 ? 4686960298 bash "ls -la",<ret>