search

brettwooldridge / HikariCP

光 HikariCP・A solid, high-performance, JDBC connection pool at last.
Apache License 2.0
19.64k stars 2.9k forks source link

Closing connection failed "java.sql.SQLRecoverableException: IO Error: Socket read timed out" #1393

Open nakshay opened 5 years ago

nakshay commented 5 years ago

Environment

HikariCP version: 3.3.1
JDK version     : 1.8.0_111
Database        : Oracle 12C.
Driver version  : 12.1.0.2

I get below exception intermittently

HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection oracle.jdbc.driver.T4CConnection@4edf4df0 failed "java.sql.SQLRecoverableException: IO Error: Socket read timed out at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:770) at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:4585) at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:138) at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:447) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: oracle.net.ns.NetException: Socket read timed out at oracle.net.ns.Packet.receive(Packet.java:350) at oracle.net.ns.DataPacket.receive(DataPacket.java:105) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305) at oracle.net.ns.NetInputStream.read(NetInputStream.java:249) at oracle.net.ns.NetInputStream.read(NetInputStream.java:171) at oracle.net.ns.NetInputStream.read(NetInputStream.java:89) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:123) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:79) at oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:426) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:390) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:249) at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:59) at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:757)

tomAndJetty commented 3 years ago

did you have resolved this problem later？ i met the same problem in the environment of oracle 11g and c3p0 connection pool.

nakshay commented 3 years ago

@tomAndJetty maybe that was because of some network issue, connection pool was getting initializedat first attempt but when connections were closed due to idle timeout the next connection add operation was getting failed. some tweaks in connection pool properties solved the issue for now. atleast.

tomAndJetty commented 3 years ago

@nakshay thanks for your reply. maybe i should turn connection pool option 'testConnection' on.

norberto-enomoto commented 3 years ago

I'm facing the same issue. Any sugestions to resolve it? 06-09-20 21:49:04.772 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:04.772 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@135c4bab: (connection has passed maxLifetime) 06-09-20 21:49:05.875 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@686ae288 failed java.sql.SQLRecoverableException: IO Error: Socket read timed out at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:919) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:2005) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) ~[HikariCP-3.4.5.jar:na] at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) [HikariCP-3.4.5.jar:na] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_241] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_241] at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_241] Caused by: java.net.SocketTimeoutException: Socket read timed out at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:174) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:98) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:534) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:485) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:62) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:908) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] ... 6 common frames omitted 06-09-20 21:49:05.926 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:05.926 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@77661966: (connection has passed maxLifetime) 06-09-20 21:49:06.922 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Pool stats (total=6, active=1, idle=5, waiting=0) 06-09-20 21:49:06.922 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:08.433 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Pool stats (total=10, active=1, idle=9, waiting=0) 06-09-20 21:49:08.433 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:15.250 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Pool stats (total=10, active=1, idle=9, waiting=0) 06-09-20 21:49:15.250 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:16.574 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Pool stats (total=10, active=1, idle=9, waiting=0) 06-09-20 21:49:16.574 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:19.784 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@135c4bab failed java.sql.SQLRecoverableException: IO Error: Socket read timed out at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:919) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:2005) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) ~[HikariCP-3.4.5.jar:na] at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) [HikariCP-3.4.5.jar:na] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_241] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_241] at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_241] Caused by: java.net.SocketTimeoutException: Socket read timed out at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:174) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:98) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:534) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:485) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:62) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:908) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] ... 6 common frames omitted 06-09-20 21:49:19.811 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:19.811 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@2e29e860: (connection has passed maxLifetime) 06-09-20 21:49:20.935 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@77661966 failed java.sql.SQLRecoverableException: IO Error: Socket read timed out at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:919) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:2005) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:143) ~[HikariCP-3.4.5.jar:na] at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:451) [HikariCP-3.4.5.jar:na] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_241] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_241] at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_241] Caused by: java.net.SocketTimeoutException: Socket read timed out at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:174) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:98) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:534) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:485) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:62) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:908) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0] ... 6 common frames omitted 06-09-20 21:49:20.960 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:20.961 DEBUG com.zaxxer.hikari.pool.PoolBase : HikariCP-ABC - Closing connection oracle.jdbc.driver.T4CConnection@7230fdc5: (connection has passed maxLifetime) 06-09-20 21:49:23.595 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Pool stats (total=6, active=1, idle=5, waiting=0) 06-09-20 21:49:23.596 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:25.216 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Pool stats (total=6, active=1, idle=5, waiting=0) 06-09-20 21:49:25.216 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:27.395 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Pool stats (total=7, active=1, idle=6, waiting=0) 06-09-20 21:49:27.396 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:28.421 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Pool stats (total=6, active=1, idle=5, waiting=0) 06-09-20 21:49:28.421 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-BH - Fill pool skipped, pool is at sufficient level. 06-09-20 21:49:28.592 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Pool stats (total=6, active=1, idle=5, waiting=0) 06-09-20 21:49:28.592 DEBUG com.zaxxer.hikari.pool.HikariPool : HikariCP-ABC - Fill pool skipped, pool is at sufficient level.

aravindmangu commented 4 months ago

@tomAndJetty maybe that was because of some network issue, connection pool was getting initializedat first attempt but when connections were closed due to idle timeout the next connection add operation was getting failed. some tweaks in connection pool properties solved the issue for now. atleast.

@nakshay what values did you use for connection pool properties ?