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

ProxyHttp response_body_filter end_of_stream always false #220

Closed
zhangyangyang3 opened this issue Apr 23, 2024 · 6 comments
Closed

ProxyHttp response_body_filter end_of_stream always false #220

zhangyangyang3 opened this issue Apr 23, 2024 · 6 comments
Assignees
@andrewhavck
Labels
Accepted This change is accepted by us and merged to our internal repo bug Something isn't working

Comments

@zhangyangyang3
Copy link

Describe the bug

ProxyHttp response_body_filter end_of_stream always false

Pingora info

Please include the following information about your environment:

Pingora version: 0.1.1
Rust version: 1.76.0
Operating system version: (debian:12)

Steps to reproduce

 fn response_body_filter(
        &self,
        session: &mut Session,
        body: &mut Option<Bytes>,
        end_of_stream: bool,
        ctx: &mut Self::CTX,
    ) -> pingora::Result<Option<std::time::Duration>>
        where
            Self::CTX: Send + Sync,
    {
        debug!("response_body_filter path:{:?}, is json:{}, lang:{}， end_of_stream:{}", session.req_header().uri, ctx.is_json, ctx.lang, end_of_stream);
        if !ctx.is_json {
            return Ok(None);
        }
        if ctx.lang == "" {
            return Ok(None);
        }

        if let Some(b) = body {
            let len = b.len();
            debug!("read body len:{}", len);
            ctx.buffer.extend(&b[..]);
            // drop the body
            b.clear();
        }

        if end_of_stream {
            let data = ctx.buffer.as_slice();
            let json = serde_json::from_slice::<JsonResult>(data);
            debug!("before i18n:{:?}", json);
            match json {
                Ok(json ) => {
                    let ret_json: String = self.convert_json(json, ctx.lang.as_str());
                    debug!("after i18n:{:?}", ret_json.as_str());
                    let bytes = ret_json.as_bytes();
                    *body = Some(Bytes::copy_from_slice(bytes));
                }
                Err(err) => {
                    warn!("convert failee,data:{}, error:{}", "", err);
                }
            }
        }
        Ok(None)
    }

Expected results

end_of_stream is always false, so the client no response body

Observed results

end_of_stream is always false.

Additional context

pub struct MyCtx {
    is_json: bool,
    buffer: Vec<u8>,
    lang: String,
}
@zhangyangyang3
Copy link
Author

it's problem may be in
pingroa_core/protocols/http/v1/clients.rs

    pub async fn read_response_task(&mut self) -> Result<HttpTask> {
        if self.should_read_resp_header() {
            let resp_header = self.read_resp_header_parts().await?;
            let end_of_body = self.is_body_done();
            debug!("Response header: {:?}", resp_header);
            trace!(
                "Raw Response header: {:?}",
                str::from_utf8(self.get_headers_raw()).unwrap()
            );
            Ok(HttpTask::Header(resp_header, end_of_body))
        } else if self.is_body_done() {
            debug!("Response is done");
            Ok(HttpTask::Done)
        } else {
            /* need to read body */
            let data = self.read_body_bytes().await?;
            let end_of_body = self.is_body_done();
            if let Some(body) = data {
                debug!("Response body: {} bytes", body.len());
                trace!("Response body: {:?}", body);
                Ok(HttpTask::Body(Some(body), end_of_body))
            } else {
                debug!("Response is done");
                Ok(HttpTask::Done)
            }
        }
        // TODO: support h1 trailer
    }

@andrewhavck
Copy link
Contributor

What do debug level logs show?

@zhangyangyang3
Copy link
Author

What do debug level logs show?

some of log like this

�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:7946
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:246
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 8192 bytes
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 8192 bytes
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 8192 bytes
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 8192 bytes

and some like

�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:7818
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:374
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 3904 bytes
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response is done
�[90m[�[0m2024-04-23T08:29:02Z �[34mDEBUG�[0m pingora_proxy::proxy_h1�[90m]�[0m upstream event: Some(Body(Some(b"pId\":\"3527277127756300288\",\"nickname\":null,\"memberStatus\":\"NORMAL\",\"swId\":null,\"updateTime\":1679644151000,\"id\":\"3527277127756300295\",\"messageNotice\":\"Y\",\"memberId\":\"3420562652330008576\"},\"allowSpeak\":\"Y\",\"hideMessage\":\"N\ .....

or

�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response header before change: ResponseHeader { base: Parts { status: 200, version: HTTP/1.1, headers: {"content-type": "application/json;charset=UTF-8", "transfer-encoding": "chunked", "date": "Tue, 23 Apr 2024 08:29:33 GMT", "keep-alive": "timeout=60", "connection": "keep-alive"} }, header_name_map: Some({"content-type": CaseHeaderName(b"Content-Type"), "transfer-encoding": CaseHeaderName(b"Transfer-Encoding"), "date": CaseHeaderName(b"Date"), "keep-alive": CaseHeaderName(b"Keep-Alive"), "connection": CaseHeaderName(b"Connection")}) }
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response header after change: ResponseHeader { base: Parts { status: 200, version: HTTP/1.1, headers: {"content-type": "application/json;charset=UTF-8", "transfer-encoding": "Chunked", "date": "Tue, 23 Apr 2024 08:29:33 GMT", "keep-alive": "timeout=60", "connection": "keep-alive"} }, header_name_map: Some({"content-type": CaseHeaderName(b"Content-Type"), "transfer-encoding": CaseHeaderName(b"Transfer-Encoding"), "date": CaseHeaderName(b"Date"), "keep-alive": CaseHeaderName(b"Keep-Alive"), "connection": CaseHeaderName(b"Connection")}) }
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:3914
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:4278
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 8192 bytes
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 8192 bytes
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 1282 bytes
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_proxy::proxy_h1�[90m]�[0m upstream event: Some(Body(Some(b"PfBRSTEH57d1cOsp6GHhEaS5Kq7jE34odfzTnRD6F41FcxJOsXf2EvlwWJBFFRAPkgCUuimLRyC2w3T2o83G44h934iHbPHz8x+Nv/UKruD+S4tApSER/OnTq24OOnx85+fWBIx8/8vCmNTOskZF/Gxsb8BDGlZWlCfVgUW7m0uLqhmXDbFoBUFdW1jo6Nb4xysjU8ScRMsezPznfvguq29I0GgzuN4nwGUjLvFROVXRlZeinC95HTn7c1lw/

@zhangyangyang3
Copy link
Author

What do debug level logs show?

�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m im_gateway::route�[90m]�[0m read body len:8192
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response body: 2410 bytes
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_core::protocols::http::v1::client�[90m]�[0m Response is done
�[90m[�[0m2024-04-23T08:29:33Z �[34mDEBUG�[0m pingora_proxy::proxy_h1�[90m]�[0m upstream event: Some(Body(Some(b"nu3/x44tfYO30AeacMBVEzbpI6XNcLoOUMlXHCPMZBLRkmNky7qfIJwtWMb/lKRShfmIV5/W3d2kK4RPqAcSF3ZQh83hdTG57JRQR1WiswKdOZYFTp0+tU6sMfWq9TKZVK4zaflt1TWNkVGhRbsbvfvnLf/7nf27t7AuNvhEZjVtZSkMjmDqhL2WihF1+ZDW5bjv4km2LxKi4BP6L7jNWubVpxCdDlNNSfJxSR5RYYqEpA9Xz3XP9gAQwkckE0KPSiCh7T2z69TyZu4J4F6m9bVd6a6Gx4Z41M/D82dviknFWKMWp9uxbbIAD21OQuzb5+lLbPSAqYKjQGAQwnEBs1p2qssqessouoLSkvCOvqM5usa2ubHV2a3t6dQrVQF1dV3md4sbt/

It print " Response is done" but end_of_stream field still false. I notice that the down stream do not reuturn Content-Type. but return "transfer-encoding".

@johnhurt johnhurt added the bug Something isn't working label Apr 26, 2024
@andrewhavck
Copy link
Contributor

I think the issue here is we don't set end_of_stream when the task is HttpTask::Done.

@andrewhavck andrewhavck added WIP We are working on this feature internally Accepted This change is accepted by us and merged to our internal repo and removed WIP We are working on this feature internally labels May 1, 2024
@andrewhavck
Copy link
Contributor

This should be fixed with our latest release.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@andrewhavck andrewhavck

Labels
Accepted This change is accepted by us and merged to our internal repo bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@andrewhavck @johnhurt @zhangyangyang3