Socket read interrupted exception while connecting to oracle DB from dropwizard application

[lohitpradhan]

Hi Team,
Our project is a dropwizard based application and we use dropwizard-jdbi library which internally uses tomcat connection pool for db operations. We are seeing an exception while executing sql script using Jdbi api. The script basically drop the schema from the Oracle DB.

Dependencies version details:

ojdbc8 version : 21.7.0.0
jdbi3-core version : 3.32.0
dropwizard version : 2.1.1

Connection pool details:

        driverClass: "oracle.jdbc.driver.OracleDriver"
        validationQueryString: "SELECT 1 from dual"
        initialSize: 5
        minSize: 5
        maxSize: 20
        removeAbandoned: true
        removeAbandonedTimeout: 600s
        maxWaitForConnection: 600s
        maxConnectionAge: false
        checkConnectionOnBorrow: true
        databaseService: "tp"
        minIdleTime: 1m
        evictionInterval: 5s
        validationInterval : 30s

Application code:

jdbi.useHandle(
                    handle ->
                            handle.createUpdate("DROP USER TEST CASCADE")
                                    .bind("username", username)
                                    .execute());

Sometimes this code gives below exception during performance test.

Caused by: org.jdbi.v3.core.statement.UnableToExecuteStatementException: java.sql.SQLRecoverableException: IO Error: Socket read interrupted [statement:"DROP USER TEST CASCADE"]
at org.jdbi.v3.core.statement.SqlStatement.internalExecute(SqlStatement.java:1796)
at org.jdbi.v3.core.result.ResultProducers.lambda$returningUpdateCount$0(ResultProducers.java:46)
at org.jdbi.v3.core.statement.Update.execute(Update.java:60)
at org.jdbi.v3.core.statement.Update.execute(Update.java:48)
at com.commons.db.DBSchemaProviderImpl.lambda$deleteDBSchema$1(DBSchemaProviderImpl.java:59)
at org.jdbi.v3.core.HandleConsumer.lambda$asCallback$0(HandleConsumer.java:32)
at org.jdbi.v3.core.Jdbi.withHandle(Jdbi.java:357)
at org.jdbi.v3.core.Jdbi.useHandle(Jdbi.java:373)
at com.commons.db.DBSchemaProviderImpl.deleteDBSchema(DBSchemaProviderImpl.java:55)
... 7 common frames omitted
Suppressed: org.jdbi.v3.core.CloseException: Exception thrown while cleaning StatementContext
at org.jdbi.v3.core.statement.StatementContext.close(StatementContext.java:593)
at org.jdbi.v3.core.result.ResultProducers.lambda$returningUpdateCount$0(ResultProducers.java:45)
... 14 common frames omitted
Caused by: java.sql.SQLRecoverableException: Closed Connection
at oracle.jdbc.driver.PhysicalConnection.requireOpenConnection(PhysicalConnection.java:11385)
at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:4056)
at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1828)
at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1811)
at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:146)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:110)
at sun.reflect.GeneratedMethodAccessor139.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:118)
at com.sun.proxy.$Proxy111.close(Unknown Source)
at org.jdbi.v3.core.statement.DefaultStatementBuilder.close(DefaultStatementBuilder.java:73)
at org.jdbi.v3.core.statement.SqlStatement.lambda$internalExecute$7(SqlStatement.java:1773)
at org.jdbi.v3.core.statement.StatementContext.close(StatementContext.java:582)
... 15 common frames omitted
Suppressed: org.jdbi.v3.core.CloseException: Failed to clear transaction status on close
at org.jdbi.v3.core.Handle.close(Handle.java:198)
at org.jdbi.v3.core.Jdbi.withHandle(Jdbi.java:355)
... 9 common frames omitted
Caused by: org.jdbi.v3.core.transaction.TransactionException: Failed to test for transaction status
at org.jdbi.v3.core.transaction.LocalTransactionHandler$BoundLocalTransactionHandler.isInTransaction(LocalTransactionHandler.java:194)
at org.jdbi.v3.core.Handle.isInTransaction(Handle.java:361)
at org.jdbi.v3.core.Handle.close(Handle.java:165)
... 10 common frames omitted
Caused by: java.sql.SQLRecoverableException: Closed Connection
at oracle.jdbc.driver.PhysicalConnection.requireOpenConnection(PhysicalConnection.java:11385)
at oracle.jdbc.driver.PhysicalConnection.getAutoCommit(PhysicalConnection.java:2559)
at sun.reflect.GeneratedMethodAccessor94.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:131)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy110.getAutoCommit(Unknown Source)
at org.jdbi.v3.core.transaction.LocalTransactionHandler$BoundLocalTransactionHandler.isInTransaction(LocalTransactionHandler.java:192)
... 12 common frames omitted
Caused by: java.sql.SQLRecoverableException: IO Error: Socket read interrupted
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:1061)
at oracle.jdbc.driver.OracleStatement.executeSQLStatement(OracleStatement.java:1530)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1310)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3745)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3940)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1009)
at sun.reflect.GeneratedMethodAccessor137.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:118)
at com.sun.proxy.$Proxy111.execute(Unknown Source)
at org.jdbi.v3.core.statement.SqlLoggerUtil.wrap(SqlLoggerUtil.java:31)
at org.jdbi.v3.core.statement.SqlStatement.internalExecute(SqlStatement.java:1788)
... 15 common frames omitted
Suppressed: java.sql.SQLRecoverableException: Closed Connection
at oracle.jdbc.driver.PhysicalConnection.requireOpenConnection(PhysicalConnection.java:11385)
at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:4056)
at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1828)
at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1811)
at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:146)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:110)
at sun.reflect.GeneratedMethodAccessor139.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:118)
at com.sun.proxy.$Proxy111.close(Unknown Source)
at org.jdbi.v3.core.statement.SqlStatement.internalExecute(SqlStatement.java:1791)
... 15 common frames omitted
Caused by: java.io.InterruptedIOException: Socket read interrupted
at oracle.net.nt.TimeoutSocketChannel.handleInterrupt(TimeoutSocketChannel.java:548)
at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:419)
at oracle.net.nt.SSLSocketChannel.readFromSocket(SSLSocketChannel.java:731)
at oracle.net.nt.SSLSocketChannel.fillReadBuffer(SSLSocketChannel.java:349)
at oracle.net.nt.SSLSocketChannel.fillAndUnwrap(SSLSocketChannel.java:279)
at oracle.net.nt.SSLSocketChannel.read(SSLSocketChannel.java:129)
at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:1118)
at oracle.net.ns.NIOPacket.readHeader(NIOPacket.java:266)
at oracle.net.ns.NIOPacket.readPacketFromSocketChannel(NIOPacket.java:198)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:140)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:113)
at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:97)
at oracle.jdbc.driver.T4CMAREngineNIO.prepareForUnmarshall(T4CMAREngineNIO.java:833)
at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMA...

Checked with DB team, they have told that there is no issue from db side and no connection drop was seen in db during that time.

Checked with JDBI team, they have told that the issue might be communication problem between your client and database server, or maybe some connection pool is behaving oddly.

Could you please someone help me on this ?
Thanks

[joschi]

@lohitpradhan Are you, by any chance, connected with the same user account to the database which you're trying to DROP?

[lohitpradhan]

No.. I am connecting with the admin user and trying to drop other user/schema.

[joschi]

Are there any timestamps for these log messages / stack traces?

How much time passes between executing the SQL statement and the connection being interrupted?

[lohitpradhan]

There were 100 users in the database. While deleting these users, 48 users deleted successfully but 52 users could not be deleted due to above error. Exception happened during this time : 2023-01-16T06:38:49Z - 2023-01-16T06:39:57Z UTC (52 errors)