What’s new in RHEL7: Viewing the journal

In a Linux distro using systemd such as RHEL7, you can view the logs by rumning journalctl.

# journalctl
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:37:48 CDT. --
Sep 25 00:00:38 server.example.com systemd-journal[232]: Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free
Sep 25 00:00:38 server.example.com systemd-journal[232]: Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpuset
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpu
...Truncated

The output will be very similar to what you see when you run “cat /var/log/messages”. You can scroll up and down and search by typing / because journalctl uses less pager. You will notice that errors are highlighted in red.

In some cases you may notice the content are quite similar to /var/log/messages. Journald can forward logs to traditional syslog such as rsyslog and that may be the default setting in your distro. For now, I just want to state that the messages you see when running journalctl are logs collected by journald which is a part of systemd.

Here after, we will refer to the logs as “the journal”. To view the journal in the reverse order, use -r.

# journalctl -r
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:40:01 CDT. --
Oct 12 05:40:01 server.example.com CROND[19083]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Oct 12 05:40:01 server.example.com systemd[1]: Starting Session 8578 of user root.
Oct 12 05:40:01 server.example.com systemd[1]: Started Session 8578 of user root.
Oct 12 05:37:48 server.example.com dbus-daemon[1050]: dbus[1050]: [system] Successfully activated service 'org.freedesktop.problems'
Oct 12 05:37:48 server.example.com dbus[1050]: [system] Successfully activated service 'org.freedesktop.problems'
Oct 12 05:37:48 server.example.com dbus[1050]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Oct 12 05:37:48 server.example.com dbus-daemon[1050]: dbus[1050]: [system] Activating service name='org.freedesktop.problems' (using

For live troubleshooting, instead of running tail -f on /var/log/messages, we will use -f.

# journalctl -f
-- Logs begin at Sun 2016-09-25 00:00:38 CDT. --
Oct 12 05:37:47 server.example.com systemd[1]: Starting Session 8577 of user root.
Oct 12 05:37:47 server.example.com sshd[18913]: pam_unix(sshd:session): session opened for user root by (uid=0)
Oct 12 05:37:47 server.example.com sshd[18913]: Starting session: shell on pts/0 for root from 137.230.243.50 port 52132
Oct 12 05:37:48 server.example.com dbus-daemon[1050]: dbus[1050]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Oct 12 05:37:48 server.example.com dbus[1050]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Oct 12 05:37:48 server.example.com dbus[1050]: [system] Successfully activated service 'org.freedesktop.problems'
Oct 12 05:37:48 server.example.com dbus-daemon[1050]: dbus[1050]: [system] Successfully activated service 'org.freedesktop.problems'
Oct 12 05:40:01 server.example.com systemd[1]: Started Session 8578 of user root.
Oct 12 05:40:01 server.example.com systemd[1]: Starting Session 8578 of user root.
Oct 12 05:40:01 server.example.com CROND[19083]: (root) CMD (/usr/lib64/sa/sa1 1 1)
^C
#

To see the last 10 lines of the journal, instead of tail -n 10 /var/log/messages, we will use journalctl -n 10.

# journalctl -n 10
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:46:24 CDT. --
Oct 12 05:40:01 server.example.com systemd[1]: Starting Session 8578 of user root.
Oct 12 05:40:01 server.example.com CROND[19083]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Oct 12 05:44:35 server.example.com selogrd[3144]: Error description: Cannot send PASSWORD record to host version 3
Oct 12 05:44:35 server.example.com selogrd[3144]: Error description: Cannot send PASSWORD record to host version 3
Oct 12 05:44:35 server.example.com selogrd[3144]: Error description: Cannot send PASSWORD record to host version 3
Oct 12 05:45:01 server.example.com systemd[1]: Started Session 8579 of user root.
Oct 12 05:45:01 server.example.com systemd[1]: Starting Session 8579 of user root.
Oct 12 05:45:01 server.example.com CROND[19253]: (root) CMD (/monitoring/CAT/disk_monitor.pl > /dev/null 2>&1)
Oct 12 05:45:04 server.example.com snmpd[1338]: Connection from UDP: [137.230.143.28]:54649->[172.22.230.92]:161
Oct 12 05:46:24 server.example.com snmpd[1338]: Connection from UDP: [137.230.143.28]:38836->[172.22.230.92]:161
#

To look at messages from the most recent boot, we use journalctl -b.

# journalctl -b
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:46:24 CDT. --
Sep 25 00:00:38 server.example.com systemd-journal[232]: Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free
Sep 25 00:00:38 server.example.com systemd-journal[232]: Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpuset
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpu
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpuacct
Sep 25 00:00:38 server.example.com kernel: Linux version 3.10.0-327.22.2.el7.x86_64 (mockbuild@x86-030.build.eng.bos.redhat.com) (gcc
Sep 25 00:00:38 server.example.com kernel: Command line: BOOT_IMAGE=/vmlinuz-3.10.0-327.22.2.el7.x86_64 root=/dev/mapper/vg00-root_lv
Sep 25 00:00:38 server.example.com kernel: Disabled fast string operations
Sep 25 00:00:38 server.example.com kernel: e820: BIOS-provided physical RAM map:

To look at previous boot messages journalctl -b -1, -2 and so on. To list the previous boot logs available, use –list-boots.

# journalctl --list-boots
-3 058f003202b84a788db48f25675ef4bc Mon 2016-10-03 05:43:20 CDT—Mon 2016-10-03 05:47:49 CDT
-2 caa1cb96301d4f76a2f96990d89f27c7 Mon 2016-10-03 05:48:06 CDT—Mon 2016-10-03 05:48:43 CDT
-1 c6067ee7fe034104842bffd6a6b58788 Mon 2016-10-03 05:50:08 CDT—Mon 2016-10-03 05:53:09 CDT
 0 0c895f7a2c5f4bb4850b9e4b23c08dba Mon 2016-10-03 05:55:22 CDT—Wed 2016-10-12 04:37:04 CDT

To view messages logged by the kernel, use -k.

# journalctl -k
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:52:11 CDT. --
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpuset
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpu
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpuacct
Sep 25 00:00:38 server.example.com kernel: Linux version 3.10.0-327.22.2.el7.x86_64 (mockbuild@x86-030.build.eng.bos.redhat.com) (gcc
Sep 25 00:00:38 server.example.com kernel: Command line: BOOT_IMAGE=/vmlinuz-3.10.0-327.22.2.el7.x86_64 root=/dev/mapper/vg00-root_lv
Sep 25 00:00:38 server.example.com kernel: Disabled fast string operations
Sep 25 00:00:38 server.example.com kernel: e820: BIOS-provided physical RAM map:
Sep 25 00:00:38 server.example.com kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009efff] usable
Sep 25 00:00:38 server.example.com kernel: BIOS-e820: [mem 0x000000000009f000-0x000000000009ffff] reserved
Sep 25 00:00:38 server.example.com kernel: BIOS-e820: [mem 0x00000000000ca000-0x00000000000cbfff] reserved

To see messages from a particular service say ssh.

# journalctl -u sshd
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:52:11 CDT. --
Sep 25 00:01:18 server.example.com systemd[1]: Started OpenSSH server daemon.
Sep 25 00:01:18 server.example.com systemd[1]: Starting OpenSSH server daemon...
Sep 25 00:01:19 server.example.com sshd[1343]: Could not load host key: /etc/ssh/ssh_host_dsa_key
Sep 25 00:01:20 server.example.com sshd[1343]: Set /proc/self/oom_score_adj from 0 to -1000
Sep 25 00:01:20 server.example.com sshd[1343]: Server listening on 0.0.0.0 port 22.
Sep 25 00:01:20 server.example.com sshd[1343]: Server listening on :: port 22.
Sep 25 00:03:26 server.example.com sshd[3679]: Set /proc/self/oom_score_adj to 0
Sep 25 00:03:26 server.example.com sshd[3679]: error: Could not load host key: /etc/ssh/ssh_host_dsa_key
Sep 25 00:03:26 server.example.com sshd[3679]: Connection from 137.230.243.50 port 60468 on 172.22.230.92 port 22
Sep 25 00:03:27 server.example.com sshd[3679]: Found matching DSA key: 

We can also filter by the log verbosity, in this example errros.

# journalctl -p err
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:52:11 CDT. --
Sep 25 00:00:38 server.example.com kernel: sd 2:0:1:0: [sdb] Assuming drive cache: write through
Sep 25 00:00:38 server.example.com kernel: sd 2:0:0:0: [sda] Assuming drive cache: write through
Sep 25 00:00:57 server.example.com kernel: piix4_smbus 0000:00:07.3: Host SMBus controller not enabled!
Sep 25 00:01:18 server.example.com dnsmasq[1321]: bad address at /etc/hosts line 2
Sep 25 00:01:21 server.example.com systemd[1]: Failed to start Crash recovery kernel arming.
Sep 25 00:01:51 server.example.com puppet-agent[3174]: (/File[/var/lib/puppet/lib]) Could not evaluate: Could not retrieve informatio
Sep 25 00:02:54 server.example.com puppet-master[3221]: Failed when searching for node server.example.com: Failed 

To view logs from today onwards, use --since today.

# journalctl  --since today
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:52:11 CDT. --
Oct 12 00:00:01 server.example.com systemd[1]: Started Session 8459 of user root.
Oct 12 00:00:01 server.example.com systemd[1]: Starting Session 8459 of user root.
Oct 12 00:00:01 server.example.com systemd[1]: Started Session 8460 of user foreman.
Oct 12 00:00:01 server.example.com systemd[1]: Starting Session 8460 of user foreman.
Oct 12 00:00:01 server.example.com systemd[1]: Started Session 8458 of user root.
Oct 12 00:00:01 server.example.com systemd[1]: Starting Session 8458 of user root.

We can also use a date if we like.

# journalctl --since 2016-10-1
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:52:11 CDT. --
Oct 01 00:00:01 server.example.com systemd[1]: Started Session 2995 of user root.
Oct 01 00:00:01 server.example.com systemd[1]: Starting Session 2995 of user root.
Oct 01 00:00:01 server.example.com systemd[1]: Started Session 2994 of user foreman.
Oct 01 00:00:01 server.example.com systemd[1]: Starting Session 2994 of user foreman.
Oct 01 00:00:01 server.example.com systemd[1]: Started Session 2993 of user root.
Oct 01 00:00:01 server.example.com systemd[1]: Starting Session 2993 of user root.
Oct 01 00:00:01 server.example.com systemd[1]: Started Session 2996 of user foreman.
Oct 01 00:00:01 server.example.com systemd[1]: Starting Session 2996 of user foreman.
Oct 01 00:00:01 server.example.com CROND[26215]: (foreman) CMD (   /usr/sbin/foreman-rak

Likewise, we can also view by stating the end time.

# journalctl --until 2016-10-1
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:55:01 CDT. --
Sep 25 00:00:38 server.example.com systemd-journal[232]: Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free
Sep 25 00:00:38 server.example.com systemd-journal[232]: Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free
Sep 25 00:00:38 server.example.com kernel: Initializing cgroup subsys cpuset
...
p/bin/pmie_check -C)
Sep 30 23:58:01 server.example.com systemd[1]: Removed slice user-997.slice.
Sep 30 23:58:01 server.example.com systemd[1]: Stopping user-997.slice.
Sep 30 23:59:56 server.example.com snmpd[1338]: Connection from UDP: [137.230.143.28]:50664->[172.22.230.92]:161

Journald adds lots of metadata about the sending service when it logs messages. We can use these fields to filter the message.

journactl tab tab will show all the available fields.

# journalctl
_AUDIT_LOGINUID=             ERRNO=                       _PID=                        _SYSTEMD_SESSION=
_AUDIT_SESSION=              _EXE=                        PRIORITY=                    _SYSTEMD_UNIT=
_BOOT_ID=                    _GID=                        __REALTIME_TIMESTAMP=        _TRANSPORT=
_CMDLINE=                    _HOSTNAME=                   _SELINUX_CONTEXT=            _UDEV_DEVLINK=
CODE_FILE=                   _KERNEL_DEVICE=              _SOURCE_REALTIME_TIMESTAMP=  _UDEV_DEVNODE=
CODE_FUNC=                   _KERNEL_SUBSYSTEM=           SYSLOG_FACILITY=             _UDEV_SYSNAME=
CODE_LINE=                   _MACHINE_ID=                 SYSLOG_IDENTIFIER=           _UID=
_COMM=                       MESSAGE=                     SYSLOG_PID=
COREDUMP_EXE=                MESSAGE_ID=                  _SYSTEMD_CGROUP=
__CURSOR=                    __MONOTONIC_TIMESTAMP=       _SYSTEMD_OWNER_UID=

To view messages from a process with PID 1 which is systemd, journalctl _PID=1.

# journalctl _PID=1
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 05:55:01 CDT. --
Sep 25 00:00:38 server.example.com systemd[1]: Started dracut cmdline hook.
Sep 25 00:00:38 server.example.com systemd[1]: Starting dracut pre-udev hook...
Sep 25 00:00:38 server.example.com systemd[1]: Started dracut pre-udev hook.
Sep 25 00:00:38 server.example.com systemd[1]: Starting udev Kernel Device Manager...
Sep 25 00:00:38 server.example.com systemd[1]: Started udev Kernel Device Manager.

Journactl can format the output in different ways.

# journalctl -o (tab tab)
cat              json             json-sse         short-iso        short-precise
export           json-pretty      short            short-monotonic  verbose

Here’s an example

# journalctl  -o json-pretty
{
        "__CURSOR" : "s=8c2eb7465ffb409f9ac1870a6fd4ab3e;i=1;b=366cd3905de94fe48b61ba27151c9df3;m=55b991;t=53d4de47a5322;x=dad424d162a94
        "__REALTIME_TIMESTAMP" : "1474779638551330",
        "__MONOTONIC_TIMESTAMP" : "5618065",
        "_BOOT_ID" : "366cd3905de94fe48b61ba27151c9df3",
        "PRIORITY" : "6",
        "_TRANSPORT" : "driver",
        "MESSAGE" : "Runtime journal is using 8.0M (max allowed 802.0M, trying to leave 1.1G free of 7.8G available \uffffffe2\uffffff86
        "MESSAGE_ID" : "ec387f577b844b8fa948f33cad9a75e6",
        "_PID" : "232",
        "_UID" : "0",
        "_GID" : "0",
        "_COMM" : "systemd-journal",
        "_EXE" : "/usr/lib/systemd/systemd-journald",
        "_CMDLINE" : "/usr/lib/systemd/systemd-journald",
        "_CAP_EFFECTIVE" : "5402800cf",
        "_SYSTEMD_CGROUP" : "/system.slice/systemd-journald.service",
        "_SYSTEMD_UNIT" : "systemd-journald.service",
        "_SYSTEMD_SLICE" : "system.slice",
        "_MACHINE_ID" : "83a4d6b5ee754b1294fffa730586e481",
        "_HOSTNAME" : "server.example.com"
}

Before we end, everything we have seen so far can be combined. For instance, to view sshd logs of verbosity err or higher, use journalctl -u sshd -p err.

# journalctl -u sshd -p err
-- Logs begin at Sun 2016-09-25 00:00:38 CDT, end at Wed 2016-10-12 06:10:01 CDT. --
Sep 25 00:03:26 server.example.com sshd[3679]: error: Could not load host key: /etc/ssh/ssh_host_dsa_key
Sep 25 00:08:10 server.example.com sshd[3935]: error: Could not load host key: /etc/ssh/ssh_host_dsa_key
Sep 25 00:12:15 server.example.com sshd[4084]: error: Could not load host key: /etc/ssh/ssh_host_dsa_key
Sep 25 00:39:25 server.example.com sshd[5150]: error: Could not load host key: 
Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s