search

paritytech / litep2p

Peer-to-peer networking library
MIT License
68 stars 10 forks source link

How to keep connection while waiting for Response #153

Open Ma233 opened 3 months ago

Ma233 commented 3 months ago

Hello, I am working on a project that using litep2p with its RequestResponse protocol.

I found that the connection will be closed if a response is not sent within 5 seconds.

I have tested both TcpTransport and QuicTransport, and they are all like this.

I am uncertain whether this relates to the issue https://github.com/paritytech/litep2p/issues/131.

Is there a correct way to keep an open connection until it respond a response? It could be manually closed if neccessary.

dmitry-markin commented 3 months ago

Hi, just to double check, did you try configuring the request-response protocol with a custom timeout? https://github.com/paritytech/litep2p/blob/ebb5f2dc89a65b7b4c67b592c9312f874be4c0fc/src/protocol/request_response/config.rs#L143

It's set by default to 5 seconds.

Ma233 commented 3 months ago

@dmitry-markin Hi, thanks for your reminder, I have now added this configuration. But there are still disconnections.

After setting the log level to trace, I found a "keep-alive timeout exceeded, downgrading connection" message. I believe this could be the reason.

dmitry-markin commented 3 months ago

Yeah, I see, the connection is downgraded if no substream is opened within 5 seconds after creating the connection. This is strange yours get closed, because sending a request over request-response protocol opens a substream.

Are you sure you send a request within 5 seconds of opening the connection? Do you know you can let litep2p establish a connection for you when sending a request using DialOptions::Dial?

Ma233 commented 3 months ago

@dmitry-markin I'm sure because the connection is created by invoking send_request. (I added peer multiaddr before send_request.)

        let request_id = self
            .p2p_server
            .request_response_handle
            .send_request(peer_id, request_data, DialOptions::Dial)
            .await?;
I'm pasting logs of response side peer here. ``` 2024-06-14T14:52:30.459694Z DEBUG litep2p::tcp::connection: accept connection address=127.0.0.1:10010 2024-06-14T14:52:30.459761Z TRACE litep2p::tcp::connection: negotiate connection role=Listener 2024-06-14T14:52:30.459790Z TRACE litep2p::tcp::connection: negotiating protocols protocols=["/noise"] 2024-06-14T14:52:30.460823Z TRACE litep2p::multistream-select: Received message: Header(V1) 2024-06-14T14:52:30.460972Z TRACE litep2p::multistream-select: Received message: Protocol(Protocol(b"/noise")) 2024-06-14T14:52:30.461028Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /noise 2024-06-14T14:52:30.461096Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /noise 2024-06-14T14:52:30.461106Z TRACE litep2p::tcp::connection: protocol negotiated protocol="/noise" 2024-06-14T14:52:30.461163Z TRACE litep2p::tcp::connection: `multistream-select` and `noise` negotiated 2024-06-14T14:52:30.461185Z DEBUG litep2p::crypto::noise: start noise handshake role=Listener 2024-06-14T14:52:30.461207Z TRACE litep2p::crypto::noise: create new noise configuration role=Listener 2024-06-14T14:52:30.463423Z TRACE litep2p::crypto::noise: get noise paylod message 2024-06-14T14:52:30.466710Z TRACE litep2p::tcp::connection: noise handshake done 2024-06-14T14:52:30.466736Z TRACE litep2p::tcp::connection: negotiating protocols protocols=["/yamux/1.0.0"] 2024-06-14T14:52:30.466787Z TRACE litep2p::crypto::noise: read data from socket nread=52 2024-06-14T14:52:30.466797Z TRACE litep2p::crypto::noise: current frame size = 50 2024-06-14T14:52:30.466836Z TRACE litep2p::multistream-select: Received message: Header(V1) 2024-06-14T14:52:30.466885Z TRACE litep2p::multistream-select: Received message: Protocol(Protocol(b"/yamux/1.0.0")) 2024-06-14T14:52:30.466894Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /yamux/1.0.0 2024-06-14T14:52:30.466908Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /yamux/1.0.0 2024-06-14T14:52:30.466917Z TRACE litep2p::tcp::connection: protocol negotiated protocol="/yamux/1.0.0" 2024-06-14T14:52:30.468269Z TRACE litep2p::tcp::connection: `yamux` negotiated 2024-06-14T14:52:30.468424Z DEBUG litep2p::yamux: new connection: 3137a751 (Server) 2024-06-14T14:52:30.468732Z TRACE litep2p::transport-manager: accept connection peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") endpoint=Listener { address: "/ip4/127.0.0.1/tcp/10010", connection_id: ConnectionId(0) } 2024-06-14T14:52:30.468859Z TRACE litep2p::tcp: start connection connection_id=ConnectionId(0) 2024-06-14T14:52:30.469097Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.469104Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.469132Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Init) 2024-06-14T14:52:30.469136Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.469157Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/control/1 endpoint=Listener { address: "/ip4/127.0.0.1/tcp/10010", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-06-14T14:52:30.470540Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.470572Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/tunnel/1 endpoint=Listener { address: "/ip4/127.0.0.1/tcp/10010", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-06-14T14:52:30.470587Z DEBUG litep2p::request-response::protocol: connection established peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/control/1 2024-06-14T14:52:30.471952Z DEBUG litep2p::request-response::protocol: connection established peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/tunnel/1 2024-06-14T14:52:30.472663Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.472674Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.472679Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.472690Z TRACE litep2p::crypto::noise: read data from socket nread=86 2024-06-14T14:52:30.472696Z TRACE litep2p::crypto::noise: current frame size = 28 2024-06-14T14:52:30.473803Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 12)) 2024-06-14T14:52:30.473809Z TRACE litep2p::yamux: 3137a751: read: (Header Data 1 (len 38) (flags 1)) 2024-06-14T14:52:30.473840Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Body (header (Header Data 1 (len 38) (flags 1))) (offset 0) (buffer-len 38)) 2024-06-14T14:52:30.473844Z TRACE litep2p::crypto::noise: current frame size = 54 2024-06-14T14:52:30.473849Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Body (header (Header Data 1 (len 38) (flags 1))) (offset 38) (buffer-len 38)) 2024-06-14T14:52:30.473907Z TRACE litep2p::yamux: 3137a751: received: (Header Data 1 (len 38) (flags 1)) 2024-06-14T14:52:30.474845Z TRACE litep2p::yamux: 3137a751: new inbound (Stream 3137a751/1) of (Connection 3137a751 Server (streams 1)) 2024-06-14T14:52:30.474889Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.474893Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.474902Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Init) 2024-06-14T14:52:30.474905Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.474909Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.474924Z TRACE litep2p::tcp::connection: accept inbound substream substream_id=SubstreamId(0) 2024-06-14T14:52:30.475871Z TRACE litep2p::tcp::connection: negotiating protocols protocols=["/pproxy/control/1", "/pproxy/tunnel/1"] 2024-06-14T14:52:30.475922Z TRACE litep2p::yamux: 3137a751/1: read 1 bytes 2024-06-14T14:52:30.475928Z TRACE litep2p::yamux: 3137a751/1: read 19 bytes 2024-06-14T14:52:30.475938Z TRACE litep2p::multistream-select: Received message: Header(V1) 2024-06-14T14:52:30.475970Z TRACE litep2p::yamux: 3137a751/1: write 20 bytes 2024-06-14T14:52:30.475974Z TRACE litep2p::yamux: 3137a751/1: update state: (from Open { acknowledged: false } to Open { acknowledged: true } -> Open { acknowledged: true }) 2024-06-14T14:52:30.476013Z TRACE litep2p::yamux: 3137a751/1: read 1 bytes 2024-06-14T14:52:30.476899Z TRACE litep2p::yamux: 3137a751/1: read 17 bytes 2024-06-14T14:52:30.476910Z TRACE litep2p::multistream-select: Received message: Protocol(Protocol(b"/pproxy/tunnel/1")) 2024-06-14T14:52:30.476917Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /pproxy/tunnel/1 2024-06-14T14:52:30.476930Z TRACE litep2p::yamux: 3137a751/1: write 18 bytes 2024-06-14T14:52:30.476936Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /pproxy/tunnel/1 2024-06-14T14:52:30.476947Z TRACE litep2p::tcp::connection: protocol negotiated protocol="/pproxy/tunnel/1" 2024-06-14T14:52:30.477825Z TRACE litep2p::tcp::connection: substream accepted and negotiated substream_id=SubstreamId(0) 2024-06-14T14:52:30.477856Z TRACE litep2p::substream: create new substream for tcp peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") codec=UnsignedVarint(Some(1048576)) 2024-06-14T14:52:30.477881Z DEBUG litep2p::protocol-set: substream opened protocol=/pproxy/tunnel/1 peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") direction=Inbound 2024-06-14T14:52:30.477912Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.478777Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.478818Z TRACE litep2p::yamux: 3137a751/1: sending: (Header Data 1 (len 20) (flags 2)) 2024-06-14T14:52:30.478826Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.478830Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Header (offset 0)) 2024-06-14T14:52:30.478863Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Body (offset 0) (buffer-len 20)) 2024-06-14T14:52:30.478871Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.478874Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.480058Z TRACE litep2p::yamux: 3137a751/1: sending: (Header Data 1 (len 18) (flags 0)) 2024-06-14T14:52:30.480064Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.480068Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Header (offset 0)) 2024-06-14T14:52:30.480080Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Body (offset 0) (buffer-len 18)) 2024-06-14T14:52:30.480086Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.480090Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.481292Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.481367Z TRACE litep2p::request-response::protocol: handle inbound substream peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/tunnel/1 2024-06-14T14:52:30.481411Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.481423Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.481430Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.483364Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.483370Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.483374Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.483382Z TRACE litep2p::crypto::noise: read data from socket nread=50 2024-06-14T14:52:30.483390Z TRACE litep2p::crypto::noise: current frame size = 28 2024-06-14T14:52:30.483397Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 12)) 2024-06-14T14:52:30.483400Z TRACE litep2p::yamux: 3137a751: read: (Header Data 1 (len 2) (flags 0)) 2024-06-14T14:52:30.483406Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Body (header (Header Data 1 (len 2) (flags 0))) (offset 0) (buffer-len 2)) 2024-06-14T14:52:30.484514Z TRACE litep2p::crypto::noise: current frame size = 18 2024-06-14T14:52:30.484521Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Body (header (Header Data 1 (len 2) (flags 0))) (offset 2) (buffer-len 2)) 2024-06-14T14:52:30.484526Z TRACE litep2p::yamux: 3137a751: received: (Header Data 1 (len 2) (flags 0)) 2024-06-14T14:52:30.484535Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.484538Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.484542Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Init) 2024-06-14T14:52:30.485332Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.485337Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.485350Z TRACE litep2p::yamux: 3137a751/1: read 1 bytes 2024-06-14T14:52:30.485354Z TRACE litep2p::yamux: 3137a751/1: read 1 bytes 2024-06-14T14:52:30.485403Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.485407Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.485410Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.486181Z TRACE litep2p::crypto::noise: read data from socket nread=245 2024-06-14T14:52:30.486186Z TRACE litep2p::crypto::noise: current frame size = 28 2024-06-14T14:52:30.486191Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 12)) 2024-06-14T14:52:30.486194Z TRACE litep2p::yamux: 3137a751: read: (Header Data 1 (len 197) (flags 0)) 2024-06-14T14:52:30.486198Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Body (header (Header Data 1 (len 197) (flags 0))) (offset 0) (buffer-len 197)) 2024-06-14T14:52:30.486201Z TRACE litep2p::crypto::noise: current frame size = 213 2024-06-14T14:52:30.486973Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Body (header (Header Data 1 (len 197) (flags 0))) (offset 197) (buffer-len 197)) 2024-06-14T14:52:30.486978Z TRACE litep2p::yamux: 3137a751: received: (Header Data 1 (len 197) (flags 0)) 2024-06-14T14:52:30.486983Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.486986Z TRACE litep2p::yamux: 3137a751: write: (WriteState::Init) 2024-06-14T14:52:30.486990Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Init) 2024-06-14T14:52:30.486993Z TRACE litep2p::yamux: 3137a751: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.487752Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.487764Z TRACE litep2p::yamux: 3137a751/1: read 197 bytes 2024-06-14T14:52:30.487791Z TRACE litep2p::request-response::protocol: inbound request peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/tunnel/1 request_id=RequestId(0) 2024-06-14T14:52:35.474650Z TRACE litep2p::transport-service: keep-alive timeout over, downgrade connection peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") connection_id=ConnectionId(0) 2024-06-14T14:52:35.474650Z TRACE litep2p::transport-service: keep-alive timeout over, downgrade connection peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") connection_id=ConnectionId(0) 2024-06-14T14:52:35.490616Z TRACE litep2p::request-response::handle: send response to peer request_id=RequestId(0) 2024-06-14T14:52:35.490690Z TRACE litep2p::request-response::protocol: send response peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/tunnel/1 request_id=RequestId(0) 2024-06-14T14:52:35.490750Z TRACE litep2p::substream: send framed peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") codec=UnsignedVarint(Some(1048576)) frame_len=38 2024-06-14T14:52:35.490781Z TRACE litep2p::yamux: 3137a751/1: write 1 bytes 2024-06-14T14:52:35.490792Z TRACE litep2p::yamux: 3137a751/1: write 38 bytes 2024-06-14T14:52:35.490902Z DEBUG litep2p::tcp::connection: protocols have disconnected, closing connection 2024-06-14T14:52:35.490953Z TRACE litep2p::yamux: 3137a751/1: update state: (from Open { acknowledged: true } to Closed -> Closed) 2024-06-14T14:52:35.490955Z TRACE litep2p::transport-service: primary connection closed peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") connection_id=ConnectionId(0) 2024-06-14T14:52:35.491006Z TRACE litep2p::transport-service: primary connection closed peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") connection_id=ConnectionId(0) 2024-06-14T14:52:35.491022Z TRACE litep2p::transport-manager: connection closed peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") connection_id=ConnectionId(0) 2024-06-14T14:52:35.492048Z DEBUG litep2p::request-response::protocol: connection closed peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/control/1 2024-06-14T14:52:35.492052Z DEBUG litep2p::request-response::protocol: connection closed peer=PeerId("12D3KooWDf8LJbVU4PLdfWvyLGpTDwXmRe1XTRWpAVB2rEqzZJJW") protocol=/pproxy/tunnel/1 ```
And here are the logs of request side. ``` 2024-06-14T14:52:30.439860Z DEBUG server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }}: h2::codec::framed_write: send frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 } 2024-06-14T14:52:30.439913Z TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }}: h2::frame::settings: encoding SETTINGS; len=18 2024-06-14T14:52:30.439933Z TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }}: h2::frame::settings: encoding setting; val=InitialWindowSize(1048576) 2024-06-14T14:52:30.440494Z TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }}: h2::frame::settings: encoding setting; val=MaxFrameSize(16384) 2024-06-14T14:52:30.440509Z TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }}: h2::frame::settings: encoding setting; val=MaxHeaderListSize(16777216) 2024-06-14T14:52:30.440978Z TRACE server_handshake:FramedWrite::buffer{frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }}: h2::codec::framed_write: encoded settings rem=27 2024-06-14T14:52:30.441068Z TRACE server_handshake: h2::server: state=Flushing(_) 2024-06-14T14:52:30.441094Z TRACE server_handshake:flush:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false 2024-06-14T14:52:30.441133Z TRACE server_handshake:flush:FramedWrite::flush: h2::codec::framed_write: flushing buffer 2024-06-14T14:52:30.441163Z TRACE server_handshake: h2::server: flush.poll=Ready 2024-06-14T14:52:30.441217Z TRACE server_handshake: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535 2024-06-14T14:52:30.441719Z TRACE server_handshake: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535 2024-06-14T14:52:30.441732Z TRACE server_handshake: h2::proto::streams::prioritize: Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) } 2024-06-14T14:52:30.441767Z TRACE server_handshake: h2::server: connection established! 2024-06-14T14:52:30.441782Z TRACE server_handshake: h2::proto::streams::recv: set_target_connection_window; target=1048576; available=65535, reserved=0 2024-06-14T14:52:30.441820Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open 2024-06-14T14:52:30.442312Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.442357Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=27 2024-06-14T14:52:30.442401Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=27}: h2::codec::framed_read: decoding frame from 27B 2024-06-14T14:52:30.442427Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=27}: h2::codec::framed_read: frame.kind=Settings 2024-06-14T14:52:30.442929Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 } 2024-06-14T14:52:30.442964Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 } 2024-06-14T14:52:30.443461Z DEBUG server_handshake:Connection{peer=Server}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) } 2024-06-14T14:52:30.443485Z TRACE server_handshake:Connection{peer=Server}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::frame::settings: encoding SETTINGS; len=0 2024-06-14T14:52:30.443963Z TRACE server_handshake:Connection{peer=Server}:poll:poll_ready:FramedWrite::buffer{frame=Settings { flags: (0x1: ACK) }}: h2::codec::framed_write: encoded settings rem=9 2024-06-14T14:52:30.443993Z TRACE server_handshake:Connection{peer=Server}:poll:poll_ready: h2::proto::settings: ACK sent; applying settings 2024-06-14T14:52:30.444026Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.444500Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=13 2024-06-14T14:52:30.444528Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: decoding frame from 13B 2024-06-14T14:52:30.444547Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=13}: h2::codec::framed_read: frame.kind=WindowUpdate 2024-06-14T14:52:30.445040Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 } 2024-06-14T14:52:30.445069Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv WINDOW_UPDATE frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 } 2024-06-14T14:52:30.445551Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=5177345; old=65535; new=5242880 2024-06-14T14:52:30.445597Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.445615Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=92 2024-06-14T14:52:30.445639Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}: h2::codec::framed_read: decoding frame from 92B 2024-06-14T14:52:30.446108Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}: h2::codec::framed_read: frame.kind=Headers 2024-06-14T14:52:30.446132Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}: h2::frame::headers: loading headers; flags=(0x4: END_HEADERS) 2024-06-14T14:52:30.446622Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: decode 2024-06-14T14:52:30.446646Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=83 kind=Indexed 2024-06-14T14:52:30.447123Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=82 kind=Indexed 2024-06-14T14:52:30.447149Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=81 kind=LiteralWithIndexing 2024-06-14T14:52:30.447670Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=68 kind=LiteralWithoutIndexing 2024-06-14T14:52:30.447796Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=34 kind=LiteralWithIndexing 2024-06-14T14:52:30.447860Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=23 kind=LiteralWithIndexing 2024-06-14T14:52:30.448373Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=92}:hpack::decode: h2::hpack::decoder: rem=10 kind=LiteralWithIndexing 2024-06-14T14:52:30.448440Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } 2024-06-14T14:52:30.448465Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv HEADERS frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } 2024-06-14T14:52:30.448921Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=1048576; old=0; new=1048576 2024-06-14T14:52:30.448935Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=2097152; old=0; new=2097152 2024-06-14T14:52:30.448958Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::streams: recv_headers; stream=StreamId(1); state=State { inner: Idle } 2024-06-14T14:52:30.449390Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: opening stream; init_window=1048576 2024-06-14T14:52:30.449424Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::store: Queue::push_back 2024-06-14T14:52:30.449438Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::store: -> first entry 2024-06-14T14:52:30.449452Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Open { local: AwaitingHeaders, remote: Streaming } }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:30.449904Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.449921Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=268 2024-06-14T14:52:30.450355Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=268}: h2::codec::framed_read: decoding frame from 268B 2024-06-14T14:52:30.450374Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=268}: h2::codec::framed_read: frame.kind=Data 2024-06-14T14:52:30.450399Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) } 2024-06-14T14:52:30.450842Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv DATA frame=Data { stream_id: StreamId(1) } 2024-06-14T14:52:30.450861Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; size=259; connection=65535; stream=1048576 2024-06-14T14:52:30.450875Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=259; window=65535; available=1048576 2024-06-14T14:52:30.451305Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=259; window=1048576; available=1048576 2024-06-14T14:52:30.451321Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Open { local: AwaitingHeaders, remote: Streaming } }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:30.451352Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.451777Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=9 2024-06-14T14:52:30.451802Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: decoding frame from 9B 2024-06-14T14:52:30.451819Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: frame.kind=Data 2024-06-14T14:52:30.452260Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } 2024-06-14T14:52:30.452283Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv DATA frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } 2024-06-14T14:52:30.452299Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: recv_data; size=0; connection=65276; stream=1048317 2024-06-14T14:52:30.452725Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=0; window=65276; available=1048317 2024-06-14T14:52:30.452741Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::state: recv_close: Open => HalfClosedRemote(AwaitingHeaders) 2024-06-14T14:52:30.452753Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: send_data; sz=0; window=1048317; available=1048317 2024-06-14T14:52:30.453180Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: HalfClosedRemote(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:30.453211Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.453227Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=9 2024-06-14T14:52:30.453660Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: decoding frame from 9B 2024-06-14T14:52:30.453678Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: h2::codec::framed_read: frame.kind=Settings 2024-06-14T14:52:30.454126Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) } 2024-06-14T14:52:30.454157Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x1: ACK) } 2024-06-14T14:52:30.454174Z DEBUG server_handshake:Connection{peer=Server}:poll: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 } 2024-06-14T14:52:30.454615Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::recv: update_initial_window_size; new=1048576; old=1048576 2024-06-14T14:52:30.454651Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.454688Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 } 2024-06-14T14:52:30.455117Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }}: h2::frame::window_update: encoding WINDOW_UPDATE; id=StreamId(0) 2024-06-14T14:52:30.455136Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }}: h2::codec::framed_write: encoded window_update rem=22 2024-06-14T14:52:30.455568Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::flow_control: inc_window; sz=983041; old=65276; new=1048317 2024-06-14T14:52:30.455593Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete 2024-06-14T14:52:30.455606Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open 2024-06-14T14:52:30.455632Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false 2024-06-14T14:52:30.456074Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer 2024-06-14T14:52:30.456113Z TRACE h2::proto::streams::streams: next_incoming; id=StreamId(1), state=State { inner: HalfClosedRemote(AwaitingHeaders) } 2024-06-14T14:52:30.456121Z TRACE h2::server: received incoming 2024-06-14T14:52:30.456128Z TRACE hyper::proto::h2::server: incoming request 2024-06-14T14:52:30.456201Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open 2024-06-14T14:52:30.456230Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:30.456685Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete 2024-06-14T14:52:30.456700Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open 2024-06-14T14:52:30.456723Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer 2024-06-14T14:52:30.457156Z DEBUG tonic_web::service: kind="other h2" content_type=Some("application/grpc") 2024-06-14T14:52:30.457186Z TRACE h2::proto::streams::recv: release_capacity; size=259 2024-06-14T14:52:30.457192Z TRACE h2::proto::streams::recv: release_connection_capacity; size=259, connection in_flight_data=259 2024-06-14T14:52:30.457215Z TRACE h2::proto::streams::recv: release_capacity; size=0 2024-06-14T14:52:30.457219Z TRACE h2::proto::streams::recv: release_connection_capacity; size=0, connection in_flight_data=0 2024-06-14T14:52:30.457230Z TRACE h2::proto::streams::streams: drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: HalfClosedRemote(AwaitingHeaders) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(2097152), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: None, pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(1048317), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_recv: false, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted } 2024-06-14T14:52:30.457603Z TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: HalfClosedRemote(AwaitingHeaders) }; is_closed=false; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:30.457974Z TRACE dephy_pproxy::command: handle request: Request { metadata: MetadataMap { headers: {"te": "trailers", "content-type": "application/grpc", "user-agent": "tonic/0.11.0"} }, message: RequestHttpServerRequest { peer_id: "12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r", data: [80, 79, 83, 84, 32, 47, 97, 112, 105, 47, 103, 101, 110, 101, 114, 97, 116, 101, 32, 72, 84, 84, 80, 47, 49, 46, 49, 13, 10, 104, 111, 115, 116, 58, 32, 49, 50, 55, 46, 48, 46, 48, 46, 49, 58, 56, 48, 56, 48, 13, 10, 117, 115, 101, 114, 45, 97, 103, 101, 110, 116, 58, 32, 99, 117, 114, 108, 47, 56, 46, 54, 46, 48, 13, 10, 97, 99, 99, 101, 112, 116, 58, 32, 42, 47, 42, 13, 10, 99, 111, 110, 116, 101, 110, 116, 45, 108, 101, 110, 103, 116, 104, 58, 32, 51, 56, 13, 10, 99, 111, 110, 116, 101, 110, 116, 45, 116, 121, 112, 101, 58, 32, 97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 120, 45, 119, 119, 119, 45, 102, 111, 114, 109, 45, 117, 114, 108, 101, 110, 99, 111, 100, 101, 100, 13, 10, 13, 10, 123, 34, 109, 111, 100, 101, 108, 34, 58, 32, 34, 108, 108, 97, 109, 97, 51, 34, 44, 32, 34, 112, 114, 111, 109, 112, 116, 34, 58, 32, 34, 104, 101, 108, 108, 111, 34, 125] }, extensions: Extensions } 2024-06-14T14:52:30.458557Z TRACE litep2p::request-response::handle: send request to peer peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") 2024-06-14T14:52:30.458723Z TRACE litep2p::request-response::protocol: send request to remote peer peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 request_id=RequestId(0) dial_options=Dial 2024-06-14T14:52:30.458845Z TRACE litep2p::request-response::protocol: started dialing peer peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 request_id=RequestId(0) 2024-06-14T14:52:30.458911Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(0) addresses={"/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r": AddressRecord { score: 0, address: "/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r", connection_id: None }} 2024-06-14T14:52:30.459076Z TRACE litep2p::transport::listener: parse multi address address="/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r" 2024-06-14T14:52:30.459505Z TRACE litep2p::tcp: connection opened connection_id=ConnectionId(0) address="/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r" canceled=false 2024-06-14T14:52:30.459580Z TRACE litep2p::transport-manager: connection opened to peer peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) address="/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r" transport=Tcp 2024-06-14T14:52:30.459644Z TRACE litep2p::transport::listener: parse multi address address="/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r" 2024-06-14T14:52:30.459699Z TRACE litep2p::tcp: negotiate connection peer=Some(PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r")) connection_id=ConnectionId(0) address="/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r" 2024-06-14T14:52:30.459759Z TRACE litep2p::transport-manager: negotiation started peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) dial_record=AddressRecord { score: 100, address: "/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r", connection_id: Some(ConnectionId(0)) } transport=Tcp 2024-06-14T14:52:30.460478Z TRACE litep2p::tcp::connection: negotiate connection role=Dialer 2024-06-14T14:52:30.460504Z TRACE litep2p::tcp::connection: negotiating protocols protocols=["/noise"] 2024-06-14T14:52:30.460574Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /noise 2024-06-14T14:52:30.461012Z TRACE litep2p::multistream-select: Received message: Header(V1) 2024-06-14T14:52:30.461176Z TRACE litep2p::multistream-select: Received message: Protocol(Protocol(b"/noise")) 2024-06-14T14:52:30.461217Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /noise 2024-06-14T14:52:30.461229Z TRACE litep2p::tcp::connection: protocol negotiated protocol="/noise" 2024-06-14T14:52:30.461239Z TRACE litep2p::tcp::connection: `multistream-select` and `noise` negotiated 2024-06-14T14:52:30.461261Z DEBUG litep2p::crypto::noise: start noise handshake role=Dialer 2024-06-14T14:52:30.461283Z TRACE litep2p::crypto::noise: create new noise configuration role=Dialer 2024-06-14T14:52:30.462798Z TRACE litep2p::crypto::noise: get noise dialer first message 2024-06-14T14:52:30.465603Z TRACE litep2p::crypto::noise: get noise paylod message 2024-06-14T14:52:30.466104Z TRACE litep2p::tcp::connection: noise handshake done 2024-06-14T14:52:30.466113Z TRACE litep2p::tcp::connection: negotiating protocols protocols=["/yamux/1.0.0"] 2024-06-14T14:52:30.466141Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /yamux/1.0.0 2024-06-14T14:52:30.466960Z TRACE litep2p::crypto::noise: read data from socket nread=70 2024-06-14T14:52:30.466971Z TRACE litep2p::crypto::noise: current frame size = 36 2024-06-14T14:52:30.466995Z TRACE litep2p::multistream-select: Received message: Header(V1) 2024-06-14T14:52:30.466999Z TRACE litep2p::crypto::noise: current frame size = 30 2024-06-14T14:52:30.467006Z TRACE litep2p::multistream-select: Received message: Protocol(Protocol(b"/yamux/1.0.0")) 2024-06-14T14:52:30.467012Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /yamux/1.0.0 2024-06-14T14:52:30.467020Z TRACE litep2p::tcp::connection: protocol negotiated protocol="/yamux/1.0.0" 2024-06-14T14:52:30.467028Z TRACE litep2p::tcp::connection: `yamux` negotiated 2024-06-14T14:52:30.467117Z DEBUG litep2p::yamux: new connection: fc17bf02 (Client) 2024-06-14T14:52:30.467270Z TRACE litep2p::transport-manager: connection opened to remote peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) endpoint=Dialer { address: "/ip4/127.0.0.1/tcp/6666", connection_id: ConnectionId(0) } record=AddressRecord { score: 100, address: "/ip4/127.0.0.1/tcp/6666/p2p/12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r", connection_id: Some(ConnectionId(0)) } 2024-06-14T14:52:30.467857Z TRACE litep2p::transport-manager: accept connection peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") endpoint=Dialer { address: "/ip4/127.0.0.1/tcp/6666", connection_id: ConnectionId(0) } 2024-06-14T14:52:30.467934Z TRACE litep2p::tcp: start connection connection_id=ConnectionId(0) 2024-06-14T14:52:30.468081Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.468088Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.468117Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Init) 2024-06-14T14:52:30.468121Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.468103Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/control/1 endpoint=Dialer { address: "/ip4/127.0.0.1/tcp/6666", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-06-14T14:52:30.468158Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.468743Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 endpoint=Dialer { address: "/ip4/127.0.0.1/tcp/6666", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-06-14T14:52:30.468778Z DEBUG litep2p::request-response::protocol: connection established peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 2024-06-14T14:52:30.468777Z DEBUG litep2p::request-response::protocol: connection established peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/control/1 2024-06-14T14:52:30.469349Z TRACE litep2p::transport-service: open substream peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 substream_id=SubstreamId(0) 2024-06-14T14:52:30.469394Z TRACE litep2p::request-response::protocol: dial succeeded, open substream peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 request_id=RequestId(0) substream_id=SubstreamId(0) 2024-06-14T14:52:30.469986Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.469992Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.469997Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.470022Z TRACE litep2p::tcp::connection: open substream protocol=Static("/pproxy/tunnel/1") substream_id=SubstreamId(0) 2024-06-14T14:52:30.470032Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.470579Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.470587Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.470600Z DEBUG litep2p::tcp::connection: open substream protocol=Static("/pproxy/tunnel/1") substream_id=SubstreamId(0) 2024-06-14T14:52:30.470629Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.470633Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.470638Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.470662Z TRACE litep2p::yamux: fc17bf02: creating new outbound stream 2024-06-14T14:52:30.471226Z DEBUG litep2p::yamux: fc17bf02: new outbound (Stream fc17bf02/1) of (Connection fc17bf02 Client (streams 0)) 2024-06-14T14:52:30.471239Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.471243Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.471251Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.471263Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.471268Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.471272Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.471830Z TRACE litep2p::tcp::connection: substream opened substream_id=SubstreamId(0) 2024-06-14T14:52:30.471882Z TRACE litep2p::tcp::connection: negotiating protocols protocols=["/pproxy/tunnel/1"] 2024-06-14T14:52:30.471925Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /pproxy/tunnel/1 2024-06-14T14:52:30.471949Z TRACE litep2p::yamux: fc17bf02/1: write 38 bytes 2024-06-14T14:52:30.471986Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.471991Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.472000Z TRACE litep2p::yamux: fc17bf02/1: sending: (Header Data 1 (len 38) (flags 1)) 2024-06-14T14:52:30.472007Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.472540Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Header (offset 0)) 2024-06-14T14:52:30.472600Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Body (offset 0) (buffer-len 38)) 2024-06-14T14:52:30.472608Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.472612Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.472618Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.472677Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.472695Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.472703Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.478960Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.478973Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.478981Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.478991Z TRACE litep2p::crypto::noise: read data from socket nread=68 2024-06-14T14:52:30.478997Z TRACE litep2p::crypto::noise: current frame size = 28 2024-06-14T14:52:30.479005Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 12)) 2024-06-14T14:52:30.479011Z TRACE litep2p::yamux: fc17bf02: read: (Header Data 1 (len 20) (flags 2)) 2024-06-14T14:52:30.479015Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Body (header (Header Data 1 (len 20) (flags 2))) (offset 0) (buffer-len 20)) 2024-06-14T14:52:30.479019Z TRACE litep2p::crypto::noise: current frame size = 36 2024-06-14T14:52:30.479511Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Body (header (Header Data 1 (len 20) (flags 2))) (offset 20) (buffer-len 20)) 2024-06-14T14:52:30.479547Z TRACE litep2p::yamux: fc17bf02: received: (Header Data 1 (len 20) (flags 2)) 2024-06-14T14:52:30.479553Z TRACE litep2p::yamux: fc17bf02/1: update state: (from Open { acknowledged: false } to Open { acknowledged: true } -> Open { acknowledged: true }) 2024-06-14T14:52:30.479622Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.479626Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.479630Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Init) 2024-06-14T14:52:30.480132Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.480137Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.480153Z TRACE litep2p::yamux: fc17bf02/1: read 1 bytes 2024-06-14T14:52:30.480159Z TRACE litep2p::yamux: fc17bf02/1: read 19 bytes 2024-06-14T14:52:30.480164Z TRACE litep2p::multistream-select: Received message: Header(V1) 2024-06-14T14:52:30.480182Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.480186Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.480190Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.480685Z TRACE litep2p::crypto::noise: read data from socket nread=66 2024-06-14T14:52:30.480691Z TRACE litep2p::crypto::noise: current frame size = 28 2024-06-14T14:52:30.480697Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 12)) 2024-06-14T14:52:30.480700Z TRACE litep2p::yamux: fc17bf02: read: (Header Data 1 (len 18) (flags 0)) 2024-06-14T14:52:30.480704Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Body (header (Header Data 1 (len 18) (flags 0))) (offset 0) (buffer-len 18)) 2024-06-14T14:52:30.481172Z TRACE litep2p::crypto::noise: current frame size = 34 2024-06-14T14:52:30.481181Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Body (header (Header Data 1 (len 18) (flags 0))) (offset 18) (buffer-len 18)) 2024-06-14T14:52:30.481186Z TRACE litep2p::yamux: fc17bf02: received: (Header Data 1 (len 18) (flags 0)) 2024-06-14T14:52:30.481193Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.481196Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.481200Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Init) 2024-06-14T14:52:30.481202Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.481718Z TRACE litep2p::crypto::noise: reset read buffer 2024-06-14T14:52:30.481735Z TRACE litep2p::yamux: fc17bf02/1: read 1 bytes 2024-06-14T14:52:30.481740Z TRACE litep2p::yamux: fc17bf02/1: read 17 bytes 2024-06-14T14:52:30.481746Z TRACE litep2p::multistream-select: Received message: Protocol(Protocol(b"/pproxy/tunnel/1")) 2024-06-14T14:52:30.481754Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /pproxy/tunnel/1 2024-06-14T14:52:30.481762Z TRACE litep2p::tcp::connection: protocol negotiated protocol="/pproxy/tunnel/1" 2024-06-14T14:52:30.482292Z TRACE litep2p::substream: create new substream for tcp peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") codec=UnsignedVarint(Some(1048576)) 2024-06-14T14:52:30.482317Z DEBUG litep2p::protocol-set: substream opened protocol=/pproxy/tunnel/1 peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") direction=Outbound(SubstreamId(0)) 2024-06-14T14:52:30.482351Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.482355Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.482359Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.482395Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.482401Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.482853Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.482409Z TRACE litep2p::request-response::protocol: substream opened, send request peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 substream_id=SubstreamId(0) request_id=RequestId(0) 2024-06-14T14:52:30.482900Z TRACE litep2p::substream: send framed peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") codec=UnsignedVarint(Some(1048576)) frame_len=197 2024-06-14T14:52:30.482925Z TRACE litep2p::yamux: fc17bf02/1: write 2 bytes 2024-06-14T14:52:30.482936Z TRACE litep2p::yamux: fc17bf02/1: write 197 bytes 2024-06-14T14:52:30.483250Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483254Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483265Z TRACE litep2p::yamux: fc17bf02/1: sending: (Header Data 1 (len 2) (flags 0)) 2024-06-14T14:52:30.483269Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483272Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Header (offset 0)) 2024-06-14T14:52:30.483289Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Body (offset 0) (buffer-len 2)) 2024-06-14T14:52:30.483296Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483299Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483729Z TRACE litep2p::yamux: fc17bf02/1: sending: (Header Data 1 (len 197) (flags 0)) 2024-06-14T14:52:30.483735Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483738Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Header (offset 0)) 2024-06-14T14:52:30.483750Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Body (offset 0) (buffer-len 197)) 2024-06-14T14:52:30.483756Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483760Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.483764Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:30.484230Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.484234Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:30.484238Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:35.471631Z TRACE litep2p::transport-service: keep-alive timeout over, downgrade connection peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) 2024-06-14T14:52:35.471632Z TRACE litep2p::transport-service: keep-alive timeout over, downgrade connection peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) 2024-06-14T14:52:35.491059Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:35.491077Z TRACE litep2p::yamux: fc17bf02: write: (WriteState::Init) 2024-06-14T14:52:35.491086Z TRACE litep2p::yamux: fc17bf02: read: (ReadState::Header (offset 0)) 2024-06-14T14:52:35.491118Z TRACE litep2p::yamux: fc17bf02/1: update state: (from Open { acknowledged: true } to Closed -> Closed) 2024-06-14T14:52:35.491171Z DEBUG litep2p::tcp::connection: connection closed with error peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") error=Decode(Io(Kind(UnexpectedEof))) 2024-06-14T14:52:35.491265Z TRACE litep2p::transport-service: primary connection closed peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) 2024-06-14T14:52:35.491293Z DEBUG litep2p::request-response::protocol: connection closed peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 2024-06-14T14:52:35.491306Z TRACE litep2p::transport-service: primary connection closed peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) 2024-06-14T14:52:35.491334Z DEBUG litep2p::yamux: fc17bf02/1: eof 2024-06-14T14:52:35.491324Z TRACE litep2p::transport-manager: connection closed peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") connection_id=ConnectionId(0) 2024-06-14T14:52:35.491771Z DEBUG litep2p::request-response::protocol: connection closed peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/control/1 2024-06-14T14:52:35.491813Z WARN dephy_pproxy: request failed: Rejected 2024-06-14T14:52:35.491858Z DEBUG litep2p::request-response::protocol: failed to handle substream event peer=PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r") protocol=/pproxy/tunnel/1 request_id=RequestId(0) error=PeerDoesntExist(PeerId("12D3KooWEuyctdqotRHsJcqy1BRTwFcVjx27Jbide8K1UyYfFV9r")) 2024-06-14T14:52:35.491941Z TRACE h2::proto::streams::send: send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }; init_window=2097152 2024-06-14T14:52:35.492389Z TRACE Prioritize::queue_frame{stream.id=StreamId(1)}: h2::proto::streams::prioritize: schedule_send stream.id=StreamId(1) 2024-06-14T14:52:35.492403Z TRACE Prioritize::queue_frame{stream.id=StreamId(1)}: h2::proto::streams::store: Queue::push_back 2024-06-14T14:52:35.492411Z TRACE Prioritize::queue_frame{stream.id=StreamId(1)}: h2::proto::streams::store: -> first entry 2024-06-14T14:52:35.492859Z TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:35.492868Z TRACE h2::proto::streams::streams: drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 2, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(2097152), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x152704d00, vtable: 0x104e111f8 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 0 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(1048317), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_recv: false, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted } 2024-06-14T14:52:35.493310Z TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:35.493733Z TRACE h2::proto::streams::streams: drop_stream_ref; stream=Stream { id: StreamId(1), state: State { inner: Closed(EndStream) }, is_counted: true, ref_count: 1, next_pending_send: None, is_pending_send: true, send_flow: FlowControl { window_size: Window(2097152), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x152704d00, vtable: 0x104e111f8 }), pending_send: Deque { indices: Some(Indices { head: 0, tail: 0 }) }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: false, next_open: None, is_pending_open: false, is_pending_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(1048317), available: Window(1048576) }, in_flight_recv_data: 0, next_window_update: None, is_pending_window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, is_recv: false, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted } 2024-06-14T14:52:35.494131Z TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=false; pending_send_empty=false; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:35.494412Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open 2024-06-14T14:52:35.494442Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:35.494467Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: poll_complete 2024-06-14T14:52:35.494477Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open 2024-06-14T14:52:35.494766Z TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(EndStream) }}: h2::proto::streams::prioritize: is_pending_reset=false 2024-06-14T14:52:35.494780Z TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(EndStream) }}: h2::proto::streams::prioritize: pop_frame; frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } 2024-06-14T14:52:35.495062Z TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(EndStream) }}: h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=1; num_send=0 2024-06-14T14:52:35.495081Z TRACE server_handshake:Connection{peer=Server}:poll:pop_frame:popped{stream.id=StreamId(1) stream.state=State { inner: Closed(EndStream) }}: h2::proto::streams::counts: dec_num_streams; stream=StreamId(1) 2024-06-14T14:52:35.495370Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: writing frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } 2024-06-14T14:52:35.495391Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) } 2024-06-14T14:52:35.495775Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::prioritize: schedule_pending_open 2024-06-14T14:52:35.495797Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false 2024-06-14T14:52:35.495826Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer 2024-06-14T14:52:35.497072Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Open 2024-06-14T14:52:35.497102Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:35.497121Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=17 2024-06-14T14:52:35.497145Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=17}: h2::codec::framed_read: decoding frame from 17B 2024-06-14T14:52:35.497444Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=17}: h2::codec::framed_read: frame.kind=GoAway 2024-06-14T14:52:35.497469Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) } 2024-06-14T14:52:35.497488Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: recv GOAWAY frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) } 2024-06-14T14:52:35.497791Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: h2::codec::framed_read: poll 2024-06-14T14:52:35.497810Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: codec closed 2024-06-14T14:52:35.497821Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::streams::streams: Streams::recv_eof 2024-06-14T14:52:35.498140Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Closing(NO_ERROR, Library) 2024-06-14T14:52:35.498153Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection closing after flush 2024-06-14T14:52:35.498166Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer 2024-06-14T14:52:35.498185Z TRACE server_handshake:Connection{peer=Server}:poll: h2::proto::connection: connection.state=Closed(NO_ERROR, Library) 2024-06-14T14:52:35.498470Z TRACE hyper::proto::h2::server: incoming connection complete 2024-06-14T14:52:35.498488Z TRACE h2::proto::streams::streams: Streams::recv_eof ```
altonen commented 3 months ago

If you don't have any other protocols open over the the connection and the request timeouts after the keep-alive timeout is over, the connection will be closed. This is expected behavior.

If you'd wish to keep the connection open, you could introduce a keep-alive protocol which just opens a new substream when a connection is established and keeps that substream open until you explicitly ask that protocol to close it. Maybe this would give the control you want?

Ma233 commented 3 months ago

@altonen Hi, I opened a pull request #155 to enable timeout configuration of RequestResponseProtocol to keep-alive. I'm not sure if this change conforms to the design concept of litep2p. It's only used to describe a direction of solution.