pingora icon indicating copy to clipboard operation
pingora copied to clipboard
verified publisher icon cloudflare

webscoket proxy always break after about 30s

Open zhangyangyang3 opened this issue 1 year ago • 7 comments

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

zhangyangyang3 avatar May 31 '24 02:05 zhangyangyang3

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

andrewhavck avatar May 31 '24 19:05 andrewhavck

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

I add the trace log trace.log

zhangyangyang3 avatar Jun 03 '24 01:06 zhangyangyang3

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

luizfonseca avatar Jun 13 '24 21:06 luizfonseca

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

I try to config PeerOptions. it seems that not work

zhangyangyang3 avatar Jun 17 '24 00:06 zhangyangyang3

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?

eaufavor avatar Jun 28 '24 18:06 eaufavor

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

zhangyangyang3 avatar Jun 29 '24 01:06 zhangyangyang3

would this issue fixed?

zhangyangyang3 avatar Aug 26 '24 00:08 zhangyangyang3