利用split工具解決一次MongoDB日誌異常問題

  • 2019 年 11 月 7 日
  • 筆記

故事背景

資料庫明細

說在前面：

  • 資料庫： MongoDB集群 4個分片節點
  • 分片節點規格： 16核 / 32G CentOS 7.4 64位
  • 數據目錄所在磁碟: 300G 49G 252G 17% /data

故事情節

  • 某天晚上剛到家不久，就接到杭州同事的電話，客戶MongoDB集群中的某個分片節點CPU飆高，初步判斷是慢查詢，現在需要拉取CPU飆高時間段的慢查詢。 心想拉取慢查詢應該很快，不就是個系統日誌嗎？ 而且還做了日誌切割一天一個，按道理很快搞定的，誰知當天晚上搞了接近三個小時也沒搞定。 究竟發生了什麼？
  • 進入到日誌目錄一看，目前保留近7天的日誌，每天的日誌量在23G~24G，我當時就想這個客戶數據量這麼大！ 後續發現日誌格式本該為普通文本文件確變成了圖片格式，究竟為何會文件格式會轉變？ 能否從圖片格式中拉取指定時間段的日誌呢？
  • 第二天到公司，由於客戶環境我們也是第一次接受，因此咱們技術專家團隊搞了一個3人的」專家會診」，經過了一番折騰總算把原因找到了，具體過程請看下文！

復現與剖析

拉取日誌異常

使用mlogfilter過濾文件時報錯說文件非mongodb的日誌文件

[root@sh_01 booboo]# mlogfilter shard.log.2018-08-01 --from 2018-08-01T15:00:00.000+0800 --to "+1h" --slow 1000 > /alidata/booboo/tf.1  報錯:非mongodb日誌格式

回到客戶伺服器檢查日誌文件格式，明細如下：

[root@MONGO-SHARD-18 logs]# file *  shard.log:            PCX ver. 2.5 image data  shard.log.2018-07-25: PCX ver. 2.5 image data  shard.log.2018-07-26: PCX ver. 2.5 image data  shard.log.2018-07-27: PCX ver. 2.5 image data  shard.log.2018-07-28: PCX ver. 2.5 image data  shard.log.2018-07-29: PCX ver. 2.5 image data  shard.log.2018-07-30: PCX ver. 2.5 image data  shard.log.2018-07-31: PCX ver. 2.5 image data  shard.log.2018-08-01: PCX ver. 2.5 image data

mongodb的日誌正常應該為：ASCII text, with very long lines，但是現在卻變成了PCX ver. 2.5 image data。需要弄清楚原因。

日誌異常分析

  • 為什麼客戶每天的日誌量達到22個G，並且每天的日誌量都是大於等於前一天？ 很顯然，日誌截斷有問題。
  • 這個是近7天的日誌，而日誌格式變成了PCX圖片格式是為何？
  • 懷疑每次日誌輪詢時都沒有真正截斷日誌！

分析原日誌切割明細

懷疑與echo >有關，進行驗證。

驗證 echo >與PCX圖片頭部0a一致

  1. 建一個空文檔log； 執行echo > log； 通過cat -A log查看文件中插入了一個符號即換行符n
  2. 通過hexdump -c log 查看測試文件頭部顯示為ASCII字元 n
  3. 通過hexdump -d log 查看測試文件頭部顯示為16進位00010 即0a
  4. 通過vim 用16進位查看文檔log可以看到log的文件頭部為0a，正是PCX圖片的頭部
  5. 生產環境查看客戶有問題的mongodb系統日誌文件格式為PCX圖片格式
  6. 通過hexdump -c log 顯示為ASCII字元，生產日誌文件頭部與測試的log一致，都是n
  7. 通過hexdump -d log顯示為16進位，生產日誌文件頭部與測試的log一致00010 即 0a

到此驗證成功:通過echo > log的方式會往文件頭部新增』0a』

復現MongoDB日誌從ASCII text轉變為PCX 格式

在測試環境中復現日誌從ASCII text變成PCX ver. 2.5 image data

  1. 通過mongo登陸資料庫執行大量的插入操作
  2. 通過echo > mongod27017.log 命令嘗試清空mongod27017.log
  3. 查看截斷後的日誌文件格式，變成了very short file (no magic)
  4. 等文檔插入完畢
  5. 通過tail -f 查看日誌明細，看到確實有日誌寫入
  6. 查看日誌格式，發現變成了PCX ver. 2.5 image data
[root@sh_01 ~]# mongo  MongoDB shell version: 3.2.16  connecting to: test  > db.auth('test_dev','uplooking')  1  > db.t1.find()  { "_id" : ObjectId("5b5ebb6796b8b74a73ee30f6"), "a" : 1, "b" : 2 }  { "_id" : ObjectId("5b5ebb6996b8b74a73ee30f7"), "a" : 1, "b" : 1 }  > for (i=1;i<200000;i++){  ... db.t1.insert({id:i})}  WriteResult({ "nInserted" : 1 })    [root@sh_01 ~]# cd /alidata/mongodb/logs  [root@sh_01 log]# ll  -rw-r--r-- 1 root root 2182 Aug  3 10:28 mongod27017.log  -rw-r--r-- 1 root root 3100 Aug  2 14:19 mongod27017.log.2018-08-02T07-18-27  -rw-r--r-- 1 root root 1526 Aug  2 15:18 mongod27017.log.2018-08-02T07-18-54  [root@sh_01 log]# file *  mongod27017.log:                     ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines    [root@sh_01 log]# echo > mongod27017.log  [root@sh_01 log]# echo > mongod27017.log  [root@sh_01 log]# ll  total 12  -rw-r--r-- 1 root root    1 Aug  3 10:29 mongod27017.log  -rw-r--r-- 1 root root 3100 Aug  2 14:19 mongod27017.log.2018-08-02T07-18-27  -rw-r--r-- 1 root root 1526 Aug  2 15:18 mongod27017.log.2018-08-02T07-18-54  [root@sh_01 log]# file *  mongod27017.log:                     very short file (no magic)  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines    [root@sh_01 log]# tail -f mongod27017.log    2018-08-03T10:30:21.936+0800 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:43720 #2 (2 connections now open)    [root@sh_01 log]# ll -h  total 12K  -rw-r--r-- 1 root root 2.8K Aug  3 10:30 mongod27017.log  -rw-r--r-- 1 root root 3.1K Aug  2 14:19 mongod27017.log.2018-08-02T07-18-27  -rw-r--r-- 1 root root 1.5K Aug  2 15:18 mongod27017.log.2018-08-02T07-18-54  [root@sh_01 log]# file *  mongod27017.log:                     PCX ver. 2.5 image data  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines    # 一邊不斷產生日誌，一邊多次執行echo>  [root@sh_01 log]# echo > mongod27017.log  [root@sh_01 log]# echo > mongod27017.log  [root@sh_01 log]# file *  mongod27017.log:                     PCX ver. 2.5 image data  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines  mongod27017.log.2018-08-03T03-09-08: PCX ver. 2.5 image data  [root@sh_01 log]# echo > mongod27017.log  [root@sh_01 log]# file *  mongod27017.log:                     very short file (no magic)  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines  mongod27017.log.2018-08-03T03-09-08: PCX ver. 2.5 image data  [root@sh_01 log]# ll -h  total 16K  -rw-r--r-- 1 root root    1 Aug  3 11:28 mongod27017.log  -rw-r--r-- 1 root root 3.1K Aug  2 14:19 mongod27017.log.2018-08-02T07-18-27  -rw-r--r-- 1 root root 1.5K Aug  2 15:18 mongod27017.log.2018-08-02T07-18-54  -rw-r--r-- 1 root root 2.9K Aug  3 11:05 mongod27017.log.2018-08-03T03-09-08  [root@sh_01 log]# file *  mongod27017.log:                     very short file (no magic)  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines  mongod27017.log.2018-08-03T03-09-08: PCX ver. 2.5 image data  [root@sh_01 log]# file *  mongod27017.log:                     PCX ver. 2.5 image data  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines  mongod27017.log.2018-08-03T03-09-08: PCX ver. 2.5 image data  [root@sh_01 log]# hexdump -c mongod27017.log  0000000  n                                0000010                                  *  0000850                 2   0   1   8   -   0   8   -   0  0000860   3   T   1   1   :   2   9   :   0   6   .   7   2   9   +   0  0000870   8   0   0       I       A   C   C   E   S   S               [  0000880   c   o   n   n   3   ]       U   n   a   u   t   h   o   r   i  0000890   z   e   d   :       n   o   t       a   u   t   h   o   r   i  00008a0   z   e   d       o   n       t   e   s   t       t   o       e  00008b0   x   e   c   u   t   e       c   o   m   m   a   n   d       {  00008c0       f   i   n   d   :       "   t   1   "   ,       f   i   l  00008d0   t   e   r   :       {   }       }  n  成功復現了客戶的情況：    第一次echo > log，文件頭部新增n    多次echo > log,文件頭部如下：    0000000  n                                0000010                                  *

成功復現了客戶的情況：

  1. 第一次echo > log，文件頭部新增n
  2. 多次echo > log,文件頭部如下：
0000000  n                                0000010                                  *

確實是mongodb日誌輪詢出了問題：

  1. echo > log會往文件頭部插入n即16進位的0a
  2. 在資料庫正常運行中，對log文件是加了鎖的，強制執行echo > log是無法進行覆蓋的，會將所有的數據全部置為0
  3. 強制覆蓋後，文件頭部變成了無數的空白

待解決問題

  • MongoDB日誌輪詢方法調整為kill -SIGUSER1 [mongodpid]
  • 修複目前已經變為圖片格式的日誌，並拉取15點到16點的日誌

解決方法

MongoDB日誌輪詢

測試環境

[root@sh_01 log]# pidof mongod  1828  [root@sh_01 log]# kill -SIGUSER1 1828  -bash: kill: SIGUSER1: invalid signal specification  [root@sh_01 log]# kill -SIGUSR1 1828  [root@sh_01 log]# ll  total 16  -rw-r--r-- 1 root root 1526 Aug  3 11:09 mongod27017.log  -rw-r--r-- 1 root root 3100 Aug  2 14:19 mongod27017.log.2018-08-02T07-18-27  -rw-r--r-- 1 root root 1526 Aug  2 15:18 mongod27017.log.2018-08-02T07-18-54  -rw-r--r-- 1 root root 2942 Aug  3 11:05 mongod27017.log.2018-08-03T03-09-08  [root@sh_01 log]# file *  mongod27017.log:                     ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-27: ASCII text, with very long lines  mongod27017.log.2018-08-02T07-18-54: ASCII text, with very long lines  mongod27017.log.2018-08-03T03-09-08: PCX ver. 2.5 image data

生產環境

修改日誌輪詢腳本：

[root@MONGO-SHARD-18 logs]# cat /etc/init.d/mongo_logspit.sh  #!/bin/bash  # 2018/08/02 Apple  #Rotate the MongoDB logs to prevent a single logfile from consuming too much disk space.    cmd=mongod  mongodpath=/opt/mongodb/bin  pidarray=`pidof ${mongodpath}/$cmd`  LOGPATH_SHARD=/data/mongodb/shard1/logs    for pid in $pidarray;do  if [ $pid ]  then      kill -SIGUSR1 $pid  fi  done  #clear logfile more than 7 days  cd $LOGPATH_SHARD  find ./ -xdev -mtime +7 -name "shard.log.*" -exec rm -f {}  ;

所有的分片都去執行：

kill -SIGUSR1 pidof mongod

分片15操作如下：其他分片同樣

[zyadmin@MONGO-SHARD-15 ~]$ sudo -i  [root@MONGO-SHARD-15 ~]# cd /data/mongodb/shard1/logs/  [root@MONGO-SHARD-15 logs]# ll -h  total 1.7G  -rw-r--r-- 1 root root 20G Aug  2 15:27 shard.log  -rw-r--r-- 1 root root 19G Jul 25 23:50 shard.log.2018-07-25  -rw-r--r-- 1 root root 19G Jul 26 23:50 shard.log.2018-07-26  -rw-r--r-- 1 root root 19G Jul 27 23:50 shard.log.2018-07-27  -rw-r--r-- 1 root root 20G Jul 28 23:50 shard.log.2018-07-28  -rw-r--r-- 1 root root 20G Jul 29 23:50 shard.log.2018-07-29  -rw-r--r-- 1 root root 20G Jul 30 23:50 shard.log.2018-07-30  -rw-r--r-- 1 root root 20G Jul 31 23:50 shard.log.2018-07-31  -rw-r--r-- 1 root root 20G Aug  1 23:50 shard.log.2018-08-01  [root@MONGO-SHARD-15 logs]# file *  shard.log:            PCX ver. 2.5 image data  shard.log.2018-07-25: PCX ver. 2.5 image data  shard.log.2018-07-26: PCX ver. 2.5 image data  shard.log.2018-07-27: PCX ver. 2.5 image data  shard.log.2018-07-28: PCX ver. 2.5 image data  shard.log.2018-07-29: PCX ver. 2.5 image data  shard.log.2018-07-30: PCX ver. 2.5 image data  shard.log.2018-07-31: PCX ver. 2.5 image data  shard.log.2018-08-01: PCX ver. 2.5 image data  [root@MONGO-SHARD-15 logs]# kill -SIGUSR1 `pidof mongod`  [root@MONGO-SHARD-15 logs]# file *  shard.log:                     ASCII text, with very long lines  shard.log.2018-07-25:          PCX ver. 2.5 image data  shard.log.2018-07-26:          PCX ver. 2.5 image data  shard.log.2018-07-27:          PCX ver. 2.5 image data  shard.log.2018-07-28:          PCX ver. 2.5 image data  shard.log.2018-07-29:          PCX ver. 2.5 image data  shard.log.2018-07-30:          PCX ver. 2.5 image data  shard.log.2018-07-31:          PCX ver. 2.5 image data  shard.log.2018-08-01:          PCX ver. 2.5 image data  shard.log.2018-08-02T07-27-29: PCX ver. 2.5 image data  [root@MONGO-SHARD-15 logs]# ll -h  total 1.7G  -rw-r--r-- 1 root root 2.0K Aug  2 15:27 shard.log  -rw-r--r-- 1 root root  19G Jul 25 23:50 shard.log.2018-07-25  -rw-r--r-- 1 root root  19G Jul 26 23:50 shard.log.2018-07-26  -rw-r--r-- 1 root root  19G Jul 27 23:50 shard.log.2018-07-27  -rw-r--r-- 1 root root  20G Jul 28 23:50 shard.log.2018-07-28  -rw-r--r-- 1 root root  20G Jul 29 23:50 shard.log.2018-07-29  -rw-r--r-- 1 root root  20G Jul 30 23:50 shard.log.2018-07-30  -rw-r--r-- 1 root root  20G Jul 31 23:50 shard.log.2018-07-31  -rw-r--r-- 1 root root  20G Aug  1 23:50 shard.log.2018-08-01  -rw-r--r-- 1 root root  20G Aug  2 15:27 shard.log.2018-08-02T07-27-29

修復異常日誌

修復思路

弄清楚日誌變更的原因以及復現過程後，不難發現，日誌因為頭部變化從而導致文件格式變更。因此推測異常日誌的組成如下：

  1. 頭部為0a
  2. 中間全部都是0
  3. 最後是正常的字元串記錄著mongodb的日誌資訊，類似於2018-08-03T10:30:21.936+0800 I NETWORK [initandlisten] connection accepted from 127.0.0.1:43720 #2 (2 connections now open)由日誌和日誌明細組成

因此修復的思路如下：

  • 23G的日誌，首先按照大小6G做切分split -b 6G log，切分成4個文件
  • 查看切分後的日誌格式，如果最後一個日誌為ASCII text則不再切分否則，將最後一個日誌繼續切分
  • 循環上一步，直到最後一個文件切分出來沒有ASCII text為止

操作明細

日誌輪詢的部署距離現在大概4個月

  1. 第一次將23G的文件以6G切分成4個文件： xaaxabxacxad，查看4個文件的屬性為
xaa:               PCX ver. 2.5 image data  xab:               PCX ver. 2.5 image data  xac:               PCX ver. 2.5 image data  xad:                PCX ver. 2.5 image data
  1. 重命名xad為x1第二次切分x1 5G，按照1G切分成5份，查看文件屬性 xaa: PCX ver. 2.5 image data xab: PCX ver. 2.5 image data xac: PCX ver. 2.5 image data xad: PCX ver. 2.5 image data xae: ASCII text, with very long lines
  2. 重名xad 為 x2 按照15M的大小切分，查看文件的屬性如下
xaa:          PCX ver. 2.5 image data  此處省略。。。  xdo:               PCX ver. 2.5 image data  xdp:               ASCII text, with very long lines  xdq:               ASCII text, with very long lines  xdr:               ASCII text, with very long lines  xds:               ASCII text, with very long lines  xdt:               ASCII text, with very long lines  xdu:               ASCII text, with very long lines  xdv:               UTF-8 Unicode text, with very long lines  xdw:               ASCII text, with very long lines  xdx:               ASCII text, with very long lines  xdy:               ASCII text, with very long lines
  1. 切分後文件類型為ASCII text的文件中找到15點~16點的文檔
[root@sh_01 mongolog_20180801]# head -n 2 xdv  re: "x86_64", version: "Kernel 3.10.0-693.2.2.el7.x86_64" } }  2018-08-01T16:13:44.958+0800 I ACCESS   [conn4972925] Successfully authenticated as principal __system on local  [root@sh_01 mongolog_20180801]# head -n 2 xdu  38422 #4967772 (445 connections now open)  2018-08-01T14:00:10.575+0800 I NETWORK  [thread1] connection accepted from 172.16.0.44:38430 #4967773 (446 connections now open)
  • xdv 的頭部是2018-08-01T16:13:44.958+0800,因此可以確定15~16的日誌在xdu中
  • xdu記錄的日誌時間段為2018-08-01T14:00:10.575+0800~2018-08-01T16:13:44.958+0800
  • 重命名xdu為mongolog.18.14_16

分析日誌

分析命令

# 獲取08月01號下午3點開始到4點執行時間超過5秒的查詢  mlogfilter mongolog.18.14_16 --from 2018-08-01T15 --to "+1h" --slow 5000 > slowlog.txt    # 獲取08月01號下午3點開始到4點語句的執行次數、用時等統計資訊  mloginfo slowlog.txt  --queries > an_slowlog.txt    # 通過mplotqueries進行慢查詢散點分布圖繪製，且只返回前10個  mplotqueries slowlog.txt --output-file 01.png --logscale --group-limit 10

慢查詢散點分布圖

[root@sh_01 booboo]# mplotqueries slowlog.txt --output-file 01.png --logscale --group-limit 10    SCATTER plot     id   #points  group      1       692  order.order      2       615  omdmain.item_region_erp      3         1  omdmain.customer  ()

總結

mongodb日誌輪詢的問題

  1. echo > log會往文件頭部插入n即16進位的0a
  2. 在資料庫正常運行中，對log文件是加了鎖的，強制執行echo > log是無法進行覆蓋的，會將所有的數據全部置為0
  3. 強制覆蓋後，文件頭部變成了無數的空白

問題解決

  • MongoDB日誌輪詢方法調整為kill -SIGUSER1 [mongodpid]
  • 修複目前已經變為圖片格式的日誌，並拉取15點到16點的日誌

該case花了一整天，從懷疑被攻擊到確認是日誌輪詢引起文件格式變更是一個關鍵轉折點；

另外PCX格式是第一次碰到，疑惑了半天~最後是@培堯發現了echo的端倪，@衾襲@大寶去驗證最終確認了問題的根源。

來源：https://www.toberoot.com/，作者：BooBooWei 轉自：高效運維公眾號

VirMach 便宜 VPS

QNews

QNews