技术问题分析-报文截断(11.20)

今天继续分析下Oracle OSB总线代理后发布的Web Service服务，在客户端消费的时候出现ESB系统级的异常，具体的异常错误信息为：

OSB-382030:Failure while un-marshalling message: Failed to parse XML text

从字面意思来看很简单，解析出来的报文无法转换为XML格式。这个问题在前面有一篇文章专门分析过，也根据该文章的方法对OSB Server进行了一些调整，主要调整了两项

1. Please keep the Keep Alive OFF

但是即使做了以上两处设置，仍然会偶尔出现Failed to parse XML text的异常错误，即问题并没有得到彻底的解决。而最终Log到的报文来看，即是不完整的被截断后的报文。

对于该问题，我们提出的第一个假设为Http中的Content-Length的值和实际传输的报文长度不一致导致。比如实际Log到的Content-Length的值为42555byte，但是在传输到42000byte的时候没有新的报文获取到，这个时候Server端在Post Time out到期后抛出异常。

从现象来看，比如客户端在01分调用该接口服务，而实际上异常抛出实际为03分，即在2分钟后可以看到有异常实例抛出并记录。即客户端虽然在01分进行了调用，但是服务端等待输入消息流，一直等待到120秒后仍然没有获取到完整的消息流，则抛出异常。这和日志间隔时间是吻合的。

而实际上我们输入的报文量在600k左右，基于这个报文量获取到所有输入根本就不需要2分钟的时长，那么究竟是什么原因导致一直等待到2分钟超时。初步分析2种可能：

1. 实际上报文已经传递完，但是报文实际长度和Content-Length不一致，导致一直等待并超时。

2. 客户端在报文没有发送完的情况下就断开连接，导致Server端没有获取到完整的报文信息。

对于服务的消费端，经过问题跟踪和排查，得到的信息是：

客户端在01分发起调用后，是在10分钟后才返回了异常信息，即Socket Read Time Out的异常信息，即等待了10分钟没有返回结果而超时。这和客户端当前的10分钟超时设置是吻合的。在10分钟超时后，客户端发起了第二次重试调用，而第二次调用服务消费成功，整体耗时在36秒左右。

即在出现Failed to parse XML text的错误后，客户端发起重试后能够成功调用。

该问题的整体发生概率在千分之一左右，即1000次左右的服务调用会出现一次Failed to parse XML text的错误，同时看到对于该错误基本都在超过500k以上的输入报文的时候出现，即消息报文中的明细行一般都比较大容易出现这种解析异常信息。而对于报文量小的接口服务调用基本都能够正常处理。

从上面的现象和日志记录来分析可以看到

客户端一直等待到10分钟才报出Socket Read Time out的错误，说明连接一直保持着，客户端要发送的报文也是发送完成了的，而是一直没有得到服务端的输出返回，最后超时。但是从实际的OSB运行实例日志来看，从01分开始运行，实际上在03分的时候就已经出现OSB-382030的异常错误，但是这个异常错误并没有在03分的时候直接返回到客户端。

这也使得我们对该问题的排查陷入了进一步的困惑中，即究竟是数据流没有传输完导致的异常，还是数据流实际传输完成了，但是OSB在解析数据流的时候出现的解析异常问题。另外还有一个思考点就是，有无可能是网络原因出现了网络闪断的情况，导致两边各自都无法完成进一步的连接和相关返回，而各自到了超时时间后报出相关的异常错误。