search

cloudflare / pingora

A library for building fast, reliable and evolvable network services.
Apache License 2.0
20.25k stars 1.1k forks source link

ProxyHttp response_body_filter end_of_stream always false #220

Closed zhangyangyang3 closed 1 month ago

zhangyangyang3 commented 2 months ago

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 commented 2 months ago

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 commented 2 months ago

What do debug level logs show?

zhangyangyang3 commented 2 months ago

What do debug level logs show?

some of log like this

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

and some like

[2024-04-23T08:29:02Z DEBUG im_gateway::route] response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:02Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:02Z DEBUG im_gateway::route] response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:02Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:02Z DEBUG im_gateway::route] response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:02Z DEBUG im_gateway::route] read body len:7818
[2024-04-23T08:29:02Z DEBUG im_gateway::route] response_body_filter path:/chat/groupInfo/listMemberInGroup, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:02Z DEBUG im_gateway::route] read body len:374
[2024-04-23T08:29:02Z DEBUG pingora_core::protocols::http::v1::client] Response body: 3904 bytes
[2024-04-23T08:29:02Z DEBUG pingora_core::protocols::http::v1::client] Response is done
[2024-04-23T08:29:02Z DEBUG pingora_proxy::proxy_h1] 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

[2024-04-23T08:29:33Z DEBUG im_gateway::route] 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")}) }
[2024-04-23T08:29:33Z DEBUG im_gateway::route] 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")}) }
[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:3914
[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:4278
[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:33Z DEBUG pingora_core::protocols::http::v1::client] Response body: 8192 bytes
[2024-04-23T08:29:33Z DEBUG pingora_core::protocols::http::v1::client] Response body: 8192 bytes
[2024-04-23T08:29:33Z DEBUG pingora_core::protocols::http::v1::client] Response body: 1282 bytes
[2024-04-23T08:29:33Z DEBUG pingora_proxy::proxy_h1] upstream event: Some(Body(Some(b"PfBRSTEH57d1cOsp6GHhEaS5Kq7jE34odfzTnRD6F41FcxJOsXf2EvlwWJBFFRAPkgCUuimLRyC2w3T2o83G44h934iHbPHz8x+Nv/UKruD+S4tApSER/OnTq24OOnx85+fWBIx8/8vCmNTOskZF/Gxsb8BDGlZWlCfVgUW7m0uLqhmXDbFoBUFdW1jo6Nb4xysjU8ScRMsezPznfvguq29I0GgzuN4nwGUjLvFROVXRlZeinC95HTn7c1lw/
zhangyangyang3 commented 2 months ago

What do debug level logs show?

[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:33Z DEBUG im_gateway::route] response_body_filter path:/member/captcha/getCaptcha, is json:true, lang:en-US， end_of_stream:false
[2024-04-23T08:29:33Z DEBUG im_gateway::route] read body len:8192
[2024-04-23T08:29:33Z DEBUG pingora_core::protocols::http::v1::client] Response body: 2410 bytes
[2024-04-23T08:29:33Z DEBUG pingora_core::protocols::http::v1::client] Response is done
[2024-04-23T08:29:33Z DEBUG pingora_proxy::proxy_h1] 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".

andrewhavck commented 2 months ago

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

andrewhavck commented 1 month ago

This should be fixed with our latest release.