Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[KYUUBI #1806] Fix LaunchEngine may be closed multiple times #1807

Closed
wants to merge 1 commit into from

Conversation

cfmcgrady
Copy link
Contributor

Why are the changes needed?

close #1806

How was this patch tested?

  • Add some test cases that check the changes thoroughly including negative and positive cases if possible

  • Add screenshots for manual tests if appropriate

  • Run test locally before make a pull request

@ulysses-you
Copy link
Contributor

It seems we should not remove the LaunchEngine until session close.

Can we override the isTimedOut of LaunchEngine and mark it never timeout ?

@yaooqinn
Copy link
Member

It seems we should not remove the LaunchEngine until session close.

not true

@yaooqinn
Copy link
Member

yaooqinn commented Jan 19, 2022

indeed, we don't need to add it into OperationManger as it's a member of the session. cc @turboFei, do we call CloseOperation separately at the client-side now?

@codecov-commenter
Copy link

Codecov Report

Merging #1807 (c70a594) into master (53bbbb7) will decrease coverage by 0.02%.
The diff coverage is 50.00%.

Impacted file tree graph

@@             Coverage Diff              @@
##             master    #1807      +/-   ##
============================================
- Coverage     59.89%   59.86%   -0.03%     
+ Complexity      264      263       -1     
============================================
  Files           275      275              
  Lines         13660    13680      +20     
  Branches       1750     1746       -4     
============================================
+ Hits           8181     8189       +8     
- Misses         4777     4793      +16     
+ Partials        702      698       -4     
Impacted Files Coverage Δ
.../org/apache/kyuubi/session/KyuubiSessionImpl.scala 82.75% <50.00%> (-1.46%) ⬇️
...apache/kyuubi/server/api/v1/SessionsResource.scala 65.34% <0.00%> (-12.31%) ⬇️
...apache/kyuubi/service/TBinaryFrontendService.scala 85.41% <0.00%> (-3.72%) ⬇️
...ache/kyuubi/server/api/v1/OperationsResource.scala 67.46% <0.00%> (-2.66%) ⬇️
...ache/kyuubi/engine/trino/TrinoProcessBuilder.scala 44.82% <0.00%> (-2.55%) ⬇️
...a/org/apache/kyuubi/metrics/MetricsConstants.scala 100.00% <0.00%> (ø)
...e/kyuubi/server/KyuubiTBinaryFrontendService.scala 96.55% <0.00%> (+0.12%) ⬆️
...org/apache/kyuubi/engine/trino/schema/RowSet.scala 90.20% <0.00%> (+0.13%) ⬆️
...org/apache/kyuubi/engine/flink/schema/RowSet.scala 63.76% <0.00%> (+1.81%) ⬆️
...cala/org/apache/kyuubi/metrics/MetricsSystem.scala 62.79% <0.00%> (+2.79%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 53bbbb7...c70a594. Read the comment docs.

@yaooqinn yaooqinn added this to the v1.4.1 milestone Jan 19, 2022
@yaooqinn yaooqinn closed this in 5bc7ea1 Jan 20, 2022
yaooqinn pushed a commit that referenced this pull request Jan 20, 2022
<!--
Thanks for sending a pull request!

Here are some tips for you:
  1. If this is your first time, please read our contributor guidelines: https://kyuubi.readthedocs.io/en/latest/community/contributions.html
  2. If the PR is related to an issue in https://github.com/apache/incubator-kyuubi/issues, add '[KYUUBI #XXXX]' in your PR title, e.g., '[KYUUBI #XXXX] Your PR title ...'.
  3. If the PR is unfinished, add '[WIP]' in your PR title, e.g., '[WIP][KYUUBI #XXXX] Your PR title ...'.
-->

### _Why are the changes needed?_
<!--
Please clarify why the changes are needed. For instance,
  1. If you add a feature, you can talk about the use case of it.
  2. If you fix a bug, you can clarify why it is a bug.
-->

close #1806

### _How was this patch tested?_
- [ ] Add some test cases that check the changes thoroughly including negative and positive cases if possible

- [ ] Add screenshots for manual tests if appropriate

- [ ] [Run test](https://kyuubi.readthedocs.io/en/latest/develop_tools/testing.html#running-tests) locally before make a pull request

Closes #1807 from cfmcgrady/kyuubi-1806.

Closes #1806

c70a594 [Fu Chen] fix

Authored-by: Fu Chen <cfmcgrady@gmail.com>
Signed-off-by: Kent Yao <yao@apache.org>
(cherry picked from commit 5bc7ea1)
Signed-off-by: Kent Yao <yao@apache.org>
@turboFei
Copy link
Member

turboFei commented Jan 21, 2022

indeed, we don't need to add it into OperationManger as it's a member of the session.

because we need fetch the launch engine log in client side, so it seems that we have to add it into operationManager.

do we call CloseOperation separately at the client-side now?

not now.

@yaooqinn
Copy link
Member

indeed, we don't need to add it into OperationManger as it's a member of the session.

because we need fetch the launch engine log in client side, so it seems that we have to add it into operationManager.

do we call CloseOperation separately at the client-side now?

not now.

I see

pan3793 pushed a commit that referenced this pull request Mar 1, 2022
…ed multiple times

### _Why are the changes needed?_

After [PR-1807](#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

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>
pan3793 pushed a commit that referenced this pull request Mar 1, 2022
…ed multiple times

### _Why are the changes needed?_

After [PR-1807](#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

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>
(cherry picked from commit 31ba97f)
Signed-off-by: Cheng Pan <chengpan@apache.org>
beryllw pushed a commit to beryllw/incubator-kyuubi that referenced this pull request Jan 11, 2024
<!--
Thanks for sending a pull request!

Here are some tips for you:
  1. If this is your first time, please read our contributor guidelines: https://kyuubi.readthedocs.io/en/latest/community/contributions.html
  2. If the PR is related to an issue in https://github.com/apache/incubator-kyuubi/issues, add '[KYUUBI #XXXX]' in your PR title, e.g., '[KYUUBI #XXXX] Your PR title ...'.
  3. If the PR is unfinished, add '[WIP]' in your PR title, e.g., '[WIP][KYUUBI #XXXX] Your PR title ...'.
-->

### _Why are the changes needed?_
<!--
Please clarify why the changes are needed. For instance,
  1. If you add a feature, you can talk about the use case of it.
  2. If you fix a bug, you can clarify why it is a bug.
-->

close apache#1806

### _How was this patch tested?_
- [ ] Add some test cases that check the changes thoroughly including negative and positive cases if possible

- [ ] Add screenshots for manual tests if appropriate

- [ ] [Run test](https://kyuubi.readthedocs.io/en/latest/develop_tools/testing.html#running-tests) locally before make a pull request

Closes apache#1807 from cfmcgrady/kyuubi-1806.

Closes apache#1806

c70a594 [Fu Chen] fix

Authored-by: Fu Chen <cfmcgrady@gmail.com>
Signed-off-by: Kent Yao <yao@apache.org>
(cherry picked from commit 5bc7ea1)
beryllw pushed a commit to beryllw/incubator-kyuubi that referenced this pull request Jan 11, 2024
… 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>
(cherry picked from commit 31ba97f)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

The LaunchEngine may be closed multiple times
5 participants