一次切割日誌引起的血案

一次切割日誌引起的血案

不少應用程序會產生日誌，有些程序已經實現了日誌切割，通常是天天一個文件。但有時這個切割並不能知足咱們的需求，例如咱們須要顆粒度更細的切割。

切割日誌的目的是什麼？

1. 日誌尺寸過大

2. 便於分析

3. 切割後歸檔，或者導入日誌平臺

切割日誌基本兩種方法：

1. 手工或者 shell

2. 工具,例如logrotate，傳統的cronolog

日誌切割方案網上有不少，不少運維也是參考這些方案進行配置，網上的例子不徹底都是對的，可能你用了不少年配置方案是錯誤的。 沒有出現故障是僥倖，由於筆者15年前就在此處栽過，因爲日誌太大，我便清空了日誌，覺得程序仍然會繼續寫入，最後直到服務器崩潰。 最近發現不少新手再談cronolog，我便想起當前發生的故障，有必要跟你們分享。

首先日誌是能夠切割的，網上的例子理論上也是可行，但咱們不能不求甚解，稀裏糊塗的用下去。

咱們首先了解一下日誌是怎麼產生的，那種日誌能夠切割，那些日誌不能切割，爲何不能切割，若是須要切割日誌怎麼處理？

首先日誌是怎麼產生的

日誌生命週期，建立/打開日誌文件，追加日誌記錄，關閉日誌文件。請看下面僞代碼。

main (){ f = open(/tmp/prog.log) ...
	...
	f.append('DEBUG .............') ...
	f.append('INFO .............') ...
	f.append('WARN .............') f.close()}

這個程序是順序運行，每次運行都會經歷，打開日誌文件，追加日誌記錄，關閉日誌文件，一個日誌生命週期結束。 在完成日誌生命周後，你就能夠切割日誌了。由於f.close()後日志文件已經被釋放。

再看下面的程序

main (){ f = open(/tmp/prog.log) loop{ ... ... f.append('DEBUG .............') ... f.append('INFO .............') ... f.append('WARN .............') if(quit){ break } } f.close()}

這個程序就不一樣了，程序運行，打開日誌文件，而後進入無窮循環，期間不斷寫入日誌，知道接到重載命令纔會關閉日誌。 那麼這個程序你就不能隨便切割日誌。你一旦修改了日誌文件，程序將不能在寫入日誌到文件中。 這個程序切割日誌的過程是這樣的

split loop { prog run prog quit && mv /tmp/prog.log /tmp/prog.2016-05-05.log }

再看下面的程序

main (){ loop{ f = open(/tmp/prog.log) loop{ ...
			...
			f.append('DEBUG .............') ...
			f.append('INFO .............') ...
			f.append('WARN .............') if(reload){ break } } f.close() }}

這個程序多了一層循環，並加入了重載功能。這個程序怎樣切割日誌呢：

split loop { prog run
	mv /tmp/prog.log /tmp/prog.YYYY-MM-DD.log
	prog reload }

若是你是程序猿，這個程序能夠優化一下，一了百了，就是在reload 的時候從新建立或打開日誌。

main (){ loop{ f = open(/tmp/prog.YYYY-MM-DD.log) loop{ ...
			...
			f.append('DEBUG .............') ...
			f.append('INFO .............') ...
			f.append('WARN .............') if(reload){ break } } f.close() }}

還有一種狀況，你會問爲何不這麼寫？

prog { log(type, msg){ f = open(/tmp/prog.YYYY-MM-DD.log) f.append(type, msg) f.close() } main(){ ...
		...
		log('INFO','..............') ...
		...
		log('DEBUG','..............') ...
		... }}

這種代碼的適應性很是強，但犧牲了IO性能，若是平凡打開/關閉文件同時進行寫IO操做，這樣的程序很難實現高併發。 因此不少高併發的程序，只會打開一第二天志文件（追加模式），不會再運行期間關閉日誌文件，直到進程發出退出信號。

讓咱們看個究竟

咱們手工模擬一第二天志分割的過程，首先開啓三個Shell終端。

第一種狀況，日誌文件被重命名

終端一，模擬打開日誌文件

[root@www.netkiller.cn ~]# cat > /tmp/test.log

終端二，重命名文件

[root@www.netkiller.cn ~]# mv /tmp/test.log /tmp/test.2016.05.05.log

終端一，輸入一些內容而後按下Ctrl+D 保存文件

[root@www.netkiller.cn ~]# cat > /tmp/test.log
Helloworld
Ctrl + D[root@www.netkiller.cn ~]# cat /tmp/test.log
cat: /tmp/test.log: No such file or directory

第二種狀況，日誌文件被刪除

終端一，模擬打開日誌文件

[root@www.netkiller.cn ~]# cat > /tmp/test.log

終端二，使用lsof查看文件的打開狀況

[root@www.netkiller.cn ~]# lsof | grep /tmp/test.log
cat       20032           root    1w      REG              253,1          0     288466 /tmp/test.log

終端三，刪除日誌文件

[root@www.netkiller.cn ~]# rm -rf /tmp/test.log

終端二，查看日誌的狀態，你能看到 deleted

[root@www.netkiller.cn ~]# lsof | grep /tmp/test.log
cat        5269           root    1w      REG              253,1          0     277445 /tmp/test.log (deleted)

終端一，回到終端一種，繼續寫入一些內容並保存，而後查看日誌文件是否有日誌記錄被寫入

[root@www.netkiller.cn ~]# cat > /tmp/test.log
Helloworld
^D[root@www.netkiller.cn ~]# cat /tmp/test.log
cat: /tmp/test.log: No such file or directory

通過上面兩個實驗，你應該明白了在日誌打開期間對日誌文件作重命名或者刪除都會形成日誌記錄的寫入失敗。

第三種狀況，日誌沒有被刪除，也沒有被重命名，而是被其餘程序作了修改

第一步，終端窗口一中建立一個文件，文件寫入一些字符串，這裏寫入 「one」，而後查看是否成功寫入。

[root@www.netkiller.cn ~]# echo one > /tmp/test.log[root@www.netkiller.cn ~]# cat /tmp/test.log
one

上面咱們能夠看到/tmp/test.log文件成功寫入一個字符串」one」

第二步，開始追加一些字符串

[root@www.netkiller.cn ~]# cat > /tmp/test.log
two

先不要保存（不要發出^D）

第三部，在終端二窗口中清空這個文件

[root@www.netkiller.cn ~]# > /tmp/test.log [root@www.netkiller.cn ~]# cat /tmp/test.log

經過cat查看/tmp/test.log文件，什麼也沒也表示操做成功。

第四步，完成字符串追加，使用Ctrl+D保存文件，最後使用cat /tmp/test.log 查看內容。

[root@www.netkiller.cn ~]# cat > /tmp/test.log
two[root@www.netkiller.cn ~]# cat /tmp/test.log

你會發現/tmp/test.log文件中沒有寫入任何內容。這表示在日誌的訪問期間，若是其餘程序修改了該日誌文件，原來的程序將沒法再寫入日誌。

讓咱們再來一次，看個究竟

終端一，建立並追加字符串到日誌文件中

# echo one > /tmp/test.log# cat /tmp/test.logone# cat >> /tmp/test.logtwo

記得不要保存

終端二，使用lsof查看文件的打開狀況

# lsof | grep /tmp/test.logcat       22631           root    1w      REG              253,1          0     277445 /tmp/test.log

終端三，開啓另外一個程序追加字符串到日誌文件中

# cat >> /tmp/test.log three

先不要保存（不要發出^D)

終端二，查看文件的打開狀況

# lsof | grep /tmp/test.logcat       22631           root    1w      REG              253,1          0     277445 /tmp/test.log
cat       23350           root    1w      REG              253,1          0     277445 /tmp/test.log

終端三，保存three字符串

# cat >> /tmp/test.log three
^D# cat /tmp/test.log three

回到終端一，繼續保存內容

# cat > /tmp/test.logtwo
^D# cat /tmp/test.logtwo
e

出現新的行狀況了，two報道最上面去了，這是由於打開文件默認文件指針是頁首，它不知道最後一次文件寫入的位置。

你能夠反覆實驗，結果相同。

# cat /tmp/test.logtwo
e
four
five

我爲何沒有使用 echo 「five」 » /tmp/test.log 這種方式追加呢？由於 cat 重定向後只要不發出^D就不會保存文件，而echo是打開文件，獲取文件尾部位置，而後追加，最後關閉文件。

經典案例分析

Nginx

[root@www.netkiller.cn ~]# cat /etc/logrotate.d/nginx
/var/log/nginx/*.log {        daily
        missingok
        rotate 52
        compress
        delaycompress
        notifempty
        create 640 nginx adm
        sharedscripts
        postrotate                [ -f /var/run/nginx.pid ] && kill -USR1 `cat /var/run/nginx.pid`        endscript}

nginx 日誌切割後會運行 kill -USR1 這個讓nginx 從新建立日誌文件或者奪回日誌文件的操做權。

怎樣監控日誌

那麼怎樣監控日誌被刪除，寫入權被其餘程序奪取？對於程序猿必定很關注這個問題。下面咱們講解怎麼監控日誌。

Linux 系統可使用 inotify 開發包來監控文件的狀態變化，包括開打，寫入，修改權限等等。

你須要啓動一個進程或者線程監控日誌文件的變化，以便隨時reload 你的主程序。

prog { sign = null
	logfile = /var/log/your.log
	
	thread monitor { inotify logfile { sign = reload } } thread worker { loop{ f = open(logfile) loop{ f.append(....) if(sign == reload) { break } } f.close() } } main(){ monitor.start() worker.start() }}

不知你是否看懂，簡單的說就是兩個並行運行的程序，一個負責日誌監控，一個負責幹活，一旦日誌發生變化就通知主程序 reload。 至於使用進程仍是線程去實現，取決於你熟悉那種語言或者你擅長的技術。

總結

小小的日誌文件有如此大的學問，目前不少應用程序寫的比較健壯，可以判斷出當前日誌被刪除，改寫。程序運行中可以在建立丟失的日誌文件，當日志被其餘程序改寫後，可以奪回寫入權。 但這樣的程序會影響程序併發性能，魚和熊掌不能兼得。看了這篇文章我想你應該對日誌有了全面瞭解，也會在接下來的工做中謹慎處理日誌。