奇妙的日志查询组合进阶篇 | 七日打卡

DailyPractice
1,855 阅读11分钟

引言

子曾经曰过不会组合命令查询日志的都不是好程序员.昨天的专栏奇妙的日志查询组合基础篇给大家简单的分析整理了常用的log查询命令,今天我们继续聊聊如何用组合查询命令从log日志中准确筛选出你想要的信息.

管道语法

Linux的查询读取命令更有特色,如果能串联起来一起用就很美滋滋了.好在linux为我们提供了串联语法-|(管道符).|是基础且重要的观念,连结上个指令的标准输出,做为下个指令的标准输入。标准语法为 actionA | actionB,表示执行完行动A后的标准输出会当做输入交由行动B继续处理并输出最后的结果集.

实践

理论终将需要实践去支撑.接下来结合应用场景去探索组合的奇妙.本篇示例日志规范衔接打印接口调用时长.

基础图

复习一下昨天的内容

tail|grep

此组合常用于实时联调.

场景1 : 测试环境刚发了一个版,测试告诉你新功能用户地址新增出现了一个BUG需要排查一下.

解决方案 : 你熟练的打开了终端进入日志目录,自信的敲下tailf xxx.log,并叫测试再点击一下该功能点.刷刷刷,因为模块接口较多,你想要排查的问题接口日志瞬间就淹没在日志海中,此时就需要用到tail|grep的组合过滤掉多余日志.

tailf xxx.log|grep '/user/address',表示我只需要日志中含有/user/address的行打印出来.模拟结果如下

3:2021-01-13 10:00:19.889 [http-nio--exec-5] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[86] - -in- POST /user/address -1349174407649693696
6:2021-01-13 10:00:20.043 [htt-5] INFO  cn.mc.app.tools.interceptor.Runtethod[126] - -out- /user/address return:{"businessId":"1349174174047932416","code":0,"data":/user/address,"message":"成功"} -time:154ms -1349174407649693696
7:2021-01-13 10:00:23.498 [httpexec-14] INFO  cn.mc.app.tools.interceptor.RimeMethod[86] - -in- GET /user/address -1349174422786936832
10:2021-01-13 10:00:23.531 [http-ec-14] INFO  cn.mc.app.tools.interceptor.RunteMethod[126] - -out- /user/address return:{"code":0,"data":[{"address":"123123","createTime":"2021-01-13T10:00:20","defaultFlag":1,"id":2,"name":"123123"}],"message":"成功"} -time:33ms -1349174422786936832

由于我们是restful规则的接口,新增删除修改的资源路径都为/user/address,这时候我们就可以用grep的正则匹配,这里有几种方法可以实现

  • tailf xxx.log|grep -n 'GET./user/address',-n代表输出行数,GET与后面的路径中间的.是匹配单个字符,因为GET后只有空格,所以这样匹配是没有问题的.举一反三,tailf xxx.log|grep -n 'GET./user/a..ress'这样的格式也是可以得出结果的
  • tailf xxx.log|grep -n 'GET'|grep /user/address',用双管道进行过滤,也是可以得到匹配的值.记住管道的概念就是从左往右依次把输出作为第二个管道的输入进行处理,直到最后一个管道处理完毕,输出最终值.
  • tailf xxx.log|grep -n 'GET.*address,.是匹配单个字符,*表示匹配零个或者多个值,所以他们组合在一起就是匹配GET后address前所有的字符,只要满足都会输出.

上面三种方式最终得出的日志结果都是相同的,过滤出GET请求的/user/address接口.

33009:2021-01-13 14:14:13.066 [http--exec-36] INFO  cn.mc.app.tools.interceptor.RunMethod[86] - -in- GET /user/address -1349238300224917504
34229:2021-01-13 14:18:06.828 [http-n0-exec-41] INFO  cn.mc.app.tools.interceptor.Runethod[86] - -in- GET /user/address -1349239280693809152
.......

经过上述的操作我们得到的仅仅只是可以排查入参或者接口通了没有,如果报错的话是匹配不到这一行的,我们需要再次运用grep的参数-after或者-before来实现,tailf xxx.log|grep -na3 'GET.*address,-a为-after的缩写,这时我们便可以找到我们想要的报错信息了,如果还看不到报错的信息,可以尝试把-a后的数值调大.

12834:2021-01-13 09:53:40.131 [http-nec-6] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[86] - -in- GET /user/address -1349172730943115264
12836-2021-01-13 09:53:40.131 [http-exec-6] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[93] - Request header:{"content-length":"111","content-type":"application/json","osversion":"14.3","versioncode":"1","device":"3","accept-encoding":"gzip","user-agent":"Dart/2.10 (dart:io)"} -1349172730943115264
12837-2021-01-13 09:53:40.286 [http-xec-6] ERROR cn.mc.app.tools.interceptor.AbstractAOPInterceptor[93] - error {}
12838-java.lang.NullPointerException: null
12839-  at cn.mc.app.user.service.impl.UserAddressServiceImpl.uppDefaultFlag(UserAddressServiceImpl.java:71)

瞧,我们最终还是找到了报错的原因

结论 : tail|grep能帮助我们在排查实时日志时过滤掉暂时不需要关注的日志,适用于实时排查数据报错以及传参问题的BUG.

cat|grep|more|less

此组合多用于历史报错和多日志文件报错排查.

场景2 : 正式环境上午发的版本,下午客户投诉说在修改地址时遇到了程序异常,需要排查一下是哪里出了问题

解决方案 : 掐指一算这是个历史遗留问题,我需要细细排查.tailf明显已经不满足我的需求了,这属于事后日志了,这时候cat就可以登场了,但是直接cat明显会爆掉,那可是生产环境,还是得用grep过滤掉一些不相关的日志.cat|grep粉墨登场.有了上面tail|grep组合的经验,这里也是轻车熟路,直接cat xxx.log|grep -n 'PUT./user/address',好家伙,果然是生产环境,还是持续滚动着日志,根本停不下来.持续一分钟后终于停了下来,此时的我陷入沉思,这明显下次不能这么干啊,这太耽误效率了.于是优化了一下查询日志条件cat xxx.log|grep -n 'PUT./user/address'|grep '^2021-xxx-xxx',用 ^ 匹配出一个大致的时间段,这样日志就少很多,但是可能我还是太年轻,低估了日志的输出量,足足刷了20秒,这时候想到还可以用linux的分页查询优化一样,于是改良此方案.改用分页查询cat xxx.log|grep -n 'PUT./user/address'|grep '^2021-xxx-xxx'|less -m,-m是less的百分比参数,可以直观的看到我们现在排查到了什么位置.

15397:2021-01-13 10:00:19.889 [http-nio-8080-exec-5] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[86] - -in- POST /user/address -1349174407649693696
43468:2021-01-13 14:54:19.278 [http-nio-8080-exec-65] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[86] - -in- POST /user/address -1349248392609533952
//这里会显示出当前进度,在此界面敲击回车,出现输入行,用/符号加上你想搜索的文字可以二次检索日志
(END)

结论 : cat|grep适用于排查事后BUG的情况,同时由于组合了grep查询,也可方便的过滤暂时无关BUG的日志.|more或者|less属于日志过多的情况下分页的一种优化,可以让我们分页读取日志,同时他们还支持检索,可以进一步检索你需要的信息.

场景3 : 还是正式环境出了BUG,但是这个BUG是前天和今天发生过,需要排查出这个问题是不是同一个原因导致的,从而找出解决方案.

解决方案 : 首先需要明确的是日志文件都是分日期按照大小进行分片存放的,前天的日志可能存在日期下的多个文件中,今天的日志还在写入,所以还没有归档.这涉及到跨文件的查询处理.我们需要用到cat|grep|more.先来看看日志的文件结构.

-rw-r--r-- 1 root root   84278926 Jan 10 23:59 mc-buy-2021-01-10.2.log
-rw-r--r-- 1 root root 1073785238 Jan 11 14:57 mc-buy-2021-01-11.0.log
-rw-r--r-- 1 root root 1073951246 Jan 11 22:18 mc-buy-2021-01-11.1.log
-rw-r--r-- 1 root root   74164855 Jan 11 23:58 mc-buy-2021-01-11.2.log
-rw-r--r-- 1 root root 1074087078 Jan 12 22:25 mc-buy-2021-01-12.0.log
-rw-r--r-- 1 root root   87643541 Jan 12 23:59 mc-buy-2021-01-12.1.log
-rw-r--r-- 1 root root  733238205 Jan 13 16:24 mc-buy.log

可以看到前天的日志被分成了三个加上今天的日志总共四个文件.使用命令cat mc-buy.log mc-buy-2021-01-10.1.log mc-buy-2021-01-10.2.log ..后面的文件依次排列 |grep -n 'PUT./user/address' | less -m 这样我们就能同时排查多个文件中匹配到该关键字的搜索结果啦. 结论 cat 文件1,文件2...|grep|less的组合可以在多日志文件中匹配出日志信息,并进行分页查看.适用于排查一些历史遗漏的问题.cat可以聚合多个文件输出,grep可以通过匹配正则或者精准匹配输出日志,可以说这两个命令是天作之合

sed 或者 cat|head|tail

细心的朋友会发现在上述几个实例中我都特意在grep后加上了-n参数,输出该日志所在的行号,这便是为了确认BUG的行号范围,再通过sed或者cat进行范围查询,精确的查出BUG的所在行.下面我们来尝试一下.以场景2为例

12834:2021-01-13 09:53:40.131 [http-nec-6] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[86] - -in- GET /user/address -1349172730943115264
12836-2021-01-13 09:53:40.131 [http-exec-6] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[93] - Request header:{"content-length":"111","content-type":"application/json","osversion":"14.3","versioncode":"1","device":"3","accept-encoding":"gzip","user-agent":"Dart/2.10 (dart:io)"} -1349172730943115264
12837-2021-01-13 09:53:40.286 [http-xec-6] ERROR cn.mc.app.tools.interceptor.AbstractAOPInterceptor[93] - error {}
12838-java.lang.NullPointerException: null
12839-  at cn.mc.app.user.service.impl.UserAddressServiceImpl.uppDefaultFlag(UserAddressServiceImpl.java:71)

可以看到空指针的异常在12838行,我们以此行数往下推20行左右便可以得知准确的报错.下面有两种实现方式

  • 尝试用sed,基础篇中有写到sed有一个行为参数p用于提取指定行,语法为'num1,num2p',-n参数过滤掉未匹配的行,最终命令sed -n '12838,12858p' xxx.log查询该报错信息

  • 用cat|head|tail的方式,首先我们补充一下他们三个的联合语法,完整语法为cat file|head -n ±num|tail -n (+num)或(num)

    1. cat file |head -n ±num,num正值代表显示文件顶部的num条数据,+符号可省略;负值表示输出顶部到距离尾部的num行的全部数据.默认num为10.
    2. cat file |tail -n (+num)或(num),num代表显示文件尾部的num条数据;加上符号表示输出从第num行开始显示全部数据.默认num为10.
    3. cat file |head -n 1000|tail -n +100,表示显示文件的第100-1000行.
    4. cat file |tail -n +100|head -n 1000,表示显示文件的第100行之后的1000行也就是100-1100的数据.
    5. cat file |tail -n 200|head -n -100,表示显示文件的倒数第100-200行
    6. cat file |head -n -100 |tail -n 300,表示显示文件倒数第100行往上300条数据.

    梳理了这一块不难得出这个地方我们应该用cat file |head -n 12858|tail -n +12838

通过这两种方法均可得出下面的结果,接下来就可以愉快的对症下药了.

java.lang.NullPointerException: null
        at cn.mc.app.user.service.impl.UserAddressServiceImpl.uppDefaultFlag(UserAddressServiceImpl.java:71)
        at cn.mc.app.user.service.impl.UserAddressServiceImpl.addUserAddress(UserAddressServiceImpl.java:49)
        at cn.mc.app.user.service.impl.UserAddressServiceImpl$$FastClassBySpringCGLIB$$c8e6a760.invoke(<generated>)
        .........
        .........
        .........
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)

后记

这两期专栏列举的日常开发排错阶段集中组合的日志查询方式,希望能够帮助到大家.其实还有很多linux查询组合,可以在评论区对我进行补充,我也能查漏补缺更新到我的专栏帮助更多的人.

avatar
文章
阅读
粉丝