记一次生产事故

一个程序猿遇到个问题,他决定用多线程解决,现在他有题了个问两。


经过

上周六刚熬夜上线新feature,次日本来要美美的睡一觉,不到9点就被客服在微信群炸醒,用户又领不到优惠券了!(什么啊你你你说清楚,为什么是呢)。

这是总部app调我们web的http接口,用户在app中抽取优惠券,然后调用我们接口后给账户充值优惠券并返回结果。用户在app点查看会跳转到我们提供的一个显示页面。

那边开发说接口404了。
我艰难的爬起床,登陆服务器查看,日志一切正常啊!又post个请求过去,一切OK啊!
然后截上图问对面,你看,我连正常啊!
对面静默了一会儿,“你们接口是https?”

我。。。

shit!当初接口文档清清楚楚写着https,之前因为接口命名和转发规则不太规范,所以前一晚大规模升级的时候把接口转发配置规范了一下,导致http接口才访问不了。
然后才知道那边也没有做任何异常处理,先是成功给用户抽中优惠券,然后再调用我们接口,一个同步的TCP接口他们居然搞成异步操作我也是醉了,亏的我还把各种错误信息和异常情况分门别类的给返回清楚,一搞人全当成正常情况处理了。

赶紧先把功能停掉,直接截取昨晚至现在的失败记录,重新处理,我这边也在nginx把http转发规则加上。

随后那边反应,还是有些失败的,有很多返回空的记录

这就不对了!http接口也开了还有失败的?难道是接口代码有问题?

后来检查了一下,果然有问题!
本来优惠券的功能只对内部系统提供dubbo服务,后来添加了对外的http服务,当时嫌tomcat太重,就用Netty4简单的写了个http服务端。
是通过继承了ChannelInboundHandlerAdapter的hanlder来实现,每个请求调用两次channelRead(ChannelHandlerContext ctx, Object msg),msg分别被拆成HttpRequest和HttpContent。

分析日志发现许多请求header正常,但丢失了上下文,仔细检查代码才发现原来定义了个Map来缓存context,初步判断是存取的时候可能ChannelHandlerContext对象发生了变化。那就是说有可能执行业务ChannelHandler的线程跟处理业务的线程不是同一个线程!

查了下Netty4线程模型的相关文档发现,Netty修改了outbound的线程模型,正好影响了业务消息发送时的线程上下文传递,最终导致线程变量丢失。
初步解决是去掉了缓存的Map,content直接取解析了的HttpContent,重新打包部署,那边调用没有再出现此类问题。

分析

线上问题暂时解决了,但之前查看日志的时候发现有这么一句:

LEAK: ByteBuf.release() was not called before it’s garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, specify the JVM option ‘-Dio.Netty.leakDetectionLevel=advanced’ or call ResourceLeakDetector.setLevel()

代码里已经将ByteBuf给release掉了,居然还会有泄漏发生,猜想这可能才是造成问题的根本原因
继续啃文档,原来这是Netty提供内存泄露的监测机制
Netty默认会从分配的ByteBuf里抽样出大约1%的来进行跟踪。如果泄漏,就会打印上述语句。
这句话报告有泄漏的发生,提示你用-D参数,把防漏等级从默认的simple升到advanced,就能具体看到被泄漏的ByteBuf被创建和访问的地方。

其中-Dio.Netty.leakDetectionLevel几个级别对应的设置如下:

  • 禁用(DISABLED) - 完全禁止泄露检测,省点消耗。
  • 简单(SIMPLE) - 默认等级,告诉我们取样的1%的ByteBuf是否发生了泄露,但总共一次只打印一次,看不到就没有了。
  • 高级(ADVANCED) - 告诉我们取样的1%的ByteBuf发生泄露的地方。每种类型的泄漏(创建的地方与访问路径一致)只打印一次。对性能有影响。
  • 偏执(PARANOID) - 跟高级选项类似,但此选项检测所有ByteBuf,而不仅仅是取样的那1%。对性能有绝大的影响。

grep了另一台服务器的日志,也有这句纪录,按照文档,添加参数,不过再也没出现过了,测试环境也开着,等下次出现,好好分析下创建和访问的地方。
另建议可以把MaxDirectMemory调大一些,然后监控一下使用情况,可以及时报警。

善后

线上bug暂时处理了,接下来就是善后问题
那边日志记录只有返回失败处理结果的,由于上下文错乱,有些实际失败的记录却返回了成功,这些就要我们这边来筛选出来。
好在我这边日志记录的比较详细,每一步处理都有迹可循,找到错乱前的那句日志,直接grep到文件里面筛选处理,正好温故了一下shell

总结

事情过去后,也要总结一下,许多地方如果之前沟通确定好就不会出问题了。

  1. 接口,尤其是对外接口一定要压测
  2. 要求对方严格按照文档开发
  3. 多线程要处理好并发情况,之前这段写的匆忙,稍后再好好研究下Netty的线程模型