iptables的nf_conntrack相关参数引起两个问题

========phanx.com========
Author:   phanx
Updated: 2015-3-23
转载请保留作者信息
=========================

某关键业务系统上频繁出现业务失败，并发生了一次大规模业务中断。
该系统采用两台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对于服务端口应该是一直开放的，不应该拒绝新建的连接啊，除非这个新建的连接有什么特殊的地方。
通过红帽的客户网站，找到了一些相关信息。  
 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

  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.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 -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 "", line 1, in
File "", 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一些容易引起问题的新特性参数进行调整的要求。当遇到应用
没有充分优化的情况下，由于这个新特性带来的性能加速恶化，也对相关故障产生了间接的影响。 因此及时更新文档，保证系统的参数基线合理显得也很重要。
最后，运维工作纷繁复杂，要静下心来仔细的看，才会发现其中的小细节。