MULE 无法接收 TCP 报文问题分析

概述

近期某使用mule的项目在与N公司联调时发现对方的请求存在严重延迟. 请求是基于TCP协议的. 

通过一步步分析, 最终定位到问题的根源并解决. 通过本文对整个过程进行下梳理和总结.

问题描述

我是6月24日突然被拉进一个微信群的. 

当时的情况是: 该项目碰到一个棘手的问题, 开发找不到问题根源, 已经联系过主机和网络, 也没有什么进展.

开发的详细描述

问题分析流程

要分析问题, 最重要的是2件事:

1. 尽可能多的细节. 并且在这些细节中, 分清楚:

a. 哪些是既定事实

b. 哪些是阐述者自己的判断.

1. 对任何事情都保持怀疑. 哪怕是:

a. 既定事实.

b. 你认为所有人都绝不可能犯的简单错误

问题梳理

再次回顾一下开发的详细描述, 事实有:

● 专线接入

● TCP协议传输

● 请求经常性的出现超时

● 渠道方反馈一直超时read timed out

● 服务器是正常接收渠道方请求

● 换另一个mule(6040) app, 应用可以立马收到.

开发自己的判断是:

● 可能是网络问题

● 可能是所在的机器缓存字段接收区分发到应用服务端口之间可能有问题. (主机问题)

第一天 - 6月24日

主机网络情况了解

1. 网络组已经抓包了, 基本可以确定不是网络问题. (但是证据不够强有力)



2. 主机组无法自证所谓的: 所在的机器缓存字段接收区分发到应用服务端口之间的状态

前一天是梳理好开发的描述, 主机和网络组也做了些测试分析, 今天首先要做的就是询问他们的测试分析情况.

对以上的描述梳理后, 事实没有更新, 但我自己基本上断定问题和主机/网络无关, 而应该是应用的问题. 



新增判断: 主机网络的判断也是:可能是应用问题.



那么接下来就是尽可能的增加应用的可观察性了, 发生问题期间, metrics指标肯定没问题, 日志也找不到问题. 那么这时候就只能用到APM监控了.

安装应用监控

这边有个小插曲, 我也大致描述一下吧.

APM监控, 我这边有2套:

● 开源APM - pinpoint

● 商业APM - Dynatrace AppMon

先装pinpoint, 装完pinpoint agent重启后, 发现拿不到请求数据. 拿不到数据2个原因:

● mule 这个组件比较特殊, 没有对应的插件;

● 报文直接走的4层TCP协议, pinpoint无法抓到4层TCP.

所以最后还是安装Dynatrace了监控.

第二天 - 6月25日

配监控和联调

1. Dynatrace已监控, 经过配置后(默认也抓不到, 因为入口点不是常用的应用传输协议. 另外后续会有另一篇文章介绍如何进行这些高阶监控配置)可以看到mule的所有Transaction.



2. 生效后再进行联调, 发现情况: mule-for N公司应用立马就可以接收到报文的, 只是接收了之后处理必超时. 其实这里就可以断定不是主机和网络的问题了. 如下图:



3.  初步怀疑是"接收报文"的方法可能有问题. 问开发, 开发不知道是哪个方法. 个人根据方法树判断, 可能是:

 com.xxxx.ap26.gateway.transport.tcp.protocol.TcpHeaderProtocol.readFully(byte[], int, int)(翻到结论可以发现, 我个人判断的并不是完全准确), 针对这个方法进行更细粒度监控. (加入sensor, 抓取第三个参数int)



4.  加入后, 发现会调用4次, 前3次都很快, 第4次超时. 第四次int是416报文长度. 但是这个却执行了近500s. 如下图:

作为对比, 正常的请求是这样的:

初步结论

1. N公司发过来的, 不论是发到mule-for N公司 8110端口还是已上线渠道6040端口, 都是450-500s 超时. 一直在socketRead读取数据. (也是通过监控看到的）

所以，之前的事实: 换另一个mule(6040) app, 应用可以立马收到 并不是事实.



2. 肯定不是网络和主机的问题. 因为mule已经收到了.



3. 肯定是应用的问题. 因为mule在处理且在开发自己写的代码处超时了. (具体见上图)

三个怀疑点

1. 怀疑报文传输处理过程出错: 看一下报文传输或者处理过程中是不是出现问题了, 报文长度416, 但是读取了480多s还在读取.



2. 怀疑编码问题: 我还是觉得可能跟报文的编码格式问题有关系. 建议对一下报文的编码格式. (这个怀疑后来验证不成立)



3. 怀疑开发的TCP相关方法实现问题:

com.xxxx.ap26.gateway.transport.tcp.protocol.TcpHeaderProtocol.readFully(java.io.InputStream, byte[], int, int)这个方法实现可能有问题 (这个怀疑其实后面也被证明不正确)

第五天 - 6月28日

因为我不是开发, 我最终只能将怀疑范围缩小到应用相关的3点. 我这边根据监控和判断, 给出了我的建议和后续的调查方向. 开发老师也是不负众望, 最终定位到了问题的根源.

问题根因详细说明

开发老师的根因详细说明:

根因及解决办法

根因

确实是TCP相关方法实现的问题, 解析TCP的方法有问题, 导致报文处理过程出错, 从而导致报文处理超时.

解决办法

开发反馈的解决办法:

解决了，换了种方式，tcpheader是我们自己封装的，现在不用它了，直接用原生TCP对象解析.



感悟和结论

1. 现在已经2020年了, 网络出问题的概率很小. 碰到问题, 请不要把网络列为第一怀疑点, 这个会带偏分析方向;



2. 出问题, 自己代码问题概率最大, 其次才是: 框架, java源代码, 主机, 网络... 所以首先要做的应该是增加自己应用的可观察性.



3. 开发如何增加代码的可观察性?

    a. 做threaddump和cpu采样

    b. 加debug日志

    c. 做trace分析.



4. APM监控真是个分析问题的神器, 像这种既不是常用软件(如tomcat, nginx...), 又不是通用协议(如: HTTP/ web service...)的情况, APM还是能追根溯源. 顺便还能帮助主机网络组老师自证清白.