Skip to content

Commit

Permalink
[KYUUBI apache#1983] [[KYUUBI apache#1806][FOLLOWUP] Fix LaunchEngine…
Browse files Browse the repository at this point in the history
… may be closed multiple times

### _Why are the changes needed?_

After [PR-1807](apache#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 apache#1983 from cfmcgrady/kyuubi-1806-followup.

Closes apache#1983

Closes apache#1806

c764269 [Fu Chen] Fix LaunchEngine may be closed multiple times

Authored-by: Fu Chen <cfmcgrady@gmail.com>
Signed-off-by: Cheng Pan <chengpan@apache.org>
  • Loading branch information
cfmcgrady authored and pan3793 committed Mar 1, 2022
1 parent d6bbe32 commit 31ba97f
Showing 1 changed file with 2 additions and 2 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -145,7 +145,7 @@ class KyuubiSessionImpl(
}

override def close(): Unit = {
if (!launchEngineOp.isTimedOut) {
if (!OperationState.isTerminal(launchEngineOp.getStatus.state)) {
closeOperation(launchEngineOp.getHandle)
}
super.close()
Expand Down

0 comments on commit 31ba97f

Please sign in to comment.