利用split工具解决一次MongoDB日志异常问题

利用split工具解决一次MongoDB日志异常问题
故事布景 数据库明细 说在前面: 数据库: 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共同 建一个空文档log; 履行echo > log; 经过cat -A log检查文件中刺进了一个符号即换行符n 经过hexdump -c log 检查测验文件头部显现为ASCII字符 n 经过hexdump -d log 检查测验文件头部显现为16进制00010 即0a 经过vim 用16进制检查文档log能够看到log的文件头部为0a,正是PCX图片的头部 出产环境检查客户有问题的mongodb体系日志文件格局为PCX图片格局 经过hexdump -c log 显现为ASCII字符,出产日志文件头部与测验的log共同,都是n 经过hexdump -d log显现为16进制,出产日志文件头部与测验的log共同00010 即 0a 到此验证成功:经过echo > log的办法会往文件头部新增’0a’ 复现MongoDB日志从ASCII text改变为PCX 格局 在测验环境中复现日志从ASCII text变成PCX ver. 2.5 image data 经过mongo登陆数据库履行很多的刺进操作 经过echo > mongod27017.log 指令测验清空mongod27017.log 检查切断后的日志文件格局,变成了very short file (no magic) 等文档刺进结束 经过tail -f 检查日志明细,看到的确有日志写入 检查日志格局,发现变成了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 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0000010 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 * 0000850 0 0 0 0 0 0 0 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 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0000010 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 * 成功复现了客户的状况: 第一次echo > log,文件头部新增n 屡次echo > log,文件头部如下: 0000000 n 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0000010 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 * 的确是mongodb日志轮询出了问题: echo > log会往文件头部刺进n即16进制的0a 在数据库正常运转中,对log文件是加了锁的,强制履行echo > log是无法进行掩盖的,会将一切的数据悉数置为0 强制掩盖后,文件头部变成了很多的空白 待解决问题 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 修正反常日志 修正思路 弄清楚日志改变的原因以及复现进程后,不难发现,日志由于头部改变然后导致文件格局改变。因而估测反常日志的组成如下: 头部为0a 中心悉数都是0 终究是正常的字符串记载着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个月 第一次将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 重命名xad为x1第2次切分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 重名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 切分后文件类型为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日志轮询的问题 echo > log会往文件头部刺进n即16进制的0a 在数据库正常运转中,对log文件是加了锁的,强制履行echo > log是无法进行掩盖的,会将一切的数据悉数置为0 强制掩盖后,文件头部变成了很多的空白 问题解决 MongoDB日志轮询办法调整为kill -SIGUSER1 [mongodpid] 修正现在现已变为图片格局的日志,并拉取15点到16点的日志 该case花了一整天,从置疑被进犯到确认是日志轮询引起文件格局改变是一个要害转折点; 别的PCX格局是第一次碰到,疑问了半响~终究是@培尧发现了echo的端倪,@衾袭@大宝去验证终究确认了问题的本源。 来历:https://www.toberoot.com/,作者:BooBooWei

留下评论

电子邮件地址不会被公开。 必填项已用*标注