1.1问题初现
该netty后台是配合远程控制开关使用,可以通过接口操作远程开关间开关或定时操 作,在使用一段时间后出现cpu爆满,日志爆满问题,排查日志发现是空报文(代码中打印了进入hanlder处理时的报文),初步怀疑是恶意请求(处理这个问题是原作者已离职,并无交接,可能我们也不知道netty里有什么要交接,这个平台是在成熟的netty后台迁移过来改造的)。
注:netty报文格式:报文头2位+报文长度2位+命令编码2位+其他内容
1.2问题初查
切换了服务器,重新解析了远程开关后台的请求域名,原服务器仍保留服务,新服务器不久后出现上述问题。初步确定是恶意攻击,进行了白名单、黑名单操作,甚至举报阿里云,于事无补,遂检查代码:代码中需要报文携带设备码(除心跳包外),所以逻辑改成,如果报文里没有设备码,或者报文长度过短直接关闭通道。但是仍然没有生效。
1.3日志表现
log1:在decode方法里打印了一次日志
log2:在channelRead方法里也打印了一次日志
log3:关闭channel前打印了一次日志
日志每次的结构:(循环输出)
log1;log2;log3;log2;log3;log2;log3;log2;log3;log2;log3……
解决问题:
2.1找到触发问题的报文
cto找到了哪一条报文,看着非常普通,这时候我还在考虑是ctx.close()方法有问题,因为通道没有关闭。
2.2问题线下复现
之前自行模拟一直无法打印出空报文(空格都有编码输出);cto使用2.1发现的初始报文复现了这个问题,这时候我们在怀疑这个报文是不是有问题(怀疑是主要业务代码的流程漏洞)。
2.3问题根源
decode方法里进行了一次粘包的处理:
int readableBytes = in.readableBytes();
while (readableBytes > 0) {
if (readableBytes == 1) {
out.add(in.readBytes(readableBytes));
readableBytes = in.readableBytes();
} else if (readableBytes > 3) {
//跳过报文头判断
in.skipBytes(2);
//获取报文内指定位置记录报文长度的报文内容
int pkgLength = in.readUnsignedShort();
//恢复报文的可读长度
in.readerIndex(in.readerIndex() - 4);
//如果报文比记录的报文长度短,就丢弃了
if (in.readableBytes() < pkgLength) {
return;
}
//输出截取后的报文 多余的报文会进行下次循环
out.add(in.readBytes(pkgLength));
readableBytes = in.readableBytes();
}
}
上面代码处理正常的报文没问题,但是异常报文:报文头不对,但读取了报文长度后,收到的实际报文长度比解析出来的表文长度长时bug出现了:第二轮循环的时候in.readableBytes()<pkgLength但是后者为0。上面复现问题的时候,cpu高占用,IDEA卡死,只能kill重启。
改进后的代码:
int readableBytes = in.readableBytes();
//过滤短报文 这个代码还是没解决半包的问题
if (readableBytes < MSG_MIN_LENGTH) {
log.info("error msg");
return;
}
//进行报文头的获取及判断
int head = in.readUnsignedShort();
if (head != CmdType.PROTO_HEADER) {
log.info("illegal msg");
return;
}
int pkgLength = in.readUnsignedShort();
in.readerIndex(in.readerIndex() - 4);
//增加了对报文长度的判断
if (in.readableBytes() < pkgLength || pkgLength < MSG_MIN_LENGTH) {
log.info("incomplete msg");
return;
}
out.add(in.readBytes(pkgLength));
由于客户端的报文由合作方已经定义好,没法增加固定结尾,
另外最长报文和最短报文差异较大,没法固定报文长度来解决半包问题,
或者是我还没找到解决的办法(找到了我再更新)。
上述改进后,再测试问题没有复现。
总结 解决未知问题应遵循的方法
i.定位发生的时机:找到原始报文
ii.测试能否复现:cpu爆满和日志疯狂就应该怀疑到是否有死循环,因为单独的恶意攻击不会造成cpu爆满,另外可以打断点定位,另外分析日志也可以发现,只在decode打印了一次,后面打印都是在channelRead打印,虽然进入了ctx.close方法,但没有关闭通道,这个问题还没法很好解释。
上面切换服务器测试的操作没问题,但是切换后的服务器没有任何请求,无法复现生产环境,所以设置对照参考意义不成立!!!
iii.如果没有更好的办法,就用笨方法,能找到问题并解决问题就是好办法。
在此感谢,帮我定位上述的问题的CTO胜哥!
ps:长时间的curd和cv以及长时间没有遇到过阻塞问题的我已经麻痹了,丧失了本心,新立了flag,在deadline到来之前,望不负初心!打工人!