第一次线上 Bug 献给了 ThreadLocal



前言

捂脸.jpg

起因

这篇博文说到的用了 Mybatis 做拦截器来记录产品以及运营变更后台内容的操作信息。本来直接在后台管理的模块操作就可以了,但是有个要求是记录操作前后的信息……因为公司大都是微服务采用的单数据源,操作人信息是在 A 服务,变更前后的信息是在 B 服务。

一开始接到任务的时候就感觉不好搞,这不是坑爹嘛直接拦截 Controller 的日志多好(小声)

经过与大佬的深入探讨,有两个技术方案。这里为了长话短说,就只讲最终实现的技术方案。

我需要在 RPC API 中加个字段来传递操作人的真实信息以及客户端 IP,B 服务接收到后通过 ThreadLocal 传递到 DAO 层,最后拦截器先去数据库查询出旧值,然后执行原来的方法,最后拼接旧值以及新值,日志入库。

这个方案很完美有没有,嗯如果没有 Bug 就很完美。

开发

经过几天的开发、提测、测试通过、上线了。

上线半小时,导师通过 kibana 观察线上的日志发现并没有什么问题。看一眼线上的数据库,卧槽记录了几张不用记录的表,操作人信息怎么都是一样的,功能倒是写的没问题,就是似乎将所有业务的增删改特定的方法都记录了……

排错

下面是段很有意思的对话

我:为什么能获取到操作人的信息,如果 A 系统没带过来的话,B 中心服务所有的操作为什么会带有脏信息……
导师:你这写的有问题啊?
我:是啊,OS:代码不都给你 review 过了么(逃)
导师:你是不是用了 ThreadLocal
我小鸡啄米似的点头
导师:讲道理线程调用结束了 ThreadLocal 不就被回收了么?
我:是啊是啊

随后导师看着逐渐增加的日志记录表陷入了沉思,我也陷入了思考……

突然灵光乍现,因为没有在拦截器的拦截方法里 remove 掉 ThreadLocal,肯定有个线程池调用了,那为什么有线程池呢?哦艹,Dubbo 默认有线程池……我没有 remove 掉,管理操作后台如果有操作可能会污染到所有线程。

复现

因为只是增加了记录日志数量,所以大佬们似乎并不急于修复数据让我先自己在本地复现一下确定原因。
我把 Dubbo 线程池的数目调成 1, DeBug 模拟登录复现了场景。Dubbo 通过线程池来处理提供 provider 的服务,如果我没有 remove 掉的话会导致相关信息一直在,GC 回收时会产生内存泄漏

修复

ThreadLocal remove 掉需要用 finally 代码块,侵入性太强,经过短暂的讨论决定新版本用注解add 以及 remove 掉 ThreadLocal,暂时的解决方案是注释掉拦截器。

总结

那天加班到了九点,第一次遇到线上的 bug 有点猝不及防。

虽然我知道 ThreadLocal 需要 remove,但是想当然以为没有线程池调用就不会有问题。
是啊没有线程池调用是没啥问题,但最骚的是忽略了 Dubbo 内部有个默认的线程池去提供服务。有了理论基础还是要有实践经验,不然容易出问题。

庆幸我是实习生,不然绩效就是 C 了(手动狗头)

------------- The End -------------
「不求打赏---只求大佬点广告」
0%