練習 18：日志：/var/log，rsyslog，logger · 笨辦法學 Linux 中文版

# 練習 18：日志：`/var/log`，`rsyslog`，`logger` > 原文：[Exercise 18. Logging, /var/log, rsyslog, logger](https://archive.fo/xmofk) > 譯者：[飛龍](https://github.com/wizardforcel) > 協議：[CC BY-NC-SA 4.0](http://creativecommons.org/licenses/by-nc-sa/4.0/) > 自豪地采用[谷歌翻譯](https://translate.google.cn/) 守護進程是在后臺運行的程序。所以問題來了：他們怎么告訴你他們在做什么？他們如何告訴你有什么問題？這個問題是由日志文件解決的，其中守護進程寫入其狀態和操作。在 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`守護進程執行，來幫助你了解這個守護進程做了什么。我為你將其寫出來： ``` Day 0 log.0 is created Day 1 mv log.0 log.1 log.0 is created Day 2 mv log.1 log.2 mv log.0 log.1 log.0 is created Day 3 mv log.2 log.3 mv log.1 log.2 mv log.0 log.1 log.0 is created Day 4 mv log.3 log.4 mv log.2 log.3 mv log.1 log.2 mv log.0 log.1 log.0 is created Day 5 mv log.4 log.5 mv log.3 log.4 mv log.2 log.3 mv log.1 log.2 mv log.0 log.1 log.0 is created Day 6 mv log.5 log.6 mv log.4 log.5 mv log.3 log.4 mv log.2 log.3 mv log.1 log.2 mv log.0 log.1 log.0 is created Day 7 rm log.6 mv log.5 log.6 mv log.4 log.5 mv log.3 log.4 mv log.2 log.3 mv log.1 log.2 mv log.0 log.1 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: sudo -s 2: cd /var/log 3: ls -altr | tail 4: tail auth.log 5: grep user1 auth.log | tail 6: /etc/init.d/exim4 restart 7: find /var/log -mmin -5 8: tail /var/log/exim4/mainlog 9: grep -irl rcconf . 10: tail ./dpkg.log 11: last 12: lastlog 13: logger local0.alert I am a kitty, sittin in ur system watchin u work ^^ 14: ls -altr | tail 15: tail messages ``` ## 你會看到什么 ``` user1@vm1:~$ sudo -s root@vm1:/home/user1# cd /var/log root@vm1:/var/log# ls -altr | tail -rw-r----- 1 root adm 46955 Jun 29 12:28 messages -rw-r----- 1 root adm 19744 Jun 29 12:28 dmesg -rw-r----- 1 root adm 696 Jun 29 12:28 daemon.log drwxr-xr-x 7 root root 4096 Jun 29 12:28 . -rw-r----- 1 root adm 60738 Jun 29 12:28 syslog -rw-r----- 1 root adm 58158 Jun 29 12:28 kern.log -rw-r----- 1 root adm 12652 Jun 29 12:28 debug -rw-rw-r-- 1 root utmp 75264 Jun 29 12:28 wtmp -rw-rw-r-- 1 root utmp 292584 Jun 29 12:28 lastlog -rw-r----- 1 root adm 38790 Jun 29 12:40 auth.log root@vm1:/var/log# tail auth.log Jun 29 12:28:22 vm1 sshd[983]: Server listening on 0.0.0.0 port 22. Jun 29 12:28:22 vm1 sshd[983]: Server listening on :: port 22. Jun 29 12:28:44 vm1 sshd[1214]: Accepted password for user1 from 194.85.195.183 port 53775 ssh2 Jun 29 12:28:44 vm1 sshd[1214]: pam_unix(sshd:session): session opened for user user1 by (uid=0) Jun 29 12:30:49 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:30:53 vm1 login[1260]: pam_securetty(login:auth): unexpected response from failed conversation function Jun 29 12:30:53 vm1 login[1260]: pam_securetty(login:auth): cannot determine username Jun 29 12:35:08 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:35:14 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:40:32 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash root@vm1:/var/log# tail auth.log | grep user1 Jun 29 12:28:44 vm1 sshd[1214]: Accepted password for user1 from 194.85.195.183 port 53775 ssh2 Jun 29 12:28:44 vm1 sshd[1214]: pam_unix(sshd:session): session opened for user user1 by (uid=0) Jun 29 12:30:49 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:35:08 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:35:14 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:40:32 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash root@vm1:/var/log# grep user1 auth.log | tail Jun 29 12:26:33 vm1 sshd[1302]: Accepted password for user1 from 194.85.195.183 port 53008 ssh2 Jun 29 12:26:33 vm1 sshd[1302]: pam_unix(sshd:session): session opened for user user1 by (uid=0) Jun 29 12:26:38 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:28:02 vm1 sshd[1302]: pam_unix(sshd:session): session closed for user user1 Jun 29 12:28:44 vm1 sshd[1214]: Accepted password for user1 from 194.85.195.183 port 53775 ssh2 Jun 29 12:28:44 vm1 sshd[1214]: pam_unix(sshd:session): session opened for user user1 by (uid=0) Jun 29 12:30:49 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:35:08 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:35:14 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash Jun 29 12:40:32 vm1 sudo: user1 : TTY=pts/0 ; PWD=/home/user1 ; USER=root ; COMMAND=/bin/bash root@vm1:/home/user1# /etc/init.d/exim4 restart Stopping MTA for restart: exim4_listener. Restarting MTA: exim4. root@vm1:/home/user1# find /var/log -mmin -5 /var/log/exim4/mainlog /var/log/auth.log root@vm1:/home/user1# tail /var/log/exim4/mainlog 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 2012-06-29 12:24:11 Start queue run: pid=1165 2012-06-29 12:24:11 End queue run: pid=1165 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 2012-06-29 12:28:22 Start queue run: pid=1196 2012-06-29 12:28:22 End queue run: pid=1196 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 2012-06-29 12:41:18 Start queue run: pid=1624 2012-06-29 12:41:18 End queue run: pid=1624 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 root@vm1:/home/user1# grep -irl rcconf . ./aptitude ./apt/history.log ./apt/term.log ./dpkg.log ./auth.log root@vm1:/home/user1# tail ./dpkg.log 2012-06-26 19:27:40 status unpacked rcconf 2.5 2012-06-26 19:27:40 status unpacked rcconf 2.5 2012-06-26 19:27:40 trigproc man-db 2.5.7-8 2.5.7-8 2012-06-26 19:27:40 status half-configured man-db 2.5.7-8 2012-06-26 19:27:40 status installed man-db 2.5.7-8 2012-06-26 19:27:41 startup packages configure 2012-06-26 19:27:41 configure rcconf 2.5 2.5 2012-06-26 19:27:41 status unpacked rcconf 2.5 2012-06-26 19:27:41 status half-configured rcconf 2.5 2012-06-26 19:27:41 status installed rcconf 2.5 root@vm1:/var/log# last user1 pts/0 sis.site Fri Jun 29 12:26 still logged in user1 pts/0 sis.site Fri Jun 29 12:14 - down (00:09) user1 pts/0 sis.site Thu Jun 28 19:40 - 11:25 (15:45) user1 pts/0 sis.site Wed Jun 27 19:14 - 17:04 (21:50) user1 pts/0 sis.site Tue Jun 26 13:54 - 18:18 (1+04:23) user1 pts/0 sis.site Thu Jun 21 15:23 - 13:11 (4+21:47) user1 pts/0 sis.site Fri Jun 15 19:34 - 12:01 (5+16:26) user1 pts/0 sis.site Fri Jun 15 19:11 - 19:34 (00:22) reboot system boot 2.6.32-5-amd64 Fri Jun 29 12:24 - 12:26 (00:02) user1 pts/0 sis.site Fri Jun 29 12:14 - down (00:09) root@vm1:/var/log# lastlog Username Port From Latest root **Never logged in** daemon **Never logged in** bin **Never logged in** sys **Never logged in** sync **Never logged in** games **Never logged in** man **Never logged in** lp **Never logged in** mail **Never logged in** news **Never logged in** uucp **Never logged in** proxy **Never logged in** www-data **Never logged in** backup **Never logged in** list **Never logged in** irc **Never logged in** gnats **Never logged in** nobody **Never logged in** libuuid **Never logged in** Debian-exim **Never logged in** statd **Never logged in** sshd **Never logged in** user1 pts/0 sis.site Fri Jun 29 12:28:45 +0400 2012 root@vm1:/var/log# logger local0.alert I am a kitty, sittin in ur system watchin u work ^^ root@vm1:/var/log# ls -altr | tail -rw-r----- 1 root adm 696 Jun 29 12:28 daemon.log drwxr-xr-x 7 root root 4096 Jun 29 12:28 . -rw-r----- 1 root adm 58158 Jun 29 12:28 kern.log -rw-r----- 1 root adm 12652 Jun 29 12:28 debug -rw-rw-r-- 1 root utmp 75264 Jun 29 12:28 wtmp -rw-rw-r-- 1 root utmp 292584 Jun 29 12:28 lastlog -rw-r----- 1 root adm 38971 Jun 29 13:17 auth.log -rw-r----- 1 root adm 229 Jun 29 13:19 user.log -rw-r----- 1 root adm 60932 Jun 29 13:19 syslog -rw-r----- 1 root adm 47047 Jun 29 13:19 messages root@vm1:/var/log# tail messages Jun 29 12:28:21 vm1 kernel: [ 1.846975] processor LNXCPU:00: registered as cooling_device0 Jun 29 12:28:21 vm1 kernel: [ 1.868828] usbcore: registered new interface driver hiddev 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 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 Jun 29 12:28:21 vm1 kernel: [ 1.895762] usbcore: registered new interface driver usbhid Jun 29 12:28:21 vm1 kernel: [ 1.895765] usbhid: v2.6:USB HID core driver Jun 29 12:28:21 vm1 kernel: [ 2.373061] EXT3 FS on vda1, internal journal Jun 29 12:28:21 vm1 kernel: [ 2.394992] loop: module loaded Jun 29 12:28:21 vm1 kernel: [ 2.413478] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input5 Jun 29 13:19:11 vm1 user1: local0.alert I am a kitty, sittin in ur system watchin u work ^^ 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）。不錯吧？