運用Log和Trace檔案排除Oracle Net問題

eddy0lion發表於2018-06-26

有時候已經正常安裝和配置了 Oracle Net 相關組建,比如服務端的 TNS Listener,以及客戶端的 tnsnames.ora,在 Oracle Server 駐留的機器上也能正常連線,但是從客戶機器上出現了無法連線 Oracle 資料庫服務的情況。

通常出現這種情況,一般要按照以下兩個步驟來排除故障:首先,需要定位發生問題的位置或者說環節;然後,根據發生問題的位置或環節找出相應的解決辦法。

由於 Oracle Net 是按照 OSI 的七層模型來設計的(它包括了會話層、表示層和應用層三個 OSI 層的功能),而底下其他層的網路功能由網路軟硬體提供,因此,故障發生的環節可大體分為兩種情況:一是 Oracle Net 的配置有問題,二是底層的網路出了問題。

要定位故障,首先得把故障從整體中分離出來,分成不同的環節,單獨進行考慮和測試驗證,逐步找出故障所在。

一般的做法是,分別排除相應情況:

1、物理連線有沒有問題?驗證這個的最簡單辦法就是看是否能夠 ping 通服務主機。

2、如果第 1 步沒有問題,主機和客戶機之間能夠 ping 通,那麼就需要檢測伺服器上的服務是否正常,即從本地是否能夠連線到資料庫(本地連線 oracle 資料庫時,一般不用網路協議,而用程式間通訊協議),在資料庫駐留的主機上,既可以利用 tnsping 工具,也可以直接使用 sqlplus 等客戶端軟體直接連線資料庫服務。

3、如果前兩步均能夠正常完成,那麼就要考慮網路連線是否被防火牆阻塞?在能夠由於 ping 工具和 Oracle 的網路測試工具 tnsping 使用的埠不相同,因此資料庫伺服器上的防火牆可能允許其他機器 ping 本機,但不一定允許 Oracle Listener 的埠(預設為1521)對外提供服務(也就是外部程式試圖連線到1521這個埠的嘗試會被防火牆阻擋),因此,即使能 ping 通,也不一定能 tnsping 通或用 sqlplus 等應用程式連線到資料庫。

對於1出現問題的情況,就需要排除物理網路連線的問題,對於2出現問題的情況,就需要考慮重新驗證和配置相應的 Oracle Net 的相關配置檔案,對於 3 出現的問題,就要考慮防火牆策略和Selinux(如果是 Linux 作業系統)以及其他型別的防護手段的配置問題。

但是,有時候,即使你前面3步都完成了,還是無法從客戶機上連線資料庫伺服器,這時恐怕就得動用 log 檔案和 trace 檔案來檢視出問題的細節了。

筆者本人就遇到過一次 redhat enterprise linux 7下面的類似情況,1、2步不用說,正常透過,問題就是進行到第三步時,防火牆也關閉了,但始終無法連線到伺服器。最後只好透過分析 trace 檔案來定位問題。

要使用 trace 檔案來分析問題,首先要配置 SQL*Net 來啟用 trace 功能,因為該功能預設情況下是停用的。

要啟用 SQL*Net 的 Trace,需要在 $ORACLE_HOME/network/admin/ 下面的 sqlnet.ora 中新增如下程式碼:



[plain] view plain copy
  1. <pre name="code" class="html">TRACE_UNIQUE_CLIENT = ON    
  2. TRACE_LEVEL_CLIENT = 16    
  3. TRACE_DIRECTORY_CLIENT = /home/u01/app/oracle/product/11.2.0/network/trace    
  4. TRACE_FILE_CLIENT = SQLNetTrace    
  5. TRACE_TIMESTAMP_CLIENT = ON    
  6. DIAG_ADR_ENABLED = OFF    
  7. #TRACE_FILELEN_CLIENT = 2048    
  8. #TRACE_FILENO_CLIENT = 2    


注意:


  • TRACE_DIRECTORY_CLIENT的路徑自己隨意,但不要以 / 結尾
  • 以上8個引數,每個引數務必頂格寫,即:不要以空格開頭
  • 以#開頭表示註釋。
各個引數含義:
  • TRACE_UNIQUE_CLIENT 設定是否為每個客戶跟蹤會話建立單獨的 trace 檔案,如果設定為 ON,那麼 trace 檔案將會設定為 SQLNetTracepid.trc(假設預設檔名為 SQLNetTrace.trc)。
  • TRACE_LEVEL_CLIENT 開啟客戶跟蹤的級別,取值為:off 或 0 表示沒有 trace 資訊輸出,user 或 4 表示使用者級跟蹤資訊,admin 或 10 表示管理級跟蹤資訊,support 或 16 表示 Oracle 支援服務級跟蹤資訊。
  • TRACE_DIRECTORY_CLIENT 指定存放客戶端 trace 檔案的目錄,預設為當前工作目錄。需要注意的是,啟動 oracle net 的使用者應該對該目錄有寫許可權。 
  • TRACE_FILE_CLIENT  指定客戶端會話 trace 檔案的名稱。
  • TRACE_TIMESTAMP_CLIENT 指定客戶端 trace 的事件記錄中是否包含時間戳,預設為 on
  • TRACE_ADR_ENABLED 是否開啟 Automatic Diagnosic Repository ,預設為 on,注意:開啟 ADR 的情況下,TRACE_DIRECTORY_CLIENT、TRACE_FILE_CLIENT 、TRACE_UNIQUE_CLIENT、 TRACE_FILELEN_CLIENT 和 TRACE_FILENO_CLIENT 5個引數將不起作用。這時的跟蹤檔案將儲存在 ADR 庫中,該庫的位置由 ADR_BASE 引數設定,ADR_BASE 的預設值為 $ORACLE_BASE ,實際的跟蹤檔案將放在該目錄下的 diag/client/user_USERNAME/HOSTID 下面。
  • TRACE_FILELEN_CLIENT 和 TRACE_FILENO_CLIENT 控制 trace 檔案大小(以KB計)和數量。
然後開始 tracing。透過 SQL*Plus 連線到相應的 tnsname,這時開始跟蹤。
獲得跟蹤檔案後,開啟 trace 檔案,分析內容,擷取部分內容如下:
[plain] view plain copy
  1. [28-1月 -2016 22:07:53:132] --- TRACE CONFIGURATION INFORMATION FOLLOWS ---        <span style="color:#ff0000;">--讀取跟蹤檔案的配置情況  
  2. [28-1月 -2016 22:07:53:132] New trace stream is C:\sqltrace\sqlnettrace_2028.trc  
  3. [28-1月 -2016 22:07:53:132] New trace level is 16  
  4. [28-1月 -2016 22:07:53:132] --- TRACE CONFIGURATION INFORMATION ENDS ---  
  5. [28-1月 -2016 22:07:53:132] --- PARAMETER SOURCE INFORMATION FOLLOWS ---  
  6. [28-1月 -2016 22:07:53:132] Attempted load of system pfile source C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\sqlnet.ora  
  7. [28-1月 -2016 22:07:53:132] Parameter source loaded successfully  
  8. [28-1月 -2016 22:07:53:132]   
  9. [28-1月 -2016 22:07:53:132] Attempted load of local pfile source c:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\sqlnet.ora  
  10. [28-1月 -2016 22:07:53:132] Parameter source was not loaded  
  11. [28-1月 -2016 22:07:53:132]   
  12. [28-1月 -2016 22:07:53:132]  -> PARAMETER TABLE LOAD RESULTS FOLLOW <-<span style="white-space:pre"> <span style="color:#ff0000;">--顯示裝載的引數值  
  13. [28-1月 -2016 22:07:53:132] Successful parameter table load  
[plain] view plain copy
  1. ……  
  2. [28-1月 -2016 22:07:53:132] --- PARAMETER SOURCE INFORMATION ENDS ---<span style="white-space:pre">          
  3. [28-1月 -2016 22:07:53:132] --- LOG CONFIGURATION INFORMATION FOLLOWS ---<span style="white-space:pre">    <span style="color:#ff0000;">--解析 SQL*NET 配置引數值,並按此連線資料庫  
  4.   
  5. ……  
  6. [28-1月 -2016 22:07:53:132] nrigbni: Unable to get data from navigation file tnsnav.ora<span style="white-space:pre">  <span style="color:#ff0000;">--首先嚐試 tnsnav.ora 配置檔案,失敗  
  7. [28-1月 -2016 22:07:53:132] nrigbni: exit  
  8. ……  
  9. [28-1月 -2016 22:07:53:148] nnfgrne: Switching to TNSNAMES adapter<span style="white-space:pre">           <span style="color:#ff0000;">-- 開始嘗試 tnsnames.ora 配置檔案  
  10. ……  
  11. [28-1月 -2016 22:07:53:148] nnftmlf_make_system_addrfile: system names file is C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\tnsnames.ora  
  12. ……<span style="white-space:pre">                                      <span style="color:#ff0000;">--解析 tnsnames.ora 內容  
  13. [28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: --- C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\tnsnames.ora TABLE HAS THE FOLLOWING CONTENTS ---  
  14. [28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: ORA11GR2 = (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = XY7B7F)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora11gr2)))  
  15. [28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: ORA11G_linux = (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 10.211.55.10)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora11g)))  
  16. [28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: ORACLR_CONNECTION_DATA = (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = IPC)(KEY = EXTPROC1521))) (CONNECT_DATA = (SID = CLRExtProc) (PRESENTATION = RO)))  
  17. [28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: --- END C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\tnsnames.ora TABLE ---  
  18. [28-1月 -2016 22:07:53:148] nnfttran: exit  
  19. [28-1月 -2016 22:07:53:148] nnftrne: Using tnsnames.ora address (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 10.211.55.10)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora11g))) for name ora11g_linux  
  20. ……  
  21. [28-1月 -2016 22:07:53:148] niotns: niotns: setting up interrupt handler...  
  22. [28-1月 -2016 22:07:53:148] niotns: Not trying to enable dead connection detection.  
  23. [28-1月 -2016 22:07:53:148] niotns: Calling address: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=10.211.55.10)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora11g)(CID=(PROGRAM=C:\app\xiaoxiao\product\11.2.0\dbhome_2\bin\sqlplus.exe)(HOST=XY7B7F)(USER=xiaoxiao))))<span style="white-space:pre">                               <span style="color:#ff0000;">-- 確定使用從 tnsnames.ora 中 ora11g_linux 解析出來的連線串  
  24. [28-1月 -2016 22:07:53:148] nsgettrans_bystring: entry  
  25. [28-1月 -2016 22:07:53:148] nttbnd2addr: entry  
  26. [28-1月 -2016 22:07:53:148] snlinGetAddrInfo: entry  
  27. [28-1月 -2016 22:07:53:148] snlinGetAddrInfo: exit  
  28. [28-1月 -2016 22:07:53:148] nttbnd2addr: using host IP address: 10.211.55.10  
  29. [28-1月 -2016 22:07:53:148] snlinFreeAddrInfo: entry  
  30. [28-1月 -2016 22:07:53:148] snlinFreeAddrInfo: exit  
  31. [28-1月 -2016 22:07:53:148] nttbnd2addr: exit  
  32. [28-1月 -2016 22:07:53:148] ntgettrans: entry  
  33. [28-1月 -2016 22:07:53:148] ntgettrans: exit  
  34. [28-1月 -2016 22:07:53:148] nsgettrans_bystring: exit  
  35. [28-1月 -2016 22:07:53:148] nscall: entry  
  36. [28-1月 -2016 22:07:53:148] nsmal: entry  
  37. [28-1月 -2016 22:07:53:148] nsmal: 280 bytes at 0x54fe70  
  38. [28-1月 -2016 22:07:53:148] nsmal: normal exit  
  39. [28-1月 -2016 22:07:53:148] nscall: connecting...  
  40. [28-1月 -2016 22:07:53:148] nlad_expand_hst: Adding an ADDRESS_LIST binding<span style="white-space:pre">    
  41. [28-1月 -2016 22:07:53:148] nlad_expand_hst: Expanding 10.211.55.10<span style="white-space:pre">        
  42. [28-1月 -2016 22:07:53:148] snlinGetAddrInfo: entry  
  43. [28-1月 -2016 22:07:53:148] snlinGetAddrInfo: exit  
  44. [28-1月 -2016 22:07:53:148] nlad_expand_hst: Already an IP address<span style="white-space:pre">           <span style="font-family: Arial, Helvetica, sans-serif;"><span style="color:#ff0000;">--解析連線串時發現已經是 IP 地址<span style="white-space:pre">  
  45.   
  46. ……  
  47. [28-1月 -2016 22:07:53:148] nttbnd2addr: using host IP address: 10.211.55.10  
  48. ……  
  49. [28-1月 -2016 22:07:53:148] nsopen: opening transport...<span style="white-space:pre">     <span style="color:#ff0000;">--嘗試開啟傳輸埠  
  50. [28-1月 -2016 22:07:53:148] nttcon: entry  
  51. [28-1月 -2016 22:07:53:148] nttcon: toc = 1  
  52. [28-1月 -2016 22:07:53:148] nttcnp: entry  
  53. [28-1月 -2016 22:07:53:148] nttcnp: creating a socket.<span style="white-space:pre">           <span style="color:#ff0000;">--建立網路套接字  
  54. [28-1月 -2016 22:07:53:148] nttcnp: exit  
  55. [28-1月 -2016 22:07:53:148] nttcni: entry  
  56. [28-1月 -2016 22:07:53:148] nttcni: Tcp conn timeout = 60000 (ms)  
  57. [28-1月 -2016 22:07:53:148] nttcni: TCP Connect TO enabled. Switching to NB  
  58. [28-1月 -2016 22:07:53:148] nttctl: entry  
  59. [28-1月 -2016 22:07:53:148] nttctl: Setting connection into non-blocking mode  
  60. [28-1月 -2016 22:07:53:148] nttcni: trying to connect to socket 484.<span style="white-space:pre">     <span style="color:#ff0000;">--開始嘗試透過套接字連線  
  61. [28-1月 -2016 22:07:53:148] ntt2err: entry  
  62. [28-1月 -2016 22:07:53:148] ntt2err: exit  
  63. [28-1月 -2016 22:07:53:148] ntctst: size of NTTEST list is 1 - not calling poll  
  64. [28-1月 -2016 22:07:53:148] sntseltst: Testing for WRITE on socket 484<span style="white-space:pre">       <span style="color:#ff0000;">--嘗試向套接字寫資料  
  65. [28-1月 -2016 22:08:14:161] sntseltst: FOUND: write request on socket 484  
  66. [28-1月 -2016 22:08:14:176] ntt2err: entry<span style="white-space:pre">                     
  67. [28-1月 -2016 22:08:14:176] ntt2err: soc 484 error - operation=1, ntresnt[0]=505, ntresnt[1]=60, ntresnt[2]=0<span style="white-space:pre">    <span style="color:#ff0000;">--發生錯誤  
  68. [28-1月 -2016 22:08:14:176] ntt2err: exit  
  69. [28-1月 -2016 22:08:14:286] nttcni: exit  
  70. [28-1月 -2016 22:08:14:286] nttcon: exit  
  71. ……  
  72. [28-1月 -2016 22:08:14:286] nladtrm: exit  
  73. [28-1月 -2016 22:08:14:286] nscall: error exit  
  74. [28-1月 -2016 22:08:14:286] nioqper:  error from nscall<span style="white-space:pre">          <span style="color:#ff0000;">--報告錯誤  
  75. [28-1月 -2016 22:08:14:286] nioqper:    ns main err code: 12535  
  76. [28-1月 -2016 22:08:14:286] nioqper:    ns (2)  err code: 12560  
  77. [28-1月 -2016 22:08:14:286] nioqper:    nt main err code: 505  
  78. [28-1月 -2016 22:08:14:286] nioqper:    nt (2)  err code: 60  
  79. [28-1月 -2016 22:08:14:286] nioqper:    nt OS   err code: 0  
  80. [28-1月 -2016 22:08:14:286] niomapnserror: entry  
  81. [28-1月 -2016 22:08:14:286] niqme: entry  
  82. [28-1月 -2016 22:08:14:286] niqme: reporting NS-12535 error as ORA-12535  
  83. [28-1月 -2016 22:08:14:286] niqme: exit  
  84. [28-1月 -2016 22:08:14:286] niomapnserror: exit  
  85. [28-1月 -2016 22:08:14:286] niotns: Couldn't connect, returning 12170  
  86. [28-1月 -2016 22:08:14:286] nioqer: entry  
  87. [28-1月 -2016 22:08:14:286] nioqer:  incoming err = 12170  
  88. [28-1月 -2016 22:08:14:286] nioqce: entry  
  89. [28-1月 -2016 22:08:14:286] nioqce: exit  
  90. [28-1月 -2016 22:08:14:286] nioqer:  returning err = 3113  
  91. [28-1月 -2016 22:08:14:286] nioqer: exit  
  92. [28-1月 -2016 22:08:14:286] niotns: exit  
  93. [28-1月 -2016 22:08:14:286] nsbfrfl: entry  
  94. [28-1月 -2016 22:08:14:286] nsbrfr: entry  
  95. [28-1月 -2016 22:08:14:286] nsbrfr: nsbfs at 0x6088300, data at 0x608b040.  
  96. [28-1月 -2016 22:08:14:286] nsbrfr: normal exit  
  97. [28-1月 -2016 22:08:14:286] nsbfrfl: normal exit  
  98. [28-1月 -2016 22:08:14:286] nigtrm: Count in the NI global area is now 1  
  99. [28-1月 -2016 22:08:14:286] nigtrm: Count in the NL global area is now 1  

可以看出,在試圖向資料庫伺服器的偵聽地址寫資料時發生錯誤。
這就奇怪了,明明已經 ping 通,在資料庫伺服器駐留的機器上也能 tnsping 通,說明網路和 LISTENER 都正常。
這時突然想起,我在嘗試關閉防火牆時,使用的命令是:
[plain] view plain copy
  1. [root@linuxoracle db_1]# service iptables stop  
  2. Redirecting to /bin/systemctl stop  iptables.service  

出現了一個提示,我當時沒有在意,從字面上看,貌似是 redhat 7 將停止網路服務的命令換成了 /bin/systemctl ,並正在重定向到那個命令。
可能是我當時理解錯了,這條提示是告訴我應該使用 systemctl 來關閉防火牆,而不是系統已經幫我自動重定向過去了!!!
因此,防火牆根本沒有關上!!!於是按照提示使用 systemctl 關閉了防火牆。再次嘗試連線,結果連線成功了!!!


如果不想看這麼詳細的 trace 檔案,oracle 還提供了一個 trcasst 實用工具來幫助我們分析跟蹤檔案:
[plain] view plain copy
  1. c:\sqltrace>trcasst  sqlnettrace_2028.trc  
  2.   
  3. Trace Assistant 實用程式: 版本 11.2.0.1.0 Production, 平臺: 2016年1月28日 22:50:49  
  4.   
  5. 版權所有 (c) 2001, 2009, Oracle。保留所有權利。  
  6.   
  7.   
  8.     *************************************************************************  
  9.     *                        Trace Assistant                                *  
  10.     *************************************************************************  
  11.   
  12. ///////////////////////////////////////////////////////////////  
  13. Error found. Error Stack follows:  
  14.               id:0  
  15.   Operation code:65  
  16.       NS Error 1:12535  
  17.       NS Error 2:12560  
  18. NT Generic Error:505  
  19.   Protocol Error:60  
  20.         OS Error:0  
  21.  NS & NT Errors Translation  
  22. 12535, 00000 "TNS: 操作超時"  
  23.  // *原因: 請求的連線無法在 listener.ora 中的 CONNECT_TIMEOUT  
  24. //引數所指定的超時值到來前完成。此  
  25. //錯誤源自 tnslsnr。  
  26. // *操作: 要麼將 CONNECT_TIMEOUT 重新配置為 0, 這表示可以無限期等待;  
  27. //要麼將 CONNECT_TIMEOUT 重新配置為某個更大的值。  
  28. //如果超時值超出可接受的時間範圍, 請啟用跟蹤  
  29. //來獲取詳細資訊。  
  30. /  
  31. 12560, 00000 "TNS: 協議介面卡錯誤"  
  32.  // *原因: 出現一般協議介面卡錯誤。  
  33. // *操作: 請檢查所用的地址是否符合相應的協議說明。在  
  34. //報告此錯誤之前, 請檢視錯誤堆疊, 檢查是否有更低層的  
  35. //傳輸錯誤。啟用跟蹤後重新執行相關操作, 以獲取更多詳細  
  36. //資料。完成相關操作後, 禁用跟蹤。  
  37. /  
  38. 00505, 00000 "操作已超時"  
  39.  // *原因: 請求的操作無法  
  40. //在超時到來前完成。  
  41. // *操作: 啟用跟蹤後重新執行相關操作, 以獲取更多詳細資料。  
  42. /  
  43. ///////////////////////////////////////////////////////////////  
  44.   
  45.   
  46. ----------------------  
  47. 跟蹤檔案統計資料:  
  48. ----------------------  
  49. 會話總數: 0  
  50.   
  51. 資料庫:  
  52.   操作計數: 開啟次數    0,  語法分析次數    0,  執行次數    0,  提取次數    0  
  53.   
  54.   
  55. ORACLE NET SERVICES:  
  56.   總呼叫數: 已傳送         0 個, 已接收         0 個,           0 oci  
  57.   總位元組數: 已傳送         0 位元組,  已接收         0 位元組  
  58.     平均位元組數: 每包傳送  位元組,  每包接收  位元組  
  59.     最大位元組數: 已傳送         0 位元組,  已接收         0 位元組  
  60.   
  61.   總計包數: 已傳送      0 個,  已接收      0 個  
  62.   
  63.   
  64.     *************************************************************************  
  65.     *                    Trace Assistant 已經完成                      *  
  66.     *************************************************************************  


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/28853590/viewspace-2156690/,如需轉載,請註明出處,否則將追究法律責任。

相關文章