An error occurs when HikariCP connection pool is used #4408

winfys · 2023-02-24T04:14:22Z

winfys
Feb 24, 2023

We used the dolphinscheduler task for scheduling and the HikariCP connection pool for sql tasks.

The following errors occur frequently:
hive driver 2.1.0
kyuubi 1.6.1
case 1
The task reported an error, but the sql was actually successful
task log

[ERROR] 2023-02-22 04:53:59.438 +0800 - execute sql error: org.apache.thrift.transport.TTransportException: java.net.SocketException: Socket closed
[ERROR] 2023-02-22 04:53:59.438 +0800 - sql task error
java.sql.SQLException: org.apache.thrift.transport.TTransportException: java.net.SocketException: Socket closed
	at org.apache.hive.jdbc.HiveStatement.waitForOperationToComplete(HiveStatement.java:363)
	at org.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:251)
	at org.apache.hive.jdbc.HiveStatement.executeUpdate(HiveStatement.java:448)
	at org.apache.hive.jdbc.HivePreparedStatement.executeUpdate(HivePreparedStatement.java:119)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
	at org.apache.dolphinscheduler.plugin.task.sql.SqlTask.executeUpdate(SqlTask.java:384)
	at org.apache.dolphinscheduler.plugin.task.sql.SqlTask.executeFuncAndSql(SqlTask.java:199)
	at org.apache.dolphinscheduler.plugin.task.sql.SqlTask.handle(SqlTask.java:151)
	at org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread.run(TaskExecuteThread.java:208)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125)
	at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:57)
	at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.thrift.transport.TTransportException: java.net.SocketException: Socket closed
	at org.apache.thrift.transport.TIOStreamTransport.flush(TIOStreamTransport.java:161)
	at org.apache.thrift.transport.TSaslTransport.flush(TSaslTransport.java:501)
	at org.apache.thrift.transport.TSaslClientTransport.flush(TSaslClientTransport.java:37)
	at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:73)
	at org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:62)
	at org.apache.hive.service.rpc.thrift.TCLIService$Client.send_GetOperationStatus(TCLIService.java:461)
	at org.apache.hive.service.rpc.thrift.TCLIService$Client.GetOperationStatus(TCLIService.java:453)
	at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.hive.jdbc.HiveConnection$SynchronizedHandler.invoke(HiveConnection.java:1427)
	at com.sun.proxy.$Proxy186.GetOperationStatus(Unknown Source)
	at org.apache.hive.jdbc.HiveStatement.waitForOperationToComplete(HiveStatement.java:332)
	... 16 common frames omitted
Caused by: java.net.SocketException: Socket closed
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
	at org.apache.thrift.transport.TIOStreamTransport.flush(TIOStreamTransport.java:159)

kyuubi log

2023/02/22 04:53:57.940 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing wangjian's query[b3930976-fbd8-4df0-ac40-1ac51fdbd56d]: RUNNING_STATE -> CLOSED_STATE
2023/02/22 04:53:59.427 INFO org.apache.kyuubi.operation.ExecuteStatement: Query[b3930976-fbd8-4df0-ac40-1ac51fdbd56d] in RUNNING_STATE
2023/02/22 04:53:59.434 WARN org.apache.kyuubi.operation.ExecuteStatement: Ignore exception in terminal state with b3930976-fbd8-4df0-ac40-1ac51fdbd56d: org.apache.kyuubi.KyuubiSQLException: Invalid OperationHandle [0d725771-375e-408e-b071-a493f2f072dd]

case 2
task log

[ERROR] 2023-02-22 02:22:19.906 +0800 - execute sql error: Could not create ResultSet: java.io.IOException: Stream closed
[ERROR] 2023-02-22 02:22:19.906 +0800 - sql task error
java.sql.SQLException: Could not create ResultSet: java.io.IOException: Stream closed
	at org.apache.hive.jdbc.HiveQueryResultSet.retrieveSchema(HiveQueryResultSet.java:284)
	at org.apache.hive.jdbc.HiveQueryResultSet.<init>(HiveQueryResultSet.java:197)
	at org.apache.hive.jdbc.HiveQueryResultSet$Builder.build(HiveQueryResultSet.java:178)
	at org.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:260)
	at org.apache.hive.jdbc.HiveStatement.executeUpdate(HiveStatement.java:448)
	at org.apache.hive.jdbc.HivePreparedStatement.executeUpdate(HivePreparedStatement.java:119)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
	at org.apache.dolphinscheduler.plugin.task.sql.SqlTask.executeUpdate(SqlTask.java:384)
	at org.apache.dolphinscheduler.plugin.task.sql.SqlTask.executeFuncAndSql(SqlTask.java:199)
	at org.apache.dolphinscheduler.plugin.task.sql.SqlTask.handle(SqlTask.java:151)
	at org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread.run(TaskExecuteThread.java:208)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125)
	at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:57)
	at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.thrift.transport.TTransportException: java.io.IOException: Stream closed
	at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129)
	at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
	at org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:376)
	at org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:453)
	at org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:435)
	at org.apache.thrift.transport.TSaslClientTransport.read(TSaslClientTransport.java:37)
	at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
	at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429)
	at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318)
	at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219)
	at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77)
	at org.apache.hive.service.rpc.thrift.TCLIService$Client.recv_GetResultSetMetadata(TCLIService.java:536)
	at org.apache.hive.service.rpc.thrift.TCLIService$Client.GetResultSetMetadata(TCLIService.java:523)
	at sun.reflect.GeneratedMethodAccessor74.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.hive.jdbc.HiveConnection$SynchronizedHandler.invoke(HiveConnection.java:1427)
	at com.sun.proxy.$Proxy186.GetResultSetMetadata(Unknown Source)
	at org.apache.hive.jdbc.HiveQueryResultSet.retrieveSchema(HiveQueryResultSet.java:252)
	... 18 common frames omitted
Caused by: java.io.IOException: Stream closed
	at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:336)
	at org.apache.thrift.transport.TI

kyuubi log

2023/02/22 02:22:16.410 INFO org.apache.kyuubi.operation.ExecuteStatement: Query[8edcc302-4122-46e5-a0e5-982b7ea886eb] in RUNNING_STATE
2023/02/22 02:22:19.846 INFO org.apache.kyuubi.operation.ExecuteStatement: Query[8edcc302-4122-46e5-a0e5-982b7ea886eb] in FINISHED_STATE
2023/02/22 02:22:19.848 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing wangjian's query[8edcc302-4122-46e5-a0e5-982b7ea886eb]: FINISHED_STATE -> CLOSED_STATE, 
2023/02/22 02:22:19.851 ERROR org.apache.kyuubi.server.KyuubiTBinaryFrontendService: Error closing operation: 
org.apache.kyuubi.KyuubiSQLException: Invalid OperationHandle [8edcc302-4122-46e5-a0e5-982b7ea886eb]
	at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69) ~[kyuubi-common_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.operation.OperationManager.getOperation(OperationManager.scala:103) ~[kyuubi-common_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.service.AbstractBackendService.closeOperation(AbstractBackendService.scala:188) ~[kyuubi-common_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.server.KyuubiServer$$anon$1.org$apache$kyuubi$server$BackendServiceMetric$$super$closeOperation(KyuubiServer.scala:111) ~[kyuubi-server_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.server.BackendServiceMetric.$anonfun$closeOperation$1(BackendServiceMetric.scala:169) ~[kyuubi-server_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23) ~[scala-library-2.12.15.jar:?]
	at org.apache.kyuubi.metrics.MetricsSystem$.timerTracing(MetricsSystem.scala:111) ~[kyuubi-metrics_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.server.BackendServiceMetric.closeOperation(BackendServiceMetric.scala:169) ~[kyuubi-server_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.server.BackendServiceMetric.closeOperation$(BackendServiceMetric.scala:167) ~[kyuubi-server_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.server.KyuubiServer$$anon$1.closeOperation(KyuubiServer.scala:111) ~[kyuubi-server_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.kyuubi.service.TFrontendService.CloseOperation(TFrontendService.scala:486) ~[kyuubi-common_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseOperation.getResult(TCLIService.java:1797) ~[hive-service-rpc-3.1.3.jar:3.1.3]
	at org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseOperation.getResult(TCLIService.java:1782) ~[hive-service-rpc-3.1.3.jar:3.1.3]
	at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39) ~[libthrift-0.9.3.jar:0.9.3]
	at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39) ~[libthrift-0.9.3.jar:0.9.3]
	at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36) ~[kyuubi-common_2.12-1.6.1-incubating.jar:1.6.1-incubating]
	at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286) ~[libthrift-0.9.3.jar:0.9.3]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_252]

Answered by pan3793

Feb 24, 2023

Basically, it's a bug of the Hive JDBC driver, which was explained in apache/hive#3379

Kyuubi Hive JDBC driver fixed this issue and add new parameters to tune the connect timeout / socket timeout #3152

View full answer

pan3793 · 2023-02-24T04:21:17Z

pan3793
Feb 24, 2023
Collaborator

Basically, it's a bug of the Hive JDBC driver, which was explained in apache/hive#3379

Kyuubi Hive JDBC driver fixed this issue and add new parameters to tune the connect timeout / socket timeout #3152

0 replies

pan3793 · 2023-02-24T04:29:05Z

pan3793
Feb 24, 2023
Collaborator

And for "Invalid SessionHandle", it was explained in FAQ

1 reply

winfys Feb 24, 2023
Author

We have modified the hive driver code

I removed HikariCP and used DriverManager to create a connection, and the problem never happened again

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

An error occurs when HikariCP connection pool is used #4408

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 2 comments 1 reply

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

An error occurs when HikariCP connection pool is used #4408

Uh oh!

Uh oh!

winfys Feb 24, 2023

Replies: 2 comments · 1 reply

Uh oh!

pan3793 Feb 24, 2023 Collaborator

Uh oh!

pan3793 Feb 24, 2023 Collaborator

Uh oh!

winfys Feb 24, 2023 Author

winfys
Feb 24, 2023

Replies: 2 comments 1 reply

pan3793
Feb 24, 2023
Collaborator

pan3793
Feb 24, 2023
Collaborator

winfys Feb 24, 2023
Author