bug: open_dal block when first read result table

[youngsofun]

Summary

reproduce:

1. start a standalone server with minio.

2. execute select 1

➜  ~ curl  --header 'Content-Type: application/json'  --request POST '127.0.0.1:8000/v1/query/'  --data-raw '{"sql": "select 1"}' -u root:
{"id":"7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40","session_id":"ffb684d5-705a-4b2c-b14d-abfbd9817ba4","session":null,"schema":{"fields":[{"name":"1","default_expr":null,"data_type":{"type":"UInt8"}}],"metadata":{}},"data":[[1]],"state":"Succeeded","error":null,"stats":{"scan_progress":{"rows":1,"bytes":1},"write_progress":{"rows":0,"bytes":0},"result_progress":{"rows":0,"bytes":0},"running_time_ms":111.567375},"affect":null,"stats_uri":"/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40","final_uri":"/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/final","next_uri":null,"kill_uri":"/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/kill"}%
➜  ~ curl -u root: 127.0.0.1:8000/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/download
^C
➜  ~ curl -u root: 127.0.0.1:8000/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/download
1

the second curl will hang there.
kill the curl, rerun, it may succeed(the last curl).

restart server

➜  ~ curl -u root: 127.0.0.1:8000/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/download
^C
➜  ~ curl -u root: 127.0.0.1:8000/v1/query/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/download
1

---

log shows it is block here o.range_reader(offset..offset + length).await? https://github.com/datafuselabs/databend/blob/main/src/query/storages/fuse/src/io/read/block_reader.rs#L354

---

download is handled by fn result_download_handler

the path is something like testbucket/admin/_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/part-9499b67c5241409199635bef81895d1e_v0.parquet

[youngsofun]

@Xuanwo may need you help

[youngsofun]

@ariesdevil Will it have something to do with the refactor of operator usage you just done?

[Xuanwo]

It's an existing issue inside the hyper connection reuse logic: The first query to ResultTableSource will always hang.

Related issue: apache/opendal#473

The root cause needs investigation. I will work on this.

[youngsofun]

read to JSON succeed.

2022-10-15T02:38:06.945354Z DEBUG read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json offset=Some(0) size=None -> got reader    
2022-10-15T02:38:06.945750Z TRACE read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}:poll_read{size=8192}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json has_read=890 -> read: 890B    
2022-10-15T02:38:06.945907Z TRACE read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}:poll_read{size=8192}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json has_read=890 -> read: 0B    
2022-10-15T02:38:06.949739Z DEBUG read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json offset=Some(0) size=None -> started    
2022-10-15T02:38:06.963176Z DEBUG read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json offset=Some(0) size=None -> got reader    
2022-10-15T02:38:06.963479Z TRACE read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}:poll_read{size=8192}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json has_read=890 -> read: 890B    
2022-10-15T02:38:06.963607Z TRACE read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json" args=OpRead { offset: Some(0), size: None }}:poll_read{size=8192}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/meta_v1.json has_read=890 -> read: 0B    
...

2022-10-15T02:38:06.971769Z DEBUG read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/part-9499b67c5241409199635bef81895d1e_v0.parquet" args=OpRead { offset: Some(4), size: Some(27) }}: opendal::services: service=s3 operation=read path=_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/part-9499b67c5241409199635bef81895d1e_v0.parquet offset=Some(4) size=Some(27) -> started 

2022-10-15T02:52:49.485691Z TRACE read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/part-9499b67c5241409199635bef81895d1e_v0.parquet" args=OpRead { offset: Some(4), size: Some(27) }}: hyper::client::pool: take? ("http", 127.0.0.1:9900): expiration = Some(90s)
2022-10-15T02:52:49.485734Z DEBUG read{path="_res/7aa8ee5d-5047-467a-aa7a-7cf4a04c3a40/_t/part-9499b67c5241409199635bef81895d1e_v0.parquet" args=OpRead { offset: Some(4), size: Some(27) }}: hyper::client::pool: reuse idle connection for ("http", 127.0.0.1:9900)


2022-10-15T02:53:08.087946Z TRACE hyper::proto::h2: send body chunk: 22 bytes, eos=false
2022-10-15T02:53:08.088135Z TRACE hyper::proto::h2: send body eos
2022-10-15T02:53:08.090925Z TRACE hyper::proto::h2: send body chunk: 175 bytes, eos=false
2022-10-15T02:53:08.091096Z TRACE hyper::proto::h2: send body eos

2022-10-15T02:53:29.536501Z TRACE hyper::proto::h2: send body chunk: 22 bytes, eos=false
2022-10-15T02:53:29.536950Z TRACE hyper::proto::h2: send body eos
2022-10-15T02:53:29.543263Z TRACE hyper::proto::h2: send body chunk: 175 bytes, eos=false
2022-10-15T02:53:29.543537Z TRACE hyper::proto::h2: send body eos

2022-10-15T02:53:29.536501Z TRACE hyper::proto::h2: send body chunk: 22 bytes, eos=false
2022-10-15T02:53:29.536950Z TRACE hyper::proto::h2: send body eos
2022-10-15T02:53:29.543263Z TRACE hyper::proto::h2: send body chunk: 175 bytes, eos=false
2022-10-15T02:53:29.543537Z TRACE hyper::proto::h2: send body eos

[ariesdevil]

@ariesdevil Will it have something to do with the refactor of operator usage you just done?

ResultTableSource still uses the old query ctx operator, So I think that does not relate to the refactoring.