apache / apache/kyuubi

[Bug] OperationLog is closed before fetching result is completed.

Open
#5,661 4 comments 0 reactions 0 assignees View on GitHub
kind:bug priority:major
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.