LinuxサーバからOracle JDBC接続するとEnd of TNS data channelやConnection resetが発生する場合の対処法

Linux Java Oracle

事象

LinuxのAPサーバ上に配置したJavaバッチプログラムからOracle DBへJDBC接続しようとするとDBコネクション取得時にエラーが出ることがあった。
体感的には、何度かバッチ起動終了を繰り返すとDBコネクション取得にかかる時間がどんどん遅くなっていき、最終的に繋がらなくなる。

DB接続部分はいつもどおりのやり方。

Class.forName("oracle.jdbc.driver.OracleDriver");
 Connection con = DriverManager.getConnection("jdbc:oracle:thin:@host:1521:sid", user, pass);

共有サーバ接続だと以下のエラー

java.sql.SQLException: IO Error: End of TNS data channel
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:458)
at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at java.sql.DriverManager.getConnection(DriverManager.java:525)
at java.sql.DriverManager.getConnection(DriverManager.java:171)
at ...
Caused by: oracle.net.ns.NetException: End of TNS data channel
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:308)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(T4CTTIoauthenticate.java:404)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:385)
... 9 more

専用サーバ接続だと以下のエラー

java.sql.SQLException: IO Error: Connection reset
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:467)
at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at java.sql.DriverManager.getConnection(DriverManager.java:525)
at java.sql.DriverManager.getConnection(DriverManager.java:171)
at ...
Caused by: java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:96)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at oracle.net.ns.DataPacket.send(DataPacket.java:210)
at oracle.net.ns.NetOutputStream.flush(NetOutputStream.java:230)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:312)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(T4CTTIoauthenticate.java:404)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:385)
... 9 more

sqlplusでのDB接続は問題なし。
End of TNS data channelで調べたところ「OracleDBとOracle JDBCドライバのバージョンが不一致の場合に発生」といった情報はあったが、バージョンを一致させても改善せず。

バッチが固まったときにスレッドダンプを取得。その内容がこちら。

kill -3
...
"main" prio=1 tid=0x00000000599cadd0 nid=0x31a8 runnable [0x00007fff03644000..0x00007fff03645c60]
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:194)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:254)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0x00002abece792fd0> (a java.io.BufferedInputStream)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0x00002abece792ce8> (a java.io.BufferedInputStream)
at sun.security.provider.SeedGenerator$URLSeedGenerator.getSeedByte(SeedGenerator.java:452)
at sun.security.provider.SeedGenerator.getSeedBytes(SeedGenerator.java:122)
at sun.security.provider.SeedGenerator.generateSeed(SeedGenerator.java:117)
at sun.security.provider.SecureRandom.engineGenerateSeed(SecureRandom.java:114)
at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:171)
- locked <0x00002abece792778> (a sun.security.provider.SecureRandom)
at java.security.SecureRandom.nextBytes(SecureRandom.java:413)
- locked <0x00002abece792b08> (a java.security.SecureRandom)
at oracle.security.o5logon.O5Logon.a(Unknown Source)
at oracle.security.o5logon.O5Logon.(Unknown Source)
at oracle.jdbc.driver.T4CTTIoauthenticate.(T4CTTIoauthenticate.java:566)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:370)
at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at java.sql.DriverManager.getConnection(DriverManager.java:525)
- locked <0x00002abe9df21a10> (a java.lang.Class)
at java.sql.DriverManager.getConnection(DriverManager.java:171)
- locked <0x00002abe9df21a10> (a java.lang.Class)
at ...

原因

DBコネクション取得時にOracleJDBCドライバ内から呼び出しているSecureRandomでのシード生成で時間がかかることがあり、一定時間以上かかるとOracleDBサーバはクライアントの操作タイムアウトとして通信を切断してしまう。

シード生成で時間がかかるのはLinuxサーバの場合のみ発生、Windowsでは発生しない。

上記のスレッドダンプを基に、SecureRandomでのシード生成の関連で調べてみると、以下のサイトがヒットした。

SecureRandom で処理が約20秒停止 - QA@IT
Bug ID: JDK-6202721 SHA1PRNG reads from /dev/random even if /dev/urandom selected

対処

Bug ID: JDK-6202721 SHA1PRNG reads from /dev/random even if /dev/urandom selected の、ワークアラウンドにあった方法で試したところ改善した。

Javaの実行時引数に「-Djava.security.egd=file:/dev/./urandom」を追加。

ちなみに、「-Djava.security.egd=file:/dev/urandom」ではうまくいかない。
サイトを見ればわかるのだが、明らかにJavaのバグなのに、「ワークアラウンドがあるので問題ではない」という回答でクローズしている。かなり強引(笑

終わりに

問題発見からこの対処に行き着くまで2週間かかった。他の仕事が立て込んでたというのもあるけど。
スレッドダンプ取ってからはするすると解決の方向に向かっていったので、固まる事象にはスレッドダンプさまさまだなあと思った。