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

webscoket proxy always break after about 30s #255

Open zhangyangyang3 opened 1 month ago

zhangyangyang3 commented 1 month ago

Describe the bug

webscoket proxy always break after about 30s

Pingora info

Please include the following information about your environment:

Pingora version: 0.2 Rust version: 1.7.8 Operating system version: docker debian

Steps to reproduce

in upstream_request_filter, response_filter, and response_body_filter if it is ws, just return Ok;

 if session.is_upgrade_req() {
            debug!("upstream_request_filter ws upgrade request");
            return Ok(());
        }

 if session.is_upgrade_req() {
            debug!("response_filter ws upgrade, header:{:?}", upstream_response);
            return Ok(());
        }

if session.is_upgrade_req() {
            debug!("response_body_filter ws upgrade， end_of_stream:{end_of_stream}");
            return Ok(None);
        }

Expected results

not break . but it always break after 30s

Observed results

pingora break the connection with out any log.

What actually happened?

pingora break the connection with out any log.

Additional context

logs: [2024-05-31T02:40:41Z DEBUG im_api_rust_gateway::route] match path:/message-ws, route:PathMapper { path: "/message-ws", proxy_path: "im-message-backend:8888" }, proxy:im-message-backend:8888 [2024-05-31T02:40:41Z DEBUG pingora_core::connectors] No reusable connection found for addr: 10.8.30.98:8888, scheme: HTTP,sni: im-gateway, [2024-05-31T02:40:41Z DEBUG pingora_core::connectors::l4] connected to new server: 10.8.30.98:8888 [2024-05-31T02:40:41Z DEBUG im_api_rust_gateway::route] upstream_request_filter ws upgrade request [2024-05-31T02:40:41Z DEBUG pingora_proxy::proxy_h1] Sending header to upstream RequestHeader { base: Parts { method: GET, uri: /message-ws?token=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.dd.Sfove5prSXN6gpczgzqrRE-TG6MNNN5NPxHaRH9oUFg_PC, version: HTTP/1.1, headers: {"host": "api.xx.xyz", "upgrade": "websocket", "accept-encoding": "gzip, br", "cf-ray": "88c399c55fe76412-LHR", "x-forwarded-proto": "http", "cf-visitor": "{\"scheme\":\"https\"}", "pragma": "no-cache", "cache-control": "no-cache", "user-agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.5359.215 Electron/22.3.27 Safari/537.36", "origin": "file://", "sec-websocket-version": "13", "accept-language": "zh-CN", "sec-websocket-key": "X0/BucmR2d04+CkRMsCJew==", "sec-websocket-extensions": "permessage-deflate; client_max_window_bits", "cf-connecting-ip": "240e:30c:d8a:c00:896f:f9ac:9c93:5bea", "cdn-loop": "cloudflare", "cf-ipcountry": "CN", "x-cloud-trace-context": "63273c657ec3d76d906c839875930daf/11640436728903102546", "connection": "Upgrade", "via": "1.1 google", "x-forwarded-for": "240e:30c:d8a:c00:896f:f9ac:9c93:5bea, 172.69.195.149, 34.49.27.154"} }, header_name_map: Some({"host": CaseHeaderName(b"Host"), "upgrade": CaseHeaderName(b"Upgrade"), "accept-encoding": CaseHeaderName(b"accept-encoding"), "cf-ray": CaseHeaderName(b"CF-RAY"), "x-forwarded-proto": CaseHeaderName(b"X-Forwarded-Proto"), "cf-visitor": CaseHeaderName(b"CF-Visitor"), "pragma": CaseHeaderName(b"Pragma"), "cache-control": CaseHeaderName(b"Cache-Control"), "user-agent": CaseHeaderName(b"Use r-Agent"), "origin": CaseHeaderName(b"Origin"), "sec-websocket-version": CaseHeaderName(b"Sec-WebSocket-Version"), "accept-language": CaseHeaderName(b"Accept-Language"), "sec-websocket-key": CaseHeaderName(b"Sec-WebSocket-Key"), "sec-websocket-extensions": CaseHeaderName(b"Sec-WebSocket-Extensions"), "cf-connecting-ip": CaseHeaderName(b"CF-Connecting-IP"), "cdn-loop": CaseHeaderName(b"CDN-Loop"), "cf-ipcountry": CaseHeaderName(b"CF-IPCountry"), "x-cloud-trace-context": CaseHeaderName(b"X-Cloud-Trace-Context"), "connection": CaseHeaderName(b"Connection"), "via": CaseHeaderName(b"Via"), "x-forwarded-for": CaseHeaderName(b"X-Forwarded-For")}), raw_path_fallback: [] } [2024-05-31T02:40:41Z DEBUG pingora_core::protocols::http::v1::client] Response header: ResponseHeader { base: Parts { status: 101, version: HTTP/1.1, headers: {"content-length": "0", "upgrade": "WebSocket", "connection": "upgrade", "sec-websocket-accept": "3msbQbeXiXEW79j3xtYxwXkvUA0="} }, header_name_map: Some({"content-length": CaseHeaderName(b"content-length"), "upgrade": CaseHeaderName(b"upgrade"), "connection": CaseHeaderName(b"connection"), "sec-websocket-accept": CaseHeaderName(b"sec-websocket-accept")}), reason_phrase: None } [2024-05-31T02:40:41Z DEBUG pingora_proxy::proxy_h1] upstream event: Some(Header(ResponseHeader { base: Parts { status: 101, version: HTTP/1.1, headers: {"content-length": "0", "upgrade": "WebSocket", "connection": "upgrade", "sec-websocket-accept": "3msbQbeXiXEW79j3xtYxwXkvUA0="} }, header_name_map: Some({"content-length": CaseHeaderName(b"content-length"), "upgrade": CaseHeaderName(b"upgrade"), "connection": CaseHeaderName(b"connection"), "sec-websocket-accept": CaseHeaderName(b"sec-websocket-accept")}), reason_phrase: None }, false)) [2024-05-31T02:40:41Z DEBUG im_api_rust_gateway::route] response_filter ws upgrade, header:ResponseHeader { base: Parts { status: 101, version: HTTP/1.1, headers: {"content-length": "0", "upgrade": "WebSocket", "connection": "upgrade", "sec-websocket-accept": "3msbQbeXiXEW79j3xtYxwXkvUA0="} }, header_name_map: Some({"content-length": CaseHeaderName(b"content-length"), "upgrade": CaseHeaderName(b"upgrade"), "connection": CaseHeaderName(b"connection"), "sec-websocket-accept": CaseHeaderName(b"sec-websocket-accept")}), reason_phrase: None } [2024-05-31T02:40:41Z DEBUG pingora_core::protocols::http::v1::server] ok upgrade handshake [2024-05-31T02:40:42Z DEBUG pingora_core::protocols::http::v1::client] Response body: 110 bytes, end: false [2024-05-31T02:40:42Z DEBUG pingora_proxy::proxy_h1] upstream event: Some(Body(Some(b"\x81l7OzTkuTQFvL+dGp7dbsQ67pxwLamUTYAM5cxbGbL4wS+8cff2jd4nPYj0BykLf4WgSHOMVuN0OPTxFsWT8iOZNLJ2Sh2PYU+kInDUQdGp+w="), false)) [2024-05-31T02:40:42Z DEBUG im_api_rust_gateway::route] response_body_filter ws upgrade， end_of_stream:false [2024-05-31T02:40:42Z DEBUG pingora_proxy::proxy_h1] downstream event [2024-05-31T02:40:42Z DEBUG pingora_proxy::proxy_h1] Read 864 bytes body from downstream [2024-05-31T02:40:42Z DEBUG pingora_proxy::proxy_h1] Write 864 bytes body to upstream [2024-05-31T02:40:42Z DEBUG pingora_core::protocols::http::v1::client] Response body: 2224 bytes, end: false [2024-05-31T02:40:42Z DEBUG pingora_proxy::proxy_h1] upstream event: Some(Body(Some(b"\x81~\x08\xac+iUWE3iUPXPDg2Ib72rZvqv3384I8Sc1JNrOMCihYhsXkQK+kU/FGtxl2VFiWRFWVa8d5B2tp5KpahJdBhl8ZKRIugoKg8TS4df0TM+TreLoIY6kfJM2PEdRoSWDiklJKmbUT/I0N/lFFZAVilJZ1wQ9wNCCu53dh7Rdero6qxfYZi4f11i/2yBouNF/DLFARxgPmoU37KPjCl5/G8eJw0SOf8/abG/4BlbLIyNg3Via6UuVaw+rNg84T2BHlyhTnRTvwV9KWnZDPH6AkwZbSS0pn3DPCT9DELu5QLsZVs3U="), false)) [2024-05-31T02:40:42Z DEBUG im_api_rust_gateway::route] response_body_filter ws upgrade， end_of_stream:false [2024-05-31T02:40:47Z DEBUG pingora_core::services::listening] new event! [2024-05-31T02:40:47Z DEBUG pingora_proxy] Successfully get a new request [2024-05-31T02:40:47Z DEBUG im_api_rust_gateway::route] health check [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::http::v1::server] HTTP shutdown connection [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::l4::stream] Dropping socket BufStream { inner: BufReader { reader: BufWriter { writer: Tcp(PollEvented { io: Some(TcpStream { addr: 10.0.3.128:8094, peer: 35.11.20.16:59324, fd: 22 }) }), buffer: 0/1460, written: 0 }, buffer: 0/65536 } } [2024-05-31T02:40:47Z DEBUG pingora_proxy::proxy_h1] downstream event [2024-05-31T02:40:47Z DEBUG pingora_proxy::proxy_h1] Read 864 bytes body from downstream [2024-05-31T02:40:47Z DEBUG pingora_proxy::proxy_h1] Write 864 bytes body to upstream [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::http::v1::client] Response body: 2224 bytes, end: false [2024-05-31T02:40:47Z DEBUG pingora_proxy::proxy_h1] upstream event: Some(Body(Some(b"\x81~\x08\xac+iUWE3iUPXPDg2Ib72rZvqv3384I8Sc1JNrOMCihYhsXkQK+kU/FGtxl2VFiWRFW2opOHBEqrn6CnmG+aJAfj2bsypFYbjvfDEX/ixjm+vYKlTqHlihSHtzhEeo3G0Hhrd3X+pReX+0RygS6QVH2uMmrwa0icKCwbY2Q45NGl5E+KX8ZSJvrxKUk8EA5KlX1e3fM/BX/SPi+l+nz2GHxD0A3U4Ol9oAAQkJ4TjTtiThzis7V8HuVsUM="), false)) [2024-05-31T02:40:47Z DEBUG im_api_rust_gateway::route] response_body_filter ws upgrade， end_of_stream:false [2024-05-31T02:40:47Z DEBUG pingora_core::services::listening] new event! [2024-05-31T02:40:47Z DEBUG pingora_proxy] Successfully get a new request [2024-05-31T02:40:47Z DEBUG im_api_rust_gateway::route] health check [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::http::v1::server] HTTP shutdown connection [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::l4::stream] Dropping socket BufStream { inner: BufReader { reader: BufWriter { writer: Tcp(PollEvented { io: Some(TcpStream { addr: 10.0.3.128:8094, peer: 35.11.24.19:39170, fd: 22 }) }), buffer: 0/1460, written: 0 }, buffer: 0/65536 } } [2024-05-31T02:40:47Z DEBUG pingora_core::services::listening] new event! [2024-05-31T02:40:47Z DEBUG pingora_proxy] Successfully get a new request [2024-05-31T02:40:47Z DEBUG im_api_rust_gateway::route] health check [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::http::v1::server] HTTP shutdown connection [2024-05-31T02:40:47Z DEBUG pingora_core::protocols::l4::stream] Dropping socket BufStream { inner: BufReader { reader: BufWriter { writer: Tcp(PollEvented { io: Some(TcpStream { addr: 10.0.3.128:8094, peer: 35.1.24.14:41010, fd: 22 }) }), buffer: 0/1460, written: 0 }, buffer: 0/65536 } } [2024-05-31T02:40:50Z DEBUG pingora_core::services::listening] new event! [2024-05-31T02:40:50Z DEBUG pingora_proxy] Successfully get a new request [2024-05-31T02:40:50Z DEBUG im_api_rust_gateway::route] health check [2024-05-31T02:40:50Z DEBUG pingora_core::protocols::http::v1::server] HTTP shutdown connection [2024-05-31T02:40:50Z DEBUG pingora_core::protocols::l4::stream] Dropping socket BufStream { inner: BufReader { reader: BufWriter { writer: Tcp(PollEvented { io: Some(TcpStream { addr: 10.0.3.128:8094, peer: 10.0.3.1:51264, fd: 22 }) }), buffer: 0/1460, written: 0 }, buffer: 0/65536 } } [2024-05-31T02:40:51Z DEBUG pingora_core::services::listening] new event! [2024-05-31T02:40:51Z DEBUG pingora_proxy] Successfully get a new request [2024-05-31T02:40:51Z DEBUG im_api_rust_gateway::route] safe check not open [2024-05-31T02:40:51Z DEBUG im_api_rust_gateway::route] match path:/message-ws, route:PathMapper { path: "/message-ws", proxy_path: "backend:8888" }, proxy:backend:8888 [2024-05-31T02:40:51Z DEBUG pingora_core::connectors] No reusable connection found for addr: 10.8.30.98:8888, scheme: HTTP,sni: im-gateway, [2024-05-31T02:40:51Z DEBUG pingora_core::connectors::l4] connected to new server: 10.8.30.98:8888 [2024-05-31T02:40:51Z DEBUG im_api_rust_gateway::route] upstream_request_filter ws upgrade request

andrewhavck commented 1 month ago

Not seeing anything obvious in the debug logs, could you provide some trace logs? Thanks.

zhangyangyang3 commented 4 weeks ago

Not seeing anything obvious in the debug logs, could you provide some trace logs? Thanks.

I add the trace log trace.log

luizfonseca commented 2 weeks ago

Do you have PeerOptions configured by any chance? (if so, check read_timeout)

zhangyangyang3 commented 2 weeks ago

Do you have PeerOptions configured by any chance? (if so, check read_timeout)

I try to config PeerOptions. it seems that not work

eaufavor commented 3 days ago

I add the trace log

The trace log is a bit hard to follow given that there are many ongoing requests. Could you point out the the timestamp when the request started and when the request broke?

zhangyangyang3 commented 3 days ago

I add the trace log

The trace log is a bit hard to follow given that there are many ongoing requests. Could you point out the the timestamp when the request started and when the request broke?

ws start at line 3. match path:/message-ws, route:PathMapper
lastline -1(271) is the end of the ws connection