From 31ba97f65a2665ddb6f4e9e383c21b2eefe12c78 Mon Sep 17 00:00:00 2001 From: Fu Chen Date: Tue, 1 Mar 2022 16:31:29 +0800 Subject: [PATCH] [KYUUBI #1983] [[KYUUBI #1806][FOLLOWUP] Fix LaunchEngine may be closed multiple times MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ### _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 Signed-off-by: Cheng Pan --- .../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 a4603022f14..8d7b0ab6dca 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()