h2
h2 copied to clipboard
Published
20 hours ago •
hyperium
hyperium
manany request is pending
https://github.com/hyperium/hyper/issues/2503
This problem is happening again in our environment. The captured packets show that H2 header information has been quickly returned. The browser is waiting for the body to be downloaded, but the body part cannot be decrypted.
The response body is actually only a few dozen bytes, but when something goes wrong, a large number of requests are pending and then suddenly recover after a long time. When the h2 request is pending, the h1 request is not pending.
Does this question have anything to do with this https://github.com/hyperium/hyper/issues/2419
Problematic Chrome Event Log
1220: URL_REQUEST
https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459
Start Time: 2021-11-01 16:47:15.733
t= 0 [st= 0] +REQUEST_ALIVE [dt=123009]
--> has_upload = false
--> is_pending = true
--> load_flags = 16386 (BYPASS_CACHE | SUPPORT_ASYNC_REVALIDATION)
--> load_state = 15 (READING_RESPONSE)
--> method = "GET"
--> net_error = -1 (ERR_IO_PENDING)
--> network_isolation_key = "https://192.7.14.2 https://192.7.14.2"
--> traffic_annotation = 101845102
--> url = "https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459"
t=122985 [st=122985] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = -1
--> stream_id = 343
--> window_size = 6291455
t=122986 [st=122986] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = 1
--> stream_id = 343
--> window_size = 6291456
t=122986 [st=122986] -HTTP_TRANSACTION_READ_BODY
t=122986 [st=122986] URL_REQUEST_JOB_FILTERED_BYTES_READ
--> byte_count = 1
t=122986 [st=122986] +HTTP_TRANSACTION_READ_BODY [dt=23]
t=123009 [st=123009] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = -91
--> stream_id = 343
--> window_size = 6291365
t=123009 [st=123009] -HTTP_TRANSACTION_READ_BODY
t=123009 [st=123009] URL_REQUEST_JOB_FILTERED_BYTES_READ
--> byte_count = 91
t=123009 [st=123009] HTTP_TRANSACTION_READ_BODY [dt=0]
t=123009 [st=123009] -REQUEST_ALIVE
1373: URL_REQUEST
https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459
Start Time: 2021-11-01 16:48:11.383
t= 55650 [st= 0] +REQUEST_ALIVE [dt=67410]
--> priority = "MEDIUM"
--> traffic_annotation = 101845102
--> url = "https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459"
t= 55650 [st= 0] NETWORK_DELEGATE_BEFORE_URL_REQUEST [dt=0]
t= 55650 [st= 0] +URL_REQUEST_START_JOB [dt=313]
--> initiator = "https://192.7.14.2:3149"
--> load_flags = 16386 (BYPASS_CACHE | SUPPORT_ASYNC_REVALIDATION)
--> method = "GET"
--> network_isolation_key = "https://192.7.14.2:3149 https://192.7.14.2:3149"
--> privacy_mode = "disabled"
--> request_type = "other"
--> site_for_cookies = "SiteForCookies: {site=https://192.7.14.2:3149; schemefully_same=true}"
--> url = "https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55650 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55651 [st= 1] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t= 55651 [st= 1] NETWORK_DELEGATE_BEFORE_START_TRANSACTION [dt=7]
t= 55658 [st= 8] HTTP_CACHE_GET_BACKEND [dt=0]
t= 55658 [st= 8] HTTP_CACHE_DOOM_ENTRY [dt=1]
--> net_error = -2 (ERR_FAILED)
t= 55659 [st= 9] HTTP_CACHE_CREATE_ENTRY [dt=1]
t= 55660 [st= 10] HTTP_CACHE_ADD_TO_ENTRY [dt=0]
t= 55660 [st= 10] +HTTP_STREAM_REQUEST [dt=0]
t= 55660 [st= 10] HTTP_STREAM_JOB_CONTROLLER_BOUND
--> source_dependency = 1375 (HTTP_STREAM_JOB_CONTROLLER)
t= 55660 [st= 10] HTTP_STREAM_REQUEST_BOUND_TO_JOB
--> source_dependency = 1376 (HTTP_STREAM_JOB)
t= 55660 [st= 10] -HTTP_STREAM_REQUEST
t= 55660 [st= 10] +HTTP_TRANSACTION_SEND_REQUEST [dt=1]
t= 55661 [st= 11] HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
--> :method: GET
:authority: 192.7.14.2:3149
:scheme: https
:path: /rest/v1/fids?ns=1613954997-405187-167778715-167772459
pragma: no-cache
cache-control: no-cache
sec-ch-ua: "Google Chrome";v="95", "Chromium";v="95", ";Not A Brand";v="99"
accept: */*
x-requested-with: XMLHttpRequest
sec-ch-ua-mobile: ?0
user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.54 Safari/537.36
sec-ch-ua-platform: "Windows"
sec-fetch-site: same-origin
sec-fetch-mode: cors
sec-fetch-dest: empty
referer: https://192.7.14.2:3149/n11
accept-encoding: gzip, deflate, br
accept-language: zh-CN,zh;q=0.9,en;q=0.8
cookie: [326 bytes were stripped]
t= 55661 [st= 11] -HTTP_TRANSACTION_SEND_REQUEST
t= 55661 [st= 11] +HTTP_TRANSACTION_READ_HEADERS [dt=300]
t= 55961 [st= 311] HTTP_TRANSACTION_READ_RESPONSE_HEADERS
--> HTTP/1.1 200
expires: Thu, 01 Jan 1970 00:00:00 GMT
pragma: no-cache
cache-control: no-cache, no-store, max-age=0
x-trace-enable: false
x-xss-protection: 1; mode=block
x-content-type-options: nosniff
x-frame-options: SAMEORIGIN
x-download-options: noopen
x-content-security-policy: default-src 'self'
content-security-policy: default-src 'self'
strict-transport-security: max-age=31536000 ; includeSubDomains
content-type: application/json;charset=UTF-8
content-length: 92
date: Mon, 01 Nov 2021 08:48:12 GMT
server: product only
t= 55961 [st= 311] -HTTP_TRANSACTION_READ_HEADERS
t= 55961 [st= 311] HTTP_CACHE_WRITE_INFO [dt=0]
t= 55961 [st= 311] NETWORK_DELEGATE_HEADERS_RECEIVED [dt=2]
t= 55963 [st= 313] -URL_REQUEST_START_JOB
t= 55963 [st= 313] URL_REQUEST_DELEGATE_RESPONSE_STARTED [dt=0]
t= 55963 [st= 313] +HTTP_TRANSACTION_READ_BODY [dt=67060]
t=123022 [st=67372] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = -1
--> stream_id = 369
--> window_size = 6291455
t=123023 [st=67373] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = 1
--> stream_id = 369
--> window_size = 6291456
t=123023 [st=67373] -HTTP_TRANSACTION_READ_BODY
t=123023 [st=67373] URL_REQUEST_JOB_FILTERED_BYTES_READ
--> byte_count = 1
t=123023 [st=67373] +HTTP_TRANSACTION_READ_BODY [dt=37]
t=123060 [st=67410] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = -91
--> stream_id = 369
--> window_size = 6291365
t=123060 [st=67410] -HTTP_TRANSACTION_READ_BODY
t=123060 [st=67410] URL_REQUEST_JOB_FILTERED_BYTES_READ
--> byte_count = 91
t=123060 [st=67410] HTTP_TRANSACTION_READ_BODY [dt=0]
t=123060 [st=67410] -REQUEST_ALIVE
Normal Chrome Event Log
8076: URL_REQUEST
https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459
Start Time: 2021-11-01 16:53:25.737
t=370004 [st= 0] +REQUEST_ALIVE [dt=324]
--> priority = "MEDIUM"
--> traffic_annotation = 101845102
--> url = "https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459"
t=370004 [st= 0] NETWORK_DELEGATE_BEFORE_URL_REQUEST [dt=0]
t=370004 [st= 0] +URL_REQUEST_START_JOB [dt=323]
--> initiator = "https://192.7.14.2:3149"
--> load_flags = 16386 (BYPASS_CACHE | SUPPORT_ASYNC_REVALIDATION)
--> method = "GET"
--> network_isolation_key = "https://192.7.14.2 https://192.7.14.2"
--> privacy_mode = "disabled"
--> request_type = "other"
--> site_for_cookies = "SiteForCookies: {site=https://192.7.14.2; schemefully_same=true}"
--> url = "https://192.7.14.2:3149/rest/v1/fids?ns=1613954997-405187-167778715-167772459"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "EXCLUDE_NOT_ON_PATH, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] COOKIE_INCLUSION_STATUS
--> operation = "send"
--> status = "INCLUDE, DO_NOT_WARN"
t=370004 [st= 0] NETWORK_DELEGATE_BEFORE_START_TRANSACTION [dt=18]
t=370022 [st= 18] HTTP_CACHE_GET_BACKEND [dt=0]
t=370022 [st= 18] HTTP_CACHE_DOOM_ENTRY [dt=0]
--> net_error = -2 (ERR_FAILED)
t=370022 [st= 18] HTTP_CACHE_CREATE_ENTRY [dt=0]
t=370022 [st= 18] HTTP_CACHE_ADD_TO_ENTRY [dt=1]
t=370023 [st= 19] +HTTP_STREAM_REQUEST [dt=0]
t=370023 [st= 19] HTTP_STREAM_JOB_CONTROLLER_BOUND
--> source_dependency = 8078 (HTTP_STREAM_JOB_CONTROLLER)
t=370023 [st= 19] HTTP_STREAM_REQUEST_BOUND_TO_JOB
--> source_dependency = 8079 (HTTP_STREAM_JOB)
t=370023 [st= 19] -HTTP_STREAM_REQUEST
t=370023 [st= 19] +HTTP_TRANSACTION_SEND_REQUEST [dt=0]
t=370023 [st= 19] HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
--> :method: GET
:authority: 192.7.14.2:3149
:scheme: https
:path: /rest/v1/fids?ns=1613954997-405187-167778715-167772459
pragma: no-cache
cache-control: no-cache
sec-ch-ua: "Google Chrome";v="95", "Chromium";v="95", ";Not A Brand";v="99"
accept: */*
x-requested-with: XMLHttpRequest
sec-ch-ua-mobile: ?0
user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.54 Safari/537.36
sec-ch-ua-platform: "Windows"
sec-fetch-site: same-origin
sec-fetch-mode: cors
sec-fetch-dest: empty
referer: https://192.7.14.2:3149/n11
accept-encoding: gzip, deflate, br
accept-language: zh-CN,zh;q=0.9,en;q=0.8
cookie: [371 bytes were stripped]
t=370023 [st= 19] -HTTP_TRANSACTION_SEND_REQUEST
t=370023 [st= 19] +HTTP_TRANSACTION_READ_HEADERS [dt=303]
t=370326 [st=322] HTTP_TRANSACTION_READ_RESPONSE_HEADERS
--> HTTP/1.1 200
expires: Thu, 01 Jan 1970 00:00:00 GMT
pragma: no-cache
cache-control: no-cache, no-store, max-age=0
x-trace-enable: false
x-xss-protection: 1; mode=block
x-content-type-options: nosniff
x-frame-options: SAMEORIGIN
x-download-options: noopen
x-content-security-policy: default-src 'self'
content-security-policy: default-src 'self'
strict-transport-security: max-age=31536000 ; includeSubDomains
content-type: application/json;charset=UTF-8
content-length: 92
date: Mon, 01 Nov 2021 08:53:26 GMT
server: product only
t=370326 [st=322] -HTTP_TRANSACTION_READ_HEADERS
t=370326 [st=322] HTTP_CACHE_WRITE_INFO [dt=0]
t=370326 [st=322] +NETWORK_DELEGATE_HEADERS_RECEIVED [dt=1]
t=370327 [st=323] HTTP2_STREAM_UPDATE_RECV_WINDOW
--> delta = -92
--> stream_id = 2729
--> window_size = 6291364
t=370327 [st=323] -NETWORK_DELEGATE_HEADERS_RECEIVED
t=370327 [st=323] -URL_REQUEST_START_JOB
t=370327 [st=323] URL_REQUEST_DELEGATE_RESPONSE_STARTED [dt=1]
t=370328 [st=324] HTTP_TRANSACTION_READ_BODY [dt=0]
t=370328 [st=324] URL_REQUEST_JOB_FILTERED_BYTES_READ
--> byte_count = 92
t=370328 [st=324] HTTP_TRANSACTION_READ_BODY [dt=0]
t=370328 [st=324] -REQUEST_ALIVE
If initial_connection_window_size is smaller than initial_window_size, will packets on a flow occupy the connection for a long time and requests on other flows can only wait?
https://github.com/hyperium/hyper/issues/2503#issuecomment-958688033
That's an interesting theory, could be! Care to try it out on a smaller example with different window sizes?
According to the test result, the value of initial_connection_window_size / initial_window_size is the number of slow streams that can be supported. If the number of slow streams exceeds the value, requests on other flows are pending.
@seanmonstar For a very simple test case, start two hypers, set up connections between the browser and the first hyper, and set up an H2 connection between the first hyper and the second hyper. According to the following configuration, when the browser downloads two large-response requests to the first hyper at the same time by speed limiting, Any other request will be pending.
let _ = hyper::server::Server::builder(incoming)
.serve(hyper::service::make_service_fn(move |_| async move {
hyper::Result::Ok(service_fn(move |req: Request<Body>| async {
let path = req.uri().path().to_owned();
let time = Instant::now();
let version = req.version();
match handle_req(req).await {
Ok(resp) => {
println!("{:?} {} {} {}", version, path, resp.status(), time.elapsed().as_millis());
Ok(resp)
}
Err(e) => {
println!("{} {} {}", path, e, time.elapsed().as_millis());
Err(e)
}
}
}))
}))
.await;
pub async fn handle_req(req: Request<Body>) -> Result<Response<Body>> {
// Forwards the request to the second hyper.
let response = gctx().request(req).await?;
Ok(response)
}
pub fn get_client() -> Client<HttpConnector> {
let tls = get_tls_connector();
let proxy_target = Some("127.0.0.1:9999".parse().unwrap());
// The number of slow requests that can be supported is (http2_initial_connection_window_size/http2_initial_stream_window_size)
Client::builder()
.http2_initial_connection_window_size(1024 * 1024 * 5)
.http2_initial_stream_window_size(1024 * 1024 * 2)
.build(HttpConnector::new(Arc::new(tls), proxy_target))
}