This is an automated email from the ASF dual-hosted git repository.
chengpan pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-kyuubi.git
The following commit(s) were added to refs/heads/master by this push:
new 31ba97f [KYUUBI #1983] [[KYUUBI #1806][FOLLOWUP] Fix LaunchEngine may
be closed multiple times
31ba97f is described below
commit 31ba97f65a2665ddb6f4e9e383c21b2eefe12c78
Author: Fu Chen <[email protected]>
AuthorDate: Tue Mar 1 16:31:29 2022 +0800
[KYUUBI #1983] [[KYUUBI #1806][FOLLOWUP] Fix LaunchEngine may be closed
multiple times
### _Why are the changes needed?_
After [PR-1807](https://github.com/apache/incubator-kyuubi/pull/1807), the
error will still occur.
```
11:11:05.589 INFO org.apache.kyuubi.operation.log.OperationLog: Creating
operation log file
/Users/fchen/Project/bigdata/incubator-kyuubi/server_operation_logs/6a640069-6a26-4817-8ad7-77385360bb9d/a09d4b0a-85ec-4640-8ab9-c6a37146fd1f
11:11:05.603 INFO org.apache.kyuubi.operation.LaunchEngine: Processing
anonymous's query[a09d4b0a-85ec-4640-8ab9-c6a37146fd1f]: INITIALIZED_STATE ->
PENDING_STATE, statement: LAUNCH_ENGINE
11:11:05.604 INFO org.apache.kyuubi.operation.LaunchEngine: Processing
anonymous's query[a09d4b0a-85ec-4640-8ab9-c6a37146fd1f]: PENDING_STATE ->
RUNNING_STATE, statement: LAUNCH_ENGINE
11:11:25.075 INFO org.apache.kyuubi.operation.LaunchEngine: Processing
anonymous's query[a09d4b0a-85ec-4640-8ab9-c6a37146fd1f]: RUNNING_STATE ->
FINISHED_STATE, statement: LAUNCH_ENGINE, time taken: 19.471 seconds
11:12:58.257 WARN org.apache.kyuubi.operation.KyuubiOperationManager:
Operation OperationHandle [type=UNKNOWN_OPERATION, identifier:
a09d4b0a-85ec-4640-8ab9-c6a37146fd1f] is timed-out and will be closed
11:12:58.258 INFO org.apache.kyuubi.operation.LaunchEngine: Processing
anonymous's query[a09d4b0a-85ec-4640-8ab9-c6a37146fd1f]: FINISHED_STATE ->
CLOSED_STATE, statement: LAUNCH_ENGINE
11:13:04.615 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
Received request of closing SessionHandle [6a640069-6a26-4817-8ad7-77385360bb9d]
11:13:04.618 INFO org.apache.kyuubi.session.KyuubiSessionManager:
SessionHandle [6a640069-6a26-4817-8ad7-77385360bb9d] is closed, current opening
sessions 0
11:13:04.619 ERROR org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
Error closing session:
org.apache.kyuubi.KyuubiSQLException: Invalid OperationHandle
[type=UNKNOWN_OPERATION, identifier: a09d4b0a-85ec-4640-8ab9-c6a37146fd1f]
at
org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69)
~[classes/:?]
at
org.apache.kyuubi.operation.OperationManager.removeOperation(OperationManager.scala:89)
~[classes/:?]
at
org.apache.kyuubi.operation.OperationManager.closeOperation(OperationManager.scala:104)
~[classes/:?]
at
org.apache.kyuubi.session.AbstractSession.$anonfun$closeOperation$1(AbstractSession.scala:181)
~[classes/:?]
at
scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
~[scala-library-2.12.15.jar:?]
at
org.apache.kyuubi.session.AbstractSession.withAcquireRelease(AbstractSession.scala:75)
~[classes/:?]
at
org.apache.kyuubi.session.AbstractSession.closeOperation(AbstractSession.scala:179)
~[classes/:?]
at
org.apache.kyuubi.session.KyuubiSessionImpl.close(KyuubiSessionImpl.scala:149)
~[classes/:?]
at
org.apache.kyuubi.session.SessionManager.closeSession(SessionManager.scala:93)
~[classes/:?]
at
org.apache.kyuubi.service.AbstractBackendService.closeSession(AbstractBackendService.scala:49)
~[classes/:?]
at
org.apache.kyuubi.server.KyuubiServer$$anon$1.org$apache$kyuubi$server$BackendServiceMetric$$super$closeSession(KyuubiServer.scala:142)
~[classes/:?]
at
org.apache.kyuubi.server.BackendServiceMetric.$anonfun$closeSession$1(BackendServiceMetric.scala:43)
~[classes/:?]
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)
~[classes/:?]
at
org.apache.kyuubi.server.BackendServiceMetric.closeSession(BackendServiceMetric.scala:43)
~[classes/:?]
at
org.apache.kyuubi.server.BackendServiceMetric.closeSession$(BackendServiceMetric.scala:41)
~[classes/:?]
at
org.apache.kyuubi.server.KyuubiServer$$anon$1.closeSession(KyuubiServer.scala:142)
~[classes/:?]
at
org.apache.kyuubi.service.TFrontendService.CloseSession(TFrontendService.scala:158)
[classes/:?]
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1397)
[hive-service-rpc-2.3.9.jar:2.3.9]
at
org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1382)
[hive-service-rpc-2.3.9.jar:2.3.9]
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:38)
[libthrift-0.16.0.jar:0.16.0]
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:38)
[libthrift-0.16.0.jar:0.16.0]
at
org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36)
[classes/:?]
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:250)
[libthrift-0.16.0.jar:0.16.0]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_202]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_202]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
11:13:04.629 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService:
Finished closing SessionHandle [6a640069-6a26-4817-8ad7-77385360bb9d]
```
```
A => LaunchEngine Operation
TCloseSessionReq
A-PENDING A-FINISHED |
Δ Δ |
| | ▽
----t1------t2------t3------t4------------------------------t5------------t6--------------t7->
| | |
▽ | ▽
A-INITIALIZED ▽ A-CLOSED (timed-out)
A-RUNNING
|<-- operation.idle.timeout -->|<--
operation.idle.timeout -->|
```
1. the variable `LaunchEngine.lastAccessTime` will be reset to
`System.currentTimeMillis()` when the operation is timeouts(at time t5).
https://github.com/apache/incubator-kyuubi/blob/67d1c5dd513327b350dac3d6855af5223a594087/kyuubi-common/src/main/scala/org/apache/kyuubi/operation/AbstractOperation.scala#L75-L89
2. when the Kyuubi server receives the request TCloseSessionReq at time t6
between t5 and t7. Since t6 < t7, `LaunchEngine.isTimedOut()` will return
false, and we will close the operation LaunchEngine again.
https://github.com/apache/incubator-kyuubi/blob/67d1c5dd513327b350dac3d6855af5223a594087/kyuubi-common/src/main/scala/org/apache/kyuubi/operation/AbstractOperation.scala#L189-L196
### _How was this patch tested?_
Pass CI.
Closes #1983 from cfmcgrady/kyuubi-1806-followup.
Closes #1983
Closes #1806
c7642693 [Fu Chen] Fix LaunchEngine may be closed multiple times
Authored-by: Fu Chen <[email protected]>
Signed-off-by: Cheng Pan <[email protected]>
---
.../src/main/scala/org/apache/kyuubi/session/KyuubiSessionImpl.scala | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git
a/kyuubi-server/src/main/scala/org/apache/kyuubi/session/KyuubiSessionImpl.scala
b/kyuubi-server/src/main/scala/org/apache/kyuubi/session/KyuubiSessionImpl.scala
index a460302..8d7b0ab 100644
---
a/kyuubi-server/src/main/scala/org/apache/kyuubi/session/KyuubiSessionImpl.scala
+++
b/kyuubi-server/src/main/scala/org/apache/kyuubi/session/KyuubiSessionImpl.scala
@@ -31,7 +31,7 @@ import org.apache.kyuubi.events.{EventLogging, KyuubiEvent,
KyuubiSessionEvent}
import org.apache.kyuubi.ha.client.ZooKeeperClientProvider._
import org.apache.kyuubi.metrics.MetricsConstants._
import org.apache.kyuubi.metrics.MetricsSystem
-import org.apache.kyuubi.operation.{Operation, OperationHandle}
+import org.apache.kyuubi.operation.{Operation, OperationHandle, OperationState}
import org.apache.kyuubi.operation.log.OperationLog
import org.apache.kyuubi.service.authentication.EngineSecurityAccessor
@@ -145,7 +145,7 @@ class KyuubiSessionImpl(
}
override def close(): Unit = {
- if (!launchEngineOp.isTimedOut) {
+ if (!OperationState.isTerminal(launchEngineOp.getStatus.state)) {
closeOperation(launchEngineOp.getHandle)
}
super.close()
