原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，轉載請保留出處。

簡介

日常分析問題時，會頻繁地查看分析日誌，但如果蠻力去查看日誌，耗時費力還不一定有效果，因此我總結了在Linux常用的一些日誌查看技巧，提升日誌閲讀效率。

grep查找日誌

在我們查找某些異常日誌時，經常需要同時查看異常前面或後面的一些日誌，因為有時前面或後面的日誌就已經標識出異常原因了，而grep的-A、-B、-C選項就提供了這種功能，如下：

# 查找ERROR日誌，以及它的後10行
$ grep -A 10 ERROR app.log

# 查找ERROR日誌，以及它的前10行
$ grep -B 10 ERROR app.log

# -C代表前10行和後10行
$ grep -C 10 ERROR app.log

查看某個時間段的日誌

有時，需要查看某個時間段的日誌，比如凌晨2點15分系統出現報警，上班後我們想看看這段時間的日誌，看能不能找到點線索，方法如下：

# 導出02:14到02:16分的日誌
awk '/2022-06-24T02:14/,/2022-06-24T02:1[6-9]/' app.log > app0215.log

# 使用sed也是可以的
sed -n '/2022-06-24T02:14/,/2022-06-24T02:1[6-9]/p' app.log > app0215.log

注：awk與sed實際並不解析時間，它們只是按正則匹配，匹配到第一個正則時，開始輸出行，直到遇到第二個正則關閉，所以如果你的日誌中沒有能匹配第二個正則的行，將導致一直輸出到尾行！所以一般需要將第二個正則變寬鬆點，如上面的/2022-06-24T02:1[6-9]/，以避免出現這種情況

查看最後10條錯誤

更多情況是，上班時發現系統有報警，於是想立馬看看剛剛發生了什麼，即查找最近的異常日誌，如下：

# 最容易想到的是tail，但有可能最後1000行日誌全是正常日誌
$ tail -n 1000 app.log | less

# 最後10條異常, tac會反向讀取日誌行，然後用grep找到10個異常日誌，再用tac又反向一次就正向了  
$ tac app.log | grep -n -m10 ERROR | tac

還有一種是從剛報警的時間點開始導出到尾行，比如從2分鐘前的5點15分開始導出，如下：

$ tac app.log | sed '/2022-06-24T17:15/q' | tac > app1715.log

原理與上面類似，只不過是換成了sed，sed默認會輸出處理的每一行，而q指令代表退出程序，所以上面程序含義是從日誌末尾開始輸出日誌，直到遇到正則/2022-06-24T17:15/停止輸出。

awk分段查找

對於像Java程序，異常日誌一般會是一段一段的，且每段帶有異常棧，如下：

但grep是一行一行過濾的，如何一整段一整段的過濾異常棧呢？awk就提供了這種功能，當將awk中RS變量指定為空時，awk就會一段一段的讀取並處理文本，如下：

# 查找異常日誌，並保留異常棧
awk -v RS= -v ORS='\n\n' '/Exception/' app_error.log | less

1. -v RS=等效於-v RS=''，設置RS變量為空，使得awk一段一段地讀取日誌
2. -v ORS='\n\n'設置ORS變量為2個換行，使得awk一段一段的輸出
3. /Exception/代表過濾出包含正則Exception的段

使用less查看

一般情況下，使用less可以更快速的查看日誌，比如通過tail -n10000取出最近1w條日誌，通過less查看，如下：

tail -n 10000 app.log | less

看日誌時，有一個很常見的需求，就是很多日誌都是當前不需要關心的，需要將它們過濾掉，less提供了&/的功能，可快速過濾掉不想看的日誌，從而找到問題日誌，如下：

操作步驟：

1. 先輸入&，再輸入!進入Non-match過濾模式。
2. 然後輸入正則netns，再按Enter，排除掉這種正常的日誌，過濾後又發現有很多drop_caches日誌。
3. 然後也是先輸入&，再輸入!，再直接按上箭頭快速獲取上次的輸入內容，再接着輸入|drop_caches，將drop_caches日誌也過濾掉。
4. 哦豁，發現了一個oom killer日誌！

使用vim查看

less可以一行一行的排除，但如果要一段一段的排除，如日誌中經常會有一些常見且無影響的錯誤日誌，這種情況可以通過vim配合awk排除，如下：

tail -n 10000 app_error.log | vim -  

操作步驟：

1. 先輸入:，進入vim的命令模式
2. 再輸入%!awk -v RS= -v ORS='\n\n' ...，執行awk命令，其中%代表當前文件所有內容，!代表執行命令，所以%!代表將當前文件內容輸入到命令中
3. 然後awk規則中輸入'\!/訂單號不存在/'並回車，這代表排除段中包含訂單號不存在的段，排除後又發現很多沒有找到該暱稱異常。
4. 接着輸入:再按上箭頭快速獲取上次輸入內容，並補充&& \!/沒有找到該暱稱/，將這種常見異常也過濾掉。
5. 哦豁，發現了一個NullPointerException異常！

其它工具

有時為節省磁盤空間，日誌會壓縮成*.gz格式，這也是可以直接查看的，如下：

# 類似cat，同時解壓並輸出內容
zcat app.log.gz  

# 類似grep，同時解壓並查找內容
zgrep -m 10 ERROR app.log.gz  

# 類似less，同時解壓並查看內容
zless app.log.gz

而在處理時間方面，dateutils工具包用起來會更方便一些，如下：

# CentOS7安裝dateutils
$ wget https://download-ib01.fedoraproject.org/pub/epel/8/Everything/x86_64/Packages/d/dateutils-0.4.9-1.el8.x86_64.rpm && rpm -Uvh dateutils-0.4.9-1.el8.x86_64.rpm
# Ubuntu安裝dateutils
$ apt install dateutils

# 根據時間範圍過濾日誌，可指定時間串格式
$ cat dmesg.log | dategrep -i '%a %b %d %H:%M:%S %Y' '>=2022-06-24T12:00:00 && <now'
[Fri Jun 24 12:15:36 2022] bash (23610): drop_caches: 3
[Fri Jun 24 13:16:16 2022] bash (30249): drop_caches: 3

# 有時我們需要將日誌中時間串轉換為unix時間綴，方便處理
$ head -n4 access.log
127.0.0.1 - - [07/May/2022:19:00:25 +0800] "GET /health HTTP/1.1" 200 4 3ms "-" "curl/7.29.0" "-" "-"
127.0.0.1 - - [07/May/2022:19:00:26 +0800] "GET /health HTTP/1.1" 200 4 2ms "-" "curl/7.29.0" "-" "-"
127.0.0.1 - - [07/May/2022:19:00:27 +0800] "GET /health HTTP/1.1" 200 4 2ms "-" "curl/7.29.0" "-" "-"
127.0.0.1 - - [07/May/2022:19:00:28 +0800] "GET /health HTTP/1.1" 200 4 2ms "-" "curl/7.29.0" "-" "-"

$ head -n4 access.log |dateconv -i '[%d/%b/%Y:%H:%M:%S %Z]' -f '%s' -z 'Asia/Shanghai' -S
127.0.0.1 - - 1651950025 "GET /health HTTP/1.1" 200 4 3ms "-" "curl/7.29.0" "-" "-"
127.0.0.1 - - 1651950026 "GET /health HTTP/1.1" 200 4 2ms "-" "curl/7.29.0" "-" "-"
127.0.0.1 - - 1651950027 "GET /health HTTP/1.1" 200 4 2ms "-" "curl/7.29.0" "-" "-"
127.0.0.1 - - 1651950028 "GET /health HTTP/1.1" 200 4 2ms "-" "curl/7.29.0" "-" "-"

注：Ubuntu中對命令進行了改名，dategrep叫dateutils.dgrep，dateconv叫dateutils.dconv

總結

這些工具組合起來還是很強大的，這也是為什麼即使在公司有日誌平台的情況下，依然還是有很多人會去使用命令行！

往期內容

接口偶爾超時，竟又是JVM停頓的鍋！
耗時幾個月，終於找到了JVM停頓十幾秒的原因
mysql的timestamp會存在時區問題？
真正理解可重複讀事務隔離級別
密碼學入門
字符編碼解惑