练习 18：日志：/var/log，rsyslog，logger

原文：Exercise 18. Logging, /var/log, rsyslog, logger

译者：飞龙

协议：CC BY-NC-SA 4.0

自豪地采用谷歌翻译

守护进程是在后台运行的程序。所以问题来了：他们怎么告诉你他们在做什么？他们如何告诉你有什么问题？这个问题是由日志文件解决的，其中守护进程写入其状态和操作。在 Debian 中，这个文件位于/var/log目录下。

但谁写入这些文件？最明显的答案是守护进程本身，这实际上往往是错误的。在某些情况下，守护程序确实会自己编写日志文件，但通常它们通过名为rsyslogd的守护程序（称为 日志记录守护程序）来实现。它将日志写入不同的文件，来简化搜索和分析。为了区分这个文件，它有一个概念叫做“设施”。这是标准设施的列表：

设施 设施说明 设施 设施说明
auth 授权相关消息 LOCAL0 本地使用 0
authPriv 敏感的安全信息 LOCAL1 本地使用1
cron Cron信息 local2 本地使用 2
daemon 系统守护程序 local3 本地使用 3
ftp FTP 守护消息 local4 本地使用 4
kern 内核消息 local5 本地使用 5
lpr 行式打印机子系统 local6 当地使用 6
mail 邮件子系统 local7 当地使用 7
news 新闻子系统
security auth 的过时名称
syslog 由 syslogd 内部生成的消息
user
uucp UUCP 子系统

每个条目也标记有严重性状态，以便分析发生了什么：

代码名称 严重性 描述 一般说明
alert 警报 必须立即采取行动。 应立即纠正，因此通知可以解决问题的人员。一个例子是丢失备用 ISP 连接。
crit 严重 严重情况。 应立即纠正，但表示主系统出现故障，一个例子就是主 ISP 连接的丢失 。
debug 调试 调试级别消息。 信息对开发人员有用，用于调试应用程序，在操作期间无用。
emerg 紧急 系统不可用 通常影响多个应用程序/服务器/站点的“紧急”状态。在这个级别，通常会通知所有技术人员。
err 错误 错误情况。 非紧急故障，应转发给开发人员或管理员；每个项目必须在给定的时间内解决。
error 错误 err 的弃用名称 —-
info 信息 信息消息 正常操作的信息 - 可以用于收集报告，测量吞吐量等 - 无需采取任何行动。
notice 注意 正常但重要的状况。 不正常但不是错误情况的事件，可能汇总为邮件发给开发者或者管理员，来定位潜在问题 - 不需要立即采取行动。
panic 紧急 emerg 的弃用名称 —-
warning 警告 警告情况。 警告消息，而不是错误，但表示如果不采取行动，将发生错误，例如文件系统 85% 占满 - 每个条目必须在给定时间内解决。
warn 警告 warning 的弃用名称 —-

因为如果日志文件留给自己，它们往往会变得非常大，并且消耗所有可用的磁盘空间，所以有一种称为轮替的机制。默认情况下，这种机制通常只保留最后 7 天的日志文件，包括今天。轮替由logrotate守护进程执行，来帮助你了解这个守护进程做了什么。我为你将其写出来：

  1. Day 0
  2.     log.0 is created
  3. Day 1
  4.     mv log.0 log.1
  5.     log.0 is created
  6. Day 2
  7.     mv log.1 log.2
  8.     mv log.0 log.1
  9.     log.0 is created
  10. Day 3
  11.     mv log.2 log.3
  12.     mv log.1 log.2
  13.     mv log.0 log.1
  14.     log.0 is created
  15. Day 4
  16.     mv log.3 log.4
  17.     mv log.2 log.3
  18.     mv log.1 log.2
  19.     mv log.0 log.1
  20.     log.0 is created
  21. Day 5
  22.     mv log.4 log.5
  23.     mv log.3 log.4
  24.     mv log.2 log.3
  25.     mv log.1 log.2
  26.     mv log.0 log.1
  27.     log.0 is created
  28. Day 6
  29.     mv log.5 log.6
  30.     mv log.4 log.5
  31.     mv log.3 log.4
  32.     mv log.2 log.3
  33.     mv log.1 log.2
  34.     mv log.0 log.1
  35.     log.0 is created
  36. Day 7
  37.     rm log.6
  38.     mv log.5 log.6
  39.     mv log.4 log.5
  40.     mv log.3 log.4
  41.     mv log.2 log.3
  42.     mv log.1 log.2
  43.     mv log.0 log.1
  44.     log.0 is created

让我重复一下：

  • 日志是一个记录时间的过程，使用自动化的计算机程序，来提供审计跟踪，可用于了解系统活动和诊断问题。
  • 日志守护程序是程序，其他程序可能要求它在日志文件中写入内容。
  • 每个日志条目具有设施（日志类别）和严重性 （它是多么重要）属性。
  • 轮替是一个过程，仅保留有限数量的日志文件，来避免填满磁盘。
  • 在 Debian 中，日志文件通常位于/var/log目录中。

这是处理日志的有用命令（要记住打开相关的手册页，并找出有什么选项）：

  • logger Hello, I have a kitty! - 编写一个自定义日志消息。
  • ls -altr /var/log - 列出日志目录，以这样一种方式，最后修改的文件到最后。
  • grep user1 /var/log/auth.log - 列出文件中包含user1的所有行。
  • grep -irl user1 /var/log - 列出所有包含user1的文件 。
  • find /var/log -mmin -10 - 找到在过去 10 分钟内被修改的任何文件。
  • tail /var/log/auth.log - 打印日志文件的最后 10 行。
  • tail -f /var/log/auth.log - 实时跟踪日志文件。配置守护进程时非常有用。

现在你将学习如何查看日志，并将一些东西写入系统日志。

这样做

  1.  1: sudo -s
  2.  2: cd /var/log
  3.  3: ls -altr | tail
  4.  4: tail auth.log
  5.  5: grep user1 auth.log | tail
  6.  6: /etc/init.d/exim4 restart
  7.  7: find /var/log -mmin -5
  8.  8: tail /var/log/exim4/mainlog
  9.  9: grep -irl rcconf .
  10. 10: tail ./dpkg.log
  11. 11: last
  12. 12: lastlog
  13. 13: logger local0.alert I am a kitty, sittin in ur system watchin u work ^^
  14. 14: ls -altr | tail
  15. 15: tail messages

你会看到什么

  1. user1@vm1:~$ sudo -s
  2. root@vm1:/home/user1# cd /var/log
  3. root@vm1:/var/log# ls -altr | tail
  4. -rw-r-----  1 root        adm   46955 Jun 29 12:28 messages
  5. -rw-r-----  1 root        adm   19744 Jun 29 12:28 dmesg
  6. -rw-r-----  1 root        adm     696 Jun 29 12:28 daemon.log
  7. drwxr-xr-x  7 root        root   4096 Jun 29 12:28 .
  8. -rw-r-----  1 root        adm   60738 Jun 29 12:28 syslog
  9. -rw-r-----  1 root        adm   58158 Jun 29 12:28 kern.log
  10. -rw-r-----  1 root        adm   12652 Jun 29 12:28 debug
  11. -rw-rw-r--  1 root        utmp  75264 Jun 29 12:28 wtmp
  12. -rw-rw-r--  1 root        utmp 292584 Jun 29 12:28 lastlog
  13. -rw-r-----  1 root        adm   38790 Jun 29 12:40 auth.log
  14. root@vm1:/var/log# tail auth.log
  15. Jun 29 12:28:22 vm1 sshd[983]: Server listening on 0.0.0.0 port 22.
  16. Jun 29 12:28:22 vm1 sshd[983]: Server listening on :: port 22.
  17. Jun 29 12:28:44 vm1 sshd[1214]: Accepted password for user1 from 194.85.195.183 port 53775 ssh2
  18. Jun 29 12:28:44 vm1 sshd[1214]: pam_unix(sshd:session): session opened for user user1 by (uid=0)
  19. Jun 29 12:30:49 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  20. Jun 29 12:30:53 vm1 login[1260]: pam_securetty(login:auth): unexpected response from failed conversation function
  21. Jun 29 12:30:53 vm1 login[1260]: pam_securetty(login:auth): cannot determine username
  22. Jun 29 12:35:08 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  23. Jun 29 12:35:14 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  24. Jun 29 12:40:32 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  25. root@vm1:/var/log# tail auth.log | grep user1
  26. Jun 29 12:28:44 vm1 sshd[1214]: Accepted password for user1 from 194.85.195.183 port 53775 ssh2
  27. Jun 29 12:28:44 vm1 sshd[1214]: pam_unix(sshd:session): session opened for user user1 by (uid=0)
  28. Jun 29 12:30:49 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  29. Jun 29 12:35:08 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  30. Jun 29 12:35:14 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  31. Jun 29 12:40:32 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  32. root@vm1:/var/log# grep user1 auth.log | tail
  33. Jun 29 12:26:33 vm1 sshd[1302]: Accepted password for user1 from 194.85.195.183 port 53008 ssh2
  34. Jun 29 12:26:33 vm1 sshd[1302]: pam_unix(sshd:session): session opened for user user1 by (uid=0)
  35. Jun 29 12:26:38 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  36. Jun 29 12:28:02 vm1 sshd[1302]: pam_unix(sshd:session): session closed for user user1
  37. Jun 29 12:28:44 vm1 sshd[1214]: Accepted password for user1 from 194.85.195.183 port 53775 ssh2
  38. Jun 29 12:28:44 vm1 sshd[1214]: pam_unix(sshd:session): session opened for user user1 by (uid=0)
  39. Jun 29 12:30:49 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  40. Jun 29 12:35:08 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  41. Jun 29 12:35:14 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  42. Jun 29 12:40:32 vm1 sudo:    user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash
  43. root@vm1:/home/user1# /etc/init.d/exim4 restart
  44. Stopping MTA for restart: exim4_listener.
  45. Restarting MTA: exim4.
  46. root@vm1:/home/user1# find /var/log -mmin -5
  47. /var/log/exim4/mainlog
  48. /var/log/auth.log
  49. root@vm1:/home/user1# tail /var/log/exim4/mainlog
  50. 2012-06-29 12:24:11 exim 4.72 daemon started: pid=1159, -q30m, listening for SMTP on [127.0.0.1]:25 [::1]:25
  51. 2012-06-29 12:24:11 Start queue run: pid=1165
  52. 2012-06-29 12:24:11 End queue run: pid=1165
  53. 2012-06-29 12:28:22 exim 4.72 daemon started: pid=1190, -q30m, listening for SMTP on [127.0.0.1]:25 [::1]:25
  54. 2012-06-29 12:28:22 Start queue run: pid=1196
  55. 2012-06-29 12:28:22 End queue run: pid=1196
  56. 2012-06-29 12:41:18 exim 4.72 daemon started: pid=1622, -q30m, listening for SMTP on [127.0.0.1]:25 [::1]:25
  57. 2012-06-29 12:41:18 Start queue run: pid=1624
  58. 2012-06-29 12:41:18 End queue run: pid=1624
  59. 2012-06-29 12:42:28 exim 4.72 daemon started: pid=1886, -q30m, listening for SMTP on [127.0.0.1]:25 [::1]:25
  60. root@vm1:/home/user1# grep -irl rcconf .
  61. ./aptitude
  62. ./apt/history.log
  63. ./apt/term.log
  64. ./dpkg.log
  65. ./auth.log
  66. root@vm1:/home/user1# tail ./dpkg.log
  67. 2012-06-26 19:27:40 status unpacked rcconf 2.5
  68. 2012-06-26 19:27:40 status unpacked rcconf 2.5
  69. 2012-06-26 19:27:40 trigproc man-db 2.5.7-8 2.5.7-8
  70. 2012-06-26 19:27:40 status half-configured man-db 2.5.7-8
  71. 2012-06-26 19:27:40 status installed man-db 2.5.7-8
  72. 2012-06-26 19:27:41 startup packages configure
  73. 2012-06-26 19:27:41 configure rcconf 2.5 2.5
  74. 2012-06-26 19:27:41 status unpacked rcconf 2.5
  75. 2012-06-26 19:27:41 status half-configured rcconf 2.5
  76. 2012-06-26 19:27:41 status installed rcconf 2.5
  77. root@vm1:/var/log# last
  78. user1    pts/0        sis.site  Fri Jun 29 12:26   still logged in
  79. user1    pts/0        sis.site  Fri Jun 29 12:14 - down   (00:09)
  80. user1    pts/0        sis.site  Thu Jun 28 19:40 - 11:25  (15:45)
  81. user1    pts/0        sis.site  Wed Jun 27 19:14 - 17:04  (21:50)
  82. user1    pts/0        sis.site  Tue Jun 26 13:54 - 18:18 (1+04:23)
  83. user1    pts/0        sis.site  Thu Jun 21 15:23 - 13:11 (4+21:47)
  84. user1    pts/0        sis.site  Fri Jun 15 19:34 - 12:01 (5+16:26)
  85. user1    pts/0        sis.site  Fri Jun 15 19:11 - 19:34  (00:22)
  86. reboot   system boot  2.6.32-5-amd64   Fri Jun 29 12:24 - 12:26  (00:02)
  87. user1    pts/0        sis.site  Fri Jun 29 12:14 - down   (00:09)
  88. root@vm1:/var/log# lastlog
  89. Username         Port     From             Latest
  90. root                                       **Never logged in**
  91. daemon                                     **Never logged in**
  92. bin                                        **Never logged in**
  93. sys                                        **Never logged in**
  94. sync                                       **Never logged in**
  95. games                                      **Never logged in**
  96. man                                        **Never logged in**
  97. lp                                         **Never logged in**
  98. mail                                       **Never logged in**
  99. news                                       **Never logged in**
  100. uucp                                       **Never logged in**
  101. proxy                                      **Never logged in**
  102. www-data                                   **Never logged in**
  103. backup                                     **Never logged in**
  104. list                                       **Never logged in**
  105. irc                                        **Never logged in**
  106. gnats                                      **Never logged in**
  107. nobody                                     **Never logged in**
  108. libuuid                                    **Never logged in**
  109. Debian-exim                                **Never logged in**
  110. statd                                      **Never logged in**
  111. sshd                                       **Never logged in**
  112. user1            pts/0    sis.site  Fri Jun 29 12:28:45 +0400 2012
  113. root@vm1:/var/log# logger local0.alert I am a kitty, sittin in ur system watchin u work ^^
  114. root@vm1:/var/log# ls -altr | tail
  115. -rw-r-----  1 root        adm     696 Jun 29 12:28 daemon.log
  116. drwxr-xr-x  7 root        root   4096 Jun 29 12:28 .
  117. -rw-r-----  1 root        adm   58158 Jun 29 12:28 kern.log
  118. -rw-r-----  1 root        adm   12652 Jun 29 12:28 debug
  119. -rw-rw-r--  1 root        utmp  75264 Jun 29 12:28 wtmp
  120. -rw-rw-r--  1 root        utmp 292584 Jun 29 12:28 lastlog
  121. -rw-r-----  1 root        adm   38971 Jun 29 13:17 auth.log
  122. -rw-r-----  1 root        adm     229 Jun 29 13:19 user.log
  123. -rw-r-----  1 root        adm   60932 Jun 29 13:19 syslog
  124. -rw-r-----  1 root        adm   47047 Jun 29 13:19 messages
  125. root@vm1:/var/log# tail messages
  126. Jun 29 12:28:21 vm1 kernel: [    1.846975] processor LNXCPU:00: registered as cooling_device0
  127. Jun 29 12:28:21 vm1 kernel: [    1.868828] usbcore: registered new interface driver hiddev
  128. Jun 29 12:28:21 vm1 kernel: [    1.895676] input: QEMU 0.14.1 QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/input/input4
  129. Jun 29 12:28:21 vm1 kernel: [    1.895743] generic-usb 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Pointer [QEMU 0.14.1 QEMU USB Tablet] on usb-0000:00:01.2-1/input0
  130. Jun 29 12:28:21 vm1 kernel: [    1.895762] usbcore: registered new interface driver usbhid
  131. Jun 29 12:28:21 vm1 kernel: [    1.895765] usbhid: v2.6:USB HID core driver
  132. Jun 29 12:28:21 vm1 kernel: [    2.373061] EXT3 FS on vda1, internal journal
  133. Jun 29 12:28:21 vm1 kernel: [    2.394992] loop: module loaded
  134. Jun 29 12:28:21 vm1 kernel: [    2.413478] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input5
  135. Jun 29 13:19:11 vm1 user1: local0.alert I am a kitty, sittin in ur system watchin u work ^^
  136. root@vm1:/var/log#

解释

  • 打开 root （超级用户）shell。这是因为作为user1工作时，出于安全的考虑，你不能读取所有日志文件。
  • 将目录更改为/var/log。
  • 按日期排序打印所有文件，最后修改的文件在底部。
  • 从auth.log打印最后 10 行，包含登录系统的信息。
  • 从auth.log打印包含user1的最后 10 行。
  • 重启exim4邮件服务器。
  • 打印最近 5 分钟内的文件更改。现在，你可以轻松找到exim4在哪个文件中 记录其操作。
  • 从exim4日志打印出最后 10 行 。
  • 在当前目录中的所有文件 搜索rcconf。现在，你可以轻松找到 Debian 包系统记录其操作的位置。
  • 从dpkg.log打印最后 10 行，含有软件包安装和删除信息。
  • 打印用户最后登录的信息。
  • 打印所有用户最近登录的信息。
  • 将你的消息传递给rsyslogd守护程序。
  • 按日期排序打印所有文件，最后修改的文件位于底部。现在你可能会看到这里就是你的消息。
  • 从消息中打印出最后10行，你可以看到你的消息确实已记录。

附加题

阅读rsyslogd和logger的手册页。
通过阅读相应的手册页，找出last和lastlog之间的区别。
阅读logrotate手册页并记住它的存在。
执行tail -f /var/log/auth.log，并生成vm1的第二个连接（如果你在 Windows 上工作，则为 putty）。不错吧？