有了链路日志增强,排查Bug小意思啦!

在工作中,相信大家最怕的一件事就是听到有人在工作群艾特你:某某功能报错啦。。。

然后你就得屁颠屁颠的去服务器看日志,日志量少还好点,多的话找起来太麻烦了。不太容易直接定位到关键地方。

东找找西找找,好不容易找到了报错的信息,却不知道当时的参数信息是什么,也不太好复现,太难了。。

改完还得写故障报告,美好的一天又没了。

要解决这类的痛点需要做下面几件事情:

  • 日志收集
  • 异常告警
  • 日志增加链路
  • API响应增加traceId
  • 异常时打印当前报错方法的参数
  • 支持调试模式

日志收集

要解决的第一个问题就是日志的集中管理,不然报错了你得去多台服务上找错误信息,效率太低了。当然也可以用ansible这种工具来做,最好的还是日志统计收集起来,通过Web页面就可以搜索查看。

日志收集的标杆就是ELK啦,不做过多讲解。像我们是用的云服务,收集起来更方便,直接页面上点点就搞定了。

日志增加链路

日志增加链路跟踪功能分为两个步骤,首先系统要有链路跟踪,然后将链路信息集成到日志中就可以了。

我用的是Spring Cloud Sleuth,主要是Sleuth对很多开源的框架都支持了,也集成了logback这样的日志框架,用起来非常方便。

Sleuth默认增强的日志格式如下:

[${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]

分别是服务名,链路ID, 工作单元ID,是否导入到zipkin中。对于日志来说最重要的就是traceId了,有了traceId就能将所有系统的日志串连起来了。

我们也可以自己扩展,增加一些其他的信息放入日志中。比如:

%X{X-REST-API:-},%X{X-RPC-SERVICE:-},%X{X-ORIGIN-INFO:-},%X{X-USER-ID:-},%X{X-BIZ-NAME:-},%X{X-BIZ-ID:-}
  • X-REST-API:入口API, 全局透传
  • X-RPC-SERVICE:入口RPC, 每个服务入口处新增
  • X-ORIGIN-INFO:来源信息(调用方应用名:IP:服务名)
  • X-USER-ID:用户ID, 全局透传
  • X-BIZ-NAME:业务名称, 全局透传, 应用内可替换
  • X-BIZ-ID:业务ID, 全局透传, 应用内可替换

有了这些扩展的信息就可以直接从日志中知道当前请求的入口API是哪个,也知道整个请求经过了哪些服务。

如果我是订单服务的负责人,当我去排查问题的时候根据日志就知道当前这个错误是上游哪个系统和哪个接口调用导致的。

日志中还带上了用户信息,知道是哪个用户的请求。

BIZ-ID和BIZ-NAME可以用于业务场景的问题排查,比如下单后就知道订单ID了,后续就可以将订单ID追加到日志中,BIZ-NAME=order, BIZ-ID=20102121212121。

后续有支付,发货,退款等等订单相关的操作,日志中都有订单ID,需要排查的时候直接根据订单ID就可以看到整个订单相关的日志信息,前提是打了这些信息。

异常告警

除了用户反馈功能异常,开发也应该在第一时间知道出问题了。所以异常告警一定要做。

一般我们的应用分为:服务应用,Job应用,异步消费应用

服务应用我们可以在统一的异常处理中进行告警,Job应用也可以在统一调度的入口进行告警,异步消费的也是一样。

可以通过消息队列告警,也可以通过制定日志的格式,通过记录日志的方式,让日志收集到日志平台,然后配置各种规则进行告警。

异常告警的时候就可以带上traceId,这样在发现异常的时候,直接通过traceId去日志平台搜索,就可以看到这个traceId相关的所有日志,对排错很有帮助,前提是你打印了关键的日志信息。

API响应增加traceId

可以通过ResponseBodyAdvice对响应结果进行统一定制,增加traceId响应。这样在出问题的时候可以通过响应的traceId直接去日志平台进行日志的搜索。

除了快速排查异常问题之外,对于性能优化的时候,我们也可以直接根据traceId去查看这个API对应的耗时情况,前提是这个traceId就是跟你们的APM系统一致就行。

异常时打印当前报错方法的参数

通过前面的操作,我们已经可以在异常的时候获取一个traceId去排查相关错误信息,也不用去多台机器随机找日志了,极大的提高了问题解决的速度。

只能说这些操作对我们的问题排查起了一半的帮助作用,比如说我现在收到一个告警,然后我去日志平台查了相关的日志,发现某行报错了。

这个时候也只能是猜测这个地方是有问题的,因为我不知道当时是什么参数导致这行报错了。所以如果能在报错的时候将当前报错方法的参数打印到日志中,也就相当于保留了出问题时的现场,解决起问题来就是分分钟的事。

具体实现方案没有固定的,最简单的方式就是写一个Aspect切到所有业务方法上,当方法抛出异常的时候记录参数信息,切记只在异常的时候做这个记录的操作,否则对性能影响很大。

效果:

com.xxx.biz.service.impl.GoodsSkuServiceImpl.createSku异常, 参数信息:{"cspuId":1, stock:10, price:100}
Caused by: java.util.NoSuchElementException: No value present
    at java.util.Optional.get(Optional.java:135)
    at com.xxx.biz.service.impl.GoodsSkuServiceImpl.createSku(GoodsSkuServiceImpl.java:682)

支持调试模式

支持调试模式指的是在某些场景下,我们可以复现出错误,但是除了当时异常时记录的参数信息,还想知道整个请求链路的参数和响应。也就是从入口处经过的所有方法都能够打印出请求和响应数据。

可以定义一个特定的请求头,在复现问题的时候带上这个请求头,由统一的框架去接收这个请求头,然后在整个链路上进行透传。再结合异常的那个Aspect将参数和结果进行日志输出即可。

效果:

xxx.xxxController.makeOrder 参数:xxx
xxx.xxxRpcService.makeOrder 参数:xxx
xxx.xxxStockRpcService.lockStock 参数:xxx
xxx.xxxStockRpcService.lockStock 响应:xxx
xxx.xxxRpcService.makeOrder 响应:xxx
xxx.xxxController.makeOrder 响应:xxx

关于作者:尹吉欢,简单的技术爱好者,《Spring Cloud微服务-全栈技术与案例解析》, 《Spring Cloud微服务 入门 实战与进阶》作者, 公众号 猿天地 发起人。

?著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 214,128评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,316评论 3 388
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 159,737评论 0 349
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,283评论 1 287
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,384评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,458评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,467评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,251评论 0 269
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,688评论 1 306
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,980评论 2 328
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,155评论 1 342
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,818评论 4 337
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,492评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,142评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,382评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,020评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,044评论 2 352

推荐阅读更多精彩内容