第13章：分析、储存与存取系统日志介绍（一）

前言

本章节，是要讲解系统日志的架构与介绍

系统日志

在一个标准的作业系统中，会有系统日志，并分别存放档案在某些路径底下，每一种之系统log档案所存放的资讯也有所不同，以下列出几个重要的系统日志档案清单：

  • /var/log/messages：这个档案会存放大部分系统之资讯，像是关於使用者验证的日志、收发信箱之处理讯息、排程工作执行以及那些系统错误有关的讯息。
  • /var/log/secure：这个档案会存放有关於作业系统上安全与验证相关事件的讯息。
  • /var/log/maillog：这个档案会存放有关於mail server的日志讯息。
  • /var/log/cron：这个档案会存放有关於排程工作执行的纪录与相关日志讯息。

写入日志讯息至档案

在写入一笔日志讯息的时候，需要注意每一个日志都有分等级的，相关的日志等级如下：

  • 当等级代号为0的时候，则此日志等级为紧急，表示作业系统无法使用，可能是server有问题。
  • 当等级代号为1的时候，则此日志等级为警告，表示这个动作必会立即的发生。
  • 当等级代号为2的时候，则此日志讯息为危急，表示有危急的事情发生。
  • 当等级代号为3的时候，则此日志讯息为错误，表示有非危急的错误发生。
  • 当等级代号为4的时候，则此日志讯息为警告，表示有警告的事件发生。
  • 当等级代号为5的时候，则此日志讯息通知，表示是正常的讯号事件讯息。
  • 当等级代号为6的时候，则日志讯息为资讯，表示是一些资讯，意思是运作正常的讯息。
  • 当等级代号为7的时候，则日志讯息为除错的意思，表示是这些讯息是除错等级的讯息。

相关的基本rsyslog设定档范例如下：

#### RULES ####

# Log all kernel messages to the console.
# Logging much else clutters up the screen.
#kern.*                                                 /dev/console

# 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

# The authpriv file has restricted access.
authpriv.*                                              /var/log/secure

# Log all the mail messages in one place.
mail.*                                                  -/var/log/maillog


# Log cron stuff
cron.*                                                  /var/log/cron

# Everybody gets emergency messages
*.emerg                                                 :omusrmsg:*

# Save news errors of level crit and higher in a special file.
uucp,news.crit                                          /var/log/spooler

# Save boot messages also to boot.log
local7.*                                                /var/log/boot.log

上述的设定档也在/etc/rsyslog.conf档案中，从弟38行开始即是，并一直到第65行，每一个种类服务都会对应到一个日志档案，这些日志档案也就是先前所提到预设的日志档案路径。

分析日志项目

首先，以下面这个范例来介绍日志中，在一行讯息中的栏位：

Sep 18 00:01:03 localhost kernel: Linux version 4.18.0-305.3.1.el8_4.x86_64 ([email protected]) (gcc version 8.4.1 20200928 (Red Hat 8.4.1-1) (GCC)) #1 SMP Thu Jun 17 07:52:48 UTC 2021

一开始会有一个时间，指的是这个日志什麽时候被记录的，接着是哪个主机传送这个讯息，程序或是程序名称以及PID（Process id）数字，来传送这个讯息的；最後就是这个传送的讯息内容。

监控日志讯息

我们可以使用tail这个指令来监控日志的讯息，透过监控日志的讯息可以及时知道日志讯息，使用这个指令并搭配-f参数便可以自动的刷新档案内容，相关的指令执行方式如下：

[rockylinux@workstation ~]$ sudo tail -f /var/log/messages
[sudo] password for rockylinux:
Oct  4 01:12:49 workstation systemd[1]: Started Cleanup of Temporary Directories.
Oct  4 01:30:02 workstation systemd[1]: Starting dnf makecache...
Oct  4 01:30:06 workstation dnf[2683]: Rocky Linux 8 - AppStream                       5.8 kB/s | 4.8 kB     00:00
Oct  4 01:30:07 workstation dnf[2683]: Rocky Linux 8 - BaseOS                          5.8 kB/s | 4.3 kB     00:00
Oct  4 01:30:09 workstation dnf[2683]: Rocky Linux 8 - Extras                          2.8 kB/s | 3.5 kB     00:01
Oct  4 01:30:10 workstation dnf[2683]: Extra Packages for Enterprise Linux Modular 8 - 6.0 kB/s | 8.1 kB     00:01
Oct  4 01:30:11 workstation dnf[2683]: Extra Packages for Enterprise Linux 8 - x86_64   11 kB/s | 8.3 kB     00:00
Oct  4 01:30:14 workstation dnf[2683]: Metadata cache created.
Oct  4 01:30:14 workstation systemd[1]: dnf-makecache.service: Succeeded.
Oct  4 01:30:14 workstation systemd[1]: Started dnf makecache.

由上述的指令执行输出的讯息可以知道，查看系统日志需要root使用者权限，而使用-f参数进行刷新的话，则此程序会卡在前景，一直监控有无新的讯息进来，若要结束的话，则按下「ctrl」加上「C」键来停止即可。

我们继续让这个监控日志讯息卡在前景，接着开启另一个终端机并输入下列的指令：

[rockylinux@workstation ~]$ logger test_message
[rockylinux@workstation ~]$

接着回去看监控日志的讯息输出，则可以看到下列的讯息：

.......
Oct  4 01:47:03 workstation rockylinux[2908]: test_message

从上述可以看到，我们发送的「test_message」之日志讯息已经成功的写到此日志档案里面了，而logger指令是用来写入一笔讯息到/var/log/messages之档案中，预设是user.notice，其对应到的等级为5。

有些服务则有自己的设定档案去定义其产生出来的日志讯息要以什麽样的等级存放与呈现，以SSHD服务举例来说，它就有自己的日志讯息等级与标签可以自行定义，相关的设定档在/etc/ssh/sshd_config档案中的第37行，并呈现此设定档之设定内容如下：

......
# Logging
#SyslogFacility AUTH
SyslogFacility AUTHPRIV
#LogLevel INFO
......

寻找事件

为了要取得日志讯息，则可以使用journalctl来做到，可以用来找寻所有系统的所有日志讯息，相关的指令执行输出的讯息如下：

[rockylinux@workstation ~]$ sudo journalctl
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 01:57:08 CST. --
Oct 04 00:57:49 workstation kernel: Linux version 4.18.0-305.19.1.el8_4.x86_64 (mockbuild@ord1-prod-x86buil>
Oct 04 00:57:49 workstation kernel: Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.19.1.el8_4.x86>
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
Oct 04 00:57:49 workstation kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using >
Oct 04 00:57:49 workstation kernel: BIOS-provided physical RAM map:
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x0000000000100000-0x000000007ffeffff] usable
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x000000007fff0000-0x000000007fffffff] ACPI data
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
Oct 04 00:57:49 workstation kernel: NX (Execute Disable) protection: active
Oct 04 00:57:49 workstation kernel: SMBIOS 2.5 present.
Oct 04 00:57:49 workstation kernel: DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Oct 04 00:57:49 workstation kernel: Hypervisor detected: KVM
Oct 04 00:57:49 workstation kernel: kvm-clock: Using msrs 4b564d01 and 4b564d00
Oct 04 00:57:49 workstation kernel: kvm-clock: cpu 0, msr 20601001, primary cpu clock
Oct 04 00:57:49 workstation kernel: kvm-clock: using sched offset of 13263841095 cycles
Oct 04 00:57:49 workstation kernel: clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4d>
Oct 04 00:57:49 workstation kernel: tsc: Detected 3292.524 MHz processor
Oct 04 00:57:49 workstation kernel: e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
lines 1-27

预设会进入阅读模式，因此需要按下「q」键来离开文字阅读器模式，若不要进入阅读器模式，则可以再加入「--no-pgaer」之参数来做到；若要印出指定的行数日志事件讯息，则可以使用-n这个参数来做到，假设要印出最後的5行日志事件讯息，则可以使用下列的指令做到：

[rockylinux@workstation ~]$ sudo journalctl -n 5
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 01:58:43 CST. --
Oct 04 01:57:08 workstation sudo[3048]: pam_unix(sudo:session): session opened for user root by rockylinux(>
Oct 04 01:57:14 workstation sudo[3048]: pam_unix(sudo:session): session closed for user root
Oct 04 01:58:43 workstation sudo[3070]: rockylinux : TTY=pts/0 ; PWD=/home/rockylinux ; USER=root ; COMMAND>
Oct 04 01:58:43 workstation sudo[3070]: pam_systemd(sudo:session): Cannot create session: Already running i>
Oct 04 01:58:43 workstation sudo[3070]: pam_unix(sudo:session): session opened for user root by rockylinux(>
lines 1-6/6 (END)

若是使用journalctl要持续监控的话，则可以加上「-f」参数来做到，这个参数会印出目前事件讯息的最後10笔，饼卡住前景进行日志事件的监控，相关执行指令的输出讯息如下：

[rockylinux@workstation ~]$ sudo journalctl -f
-- Logs begin at Mon 2021-10-04 00:57:49 CST. --
Oct 04 02:00:33 workstation sudo[3096]: pam_unix(sudo:session): session opened for user root by rockylinux(uid=0)
Oct 04 02:00:34 workstation sudo[3096]: pam_unix(sudo:session): session closed for user root
Oct 04 02:01:01 workstation CROND[3100]: (root) CMD (run-parts /etc/cron.hourly)
Oct 04 02:01:01 workstation run-parts[3103]: (/etc/cron.hourly) starting 0anacron
Oct 04 02:01:01 workstation anacron[3111]: Anacron started on 2021-10-04
Oct 04 02:01:01 workstation anacron[3111]: Normal exit (0 jobs run)
Oct 04 02:01:01 workstation run-parts[3113]: (/etc/cron.hourly) finished 0anacron
Oct 04 02:01:53 workstation sudo[3122]: rockylinux : TTY=pts/0 ; PWD=/home/rockylinux ; USER=root ; COMMAND=/bin/journalctl -f
Oct 04 02:01:53 workstation sudo[3122]: pam_systemd(sudo:session): Cannot create session: Already running in a session or user slice
Oct 04 02:01:53 workstation sudo[3122]: pam_unix(sudo:session): session opened for user root by rockylinux(uid=0)

若要看其他的权限与等级的日志讯息，则可以加上「-p」参数并搭配等级的名称，以下面执行指令的为例：

[rockylinux@workstation ~]$ sudo journalctl -p info
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 02:05:32 CST. --
Oct 04 00:57:49 workstation kernel: Linux version 4.18.0-305.19.1.el8_4.x86_64 (mockbuild@ord1-prod-x86buil>
Oct 04 00:57:49 workstation kernel: Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.19.1.el8_4.x86>
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
Oct 04 00:57:49 workstation kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using >
Oct 04 00:57:49 workstation kernel: BIOS-provided physical RAM map:
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x0000000000100000-0x000000007ffeffff] usable
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x000000007fff0000-0x000000007fffffff] ACPI data
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
Oct 04 00:57:49 workstation kernel: NX (Execute Disable) protection: active
Oct 04 00:57:49 workstation kernel: SMBIOS 2.5 present.
Oct 04 00:57:49 workstation kernel: DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Oct 04 00:57:49 workstation kernel: Hypervisor detected: KVM
Oct 04 00:57:49 workstation kernel: kvm-clock: Using msrs 4b564d01 and 4b564d00
Oct 04 00:57:49 workstation kernel: kvm-clock: cpu 0, msr 20601001, primary cpu clock
Oct 04 00:57:49 workstation kernel: kvm-clock: using sched offset of 13263841095 cycles
Oct 04 00:57:49 workstation kernel: clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4d>
Oct 04 00:57:49 workstation kernel: tsc: Detected 3292.524 MHz processor
Oct 04 00:57:49 workstation kernel: last_pfn = 0x7fff0 max_arch_pfn = 0x400000000
lines 1-27

同样的，也可以指定时间，假设要看从今天开始的日志讯息，则可以搭配--since这个参数来做到，相关执行指令输出的讯息如下：

[rockylinux@workstation ~]$ sudo journalctl --since today
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 02:06:44 CST. --
Oct 04 00:57:49 workstation kernel: Linux version 4.18.0-305.19.1.el8_4.x86_64 (mockbuild@ord1-prod-x86buil>
Oct 04 00:57:49 workstation kernel: Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.19.1.el8_4.x86>
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
Oct 04 00:57:49 workstation kernel: x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
Oct 04 00:57:49 workstation kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using >
Oct 04 00:57:49 workstation kernel: BIOS-provided physical RAM map:
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x0000000000100000-0x000000007ffeffff] usable
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x000000007fff0000-0x000000007fffffff] ACPI data
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
Oct 04 00:57:49 workstation kernel: BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
Oct 04 00:57:49 workstation kernel: NX (Execute Disable) protection: active
Oct 04 00:57:49 workstation kernel: SMBIOS 2.5 present.
Oct 04 00:57:49 workstation kernel: DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Oct 04 00:57:49 workstation kernel: Hypervisor detected: KVM
Oct 04 00:57:49 workstation kernel: kvm-clock: Using msrs 4b564d01 and 4b564d00
Oct 04 00:57:49 workstation kernel: kvm-clock: cpu 0, msr 20601001, primary cpu clock
Oct 04 00:57:49 workstation kernel: kvm-clock: using sched offset of 13263841095 cycles
Oct 04 00:57:49 workstation kernel: clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4d>
Oct 04 00:57:49 workstation kernel: tsc: Detected 3292.524 MHz processor
Oct 04 00:57:49 workstation kernel: e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
lines 1-27

另外，也可以使用指定区间时间方式，来设定一个区间中所有的日志讯息印出来，相关的执行指令结果与输出如下所示：

[rockylinux@workstation ~]$ sudo journalctl --since "2021-10-04 02:00" --until "2021-10-04 02:01"
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 02:10:47 CST. --
Oct 04 02:00:33 workstation sudo[3096]: rockylinux : TTY=pts/0 ; PWD=/home/rockylinux ; USER=root ; COMMAN>
Oct 04 02:00:33 workstation sudo[3096]: pam_systemd(sudo:session): Cannot create session: Already running >
Oct 04 02:00:33 workstation sudo[3096]: pam_unix(sudo:session): session opened for user root by rockylinux>
Oct 04 02:00:34 workstation sudo[3096]: pam_unix(sudo:session): session closed for user root
lines 1-5/5 (END)

从上述的执行指令所输出讯息得知，指定了从「2021-10-04 02:00」到「2021-10-04 02:01」之间所有的日志讯息。

若要印出更进一步的日志讯息，则可以加上「-o」指令来做到，并印出每一行日志讯息更进一步的资讯，相关执行指令的方式如下：

[rockylinux@workstation ~]$ sudo journalctl -o verbose
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 02:12:14 CST. --
Mon 2021-10-04 00:57:49.016975 CST [s=bb474c55c28e46f4acdf3f7ab2cb8098;i=1;b=b799208c374f4d01a15b01fc01908>
    _SOURCE_MONOTONIC_TIMESTAMP=0
    _TRANSPORT=kernel
    PRIORITY=5
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 02:12:14 CST. --
Mon 2021-10-04 00:57:49.016975 CST [s=bb474c55c28e46f4acdf3f7ab2cb8098;i=1;b=b799208c374f4d01a15b01fc01908>
    _SOURCE_MONOTONIC_TIMESTAMP=0
......

此外，也可以使用「_SYSTEMD_UNIT」与「_PID」之参数来指定要观看某一个背景服务的日志讯息，以Apache server为例，可以知道背景服务名称为「httpd.service」，并可以使用「sudo systemctl status httpd.service」来观看此背景服务目前跑在哪一个process id上，假设prcoess id为1230，而相关执行指令所输出的讯息如下：

[rockylinux@workstation ~]$ sudo journalctl _SYSTEMD_UNIT=httpd.service _PID=1230
-- Logs begin at Mon 2021-10-04 00:57:49 CST, end at Mon 2021-10-04 02:19:10 CST. --
Oct 04 00:58:36 workstation httpd[1230]: AH00558: httpd: Could not reliably determine the server's fully q>
Oct 04 00:58:36 workstation httpd[1230]: Server configured, listening on: port 80
lines 1-3/3 (END)

课後练习

  • 请打开「workstation」虚拟机器，并以「rockylinux」之使用者登入并开启终端机。
  • 使用「tail」这个指令来监控「/var/log/messages」上的日志讯息，并设法在监控期间发送一个日志等级为user.notice之讯息。
  • 除了使用「-n」参数来观看目前指定日志讯息内容之最後行数，也可以用其他的指令搭配做到，请使用「tail」指令并找出最後10行的日志讯息，要同时用到「journalctl」与「tail」指令，并请以一行完成这个指令。
  • 找到SSHD服务目前所执行的程序状态与资讯，并取得其prcoess id，并使用「journalctl」来指定SSHD服务与其prcoess id找到SSHD相关的日志讯息。

<<:  考试的日子

>>:  Day18 Refs 和 DOM

day24_如何采购 ARM 版本的 Linux 呢

ARM 版本的 Linux 该怎麽买呢？ 目前还较为少见，主要的产品为 树莓派 与 Pinebook...

Kotlin Android 第17天，从 0 到 ML - MVVM架构 - LiveData

前言: 学会了ViewModel，接下来就是建立观察 LiveData。 大纲 : LiveData...

[Day 32] 自我介绍後台及前台(一) - 取得使用者资料

自我介绍後台及前台 自定义性别 我们现在要开始做自我介绍的後台部分, 在这里我们要先建一个Enum,...

D09 / 为什麽我的按钮这麽长? - Intrinsic measurements

今天大概会聊到的范围 Intrinsic measurements 今天的标题可能会让人有点疑惑，...

Clean architecture in Android

要谈架构的话当然一定会聊到这现在最夯最流行的 Clean architecture，虽然在前面的文章...