[Bug] OperationLog is closed before fetching result is completed.
- Dominant language
- Scala
- Stars
- 2.4k
- Forks
- 1k
- PR merge metrics
- No merged PRs in 30d
Description
### Code of Conduct
- [X] I agree to follow this project's [Code of Conduct](https://www.apache.org/foundation/policies/conduct)
### Search before asking
- [X] I have searched in the [issues](https://github.com/apache/kyuubi/issues?q=is%3Aissue) and found no similar issues.
### Describe the bug
OperationLog is closed before fetching result is completed.
```java
content: 2023-11-09 18:05:00.305 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing 138502236's query[b899c336-34bb-409a-bd74-f48b6f48e9f0]: RUNNING_STATE -> FINISHED_STATE, time taken: 2.134 seconds
content: 2023-11-09 18:05:00.315 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing 138502236's query[b899c336-34bb-409a-bd74-f48b6f48e9f0]: FINISHED_STATE -> CLOSED_STATE, time taken: 2.144 seconds
content: 2023-11-09 18:05:00.318 INFO org.apache.kyuubi.client.KyuubiSyncThriftClient: TCloseOperationReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:1D 28 8D D7 04 B6 43 19 A0 64 1D 8E 9A E0 0A 7C, secret:C2 EE 5B 97 3E A0 41 FC AC 16 9B D7 08 ED 8F 38), operationType:EXECUTE_STATEMENT, hasResultSet:true)) succeed on engine side
content: 2023-11-09 18:05:00.318 INFO org.apache.kyuubi.operation.log.OperationLog: Entry operationLog close.
content: 2023-11-09 18:05:00.318 INFO org.apache.kyuubi.operation.log.OperationLog: Delete operationLog path=/opt/kyuubi/work/server_operation_logs/b99c4569-bf6f-49e0-8eb7-b5ea86d1d623/b899c336-34bb-409a-bd74-f48b6f48e9f0
content: 2023-11-09 18:05:00.320 ERROR org.apache.kyuubi.server.KyuubiTBinaryFrontendService: Error fetching results:
content: org.apache.kyuubi.KyuubiSQLException: Invalid OperationHandle [b899c336-34bb-409a-bd74-f48b6f48e9f0]
content: at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69) ~[kyuubi-common_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.operation.OperationManager.getOperation(OperationManager.scala:103) ~[kyuubi-common_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.service.AbstractBackendService.fetchResults(AbstractBackendService.scala:205) ~[kyuubi-common_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.server.KyuubiServer$$anon$1.org$apache$kyuubi$server$BackendServiceMetric$$super$fetchResults(KyuubiServer.scala:147) ~[kyuubi-server_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.server.BackendServiceMetric.$anonfun$fetchResults$1(BackendServiceMetric.scala:188) ~[kyuubi-server_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.metrics.MetricsSystem$.timerTracing(MetricsSystem.scala:111) ~[kyuubi-metrics_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.server.BackendServiceMetric.fetchResults(BackendServiceMetric.scala:187) ~[kyuubi-server_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.server.BackendServiceMetric.fetchResults$(BackendServiceMetric.scala:182) ~[kyuubi-server_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.server.KyuubiServer$$anon$1.fetchResults(KyuubiServer.scala:147) ~[kyuubi-server_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.kyuubi.service.TFrontendService.FetchResults(TFrontendService.scala:530) ~[kyuubi-common_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.hive.service.rpc.thrift.TCLIService$Processor$FetchResults.getResult(TCLIService.java:1837) ~[hive-service-rpc-3.1.3.jar:3.1.3]
content: at org.apache.hive.service.rpc.thrift.TCLIService$Processor$FetchResults.getResult(TCLIService.java:1822) ~[hive-service-rpc-3.1.3.jar:3.1.3]
content: at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39) ~[libthrift-0.9.3.jar:0.9.3]
content: at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39) ~[libthrift-0.9.3.jar:0.9.3]
content: at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36) ~[kyuubi-common_2.12-1.7.1-SNAPSHOT.jar:1.7.1-SNAPSHOT]
content: at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286) ~[libthrift-0.9.3.jar:0.9.3]
content: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_362]
content: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_362]
content: at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_362]
```
### Affects Version(s)
branch-1.7
### Kyuubi Server Log Output
_No response_
### Kyuubi Engine Log Output
_No response_
### Kyuubi Server Configurations
_No response_
### Kyuubi Engine Configurations
_No response_
### Additional context
_No response_
### Are you willing to submit PR?
- [ ] Yes. I would be willing to submit a PR with guidance from the Kyuubi community to fix.
- [ ] No. I cannot submit a PR at this time.
Contributor guide
Research direction
Start by tracing the fetchResults path in AbstractBackendService.scala:205 and TFrontendService.scala:530, then inspect OperationManager.scala:103 and the OperationLog closure shown in the report. Reproduce the logged sequence and determine why the operation is removed before fetching finishes; done means fetching the result no longer fails with Invalid OperationHandle.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- scala
- Domain
- api, backend
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100