메뉴 건너뛰기

검색창 닫기

Korea Oracle User Group

Admin

ORA-3136 inbound connection time out & JDBC Io exception: Connection reset

Talros 2023.02.24 14:11 조회 수 : 677 추천:1


 개발자로 부터 디비로 접속 하는 과정에서 간헐적으로 에러가 발생을 한다는 문의를 받게 되어 로그를 확인 해보니 비슷한 시간대에 ORA-3136 이 발생 하는 것을 확인 했습니다.

 

[2023-02-09 16:31:06.127] [ERROR] [main] [CommandLineJobRunner][355] Job Terminated in error: Error creating bean with name 'jobOperator' defined in class path resource [batch-context.xml]: Cannot resolve reference to bean 'jobLauncher' while setting bean property 'jobLauncher'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'jobLauncher' defined in class path resource [batch-context.xml]: Cannot resolve reference to bean 'jobRepository' while setting bean property 'jobRepository'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'jobRepository' defined in class path resource [batch-context.xml]: Invocation of init method failed; nested exception is org.springframework.jdbc.support.MetaDataAccessException: Could not get Connection for extracting meta data; nested exception is org.springframework.jdbc.UserSyncFromCandyMenualJob: Could not get JDBC Connection; nested exception is org.apache.commons.dbcp.Job Terminated in error: Err: Cannot create PoolableConnectionFactory (Io exception: Connection reset)

 

 해당 에러가 alert log 에 발생을 하는 이유는 

 오라클 넷 파라미터인 SQLNET.INBOUND_CONNECT_TIMEOUT 과 INBOUND_CONNECT_TIMEOUT_listener_name (디폴트 60초) 에 의해
 클라이언트가 자격 증명을 제공하지 못하거나 어떠한 이유든지 60초 이내에 인증 프로세스를 마치지 못하는 경우 이러한 오류가 발생됩니다.

 

 : 예 ) alert log 에서 발생한 로그

 

Thu Feb 23 15:57:49 2023   << 메시지가 발생 한 시점
 
 
***********************************************************************
 
Fatal NI connect error 12170.
 
  VERSION INFORMATION:
        TNS for Linux: Version 12.1.0.2.0 - Production
        Oracle Bequeath NT Protocol Adapter for Linux: Version 12.1.0.2.0 - Production
        TCP/IP NT Protocol Adapter for Linux: Version 12.1.0.2.0 - Production
  Time: 23-2월 -2023 15:57:49
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12535
    
TNS-12535: TNS:작동이 중단중입니다
    ns secondary err code: 12606
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.0.10)(PORT=47704))   << 포트 번호를 확인 합니다.
Thu Feb 23 15:57:49 2023
WARNING: inbound connection timed out (ORA-3136)

 

: 예 ) listener.log

 

23-2월 -2023 15:56:49 * (CONNECT_DATA=(SID=testdb)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTO
COL=tcp)(HOST=192.168.0.10)(PORT=47704)) * establish * testdb * 0. << alert log 에서 확인 한 포트와 같은 접속 로그를 보면 
60초 전에 접속을 한 것을 확인 할 수 있다.

 

오라클에서 가이드 하는 점검 방법 입니다.

1. 데이터베이스 서버에 로컬 연결 성공 및 속도를 확인한다.
2. 로컬 연결이 빠른 경우, 네트워크 관리자의 도움하에 네트워크 지연을 확인한다.
3. 데이터베이스 성능 저하 여부를 확인한다.
4. 경고 로그에 중요한 오류를 확인하고 먼저 해결한다. 예, ORA-600 또는 ORA-7445.
    이런 중요한 오류는 데이터베이스 서버의 속도 저하를 일으킬 수 있다.

 

클라이언트 서버 역시 OS,서버,네트워크 부하를 확인 했지만 이상이 없었습니다.

 

클라이언트가 60초 이내에 접속을 못 하는 다른 사례를 확인 하기 위해 조사 하는 중 jdbc 관련 된 내용을 하나 발견 했습니다.

 

JDBC - Version 11.2.0.1.0 and later
Information in this document applies to any platform.
JDBC connection establishment with 11.2.x databases uses a new connection mechanism (o5logon) that requires the use of random numbers. These numbers are typically generated by a special device (/dev/random). However, this random number generator relies on entropy in order to generate sufficiently random numbers. This entropy comes from things like mouse pointer movement and keyboard entry. When there is insufficient entropy, the random number generator will not return any numbers. When this happens, the o5logon used by the JDBC library stalls, and has to wait until sufficient entropy is available. To address this issue, /dev/urandom is used instead. This device does not block, so JDBC connection establishment is not delayed.

 

JDBC 11.2.0.1 버전 이후 접속 메카니즘 변경으로 난수가 필요 하게 되었습니다.  JDBC 에서 사용 하는 난수는 /dev/random 에서 생산 후 저장 하는 entropy pool 에서 꺼내 쓰게

되는데 기본 적으로 해당 풀을 소모하다 일정 수치 이하로 내려 가게 되면 난수가 생성 될 때 까지 대기를 하게 되어 접속이 지연 될 수 있고 이를 해결 하기 위해 난수 생성 대기를 하지

않는  /dev/urandom  를 이용 하라는 내용 입니다.

 

실제 위의 사례에 의한 것인지 테스트 해보기로 하였습니다.

 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
# 테스트에 사용한 스크립트 
 
import java.sql.*;
public class DBConnTest {
 
public static void main(String[] args) {
 
  Connection conn=null;
 
  try {
 
        Class.forName("oracle.jdbc.driver.OracleDriver");
        System.out.println("JDBC Driver Loading Success");
        long start = System.currentTimeMillis();
        conn=DriverManager.getConnection("jdbc:oracle:thin:@192.168.0.10:1521:testdb", "system", "oracle");
        System.out.println(args[0] + " Connected..");
        long stop = System.currentTimeMillis();
        System.out.println(args[0] + " connected Time" + (stop - start) + " ms.");
 
        conn.close();
 
  } catch (ClassNotFoundException cnfe) {
        System.out.println(args[0] + " Not Found Class.."+cnfe.getMessage());
  } catch(SQLException se){
        System.out.println(args[0] + " " + se.getMessage());
  } finally {
        if(conn != null)   try {conn.close();} catch (SQLException e) { e.printStackTrace();}
   }
 }
}

 

엔트로피 확인을 위한 스크립트

 

1
2
3
4
5
while [ 1 ];do
date
cat /proc/sys/kernel/random/entropy_avail
sleep 1
done

 

java 를 실행

 



testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 1 &
[1] 28535
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 2 &
[2] 28536
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 3 &
[3] 28537
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 4 &
[4] 28538
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 5 &
[5] 28539
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 6 &
[6] 28540
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 7 &
[7] 28541
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 8 &
[8] 28542
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Doracle.jdbc.Trace=true -Djava.util.logging.config.file=/home/oracle/DBA/script/SHELL/java/Logging.properties DBConnTest 9 &  << 9번 째 프로세스에는 Trace 를 남김
[9] 28551
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java DBConnTest 10 &
[10] 28673
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> JDBC Driver Loading Success
  BC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
7 Connected..
7 connected Time3252 ms.
6 Connected..
6 connected Time37429 ms.
4 Connected..
4 connected Time41950 ms.
10 Connected..
10 connected Time43501 ms.
1 Connected..
1 connected Time52981 ms.
2 IO Error: Connection reset    << 프로그램 접속이 안되고 에러가 발생
9 IO Error: Connection reset    << 9 번째 역시 접속이 안되고 에러가 발생 
8 IO Error: Connection reset
3 IO Error: Connection reset
5 IO Error: Connection reset

 

 

JDBC trace 내용 에서 포트를 확인

 


Feb 24, 2023 1:26:58 PM oracle.net.ns.NSProtocol establishConnection
TRACE_20: 39BA5A14 Debug: Session Attributes:
sdu=8192, tdu=2097152
nt: host=192.168.0.10, port=1521
    socket_timeout=60000, socketOptions={20=false, 18=false, 17=0, 2=60000, 24=50, 23=40, 1=NO, 0=YES}
    socket=Socket[addr=/192.168.0.10,port=1521,localport=50303]

ntInputStream : java.net.SocketInputStream@38082d64
 

 

alert log 에서 같은 포트의 메세지 확인

 


Fatal NI connect error 12170.

  VERSION INFORMATION:
        TNS for Linux: Version 12.1.0.2.0 - Production
        Oracle Bequeath NT Protocol Adapter for Linux: Version 12.1.0.2.0 - Production
        TCP/IP NT Protocol Adapter for Linux: Version 12.1.0.2.0 - Production
  Time: 24-2월 -2023 13:27:58
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12535
    
TNS-12535: TNS:작동이 중단중입니다
    ns secondary err code: 12606
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.0.10)(PORT=50303))
Fri Feb 24 13:27:58 2023
WARNING: inbound connection timed out (ORA-3136)

 

listener log 에서 1분 전 접속 후 에러 확인

 

24-2월 -2023 13:26:58 * (CONNECT_DATA=(SID=testdb)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTO
COL=tcp)(HOST=192.168.0.10)(PORT=50303)) * establish * testdb * 0

 

 

엔트로피 확인 내용

 


Fri Feb 24 13:27:53 KST 2023
55
Fri Feb 24 13:27:54 KST 2023
21
Fri Feb 24 13:27:55 KST 2023
42
Fri Feb 24 13:27:56 KST 2023
50
Fri Feb 24 13:27:57 KST 2023
21
Fri Feb 24 13:27:58 KST 2023
3
Fri Feb 24 13:27:59 KST 2023
3
Fri Feb 24 13:28:00 KST 2023
35
Fri Feb 24 13:28:01 KST 2023
53
Fri Feb 24 13:28:02 KST 2023
10
Fri Feb 24 13:28:03 KST 2023
25
Fri Feb 24 13:28:04 KST 2023
45
Fri Feb 24 13:28:05 KST 2023
55
Fri Feb 24 13:28:06 KST 2023
2
Fri Feb 24 13:28:07 KST 2023
32
Fri Feb 24 13:28:08 KST 2023
49
Fri Feb 24 13:28:09 KST 2023
10
Fri Feb 24 13:28:10 KST 2023
20
Fri Feb 24 13:28:11 KST 2023
45
Fri Feb 24 13:28:12 KST 2023
60
Fri Feb 24 13:28:13 KST 2023
60
Fri Feb 24 13:28:14 KST 2023
18
Fri Feb 24 13:28:15 KST 2023
61
Fri Feb 24 13:28:16 KST 2023
148
Fri Feb 24 13:28:17 KST 2023
128
Fri Feb 24 13:28:18 KST 2023
132
Fri Feb 24 13:28:19 KST 2023
132

 

 

 접속 테스트 이후 엔트로피가 100 이상으로 회복 하는 것을 확인 할 수 있다.

 

 난수를 /dev/urandom 으로 변경 후 접속 테스트

 

 -Djava.security.egd=file:///dev/urandom 옵션으로 강제로 변경

 



testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 1 &
[1] 30011
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 2 &
[2] 30012
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 3 &
[3] 30015
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 4 &
[4] 30017
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 5 &
[5] 30052
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 6 &
[6] 30059
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 7 &
[7] 30061
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 8 &
[8] 30066
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom -Doracle.jdbc.Trace=true -Djava.util.logging.config.file=/home/oracle/DBA/script/SHELL/java/Logging.properties DBConnTest 9 &
[9] 30074
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> java -Djava.security.egd=file:///dev/urandom DBConnTest 10 &
[10] 30086
testora.localdomain@oracle:testdb:/home/oracle/DBA/script/SHELL/java> JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
JDBC Driver Loading Success
3 Connected..
3 connected Time3470 ms.
6 Connected..
6 connected Time3141 ms.
7 Connected..
7 connected Time3500 ms.
10 Connected..
10 connected Time3091 ms.
1 Connected..
1 connected Time4026 ms.
2 Connected..
2 connected Time4266 ms.
4 Connected..
4 connected Time4108 ms.
5 Connected..
5 connected Time3873 ms.
9 Connected..
9 connected Time3247 ms.
8 Connected..
8 connected Time3430 ms.

 

디비 시스템의 부하가 없음에도 클라이언트 접속 에러가 발생을 하면 위의 사례를 확인 해보면 좋을 거 같습니다.

 

참조 문서 : 문제해결 가이드 ORA-3136: WARNING Inbound Connection Timed Out (Doc ID 2115564.1)

 

, , , , , , 이 게시물을
목록
번호 제목 글쓴이 날짜 조회 수
34 Oracle Archive log 사용량 확인(GV$ARCHIVED_LOG) [1] 에밀리오 2016.08.04 11149
33 내가 돌린 SQL ID 찾기 [1] Talros 2016.05.12 8782
32 DBMS_SCHEDULER을 통해 OS 레벨(EXTERNAL)의 shell 수행하기 명품관 2017.04.05 5761
31 오라클 패치 정보를 조회할 수 있는 뷰 DBA_REGISTRY_SQLPATCH 명품관 2017.03.02 5470
30 Schema Password 복사 하기 Talros 2016.10.05 3264
29 Fixed Table에 대한 권한은 직접적으로 부여되지 않는다. 명품관 2016.08.26 2670
28 [12cR2 이상] 오브젝트 이름 30자이상 사용 가능 우뽕 2020.01.22 2479
27 Oracle Resource Limit를 이용한 간단한 Parameter Check (GV$RESOURCE_LIMIT) 에밀리오 2016.07.15 2236
26 Partition 추가의 계절 - Range Partition 추가시 알아 두어야할 부분 [1] 명품관 2015.12.03 2209
25 Kill Session Script (GV$SESSION) 에밀리오 2016.07.12 2126
24 Alert Log를 SQL 사용하여 보기 (X$DBGALERTEXT) [1] 에밀리오 2016.01.28 2019
23 Pga 메모리 설정관련 내용 [1] 우뽕 2021.03.05 1781
22 Alert log 에서 갑자기 패치 정보가 나타나는 현상 Talros 2019.09.23 1636
21 테이블 컬럼의 Default 값에 대한 흔적은 Dictionary에 계속 남게 된다. 명품관 2016.04.05 1585
20 Block Cleanout(블럭 클린아웃) 명품관 2016.09.23 1488
19 Schema password 재 사용 불가능 하게 하기 [1] Talros 2022.01.26 1283
18 DB option Enable / Disable 정리 방법 - Mos 참고 file 우뽕 2021.01.31 1209
17 Active Session History를 이용한 TOP SQL 분석 (GV$ACTIVE_SESSION_HISTORY) 에밀리오 2016.07.12 1195
16 RECO 프로세스 트레이스 발생 하면서 ORA-02019 에러 발생시 명품관 2021.01.12 995
15 SQL Plan Management(SPM) - 1 파라미터의 기능 확인 명품관 2020.03.19 982
쓰기 태그
위로