[转]F5负载均衡环境下某应用故障分析案例

作者：易隐者发布于：2012-7-18 13:45 Wednesday 分类：案例讨论

本文来自互联网，非我原创，原文章名为《高级TCP/IP网络排错》，该案例出自其第三节：用OmniPeek解决网络中的难题。

如该案例作者看到我的转载请跟我联系，可以做个朋友，切磋一下技术问题，如果哪位网友知道该案例的原作者，也烦请留言告知。

【我的点评】：

1，充分运用了中间设备自带的抓包功能（对中间设备自带抓包功能感兴趣的兄弟，请参阅我的文章《常见系统和网关设备自带抓包功能介绍及操作指南》），提高了分析效率；

2，整个过程使用对比分析法（参见我的文章《疑难网络故障的分析方法和原理之对比分析法》），发现进出F5报文的差异，快速界定异常问题产生的原因是F5、客户端还是服务器；

3，在做数据包分析之前，确定了业务报文交互路径，明确可能的故障点，为下一步的排查提供了基础，但是从作者给的拓扑结构上看，出来F5之外，这个数据路径应该还会经过那台旁接的防火墙；

4，“F5日志中报端口无法到达”，此问题不太像是指物理端口不可达，个人感觉是指UDP端口不可达的可能性更大一些；

【原文全文】：

1 问题提出
某系统割接上线后，由于f5设备始终未处于正常工作状态导致系统故障频繁，严重影响业务的正常运营。由于此系统历经旧系统扩容改造后系统环境较复杂，给故障问题的诊断带来了不便。
故障的表现为：正常运行的系统突然出现业务中断，与主数据库的连接无法打开，持续时间在30秒到2分钟之间，然后系统又突然恢复正常。此故障有时半个月没出现一次，有时一天出现5、6次，故障的间隔时间没有规律。

2 F5现网部署情况
新系统上线后，新增负载均衡设备F5（单点），如下图所示：

其中在F5看来黑线部份的VLAN10和红色部份的VLAN114在系统的主交换机中属于同一个广播域（同一VLAN）。
在F5上设置的健康检测机制：每隔5秒钟，F5定期Get F5后面的每一台应用服务器的一个特殊网页，这个特殊动作会引起应用服务器通过F5去数据库服务器中取一个特殊的字符串，如果能取到这个字符串，F5就认为系统是正常的，如果取不到，F5就认为系统或数据库服务器不正常，断开对某一台应用服务的请求，把请求转发到同一个Pool中的另一台服务器中，如果都Get不到，则F5断开所有对应用服务器的请求。

       7月26日F5随着新系统上线后开始在现网运行，系统稳定工作了13天后中，就不断发现系统出现短暂的突然中断，现象是F5应用层检测发现不能检测到数据库的连接，约一分钟后又恢复正常。
       由于F5是一个单点设备，因此重点关注F5的问题，经过不断地优化系统，发现F5的系统日志中报端口无法到达，怀疑是某个与交换机端口的连接有问题，采用双千兆做成Etherchannel后运行几天后还是报交换机端口错误。由于外部线路已经采用双端口channel，F5与交换机端口出错的可能性极小，怀疑这个提示可能表示内部的端口不可达，也就是说它的硬件出了问题，更换一台硬件后，不再报“端口不可达”错误。
       更换新硬件后只稳定运行几天，F5的应用层检测程序就开始频繁报告应用层监控出错，经常是F5后面的４台两种不同类型的应用服务器同时报监控错误，由于认为在概率上不可能存在４台两种不同类型的服务器同时出错，而且也不可能两台HP的小型机同时出错。所以重点把目光集中在F5上，反复对F5设备进行了优化，但一直没有实际的效果，
3 问题分析和解决
       在这种情况下我们决定从捕获应用服务器－－F5－－主数据库之间的报文，从底层的抓包上着手分析故障的原因，抓包点分布如下图所示：

捕获报文如下：

从故障的症状上看，是数据库服务器向应用服务器10.10.1.23发出TCP reset报文，断开了TCP连接。因为应用服务器是经F5做NAT转换成192.168.114.185与数据库连接的，再查看F5（114.185）与数据库的连接报文统计如下：
Packet Source Destination Size Date Absolute Time Cumulative Bytes Protocol Decode: TCP Flags
110 192.168.114.185 192.168.114.20 64 2008-10-23 43:57.2 64 TNS %00010000 ...A....
2175 192.168.114.185 192.168.114.20 64 2008-10-23 43:59.0 128 TNS %00010000 ...A....
3765 192.168.114.185 192.168.114.20 64 2008-10-23 44:00.6 192 TNS %00010000 ...A....
4563 192.168.114.185 192.168.114.20 64 2008-10-23 44:01.4 256 TNS %00010000 ...A....
4643 192.168.114.185 192.168.114.20 64 2008-10-23 44:01.6 320 TNS %00010000 ...A....
6872 192.168.114.185 192.168.114.20 64 2008-10-23 44:02.4 384 TNS %00010000 ...A....
16805 192.168.114.185 192.168.114.20 64 2008-10-23 44:19.0 2880 TNS %00010000 ...A....
16908 192.168.114.185 192.168.114.20 64 2008-10-23 44:20.0 2944 TNS %00010000 ...A....
18369 192.168.114.185 192.168.114.20 64 2008-10-23 44:21.5 3008 TNS %00010000 ...A....
18680 192.168.114.185 192.168.114.20 64 2008-10-23 44:21.9 3072 TNS %00010000 ...A....
18700 192.168.114.185 192.168.114.20 64 2008-10-23 44:22.2 3136 TNS %00010000 ...A....
18750 192.168.114.185 192.168.114.20 64 2008-10-23 44:22.4 3200 TNS %00010000 ...A....
19027 192.168.114.185 192.168.114.20 64 2008-10-23 44:23.9 3264 TNS %00010000 ...A....
19029 192.168.114.185 192.168.114.20 64 2008-10-23 44:23.9 3328 TNS %00010000 ...A....
19513 192.168.114.185 192.168.114.20 64 2008-10-23 44:25.2 3392 TNS %00010000 ...A....
20601 192.168.114.185 192.168.114.20 64 2008-10-23 44:28.9 3456 TNS %00010000 ...A....
20603 192.168.114.185 192.168.114.20 64 2008-10-23 44:29.0 3520 TNS %00010000 ...A....
20693 192.168.114.185 192.168.114.20 64 2008-10-23 44:29.2 3584 TNS %00010100 ...A.R..
20694 192.168.114.20 192.168.114.185 64 2008-10-23 44:29.2 3648 TNS %00000100 .....R..
20695 192.168.114.20 192.168.114.185 64 2008-10-23 44:29.2 3712 TNS %00000100 .....R..
20892 192.168.114.185 192.168.114.20 64 2008-10-23 44:30.6 3776 TNS %00010100 ...A.R..
20893 192.168.114.20 192.168.114.185 64 2008-10-23 44:30.6 3840 TNS %00000100 .....R..
20894 192.168.114.20 192.168.114.185 64 2008-10-23 44:30.6 3904 TNS %00000100 .....R..
20911 192.168.114.185 192.168.114.20 64 2008-10-23 44:30.7 3968 TNS %00010100 ...A.R..
20912 192.168.114.20 192.168.114.185 64 2008-10-23 44:30.7 4032 TNS %00000100 .....R..
20913 192.168.114.20 192.168.114.185 64 2008-10-23 44:30.7 4096 TNS %00000100 .....R..
20938 192.168.114.185 192.168.114.20 64 2008-10-23 44:31.0 4160 TNS %00010100 ...A.R..
20941 192.168.114.20 192.168.114.185 64 2008-10-23 44:31.0 4224 TNS %00000100 .....R..
20942 192.168.114.20 192.168.114.185 64 2008-10-23 44:31.0 4288 TNS %00000100 .....R..
21006 192.168.114.185 192.168.114.20 64 2008-10-23 44:32.0 4352 TNS %00010100 ...A.R..
21009 192.168.114.20 192.168.114.185 64 2008-10-23 44:32.0 4416 TNS %00000100 .....R..
21010 192.168.114.20 192.168.114.185 64 2008-10-23 44:32.0 4480 TNS %00000100 .....R..
21017 192.168.114.185 192.168.114.20 64 2008-10-23 44:32.0 4544 TNS %00010100 ...A.R..
21020 192.168.114.20 192.168.114.185 64 2008-10-23 44:32.0 4608 TNS %00000100 .....R..
21021 192.168.114.20 192.168.114.185 64 2008-10-23 44:32.0 4672 TNS %00000100 .....R..
21030 192.168.114.185 192.168.114.20 64 2008-10-23 44:32.1 4736 TNS %00010100 ...A.R..
21031 192.168.114.20 192.168.114.185 64 2008-10-23 44:32.1 4800 TNS %00000100 .....R..
21032 192.168.114.20 192.168.114.185 64 2008-10-23 44:32.1 4864 TNS %00000100 .....R..
21070 192.168.114.185 192.168.114.20 64 2008-10-23 44:32.7 4928 TNS %00010100 ...A.R..
其中TCP Flags字段中...A.R..发出了ACK/Reset，说明185发出了如下的信息：
1、收到了114.20的信息，所以应答为ACK
2、 185认为有问题，所以发出了Reset信息，断开了与数据库的连接。
解码的报文如下：

从上面的解码看出，192.168.114.185向192.168.114.20发出了一个TCP ACK/Reset的报文，而此时的客户端并没有发出这种报文，所以故障看起来像是发出TCP reset报文的根源在于F5。再查询一下192.168.114.185之前的几个报文：
10.10.1.22向192.168.114.20发出了数据库的操作请求，ACK/Push置1,注意到此报文的Seq/ACK：2985731990/1217522607

下一个包如下：

对此序列号Seq/ACK：2985731990/1217522607一致，只是源地址不一致，说明这个报文是F5收到后做了一个地址转换，并发送到数据库服务器，再查看下一个报文：

F5接着就发了一个ACK/Reset报文送到数据库服务器，数据库服务器响应Reset报文到114.185，

然后F5转换后送到10.10.1.22

结论：F5自作主张向数据库发出ACK/Reset报文，是导致大量TCP连接被断开的原因，
进一步检查为什么F5会向数据库发出大量的ACK/Reset报文:
分析捕获的报文，观察114.20响应座席中间件经F5转发的请求从7：44：29.185586开始，每次回应两个相同的报文，如下图蓝影所示：

然后F5认为响应不正常，发出ACK/Reset报文断开连接，每次F5发出ACK/Reset报文都是收到114.20发出的两个相同的报文，这个过程持继到TCP连接持被断开，进一步观察发现故障期间F5发出一个Ping，114.20响应了四个完全相同的 Ping Reply。

再察看114.20响应查询台经F5转发的请求

现象一样，在7:44:29.135909秒开始114.20响应114.165时发出了两个完全一样的报文，导致F5发出ACK/Reset断开连接，165到114.20发出的Ping也一样得到了四个相同的回应

观察114.21对座席中间件服务器的响应

从7：44：29.113430秒开始，114.21响应查询台请求的报文为两个完全一样的报文，导致F5发ACK/Reset，断开连接。响应Ping的请求也同时为4个，如下图：

对际114.21对座席中间件的请求响应如下：

       从7:44:29,424117秒开始，数据库服务器114.21对于应用的查询都响应相同的报文（duplicate packet），F5认为受到了网络攻击，因此F5发出ACK/Reset报文，关闭TCP连接，造成应用的中断并且故障期间数据库服务器一直响应相同的重复的报（duplicate packet）文，所以新的TCP连接始终建立不起来，直到数据库服务器不响应duplicate packet后，系统才恢复正常。
       经与HP公司联系，把相关捕获的报文发给HP的技术支持，HP承认他们的操作系统以前在特殊的情况下出现过类似的现象（duplicate packet），随后HP给出解决问题的相关补丁。在进行操作系统补丁修复后，不再出现相同的问题，难题似乎已经解决。
       系统稳定运行了几天之后，又出现了相似的问题，从抓包的分析的结果来看，已经没有出现HP数据库服务器（duplicate packet）响应，但对捕获的TCP报文中分析中，发现用前面做过的TCP过滤ACK/RST模板过滤后，依然发现大量的ACK/RST报文，但这次引起F5断开连接的原因不是数据库服务器的duplicate packet响应了，
从捕获的报文中看到，这一次F5没有任何理由就直接向应用服务器和数据库两连发送ACK/RST，断开了两边的TCP连接，由于没有找到任何证据证明在F5发出ACK/RST的报文之前，数据库和应用服务器有发出任何异常的报文，这一次，我们认为断开连接的原因是F5自身的问题造成的，F5厂家对此现象也迷惑不解，想在实验室模拟也无法重现故障现象，经与F5厂商多次的交涉，由于我们提出相关有力的抓包证据，证明确实是F5设备在没有任何先兆的情况下，主动断开应用服务器和数据库服务器之间的TCP连接，F5厂家反反复复地分析了捕获的报文，最后终于发现在代理商给出的解决方案中存在问题，如下图中所示：

按照标准的F5应用解决方案，Vlan10和Vlan114应该是设成不同的广播域的，保证Vlan114与Vlan10的广播相互隔离，但在此次改造中，F5的代理商在项目实施时为了图省事，就把F5设备的Vlan10与原系统的VLan114放在一个广播域中，由于实施后观察一段时间（大约二周）没有发现问题，而且据他的经验在以前类似的项目中也用过相同的解决方案，一直是正常的。所以一点都没有怀疑是设置的问题。
经过在与F5相连的交换机上设置，把Vlan10和Vlan114设置成不同的广播域后，不再出现F5自主断开TCP连接的事。

总结：对TCP协议的深刻理解有利于我们找到问题的根本原因，利用OmniPeek的高级过滤功能，能够快速地在大量的报文中找到出现问题的报文，同时也有利于用户与厂商沟通确认问题的根本原因。

标签: 负载均衡 F5 omnipeek RST 应用故障端口不可达