iptables的nf_conntrack相关参数引发两个问

某关键业务系统上频繁出现业务失败，并发生了一次大规模业务中断。
该系统采用两台IBM Power 740运行AIX 6.1＋Oracle 11gR2 RAC做为数据库服务器，两台DELL PowerEdge R720做为应用服务器，前端采用F5做为负载均衡设备。
数据库服务器和应用服务器之间有Cisco ASA5585硬件防火墙进行访问控制。
应用服务器上运行自行开发的C程序，经过Oracle Client提供的接口，以长链接的方式访问RAC数据库。
故障时，先检查了数据库服务器的系统负载，发现相对于正常时期，CPU负载偏高，IO负载明显升高，IOPS达到13000左右。
正常时的负载

异常时的负载


检查数据库相关日志，发现有大量的TNS错误：

• 复制内容到剪贴板

  代码:

  Fatal NI connect error 12170.
VERSION INFORMATION:  VERSION INFORMATION:
TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production


  VERSION INFORMATION:
TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production


  VERSION INFORMATION:
TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production


  VERSION INFORMATION:
TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
Mon Feb 23 13:22:16 2015
  Time: 23-Feb-2015 13:22:16




***********************************************************************  Time: 23-Feb-2015 13:22:16


  Time: 23-Feb-2015 13:22:16
  Time: 23-Feb-2015 13:22:16
  Tracing not turned on.
  Tracing not turned on.


Fatal NI connect error 12170.
  Tracing not turned on.
  Tracing not turned on.
  Tns error struct:
  Tns error struct:


  VERSION INFORMATION:
TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
  Tns error struct:
  Tns error struct:
    ns main err code: 12535
    ns main err code: 12535
  Time: 23-Feb-2015 13:22:16
    ns main err code: 12535
    
    ns main err code: 12535
    
  Tracing not turned on.
    
    
  Tns error struct:
TNS-12535: TNS:operation timed out
TNS-12535: TNS:operation timed out
TNS-12535: TNS:operation timed out
    ns secondary err code: 12560
    ns main err code: 12535
TNS-12535: TNS:operation timed out
    ns secondary err code: 12560
    ns secondary err code: 12560
    nt main err code: 505
    
    ns secondary err code: 12560
    nt main err code: 505
    
    nt main err code: 505
    
    nt main err code: 505
TNS-12535: TNS:operation timed out
    TNS-00505: Operation timed out


TNS-00505: Operation timed out
    
    ns secondary err code: 12560
TNS-00505: Operation timed out
    nt secondary err code: 78
    nt secondary err code: 78
    nt main err code: 505
TNS-00505: Operation timed out
    nt secondary err code: 78
    nt OS err code: 0
    nt OS err code: 0
    
    nt secondary err code: 78
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.32.70)(PORT=37975))
TNS-00505: Operation timed out
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.32.70)(PORT=25972))
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.32.70)(PORT=9108))
    nt secondary err code: 78
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.32.70)(PORT=52073))
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=10.1.32.70)(PORT=49148))
Mon Feb 23 13:22:16 2015

再检查应用服务器端，发现应用服务进程大量处于Busy状态，没法处理应用数据。再检查应用服务器到数据库的链接状况，发现数据库上报告timeout的链接，在应用服务器上仍然处于ESTABLISHED状态。

• 复制内容到剪贴板

  代码:

  [sysadmin@appsrv1 ~]$ netstat -an|grep 10.1.197.15
tcp 0 0 10.1.32.70:37975 10.1.197.15:1521 ESTABLISHED
tcp 0 0 10.1.32.70:25972 10.1.197.15:1521 ESTABLISHED
tcp 0 0 10.1.32.70:9108 10.1.197.15:1521 ESTABLISHED
tcp 0 0 10.1.32.70:52073 10.1.197.15:1521 ESTABLISHED
tcp 0 0 10.1.32.70:49148 10.1.197.15:1521 ESTABLISHED
.
.
.
.

这时候，怀疑是否是ASA阻断了数据库和应用之间的链接。检查ASA配置后发现超时时间设置的是8个小时，这个业务在低谷期也不会出现8小时空闲，而且应用程序会在空闲的时候按期探测数据库长链接是否可用。

所以，以为 不太多是常见 的 空闲 超时致使的链接中断。  继续进行 分析，发现数据库里面有较多 的direct path read 等待事件。观察应用SQL的执行计划，发现有大量的全表扫描，而且某些SQL的执行时间较长，
超过了60秒 。 很显然这是常见的11g Direct Path Read的反作用，要么让应用开发组去优化SQL，要么关掉11g的针对串行的直接路径读。这样就会缓解系统IO繁忙的状况。这样SQL的执行时间也会下降，若是在
合理的范围内，就不会引起这个故障了。

可是，仅仅是这个缘由，应该不会引发TNS Time out的状况，性能很差，SQL执行时间过长，只是让这个问题浮现了出来，并非这个故障的根本缘由。
因此还得继续分析是什么致使应用服务器和数据库服务器之间的已创建链接被单向断掉。

应用组把挂死的服务器进程kill掉后，重启了服务进程，业务暂时是恢复了。
这时候，让应用组找到链接中断时执行的相应的SQL和链接端口，再找到网络组的兄弟帮忙，从Riverbed Cascade上提取了RAC一个节点和其中一个APP的对应端口的通讯流，用wireshark打开进行分析。
咱们从ARW和ASH报告中发现引发中断的状况中，SQL执行时间都较长，基本达到了5分钟左右。 而后针对这些执行较长的SQL的链接数据流分析，应用服务器在提交SQL执行请求后等待数据库服务器回复。
数据库服务器在执行完之后返回数据给应用服务器时，应用服务器就一直没法接收到数据了，而后数据库服务器就一直重传，直到超时，而后报错TNS Time out。

从这个TCP流上能够清楚看到，appsrv1在12:20.040144的时候提交了SQL执行请求，紧接着收到了racdb1的ACK报文，说明racdb1成功接收了这个请求，而且开始执行。
在15:55.30881的时候，racdb1执行完这个SQL后开始向appsrv1返回结果，SQL执行了215秒左右。这时候，appsrv1没有任何回应。直到最后超时，racdb1发出重置链接的RST报文。

这个状况，老是感受不对，为何appsrv1莫名其妙的不响应了呢？ appsrv1并无宕机，网络链接也正常的，百思不得其解。 最后想实在没有办法的话，只能到appsrv1上去抓包看看。
因为appsrv1比较繁忙，在没法肯定故障发生的状况下持续抓包的记录数据确定会至关庞大，而且确定会对应用服务器形成较大的压力，而且存储空间也是个问题。
这时候，应用组的人报告说偶尔会有一两个服务进程出现挂死的状况。 因而决定去碰碰运气，设好capture条件，只抓取与racdb1的通讯，与其他关联应用服务器的包所有过滤掉，抓了5分钟，就已经有20个G的数据了。
这么大的数据，个人4G内存i3小破本子开起来都是个问题，因而找了一台强力的测试服务器，传上去看看。   翻着翻着发现了一些TCP重传，看起来像故障的现象了，可是发现appsrv1对于重传却返回了
ICMP  Host Administratively Prohibited，并非彻底没有反应。 因而再找网络组按照时间段提取数据，发现故障时是同样的，在racdb1重传的时候，appsrv1每一个重传都回应了 ICMP  Host Administratively Prohibited。

原来，网络组的哥们从Riverbed Cascade里面提取数据流的时候是设定了只提取TCP相关端口的报文，ICMP报文就被漏掉了，没有提取出来。因而，从新提取故障时候的TCP流和相关数据包。



这个时候就能够看到完整的信息了。确实每一个重传都有回应的。
TCP流是创建起来的，iptables里面也应该也有正常的流状态信息，为何会被appsrv1拒绝呢？
继续对appsrv1进行检查，发现 /etc/sysctl.conf里面配置了这么一句

复制内容到剪贴板

代码:

net.netfilter.nf_conntrack_tcp_timeout_established = 300

就是它让iptables对于已创建的链接，300秒若没有活动，那么则清除掉，默认的时间是432000秒(5天)。
问是谁设置的这个参数，答复是应用组在上线前作性能测试时，按照应用供应商的建议修改的。为啥要改，为啥改为这个值也不清楚 。
好吧，应该就是它了，改回默认的值 432000 应该就能解决了。同时让应用组的优化优化SQL，就能够写故障报告了。
故事就到这里就完了？    固然不是。 在调整了这个值后，一开始还风平浪静。过了一段时间，应用组又来报告说，又出现了不多的
业务超时，并且有愈来愈频繁的趋势，从一天一两次到一条一二十次。真是不省心啊。。

继续了解状况，此次仿佛跟数据库服务器没啥关系了，是这个应用服务器到服务器总线应用之间的链接出现了问题。服务总线应用服务器向该应用服务器发起链接的时候，偶尔会被拒绝。
考虑到应用服务器以前有F5来做为负载均衡，先检查了F5上应用服务状态有没有异常，结果良好，F5上对应用的健康探测没有异常。 好吧，仍是直接看数据流，为啥会拒绝应用链接。
服务总线应用服务器和该应用服务器之间通讯是短链接，有业务调用的时候，由服务总线方发起链接。应用组找到了被拒绝的链接，经过debug日志找到相关端口信息，继续让网络组
提取相关链接数据包。

这里能够看到，在svcbus2向appsrv1发起请求后，一样有应答，可是一分钟后，svcbus2关闭了链接。再过了3分钟appsrv1处理完请求后返回数据给svcbus2的时候就被svcbus2给拒绝掉了，而后一样也是不停重传，最后超时。
应用组说svcbus2上，应用有一个60秒超时的机制，当对端在60秒内没有返回结果就直接关闭这个请求，断掉链接。 
从上面的报文也能够看到，svcbus2发起了FIN报文，可是因为appsrv1没有处理完，因此这个链接关闭是单向的，直到appsrv1处理完成，重传数据超时，链接彻底关闭。
这和svcbus2新建链接到appsrv1被拒绝有啥关系呢？我一时也没有想明白。  appsrv1上的iptables对于服务端口应该是一直开放的，不该该拒绝新建的链接啊，除非这个新建的链接有什么特殊的地方。
经过红帽的客户网站，找到了一些相关信息。  
https://access.redhat.com/solutions/73353   iptables randomly drops new connection requests

• if /proc/net/ipv4/netfilter/ip_conntrack_tcp_loose is set to 1, iptables creates a new connection-tracking entry after receiving any packet, not just packets with the SYN flag set

• the ip_conntrack_tcp_loose setting is useful in firewalls for keeping already established connections unaffected if the firewall restarts, but this causes issues in the following scenario:

  • a client initiates a new connection with the same source port it used in a previous connection

  • the server already has an iptables connection-tracking entry for the same IP address and port, with states ESTABLISHED and UNREPLIED

  • the default rule gets hit, instead of the desired one

  • the packet is dropped, and the server returns icmp-host-prohibited

https://access.redhat.com/solutions/73273   Why iptables sporadically drops initial connections requests?
This behavior is caused by enabling ip_conntrack_tcp_loose sysctl parameter which enables iptables to create a conntrack entry whenever it sees any packet from any direction and not just SYN packet. 
This is called connection picking and is usually used by the firewalls to ensure that the ongoing end to end sessions remain active if for some reason the firewall gets restarted. But this feature is not needed in standalone servers.



这里面提到了iptables在规则为allow的状况下也会对某些数据包drop的状况。大意就是在默认状况下(/proc/net/ipv4/netfilter/ip_conntrack_tcp_loose 为1时)，iptables会对即时是不完整的TCP链接也会记录其状态，这样避免
iptables重启的时候影响已有的链接，可是会影响一些特殊状况。

咱们的应用正好就出现了这种特殊状况。当svcbus2由于等待appsrv1应答超时的时候，关闭了链接。而appsrv1上的nf_conntrack表中，当收到svcbus2发送的FIN包是，对于这个链接的记录会变成CLOSE_WAIT状态，而后在60秒后，
条目被清除。 可是，当appsrv1开始回应数据的时候，nf_conntrack表中又出现了这个链接的条目，而且状态是ESTABLISHED [UNREPLIED]。

• 复制内容到剪贴板

  代码:

  [root@appsrv1 ~]# grep 51522 /proc/net/nf_conntrack
    ipv4     2 tcp      6 35 CLOSE_WAIT src=10.1.32.70 dst=10.1.41.192 sport=9102 dport=51522 src=10.1.41.192 dst=10.1.32.70 sport=51522 dport=9102 [ASSURED] mark=0 secmark=0 use=2
.
.
wait more seconds
.
.
[root@appsrv1 ~]# grep 51522 /proc/net/nf_conntrack
ipv4 2 tcp 6 431965 ESTABLISHED src=10.1.32.70 dst=10.1.41.192 sport=9102 dport=51522 [UNREPLIED] src=10.1.41.192 dst=10.1.32.70 sport=51522 dport=9102 mark=0 secmark=0 use=2

这个条目，因为默认的 net.netfilter.nf_conntrack_tcp_timeout_established =
432000 的影响，会一直保持5天，直到红色那个值变为0才会被清除。 这就致使了当svcbus2再以相同的源端口51522向appsrv1发起链接的时候，appsrv1的iptables
会拒绝掉这个请求。
那是否是设置net.ipv4.netfilter.ip_conntrack_tcp_loose=0就好了呢，引发的反作用又怎么消除呢？
反复想了想，仍是不想就这样了，决定看看有没有其它更优的方法。

到测试环境模拟这个故障，服务端口就用TCP 8888，客户机源端口就用TCP 22222

• 复制内容到剪贴板

  代码:

  1.配置服务器的iptables 容许tcp 8888端口.
2.用python来创建一个监听服务，监听在tcp 8888.
[root@server ~]# python
Python 2.6.6 (r266:84292, Sep 4 2013, 07:46:00)
[GCC 4.4.7 20120313 (Red Hat 4.4.7-3)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import socket
>>> serversocket = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
>>> serversocket.bind(("0.0.0.0",8888))
>>> serversocket.listen(5)
>>> (clientsocket, address) = serversocket.accept()


3. 从客户端以tcp 22222为源端口发起链接，并发送请求数据
[root@client ~]# python
Python 2.6.6 (r266:84292, Sep 4 2013, 07:46:00)
[GCC 4.4.7 20120313 (Red Hat 4.4.7-3)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import socket
>>> s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
>>> s.bind(("0.0.0.0",22222))
>>> s.connect(("1.1.1.101",8888))
>>> s.send("request",100)

在server端检查iptable contrack 的状态
[root@server ~]# grep 103 /proc/net/nf_conntrack
ipv4 2 tcp 6 431949 ESTABLISHED src=1.1.1.103 dst=1.1.1.101 sport=22222 dport=8888 src=1.1.1.101 dst=1.1.1.103 sport=8888 dport=22222 [ASSURED] mark=0 secmark=0 use=2
Wait some seconds, then close the connection on client.
>>> s.close()
>>> exit()

继续检查server端的iptable contrack 状态
[root@server ~]# grep 103 /proc/net/nf_conntrack
ipv4 2 tcp 6 54 CLOSE_WAIT src=1.1.1.103 dst=1.1.1.101 sport=22222 dport=8888 src=1.1.1.101 dst=1.1.1.103 sport=8888 dport=22222 [ASSURED] mark=0 secmark=0 use=2
[root@server ~]# sleep 55
[root@server ~]# grep 103 /proc/net/nf_conntrack
server端的条目消失了.


4. 当server端向client发送响应数据的时候
>>> clientsocket.recv(1000)
'request'
>>> clientsocket.send("respond",100)

再到server端查看iptable contrack 状态就会发现有 ESTABLISHED[UNREPLIED] 条目.
可是看TCP 链接的状态倒是 CLOSE_WAIT.

[root@server ~]# grep 103 /proc/net/nf_conntrack
ipv4 2 tcp 6 431996 ESTABLISHED src=1.1.1.10
1 dst=1.1.1.103 sport=8888 dport=22222 [UNREPLIED] src=1.1.1.103 dst=1.1.1.101 sport=22222 dport=8888 mark=0 secmark=0 use=2
[root@server ~]# netstat -ntp|grep 103
tcp 1 7 1.1.1.101:8888 1.1.1.103:22222 CLOSE_WAIT 28978/python

这个时候，从wireshark上抓包也发现了client拒绝server的响应数据并发送ICMP[host administratively prohibited].
当server端TCP链接CLOSE_WAIT超时后, 受到net.netfilter.nf_conntrack_tcp_timeout_established参数的控制，nf_contrack表中ESTABLISHED[UNREPLIED] 条目是依然存在的。

[root@server ~]# netstat -ntp|grep 103
[root@server ~]# grep 103 /proc/net/nf_conntrack
ipv4 2 tcp 6 431066 ESTABLISHED src=1.1.1.101 dst=1.1.1.103 sport=8888 dport=22222 [UNREPLIED] src=1.1.1.103 dst=1.1.1.101 sport=22222 dport=8888 mark=0 secmark=0 use=2

监听端口状态是正常的
[root@server ~]# netstat -nplt|grep 8888
tcp 0 0 0.0.0.0:8888 0.0.0.0:* LISTEN 28978/python


5. 这个时候，当client再以tcp 22222为源端口向tcp 8888发起链接，server端的iptables就拒绝了这个SYN报文. client端链接报错。
[root@client ~]# python
Python 2.6.6 (r266:84292, Sep 4 2013, 07:46:00)
[GCC 4.4.7 20120313 (Red Hat 4.4.7-3)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import socket
>>> s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
>>> s.bind(("0.0.0.0",22222))
>>> s.connect(("1.1.1.101",8888))
Traceback (most recent call last):
File "<stdin>", line 1, in <module>
File "<string>", line 1, in connect
socket.error: [Errno 113] No route to host
>>>

通过这个模拟，也验证了故障的成因，那么要解决问题，就简单了。

有两边能够想办法，一是appsrv1这边，若是让该条目早点过时，那么只要端口重用不是特别快的状况下，这个问题就不会发生。
在不改造应用的状况下，这是一个较好的临时解决方案，可是过时时间设多久，要先要知足前一个问题的SQL最长执行时间，而后观察端口重用的时间有没有短于SQL最长执行时间。

appsrv1这边存在条目的缘由是返回数据被拒绝后的TCP重传数据包被iptables nf_conntrack记录，svcbus2又没有响应的TCP回应报文。
那么另一个方法就是若是能让svcbus2正常响应就解决了。   怎么能正常解决呢？

iptables nf_contrack 还有另一个参数 net.netfilter.nf_conntrack_tcp_timeout_close_wait。 默认是60秒跟TCP的CLOSE_WAIT 超时时间是一致的。经过试验模拟这个故障发现，若是把这个时间设长，超过TCP  CLOSE_WAIT 超时时间 ，
那么在TCP链接关闭后，appsrv1的返回报文还能够到达svcbus2的内核， svcbus2会直接发送TCP RST包将这个链接重置。这样appsrv1上的TCP链接和nf_contrack中的条目都会清除掉。

看模拟的过程。




当 appsrv-test 在svcbus-test发送FIN链接后过了127秒开始发送响应数据，这时候svcbus-test就马上回应了RST报文，后来svcbus-test半个小时候在从新再用tcp 22222端口向appsrv-test tcp 8888发起链接的时候，问题问题，链接能够正常创建了。
固然这种处理方法应用层会收到错误，要对这个错误进行处理才行。

因为第二种方法还涉及应用代码的调整和测试，所以经过观察发现SQL最长执行时间在15分钟左右，服务总线源端口重用时间大概在4个小时，可是因为重用源端口的时候，目标端口还不必定是appsrv上的对应端口，所以4小时不必定造成冲突。
综合考虑了一下，设置
net.netfilter.nf_conntrack_tcp_timeout_establishe=7200 是一个比较合适的解决方法。调整后，通过近期的观察，没有出现业务失败了。


经验：
系统参数调整要当心，特别是对应用行为不清楚的状况下，要多测试。该业务系统就是没有通过严格的测试，为了赶目标节点匆匆上线继而发生后续故障。
另外，在系统软件部署的时候，管理员使用的文档中没有及时更新，缺少了对Oracle 11g一些容易引发问题的新特性参数进行调整的要求。当遇到应用
没有充分优化的状况下，因为这个新特性带来的性能加速恶化，也对相关故障产生了间接的影响。 所以及时更新文档，保证系统的参数基线合理显得也很重要。
最后，运维工做纷繁复杂，要静下心来仔细的看，才会发现其中的小细节。