Systemd – Python Service Not Sending All Output to Syslog

pythonsyslogsystemd

I have a custom service and have explicitly called for all stdout & stderr to be sent to syslog in the config file, however only some of the output appears in both syslog and the journal (they are consistent).

I my desperation I have done the following in the service files:

StandardOutput=syslog+console
StandardError=syslog+console

The service is a python script and I write to stdout using the 'print' statement (Python 2.7). These items seem to be lost to the ether, while other command outputs write correctly both to syslog and journald. If I run the script interactively everything appears in stdout as expected.

What is lacking in my knowledge?

Best Answer

JdeBP's comment was the correct solution:

Systemd Python service not sending all output to syslog

The solution was to add the -u option to the interpreter to make standard streams send their output unbuffered.

Update

As mikemaccana notes, the systemd journal is now the standard logging device for most distros. To view the stdout and stderr of a systemd unit use the journalctl command.

sudo journalctl -u [unit]

Original Answer

By default stdout and stderr of a systemd unit are sent to syslog.

If you're using the full systemd, this will be accesible via journalctl. On Fedora, it should be /var/log/messages but syslog will put it where your rules say.

Due to the date of the post, and assuming most people that are exposed to systemd are via fedora, you were probably hit by the bug described here: https://bugzilla.redhat.com/show_bug.cgi?id=754938 It has a good explanation of how it all works too =) (This was a bug in selinux-policy that caused error messages to not be logged, and was fixed in selinux-policy-3.10.0-58.fc16)

Bash Command History – How to Send to Syslog

This approach seems to be what you're looking for. This article discusses it, titled: Improving Bash Forensics Capabilities.

Excerpt:

While discussing with him about this topic, I realized that there are some ways to fine tune the history of commands to improve forensics investigations. In 2009, I also wrote a blog post about Bash which gave some ideas to send a Bash command history to a remote Syslog server. I checked my web logs and this blog post remains popular with more than 1000 visits for the last 30 days! Note that my blog post is outdated: Since the version 4.1, Bash supports Syslog natively but in most distribution, it is not enabled. To use this feature, you need to recompile your shell.

I found this not very convenient but the good point is that it cannot be disabled by the user (except if he switches his shell to another shell or another Bash binary). You just have to define "SYSLOG_HISTORY" in config-top.h:
$ vi config-top.h
#define SYSLOG_HISTORY
#if defined (SYSLOG_HISTORY)
#  define SYSLOG_FACILITY LOG_USER
#  define SYSLOG_LEVEL LOG_INFO
#endif

./configure
make install

So it would seem that though the feature is available in Bash 4.1+ it's likely not compiled by default with the Bash in most of the popular distros.

I haven't found a method for seeing what options a given Bash was compiled with, so to answer that question, you'll likely need to look to the upstream .spec file used when building the Bash RPM, for example, on Redhat distros, the same approach can be used for Debian based distros as well.

As confirmation I looked in the Bash .spec file for the Bash included with CentOS 7.2.1511 and it does not have this enabled:

$ grep configure bash.spec
%configure --with-bash-malloc=no --with-afs
- Use the configure macro instead of calling ./configure directly

Rolling your own RPM

Here are the steps that I used to build my own Bash using the gist of what the above details spelled out.

download & install source

To start I downloaded a source RPM (SRPM) of Bash that's available for CentOS 7.x. After downloading it I installed it into my rpmbuild directory:

$ rpmdev-setuptree
$ rpm -ivh bash-4.2.46-20.el7_2.src.rpm

patch

This will unpack files into rpmbuild/SPEC & rpmbuild/SOURCES. Now we're going to make a copy of the contents of the unpacked Bash tar.gz file using these steps:

$ cd rpmbuild/SOURCES
$ tar zxf bash-4.2.tar.gz
$ cp -prf bash-4.2 bash-4.2-orig
$ cd bash-4.2

Edit rpmbuild/SOURCES/bash-4.2/config-top.h and make it look like this:

/* Define if you want each line saved to the history list in bashhist.c:
   bash_add_history() to be sent to syslog(). */
#define SYSLOG_HISTORY
#if defined (SYSLOG_HISTORY)
#  define SYSLOG_FACILITY LOG_LOCAL1
#  define SYSLOG_LEVEL LOG_DEBUG
#endif

Edit rpmbuild/SOURCES/bash-4.2/bashhist.c and make bash_syslog_history function look like this:

void
bash_syslog_history (line)
     const char *line;
{
  char trunc[SYSLOG_MAXLEN];

  if (strlen(line) < SYSLOG_MAXLEN)
    syslog (SYSLOG_FACILITY|SYSLOG_LEVEL, "HISTORY: PID=%d UID=%d USER=%s CMD=%s", getpid(), current_user.uid, current_user.user_name, line);
  else
    {
      strncpy (trunc, line, SYSLOG_MAXLEN);
      trunc[SYSLOG_MAXLEN - 1] = '\0';
      syslog (SYSLOG_FACILITY|SYSLOG_LEVEL, "HISTORY: PID=%d UID=%d USER=%s CMD(TRUNCATED)=%s", getpid(), current_user.uid, current_user.user_name, trunc);
    }
}

Now generate a .patch file which includes our changes to these 2 files:

$ cd $HOME/rpmbuild/SOURCES
$ diff -Npru bash-4.2-orig bash-4.2 > bash_history_rsyslog.patch

Add these lines to $HOME/rpmbuid/SPEC/bash.spec. Put these lines into the appropriate places in the SPEC file:

# history syslog
Patch144: bash_history_rsyslog.patch
...
...
%patch144 -p1 -b .history_rsyslog

build

Now build it:

$ cd $HOME/rpmbuild/SPEC
$ rpmbuild -ba bash.spec

The tail end of this build will look like this:

...
Processing files: bash-debuginfo-4.2.46-20.el7.centos.x86_64
Provides: bash-debuginfo = 4.2.46-20.el7.centos bash-debuginfo(x86-64) = 4.2.46-20.el7.centos
Requires(rpmlib): rpmlib(FileDigests) <= 4.6.0-1 rpmlib(PayloadFilesHavePrefix) <= 4.0-1 rpmlib(CompressedFileNames) <= 3.0.4-1
Checking for unpackaged file(s): /usr/lib/rpm/check-files /home/vagrant/rpmbuild/BUILDROOT/bash-4.2.46-20.el7.centos.x86_64
Wrote: /home/vagrant/rpmbuild/RPMS/x86_64/bash-4.2.46-20.el7.centos.x86_64.rpm
Wrote: /home/vagrant/rpmbuild/RPMS/x86_64/bash-doc-4.2.46-20.el7.centos.x86_64.rpm
Wrote: /home/vagrant/rpmbuild/RPMS/x86_64/bash-debuginfo-4.2.46-20.el7.centos.x86_64.rpm
Executing(%clean): /bin/sh -e /var/tmp/rpm-tmp.nGworU
+ umask 022
+ cd /home/vagrant/rpmbuild/BUILD
+ cd bash-4.2
+ rm -rf /home/vagrant/rpmbuild/BUILDROOT/bash-4.2.46-20.el7.centos.x86_64
+ exit 0

install

Once complete, we can install the resulting RPM:

$ sudo rpm -ivh --force $HOME/rpmbuild/RPMS/x86_64/bash-4.2.46-20.el7.centos.x86_64.rpm
Preparing...                          ################################# [100%]
Updating / installing...
   1:bash-4.2.46-20.el7.centos        ################################# [100%]

configure rsyslog

Now modify rsyslog's /etc/rsyslog.conf config:

$ sudo vim /etc/rsyslog.conf
...
...
$ModLoad imudp
$UDPServerRun 514 
$ModLoad imtcp
$InputTCPServerRun 514

...
...

#### GLOBAL DIRECTIVES ####
$template IpTemplate,"/var/log/bash-log/%FROMHOST-IP%.log"
*.* ?IpTemplate
& ~

...
...

Then restart Rsyslog:

$ sudo systemctl restart rsyslog

test & confirm

Now run a new instance of Bash as root, and run a couple of commands:

$ sudo -Es
$ ls

And tail the log file, /var/log/bash-log/127.0.0.1.log:

$ tail /var/log/bash-log/127.0.0.1.log
2018-07-19T23:23:37.568131-04:00 centos7 bash: HISTORY: PID=12511 UID=1000 USER=vagrant CMD=sudo -Es
2018-07-19T23:23:37.573825-04:00 centos7 sudo: vagrant : TTY=pts/0 ; PWD=/home/vagrant/rpmbuild/SOURCES ; USER=root ; COMMAND=/bin/bash
2018-07-19T23:23:37.589258-04:00 centos7 systemd-logind: Got message type=signal sender=org.freedesktop.DBus destination=n/a object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameOwnerChanged cookie=4454 reply_cookie=0 error=n/a
2018-07-19T23:23:37.590633-04:00 centos7 dbus[588]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
2018-07-19T23:23:37.590806-04:00 centos7 dbus-daemon: dbus[588]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
2018-07-19T23:23:37.592160-04:00 centos7 dbus[588]: [system] Activated service 'org.freedesktop.problems' failed: Failed to execute program /lib64/dbus-1/dbus-daemon-launch-helper: Success
2018-07-19T23:23:37.592311-04:00 centos7 dbus-daemon: dbus[588]: [system] Activated service 'org.freedesktop.problems' failed: Failed to execute program /lib64/dbus-1/dbus-daemon-launch-helper: Success
2018-07-19T23:23:37.602174-04:00 centos7 systemd-logind: Got message type=signal sender=org.freedesktop.DBus destination=n/a object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameOwnerChanged cookie=4455 reply_cookie=0 error=n/a
2018-07-19T23:23:38.520300-04:00 centos7 bash: HISTORY: PID=12585 UID=0 USER=root CMD=ls
2018-07-19T23:23:49.210406-04:00 centos7 bash: HISTORY: PID=12585 UID=0 USER=root CMD=tail /var/log/bash-log/127.0.0.1.log

Notice the CMD=... lines in this log? These are the commands we just ran, a ls & tail.

Prebuilt?

To help people out with this I've taken the liberty to build the Bash RPM with the modifications made in Copr.

https://copr.fedorainfracloud.org/coprs/slmingol/bash/

Best Answer

Related Solutions

Systemd – How to View stdout/stderr of a Service

Update

Bash Command History – How to Send to Syslog

Rolling your own RPM

Prebuilt?

Related Question