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一些容易引發問題的新特性參數進行調整的要求。當遇到應用
沒有充分優化的狀況下，因爲這個新特性帶來的性能加速惡化，也對相關故障產生了間接的影響。 所以及時更新文檔，保證系統的參數基線合理顯得也很重要。
最後，運維工做紛繁複雜，要靜下心來仔細的看，纔會發現其中的小細節。