By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement . We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account Closing connection failed "java.sql.SQLRecoverableException: IO Error: Socket read timed out" #1393 Closing connection failed "java.sql.SQLRecoverableException: IO Error: Socket read timed out" #1393 nakshay opened this issue Jun 19, 2019 · 5 comments

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)

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.

@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 ?