How to log systemd service state changes

Log systemd service state changes using rsyslog.

At first, look how the log entry looks like as it will come in handy in the next step.

$ sudo journalctl --follow --output verbose _TRANSPORT=journal SYSLOG_IDENTIFIER=systemd

Wed 2021-04-14 20:50:55.891441 UTC [s=9427351f18774a69b609ca7e9f914343;i=e2a;b=89d52c9da1f84b029e4f8270bec49e31;m=27bc63dbe5;t=5bff4e73b2823;x=7394e861da280911]
    _MACHINE_ID=8a3d7205b9ac458386ceba4c795decbb
    _HOSTNAME=bullseye
    PRIORITY=6
    SYSLOG_FACILITY=3
    SYSLOG_IDENTIFIER=systemd
    _UID=0
    _GID=0
    _SELINUX_CONTEXT=unconfined
    _TRANSPORT=journal
    _CAP_EFFECTIVE=1ffffffffff
    TID=1
    CODE_FILE=src/core/job.c
    JOB_TYPE=start
    _PID=1
    _COMM=systemd
    _EXE=/usr/lib/systemd/systemd
    _SYSTEMD_CGROUP=/init.scope
    _SYSTEMD_UNIT=init.scope
    _SYSTEMD_SLICE=-.slice
    CODE_LINE=940
    CODE_FUNC=job_log_done_status_message
    JOB_RESULT=done
    MESSAGE_ID=39f53479d3a045ac8e11786248231fbf
    UNIT=nginx.service
    MESSAGE=Started A high performance web server and a reverse proxy server.
    _BOOT_ID=89d52c9da1f84b029e4f8270bec49e31
    _CMDLINE=/lib/systemd/systemd --system --deserialize 35
    JOB_ID=2730
    INVOCATION_ID=ffd64fa6e3d744f5b18d76243c7dbde2
    _SOURCE_REALTIME_TIMESTAMP=1618433455891441

Create rsyslog configuration.

$ cat <<EOF | sudo tee /etc/rsyslog.d/systemd.conf
module(load="imjournal" IgnorePreviousMessages="on")
module(load="mmjsonparse")

template(name="systemd_message_template" type="string" string="%TIMESTAMP% %HOSTNAME% %programname%  %msg% [%\$!UNIT%, %\$!JOB_TYPE%, %\$!JOB_RESULT%, %\$!CODE_FUNC%]\n" )

action(type="mmjsonparse")
if \$programname == 'systemd' and \$!UNIT != "" then {
   action(type="omfile" file="/var/log/systemd_service_state.log" template="systemd_message_template")
}
EOF

module(load="imjournal" IgnorePreviousMessages="on")
module(load="mmjsonparse")

template(name="systemd_message_template" type="string" string="%TIMESTAMP% %HOSTNAME% %programname%  %msg% [%$!UNIT%, %$!JOB_TYPE%, %$!JOB_RESULT%, %$!CODE_FUNC%]\n" )

action(type="mmjsonparse")
if $programname == 'systemd' and $!UNIT != "" then {
   action(type="omfile" file="/var/log/systemd_service_state.log" template="systemd_message_template")
}

Test rsyslogd configuration.

$ sudo rsyslogd -N 1

rsyslogd: version 8.2102.0, config validation run (level 1), master config /etc/rsyslog.conf
rsyslogd: End of config validation run. Bye.

Restart rsyslogd service.

$ sudo systemctl restart rsyslog

This is how nginx restart operation is logged.

$ cat  /var/log/systemd_service_state.log

Apr 14 21:48:23 bullseye systemd  Stopping A high performance web server and a reverse proxy server... [nginx.service, stop, , job_log_begin_status_message]
Apr 14 21:48:23 bullseye systemd  nginx.service: Succeeded. [nginx.service, , , unit_log_success]
Apr 14 21:48:23 bullseye systemd  Stopped A high performance web server and a reverse proxy server. [nginx.service, restart, done, job_log_done_status_message]
Apr 14 21:48:23 bullseye systemd  Starting A high performance web server and a reverse proxy server... [nginx.service, start, , job_log_begin_status_message]
Apr 14 21:48:23 bullseye systemd  Started A high performance web server and a reverse proxy server. [nginx.service, start, done, job_log_done_status_message]

This is how system restart operation is logged.

$ cat /var/log/systemd_service_state.log

Apr 14 21:49:19 bullseye systemd  e2scrub_reap.service: Succeeded. [e2scrub_reap.service, , , unit_log_success]
Apr 14 21:49:19 bullseye systemd  Finished Remove Stale Online ext4 Metadata Check Snapshots. [e2scrub_reap.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Found device 82540EM Gigabit Ethernet Controller (PRO/1000 MT Desktop Adapter). [sys-subsystem-net-devices-eth0.device, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started ifup for eth0. [ifup@eth0.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started User Login Management. [systemd-logind.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Finished Helper to synchronize boot up for ifupdown. [ifupdown-pre.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Starting Raise network interfaces... [networking.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  Finished Raise network interfaces. [networking.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Reached target Network. [network.target, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Starting chrony, an NTP client/server... [chrony.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  Starting MariaDB 10.5.9 database server... [mariadb.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  Starting A high performance web server and a reverse proxy server... [nginx.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  Condition check resulted in fast remote file copy program daemon being skipped. [rsync.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Starting OpenBSD Secure Shell server... [ssh.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  Starting Permit User Sessions... [systemd-user-sessions.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  Started Unattended Upgrades Shutdown. [unattended-upgrades.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Finished Permit User Sessions. [systemd-user-sessions.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Getty on tty1. [getty@tty1.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Reached target Login Prompts. [getty.target, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started OpenBSD Secure Shell server. [ssh.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started chrony, an NTP client/server. [chrony.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Reached target System Time Synchronized. [time-sync.target, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Daily apt download activities. [apt-daily.timer, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Daily apt upgrade and clean activities. [apt-daily-upgrade.timer, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Periodic ext4 Online Metadata Check for All Filesystems. [e2scrub_all.timer, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Discard unused blocks once a week. [fstrim.timer, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Daily rotation of log files. [logrotate.timer, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started Daily man-db regeneration. [man-db.timer, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Reached target Timers. [timers.target, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  nginx.service: Failed to parse PID from file /run/nginx.pid: Invalid argument [nginx.service, , , service_load_pid_file]
Apr 14 21:49:19 bullseye systemd  Started A high performance web server and a reverse proxy server. [nginx.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Started MariaDB 10.5.9 database server. [mariadb.service, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Reached target Multi-User System. [multi-user.target, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Reached target Graphical Interface. [graphical.target, start, done, job_log_done_status_message]
Apr 14 21:49:19 bullseye systemd  Starting Update UTMP about System Runlevel Changes... [systemd-update-utmp-runlevel.service, start, , job_log_begin_status_message]
Apr 14 21:49:19 bullseye systemd  systemd-update-utmp-runlevel.service: Succeeded. [systemd-update-utmp-runlevel.service, , , unit_log_success]
Apr 14 21:49:19 bullseye systemd  Finished Update UTMP about System Runlevel Changes. [systemd-update-utmp-runlevel.service, start, done, job_log_done_status_message]
Apr 14 21:53:03 bullseye systemd  Created slice User Slice of UID 1000. [user-1000.slice, start, done, job_log_done_status_message]
Apr 14 21:53:03 bullseye systemd  Starting User Runtime Directory /run/user/1000... [user-runtime-dir@1000.service, start, , job_log_begin_status_message]
Apr 14 21:53:03 bullseye systemd  Finished User Runtime Directory /run/user/1000. [user-runtime-dir@1000.service, start, done, job_log_done_status_message]
Apr 14 21:53:03 bullseye systemd  Starting User Manager for UID 1000... [user@1000.service, start, , job_log_begin_status_message]
Apr 14 21:53:03 bullseye systemd  Started User Manager for UID 1000. [user@1000.service, start, done, job_log_done_status_message]
Apr 14 21:53:03 bullseye systemd  Started Session 1 of user vagrant. [session-1.scope, start, done, job_log_done_status_message]

See imjournal: Systemd Journal Input Module web-page for more information.