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.

Sign up for GitHub

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

Jump to bottom

manany request is pending #573

Open
silence-coding opened this issue Nov 1, 2021 · 8 comments
Open

manany request is pending #573

silence-coding opened this issue Nov 1, 2021 · 8 comments

Comments

@silence-coding
Copy link
Contributor

silence-coding commented Nov 1, 2021 •
edited

hyperium/hyper#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.

image
image
@silence-coding
Copy link
Contributor Author

Does this question have anything to do with this hyperium/hyper#2419

@silence-coding
Copy link
Contributor Author

silence-coding commented Nov 1, 2021 •
edited

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

@silence-coding
Copy link
Contributor Author

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

@silence-coding silence-coding mentioned this issue Nov 1, 2021
Closed
@silence-coding
Copy link
Contributor Author

silence-coding commented Nov 3, 2021 •
edited

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?

hyperium/hyper#2503 (comment)

@seanmonstar
Copy link
Member

That's an interesting theory, could be! Care to try it out on a smaller example with different window sizes?

@silence-coding
Copy link
Contributor Author

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.

@silence-coding
Copy link
Contributor Author

silence-coding commented Nov 5, 2021 •
edited

@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))
}

@silence-coding
Copy link
Contributor Author

How to deal with this issue in the future?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@seanmonstar @silence-coding