技术问题分析-报文截断(11.20)
(2018-11-20 19:37:43)
标签:
osb |
分类: IT咨询 |
今天继续分析下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
2. Increase the Post Timeout from 30 seconds to 120seconds
2. Increase the Post Timeout from 30 seconds to 120seconds
但是即使做了以上两处设置,仍然会偶尔出现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在解析数据流的时候出现的解析异常问题。另外还有一个思考点就是,有无可能是网络原因出现了网络闪断的情况,导致两边各自都无法完成进一步的连接和相关返回,而各自到了超时时间后报出相关的异常错误。
前一篇:产品型售前(11.19)