一次切割日誌引發的血案
一次切割日誌引發的血案
很多應用程式會產生日誌，有些程式已經實現了日誌切割，一般是每天一個檔案。但有時這個切割並不能滿足我們的需求，例如我們需要顆粒度更細的切割。
切割日誌的目的是什麼？
- 日誌尺寸過大
- 便於分析
- 切割後歸檔，或者匯入日誌平臺
切割日誌基本兩種方法：
- 手工或者 shell
- 工具,例如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終端。
第一種情況，日誌檔案被重新命名
終端一，模擬開啟日誌檔案
[[email protected] ~]# cat > /tmp/test.log終端二，重新命名檔案
[[email protected] ~]# mv /tmp/test.log /tmp/test.2016.05.05.log終端一，輸入一些內容然後按下Ctrl+D 儲存檔案
[[email protected] ~]# cat > /tmp/test.log
Helloworld
Ctrl + D[[email protected] ~]# cat /tmp/test.log
cat: /tmp/test.log: No such file or directory第二種情況，日誌檔案被刪除
終端一，模擬開啟日誌檔案
[[email protected] ~]# cat > /tmp/test.log終端二，使用lsof檢視檔案的開啟情況
[[email protected] ~]# lsof | grep /tmp/test.log
cat 20032 root 1w REG 253,1 0 288466 /tmp/test.log終端三，刪除日誌檔案
[[email protected] ~]# rm -rf /tmp/test.log 終端二，檢視日誌的狀態，你能看到 deleted
[[email protected] ~]# lsof | grep /tmp/test.log
cat 5269 root 1w REG 253,1 0 277445 /tmp/test.log (deleted)終端一，回到終端一種，繼續寫入一些內容並儲存，然後檢視日誌檔案是否有日誌記錄被寫入
[[email protected] ~]# cat > /tmp/test.log
Helloworld
^D[[email protected] ~]# cat /tmp/test.log
cat: /tmp/test.log: No such file or directory經過上面兩個實驗，你應該明白了在日誌開啟期間對日誌檔案做重新命名或者刪除都會造成日誌記錄的寫入失敗。
第三種情況，日誌沒有被刪除，也沒有被重新命名，而是被其他程式做了修改
第一步，終端視窗一中建立一個檔案，檔案寫入一些字串，這裡寫入 “one”，然後檢視是否成功寫入。
[[email protected] ~]# echo one > /tmp/test.log[[email protected] ~]# cat /tmp/test.log
one上面我們可以看到/tmp/test.log檔案成功寫入一個字串”one”
第二步，開始追加一些字串
[[email protected] ~]# cat > /tmp/test.log
two先不要儲存（不要發出^D）
第三部，在終端二視窗中清空這個檔案
[[email protected] ~]# > /tmp/test.log
[[email protected] ~]# cat /tmp/test.log通過cat檢視/tmp/test.log檔案，什麼也沒也表示操作成功。
第四步，完成字串追加，使用Ctrl+D儲存檔案，最後使用cat /tmp/test.log 檢視內容。
[[email protected] ~]# cat > /tmp/test.log
two[[email protected] ~]# 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
[[email protected] ~]# 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。 至於使用程序還是執行緒去實現，取決於你熟悉那種語言或者你擅長的技術。
總結
小小的日誌檔案有如此大的學問，目前很多應用程式寫的比較健壯，能夠判斷出當前日誌被刪除，改寫。程式執行中能夠在建立丟失的日誌檔案，當日志被其他程式改寫後，能夠奪回寫入權。 但這樣的程式會影響程式併發效能，魚和熊掌不能兼得。看了這篇文章我想你應該對日誌有了全面瞭解，也會在接下來的工作中謹慎處理日誌。