Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fix(pnet): flush nonce in handshake #3476

Merged
merged 12 commits into from
Feb 28, 2023
Merged

fix(pnet): flush nonce in handshake #3476

merged 12 commits into from
Feb 28, 2023

Conversation

hanabi1224
Copy link
Contributor

@hanabi1224 hanabi1224 commented Feb 16, 2023 •
edited by thomaseizinger
Loading

Description

Previously, we did not flush the nonce within the handshake to the stream. This caused problems when pnet was composed with the websocket transport. Inserting a flush fixes these compatibility problems.

Resolves #3475.

Notes

To reproduce fix the bug in #3475

Links to any relevant issues

Open Questions

Change checklist

  • I have performed a self-review of my own code
  • I have made corresponding changes to the documentation
  • I have added tests that prove my fix is effective or that my feature works
  • A changelog entry has been made in the appropriate crates

@hanabi1224 hanabi1224 mentioned this pull request Feb 16, 2023
Closed
@hanabi1224 hanabi1224 changed the title pnet smoke tests test: pnet smoke tests Feb 16, 2023
@hanabi1224 hanabi1224 marked this pull request as ready for review February 19, 2023 23:13
@thomaseizinger
Copy link
Contributor

Thanks for opening this!

Anything interesting in the logs? For example, do you see this one?

https://github.com/libp2p/rust-libp2p/blob/master/transports/websocket/src/framed.rs#L387

@hanabi1224
Copy link
Contributor Author

@thomaseizinger here're the trace logs of can_establish_connection_websocket

running 1 test
2023-02-28T01:03:01.877283Z DEBUG libp2p_tcp: listening on 127.0.0.1:0    
2023-02-28T01:03:01.877514Z TRACE mio::poll: registering event source with poller: token=Token(0), interests=READABLE | WRITABLE    
2023-02-28T01:03:01.877604Z DEBUG libp2p_websocket::framed: Listening on /ip4/127.0.0.1/tcp/35559/ws    
2023-02-28T01:03:01.877651Z DEBUG libp2p_swarm: Listener ListenerId(7536652105554812243); New address: "/ip4/127.0.0.1/tcp/35559/ws"    
2023-02-28T01:03:01.877872Z TRACE libp2p_websocket::framed: Dialing websocket address: WsAddress { host_port: "127.0.0.1:35559", path: "/", dns_name: None, use_tls: false, tcp_addr: "/ip4/127.0.0.1/tcp/35559" }    
2023-02-28T01:03:01.877929Z DEBUG libp2p_tcp: dialing 127.0.0.1:35559    
2023-02-28T01:03:01.878035Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE    
2023-02-28T01:03:01.878132Z TRACE mio::poll: registering event source with poller: token=Token(2), interests=READABLE | WRITABLE    
2023-02-28T01:03:01.878170Z DEBUG libp2p_tcp: Incoming connection from /ip4/127.0.0.1/tcp/54106 at /ip4/127.0.0.1/tcp/35559    
2023-02-28T01:03:01.878290Z TRACE libp2p_websocket::framed: TCP connection to 127.0.0.1:35559 established.    
2023-02-28T01:03:01.878322Z TRACE libp2p_websocket::framed: Sending websocket handshake to 127.0.0.1:35559    
2023-02-28T01:03:01.878408Z TRACE libp2p_websocket::framed: incoming connection from /ip4/127.0.0.1/tcp/54106/ws    
2023-02-28T01:03:01.878444Z TRACE libp2p_websocket::framed: receiving websocket handshake request from /ip4/127.0.0.1/tcp/54106/ws    
2023-02-28T01:03:01.878527Z TRACE soketto: read 154 bytes    
2023-02-28T01:03:01.878601Z TRACE libp2p_websocket::framed: accepting websocket handshake request from /ip4/127.0.0.1/tcp/54106/ws    
2023-02-28T01:03:01.878696Z TRACE libp2p_pnet: exchanging nonces    
2023-02-28T01:03:01.878773Z TRACE soketto: read 152 bytes    
2023-02-28T01:03:01.878836Z TRACE libp2p_websocket::framed: websocket handshake with 127.0.0.1:35559 successful    
2023-02-28T01:03:01.878871Z TRACE libp2p_pnet: exchanging nonces    
2023-02-28T01:03:06.876670Z TRACE mio::poll: deregistering event source from poller    
thread 'can_establish_connection_websocket' panicked at 'called `Result::unwrap()` on an `Err` value: Elapsed(())', transports/pnet/tests/smoke.rs:56:47
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
2023-02-28T01:03:06.877087Z TRACE mio::poll: deregistering event source from poller    
2023-02-28T01:03:06.877202Z TRACE mio::poll: deregistering event source from poller    
test can_establish_connection_websocket ... FAILED

can_establish_connection_tcp:

running 1 test
2023-02-28T01:04:35.141167Z DEBUG libp2p_tcp: listening on 127.0.0.1:0    
2023-02-28T01:04:35.141457Z TRACE mio::poll: registering event source with poller: token=Token(0), interests=READABLE | WRITABLE    
2023-02-28T01:04:35.141596Z DEBUG libp2p_swarm: Listener ListenerId(8542997022265834147); New address: "/ip4/127.0.0.1/tcp/44959"    
2023-02-28T01:04:35.141760Z DEBUG libp2p_tcp: dialing 127.0.0.1:44959    
2023-02-28T01:04:35.142188Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE    
2023-02-28T01:04:35.142366Z TRACE mio::poll: registering event source with poller: token=Token(2), interests=READABLE | WRITABLE    
2023-02-28T01:04:35.142416Z DEBUG libp2p_tcp: Incoming connection from /ip4/127.0.0.1/tcp/51992 at /ip4/127.0.0.1/tcp/44959    
2023-02-28T01:04:35.142571Z TRACE libp2p_pnet: exchanging nonces    
2023-02-28T01:04:35.142669Z TRACE libp2p_pnet: exchanging nonces    
2023-02-28T01:04:35.142863Z TRACE libp2p_pnet: setting up ciphers    
2023-02-28T01:04:35.143138Z TRACE libp2p_pnet: setting up ciphers    
2023-02-28T01:04:35.143305Z DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /noise    
2023-02-28T01:04:35.143386Z TRACE libp2p_pnet::crypt_writer: encrypted 28 bytes    
2023-02-28T01:04:35.143519Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:04:35.143587Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:04:35.143632Z TRACE libp2p_pnet: read 19 bytes    
2023-02-28T01:04:35.143673Z TRACE libp2p_pnet: decrypted 19 bytes    
2023-02-28T01:04:35.143722Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:04:35.143764Z TRACE libp2p_pnet::crypt_writer: encrypted 20 bytes    
2023-02-28T01:04:35.143829Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:04:35.143854Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:04:35.143878Z TRACE libp2p_pnet: read 7 bytes    
2023-02-28T01:04:35.143898Z TRACE libp2p_pnet: decrypted 7 bytes    
2023-02-28T01:04:35.143919Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/noise"))    
2023-02-28T01:04:35.143942Z DEBUG multistream_select::listener_select: Listener: confirming protocol: /noise    
2023-02-28T01:04:35.143967Z TRACE libp2p_pnet::crypt_writer: encrypted 8 bytes    
2023-02-28T01:04:35.143992Z DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /noise    
2023-02-28T01:04:35.144715Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.144793Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.144961Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:04:35.145020Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:04:35.145084Z TRACE libp2p_pnet: read 19 bytes    
2023-02-28T01:04:35.145127Z TRACE libp2p_pnet: decrypted 19 bytes    
2023-02-28T01:04:35.145178Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:04:35.198229Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:04:35.198308Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:04:35.198363Z TRACE libp2p_pnet: read 7 bytes    
2023-02-28T01:04:35.198399Z TRACE libp2p_pnet: decrypted 7 bytes    
2023-02-28T01:04:35.198439Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/noise"))    
2023-02-28T01:04:35.198477Z DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /noise    
2023-02-28T01:04:35.199013Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.199484Z TRACE libp2p_noise::io::framed: write: cipher text len = 32 bytes    
2023-02-28T01:04:35.199513Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 32, buf: [0, 32], off: 0 }    
2023-02-28T01:04:35.199539Z TRACE libp2p_noise::io::framed: write: frame len (32, [0, 32], 0/2)    
2023-02-28T01:04:35.199567Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:04:35.199608Z TRACE libp2p_noise::io::framed: write state WriteData { len: 32, off: 0 }    
2023-02-28T01:04:35.199636Z TRACE libp2p_pnet::crypt_writer: encrypted 32 bytes    
2023-02-28T01:04:35.199650Z TRACE libp2p_noise::io::framed: write: 32/32 bytes written    
2023-02-28T01:04:35.199657Z TRACE libp2p_noise::io::framed: write: finished with 32 bytes    
2023-02-28T01:04:35.199678Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.199691Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.199700Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.199809Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.199863Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:04:35.199887Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:04:35.199909Z TRACE libp2p_noise::io::framed: read: frame len = 32    
2023-02-28T01:04:35.199927Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 32, off: 0 }    
2023-02-28T01:04:35.258180Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 32, off: 0 }    
2023-02-28T01:04:35.258276Z TRACE libp2p_pnet: read 32 bytes    
2023-02-28T01:04:35.258320Z TRACE libp2p_pnet: decrypted 32 bytes    
2023-02-28T01:04:35.258352Z TRACE libp2p_noise::io::framed: read: 32/32 bytes    
2023-02-28T01:04:35.258382Z TRACE libp2p_noise::io::framed: read: decrypting 32 bytes    
2023-02-28T01:04:35.258443Z TRACE libp2p_noise::io::framed: read: payload len = 0 bytes    
2023-02-28T01:04:35.258506Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.259623Z TRACE libp2p_noise::io::framed: write: cipher text len = 200 bytes    
2023-02-28T01:04:35.259651Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 200, buf: [0, 200], off: 0 }    
2023-02-28T01:04:35.259681Z TRACE libp2p_noise::io::framed: write: frame len (200, [0, 200], 0/2)    
2023-02-28T01:04:35.259710Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:04:35.259751Z TRACE libp2p_noise::io::framed: write state WriteData { len: 200, off: 0 }    
2023-02-28T01:04:35.259809Z TRACE libp2p_pnet::crypt_writer: encrypted 200 bytes    
2023-02-28T01:04:35.259840Z TRACE libp2p_noise::io::framed: write: 200/200 bytes written    
2023-02-28T01:04:35.259864Z TRACE libp2p_noise::io::framed: write: finished with 200 bytes    
2023-02-28T01:04:35.259885Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.259916Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.259938Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.260006Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.260040Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:04:35.260051Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:04:35.260058Z TRACE libp2p_noise::io::framed: read: frame len = 200    
2023-02-28T01:04:35.260068Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 200, off: 0 }    
2023-02-28T01:04:35.308238Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 200, off: 0 }    
2023-02-28T01:04:35.308339Z TRACE libp2p_pnet: read 200 bytes    
2023-02-28T01:04:35.308420Z TRACE libp2p_pnet: decrypted 200 bytes    
2023-02-28T01:04:35.308450Z TRACE libp2p_noise::io::framed: read: 200/200 bytes    
2023-02-28T01:04:35.308477Z TRACE libp2p_noise::io::framed: read: decrypting 200 bytes    
2023-02-28T01:04:35.309187Z TRACE libp2p_noise::io::framed: read: payload len = 104 bytes    
2023-02-28T01:04:35.309274Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.309646Z TRACE libp2p_noise::io::framed: write: cipher text len = 168 bytes    
2023-02-28T01:04:35.309673Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 168, buf: [0, 168], off: 0 }    
2023-02-28T01:04:35.309701Z TRACE libp2p_noise::io::framed: write: frame len (168, [0, 168], 0/2)    
2023-02-28T01:04:35.309728Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:04:35.309755Z TRACE libp2p_noise::io::framed: write state WriteData { len: 168, off: 0 }    
2023-02-28T01:04:35.309818Z TRACE libp2p_pnet::crypt_writer: encrypted 168 bytes    
2023-02-28T01:04:35.309846Z TRACE libp2p_noise::io::framed: write: 168/168 bytes written    
2023-02-28T01:04:35.309869Z TRACE libp2p_noise::io::framed: write: finished with 168 bytes    
2023-02-28T01:04:35.309890Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.310235Z TRACE libp2p_core::upgrade::apply: Upgraded outbound stream to /noise    
2023-02-28T01:04:35.310298Z DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /yamux/1.0.0    
2023-02-28T01:04:35.310331Z TRACE libp2p_noise::io: write: buffered 34 bytes    
2023-02-28T01:04:35.310355Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.310388Z TRACE libp2p_noise::io: flush: sending 34 bytes    
2023-02-28T01:04:35.310427Z TRACE libp2p_noise::io::framed: write: cipher text len = 50 bytes    
2023-02-28T01:04:35.310448Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 50, buf: [0, 50], off: 0 }    
2023-02-28T01:04:35.310472Z TRACE libp2p_noise::io::framed: write: frame len (50, [0, 50], 0/2)    
2023-02-28T01:04:35.310496Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:04:35.310524Z TRACE libp2p_noise::io::framed: write state WriteData { len: 50, off: 0 }    
2023-02-28T01:04:35.310553Z TRACE libp2p_pnet::crypt_writer: encrypted 50 bytes    
2023-02-28T01:04:35.310593Z TRACE libp2p_noise::io::framed: write: 50/50 bytes written    
2023-02-28T01:04:35.310614Z TRACE libp2p_noise::io::framed: write: finished with 50 bytes    
2023-02-28T01:04:35.310634Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.310650Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.310686Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.310833Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.310902Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:04:35.310946Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:04:35.311007Z TRACE libp2p_noise::io::framed: read: frame len = 168    
2023-02-28T01:04:35.311070Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 168, off: 0 }    
2023-02-28T01:04:35.358246Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 168, off: 0 }    
2023-02-28T01:04:35.358377Z TRACE libp2p_pnet: read 168 bytes    
2023-02-28T01:04:35.358436Z TRACE libp2p_pnet: decrypted 168 bytes    
2023-02-28T01:04:35.358461Z TRACE libp2p_noise::io::framed: read: 168/168 bytes    
2023-02-28T01:04:35.358484Z TRACE libp2p_noise::io::framed: read: decrypting 168 bytes    
2023-02-28T01:04:35.359058Z TRACE libp2p_noise::io::framed: read: payload len = 104 bytes    
2023-02-28T01:04:35.359539Z TRACE libp2p_core::upgrade::apply: Upgraded inbound stream to /noise    
2023-02-28T01:04:35.359598Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.359621Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.359652Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:04:35.359675Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:04:35.359695Z TRACE libp2p_noise::io::framed: read: frame len = 50    
2023-02-28T01:04:35.359717Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 50, off: 0 }    
2023-02-28T01:04:35.359747Z TRACE libp2p_pnet: read 50 bytes    
2023-02-28T01:04:35.359785Z TRACE libp2p_pnet: decrypted 50 bytes    
2023-02-28T01:04:35.359803Z TRACE libp2p_noise::io::framed: read: 50/50 bytes    
2023-02-28T01:04:35.359811Z TRACE libp2p_noise::io::framed: read: decrypting 50 bytes    
2023-02-28T01:04:35.359833Z TRACE libp2p_noise::io::framed: read: payload len = 34 bytes    
2023-02-28T01:04:35.359854Z TRACE libp2p_noise::io: read: copied 1/34 bytes    
2023-02-28T01:04:35.359879Z TRACE libp2p_noise::io: read: copied 20/34 bytes    
2023-02-28T01:04:35.359892Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:04:35.359928Z TRACE libp2p_noise::io: write: buffered 20 bytes    
2023-02-28T01:04:35.359950Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.359968Z TRACE libp2p_noise::io: flush: sending 20 bytes    
2023-02-28T01:04:35.360009Z TRACE libp2p_noise::io::framed: write: cipher text len = 36 bytes    
2023-02-28T01:04:35.360027Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 36, buf: [0, 36], off: 0 }    
2023-02-28T01:04:35.360046Z TRACE libp2p_noise::io::framed: write: frame len (36, [0, 36], 0/2)    
2023-02-28T01:04:35.360069Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:04:35.360108Z TRACE libp2p_noise::io::framed: write state WriteData { len: 36, off: 0 }    
2023-02-28T01:04:35.360135Z TRACE libp2p_pnet::crypt_writer: encrypted 36 bytes    
2023-02-28T01:04:35.360147Z TRACE libp2p_noise::io::framed: write: 36/36 bytes written    
2023-02-28T01:04:35.360165Z TRACE libp2p_noise::io::framed: write: finished with 36 bytes    
2023-02-28T01:04:35.360178Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.360192Z TRACE libp2p_noise::io: read: copied 21/34 bytes    
2023-02-28T01:04:35.360211Z TRACE libp2p_noise::io: read: copied 34/34 bytes    
2023-02-28T01:04:35.360229Z TRACE libp2p_noise::io: read: frame consumed    
2023-02-28T01:04:35.360249Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/yamux/1.0.0"))    
2023-02-28T01:04:35.360272Z DEBUG multistream_select::listener_select: Listener: confirming protocol: /yamux/1.0.0    
2023-02-28T01:04:35.360298Z TRACE libp2p_noise::io: write: buffered 14 bytes    
2023-02-28T01:04:35.360318Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.360326Z TRACE libp2p_noise::io: flush: sending 14 bytes    
2023-02-28T01:04:35.360354Z TRACE libp2p_noise::io::framed: write: cipher text len = 30 bytes    
2023-02-28T01:04:35.360372Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 30, buf: [0, 30], off: 0 }    
2023-02-28T01:04:35.360391Z TRACE libp2p_noise::io::framed: write: frame len (30, [0, 30], 0/2)    
2023-02-28T01:04:35.360411Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:04:35.360434Z TRACE libp2p_noise::io::framed: write state WriteData { len: 30, off: 0 }    
2023-02-28T01:04:35.360455Z TRACE libp2p_pnet::crypt_writer: encrypted 30 bytes    
2023-02-28T01:04:35.360476Z TRACE libp2p_noise::io::framed: write: 30/30 bytes written    
2023-02-28T01:04:35.360509Z TRACE libp2p_noise::io::framed: write: finished with 30 bytes    
2023-02-28T01:04:35.360527Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.360546Z DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /yamux/1.0.0    
2023-02-28T01:04:35.360576Z DEBUG yamux::connection: new connection: b2de4c0c (Server)    
2023-02-28T01:04:35.360620Z TRACE libp2p_core::upgrade::apply: Upgraded inbound stream to /yamux/1.0.0    
2023-02-28T01:04:35.360808Z DEBUG libp2p_swarm: Connection established: PeerId("12D3KooWHbKEy8pz1gKaYNWi6d2fQMHRjwJjB7jp2ajkWVPBVCcz") Listener { local_addr: "/ip4/127.0.0.1/tcp/44959", send_back_addr: "/ip4/127.0.0.1/tcp/51992" }; Total (peer): 1.    
2023-02-28T01:04:35.360941Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.360973Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:04:35.360994Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:04:35.361022Z TRACE libp2p_noise::io::framed: read: frame len = 36    
2023-02-28T01:04:35.361040Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 36, off: 0 }    
2023-02-28T01:04:35.361103Z TRACE yamux::frame::io: b2de4c0c: write: (WriteState::Init)    
2023-02-28T01:04:35.361140Z TRACE yamux::frame::io: b2de4c0c: read: (ReadState::Init)    
2023-02-28T01:04:35.361171Z TRACE yamux::frame::io: b2de4c0c: read: (ReadState::Header (offset 0))    
2023-02-28T01:04:35.361191Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.361208Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.361234Z TRACE yamux::frame::io: b2de4c0c: write: (WriteState::Init)    
2023-02-28T01:04:35.361254Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:04:35.361291Z TRACE yamux::frame::io: b2de4c0c: read: (ReadState::Header (offset 0))    
2023-02-28T01:04:35.361311Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.408341Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 36, off: 0 }    
2023-02-28T01:04:35.408432Z TRACE libp2p_pnet: read 36 bytes    
2023-02-28T01:04:35.408479Z TRACE libp2p_pnet: decrypted 36 bytes    
2023-02-28T01:04:35.408505Z TRACE libp2p_noise::io::framed: read: 36/36 bytes    
2023-02-28T01:04:35.408529Z TRACE libp2p_noise::io::framed: read: decrypting 36 bytes    
2023-02-28T01:04:35.408568Z TRACE libp2p_noise::io::framed: read: payload len = 20 bytes    
2023-02-28T01:04:35.408601Z TRACE libp2p_noise::io: read: copied 1/20 bytes    
2023-02-28T01:04:35.408643Z TRACE libp2p_noise::io: read: copied 20/20 bytes    
2023-02-28T01:04:35.408656Z TRACE libp2p_noise::io: read: frame consumed    
2023-02-28T01:04:35.408685Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:04:35.408712Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:04:35.408747Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:04:35.408775Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:04:35.408796Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:04:35.408817Z TRACE libp2p_noise::io::framed: read: frame len = 30    
2023-02-28T01:04:35.408836Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 30, off: 0 }    
2023-02-28T01:04:35.408860Z TRACE libp2p_pnet: read 30 bytes    
2023-02-28T01:04:35.408882Z TRACE libp2p_pnet: decrypted 30 bytes    
2023-02-28T01:04:35.408902Z TRACE libp2p_noise::io::framed: read: 30/30 bytes    
2023-02-28T01:04:35.408921Z TRACE libp2p_noise::io::framed: read: decrypting 30 bytes    
2023-02-28T01:04:35.408943Z TRACE libp2p_noise::io::framed: read: payload len = 14 bytes    
2023-02-28T01:04:35.408965Z TRACE libp2p_noise::io: read: copied 1/14 bytes    
2023-02-28T01:04:35.408987Z TRACE libp2p_noise::io: read: copied 14/14 bytes    
2023-02-28T01:04:35.409007Z TRACE libp2p_noise::io: read: frame consumed    
2023-02-28T01:04:35.409029Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/yamux/1.0.0"))    
2023-02-28T01:04:35.409053Z DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /yamux/1.0.0    
2023-02-28T01:04:35.409084Z DEBUG yamux::connection: new connection: e5f197bb (Client)    
2023-02-28T01:04:35.409124Z TRACE libp2p_core::upgrade::apply: Upgraded outbound stream to /yamux/1.0.0    
2023-02-28T01:04:35.409295Z DEBUG libp2p_swarm: Connection established: PeerId("12D3KooWR7sA3R9yp4oRcPzLbrRWCpHgmwP62XQeo47UABQATibr") Dialer { address: "/ip4/127.0.0.1/tcp/44959", role_override: Dialer }; Total (peer): 1.    
2023-02-28T01:04:35.409457Z TRACE mio::poll: deregistering event source from poller    
2023-02-28T01:04:35.409559Z TRACE mio::poll: deregistering event source from poller    
2023-02-28T01:04:35.409632Z TRACE mio::poll: deregistering event source from poller    
test can_establish_connection_tcp ... ok

can_establish_connection_memory:

running 1 test
2023-02-28T01:05:30.745174Z DEBUG libp2p_swarm: Listener ListenerId(10624651771940654525); New address: "/memory/18427787989218526450"    
2023-02-28T01:05:30.745405Z TRACE libp2p_pnet: exchanging nonces    
2023-02-28T01:05:30.745539Z TRACE libp2p_pnet: exchanging nonces    
2023-02-28T01:05:30.745585Z TRACE libp2p_pnet: setting up ciphers    
2023-02-28T01:05:30.745678Z TRACE libp2p_pnet: setting up ciphers    
2023-02-28T01:05:30.745742Z DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /noise    
2023-02-28T01:05:30.745785Z TRACE libp2p_pnet::crypt_writer: encrypted 28 bytes    
2023-02-28T01:05:30.745829Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:05:30.745859Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:05:30.745881Z TRACE libp2p_pnet: read 19 bytes    
2023-02-28T01:05:30.745900Z TRACE libp2p_pnet: decrypted 19 bytes    
2023-02-28T01:05:30.745910Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:05:30.745937Z TRACE libp2p_pnet::crypt_writer: encrypted 20 bytes    
2023-02-28T01:05:30.745965Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:05:30.745987Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:05:30.746008Z TRACE libp2p_pnet: read 7 bytes    
2023-02-28T01:05:30.746026Z TRACE libp2p_pnet: decrypted 7 bytes    
2023-02-28T01:05:30.746046Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/noise"))    
2023-02-28T01:05:30.746069Z DEBUG multistream_select::listener_select: Listener: confirming protocol: /noise    
2023-02-28T01:05:30.746084Z TRACE libp2p_pnet::crypt_writer: encrypted 8 bytes    
2023-02-28T01:05:30.746107Z DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /noise    
2023-02-28T01:05:30.746433Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:05:30.746459Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.746502Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:05:30.746528Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:05:30.746548Z TRACE libp2p_pnet: read 19 bytes    
2023-02-28T01:05:30.746567Z TRACE libp2p_pnet: decrypted 19 bytes    
2023-02-28T01:05:30.746587Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:05:30.746608Z TRACE libp2p_pnet: read 1 bytes    
2023-02-28T01:05:30.746627Z TRACE libp2p_pnet: decrypted 1 bytes    
2023-02-28T01:05:30.746647Z TRACE libp2p_pnet: read 7 bytes    
2023-02-28T01:05:30.746665Z TRACE libp2p_pnet: decrypted 7 bytes    
2023-02-28T01:05:30.746685Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/noise"))    
2023-02-28T01:05:30.746706Z DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /noise    
2023-02-28T01:05:30.746994Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.747312Z TRACE libp2p_noise::io::framed: write: cipher text len = 32 bytes    
2023-02-28T01:05:30.747336Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 32, buf: [0, 32], off: 0 }    
2023-02-28T01:05:30.747358Z TRACE libp2p_noise::io::framed: write: frame len (32, [0, 32], 0/2)    
2023-02-28T01:05:30.747378Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:05:30.747406Z TRACE libp2p_noise::io::framed: write state WriteData { len: 32, off: 0 }    
2023-02-28T01:05:30.747429Z TRACE libp2p_pnet::crypt_writer: encrypted 32 bytes    
2023-02-28T01:05:30.747450Z TRACE libp2p_noise::io::framed: write: 32/32 bytes written    
2023-02-28T01:05:30.747468Z TRACE libp2p_noise::io::framed: write: finished with 32 bytes    
2023-02-28T01:05:30.747475Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.747483Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:05:30.747489Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.747512Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.747522Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:05:30.747528Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:05:30.747539Z TRACE libp2p_noise::io::framed: read: frame len = 32    
2023-02-28T01:05:30.747547Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 32, off: 0 }    
2023-02-28T01:05:30.747554Z TRACE libp2p_pnet: read 32 bytes    
2023-02-28T01:05:30.747560Z TRACE libp2p_pnet: decrypted 32 bytes    
2023-02-28T01:05:30.747566Z TRACE libp2p_noise::io::framed: read: 32/32 bytes    
2023-02-28T01:05:30.747571Z TRACE libp2p_noise::io::framed: read: decrypting 32 bytes    
2023-02-28T01:05:30.747584Z TRACE libp2p_noise::io::framed: read: payload len = 0 bytes    
2023-02-28T01:05:30.747599Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.748433Z TRACE libp2p_noise::io::framed: write: cipher text len = 200 bytes    
2023-02-28T01:05:30.748460Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 200, buf: [0, 200], off: 0 }    
2023-02-28T01:05:30.748482Z TRACE libp2p_noise::io::framed: write: frame len (200, [0, 200], 0/2)    
2023-02-28T01:05:30.748503Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:05:30.748531Z TRACE libp2p_noise::io::framed: write state WriteData { len: 200, off: 0 }    
2023-02-28T01:05:30.748571Z TRACE libp2p_pnet::crypt_writer: encrypted 200 bytes    
2023-02-28T01:05:30.748593Z TRACE libp2p_noise::io::framed: write: 200/200 bytes written    
2023-02-28T01:05:30.748612Z TRACE libp2p_noise::io::framed: write: finished with 200 bytes    
2023-02-28T01:05:30.748629Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.748649Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:05:30.748667Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.748704Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.748730Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:05:30.748750Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:05:30.748768Z TRACE libp2p_noise::io::framed: read: frame len = 200    
2023-02-28T01:05:30.748779Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 200, off: 0 }    
2023-02-28T01:05:30.748799Z TRACE libp2p_pnet: read 200 bytes    
2023-02-28T01:05:30.748835Z TRACE libp2p_pnet: decrypted 200 bytes    
2023-02-28T01:05:30.748854Z TRACE libp2p_noise::io::framed: read: 200/200 bytes    
2023-02-28T01:05:30.748872Z TRACE libp2p_noise::io::framed: read: decrypting 200 bytes    
2023-02-28T01:05:30.749393Z TRACE libp2p_noise::io::framed: read: payload len = 104 bytes    
2023-02-28T01:05:30.749452Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.749749Z TRACE libp2p_noise::io::framed: write: cipher text len = 168 bytes    
2023-02-28T01:05:30.749771Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 168, buf: [0, 168], off: 0 }    
2023-02-28T01:05:30.749792Z TRACE libp2p_noise::io::framed: write: frame len (168, [0, 168], 0/2)    
2023-02-28T01:05:30.749813Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:05:30.749839Z TRACE libp2p_noise::io::framed: write state WriteData { len: 168, off: 0 }    
2023-02-28T01:05:30.749877Z TRACE libp2p_pnet::crypt_writer: encrypted 168 bytes    
2023-02-28T01:05:30.749900Z TRACE libp2p_noise::io::framed: write: 168/168 bytes written    
2023-02-28T01:05:30.749919Z TRACE libp2p_noise::io::framed: write: finished with 168 bytes    
2023-02-28T01:05:30.749936Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.750212Z TRACE libp2p_core::upgrade::apply: Upgraded outbound stream to /noise    
2023-02-28T01:05:30.750262Z DEBUG multistream_select::dialer_select: Dialer: Proposed protocol: /yamux/1.0.0    
2023-02-28T01:05:30.750288Z TRACE libp2p_noise::io: write: buffered 34 bytes    
2023-02-28T01:05:30.750308Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.750326Z TRACE libp2p_noise::io: flush: sending 34 bytes    
2023-02-28T01:05:30.750355Z TRACE libp2p_noise::io::framed: write: cipher text len = 50 bytes    
2023-02-28T01:05:30.750374Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 50, buf: [0, 50], off: 0 }    
2023-02-28T01:05:30.750394Z TRACE libp2p_noise::io::framed: write: frame len (50, [0, 50], 0/2)    
2023-02-28T01:05:30.750414Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:05:30.750437Z TRACE libp2p_noise::io::framed: write state WriteData { len: 50, off: 0 }    
2023-02-28T01:05:30.750462Z TRACE libp2p_pnet::crypt_writer: encrypted 50 bytes    
2023-02-28T01:05:30.750483Z TRACE libp2p_noise::io::framed: write: 50/50 bytes written    
2023-02-28T01:05:30.750492Z TRACE libp2p_noise::io::framed: write: finished with 50 bytes    
2023-02-28T01:05:30.750509Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.750529Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:05:30.750547Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.750589Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.750615Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:05:30.750635Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:05:30.750653Z TRACE libp2p_noise::io::framed: read: frame len = 168    
2023-02-28T01:05:30.750673Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 168, off: 0 }    
2023-02-28T01:05:30.750694Z TRACE libp2p_pnet: read 168 bytes    
2023-02-28T01:05:30.750730Z TRACE libp2p_pnet: decrypted 168 bytes    
2023-02-28T01:05:30.750748Z TRACE libp2p_noise::io::framed: read: 168/168 bytes    
2023-02-28T01:05:30.750766Z TRACE libp2p_noise::io::framed: read: decrypting 168 bytes    
2023-02-28T01:05:30.751056Z TRACE libp2p_noise::io::framed: read: payload len = 104 bytes    
2023-02-28T01:05:30.751349Z TRACE libp2p_core::upgrade::apply: Upgraded inbound stream to /noise    
2023-02-28T01:05:30.751404Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:05:30.751425Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.751449Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:05:30.751469Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:05:30.751486Z TRACE libp2p_noise::io::framed: read: frame len = 50    
2023-02-28T01:05:30.751494Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 50, off: 0 }    
2023-02-28T01:05:30.751513Z TRACE libp2p_pnet: read 50 bytes    
2023-02-28T01:05:30.751536Z TRACE libp2p_pnet: decrypted 50 bytes    
2023-02-28T01:05:30.751554Z TRACE libp2p_noise::io::framed: read: 50/50 bytes    
2023-02-28T01:05:30.751571Z TRACE libp2p_noise::io::framed: read: decrypting 50 bytes    
2023-02-28T01:05:30.751592Z TRACE libp2p_noise::io::framed: read: payload len = 34 bytes    
2023-02-28T01:05:30.751612Z TRACE libp2p_noise::io: read: copied 1/34 bytes    
2023-02-28T01:05:30.751632Z TRACE libp2p_noise::io: read: copied 20/34 bytes    
2023-02-28T01:05:30.751652Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:05:30.751677Z TRACE libp2p_noise::io: write: buffered 20 bytes    
2023-02-28T01:05:30.751698Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.751706Z TRACE libp2p_noise::io: flush: sending 20 bytes    
2023-02-28T01:05:30.751722Z TRACE libp2p_noise::io::framed: write: cipher text len = 36 bytes    
2023-02-28T01:05:30.751728Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 36, buf: [0, 36], off: 0 }    
2023-02-28T01:05:30.751735Z TRACE libp2p_noise::io::framed: write: frame len (36, [0, 36], 0/2)    
2023-02-28T01:05:30.751743Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:05:30.751758Z TRACE libp2p_noise::io::framed: write state WriteData { len: 36, off: 0 }    
2023-02-28T01:05:30.751783Z TRACE libp2p_pnet::crypt_writer: encrypted 36 bytes    
2023-02-28T01:05:30.751805Z TRACE libp2p_noise::io::framed: write: 36/36 bytes written    
2023-02-28T01:05:30.751824Z TRACE libp2p_noise::io::framed: write: finished with 36 bytes    
2023-02-28T01:05:30.751842Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.751862Z TRACE libp2p_noise::io: read: copied 21/34 bytes    
2023-02-28T01:05:30.751882Z TRACE libp2p_noise::io: read: copied 34/34 bytes    
2023-02-28T01:05:30.751900Z TRACE libp2p_noise::io: read: frame consumed    
2023-02-28T01:05:30.751920Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/yamux/1.0.0"))    
2023-02-28T01:05:30.751943Z DEBUG multistream_select::listener_select: Listener: confirming protocol: /yamux/1.0.0    
2023-02-28T01:05:30.751967Z TRACE libp2p_noise::io: write: buffered 14 bytes    
2023-02-28T01:05:30.751986Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.752004Z TRACE libp2p_noise::io: flush: sending 14 bytes    
2023-02-28T01:05:30.752035Z TRACE libp2p_noise::io::framed: write: cipher text len = 30 bytes    
2023-02-28T01:05:30.752053Z TRACE libp2p_noise::io::framed: write state WriteLen { len: 30, buf: [0, 30], off: 0 }    
2023-02-28T01:05:30.752073Z TRACE libp2p_noise::io::framed: write: frame len (30, [0, 30], 0/2)    
2023-02-28T01:05:30.752093Z TRACE libp2p_pnet::crypt_writer: encrypted 2 bytes    
2023-02-28T01:05:30.752114Z TRACE libp2p_noise::io::framed: write state WriteData { len: 30, off: 0 }    
2023-02-28T01:05:30.752135Z TRACE libp2p_pnet::crypt_writer: encrypted 30 bytes    
2023-02-28T01:05:30.752156Z TRACE libp2p_noise::io::framed: write: 30/30 bytes written    
2023-02-28T01:05:30.752175Z TRACE libp2p_noise::io::framed: write: finished with 30 bytes    
2023-02-28T01:05:30.752192Z TRACE libp2p_noise::io::framed: write state Ready    
2023-02-28T01:05:30.752211Z DEBUG multistream_select::listener_select: Listener: sent confirmed protocol: /yamux/1.0.0    
2023-02-28T01:05:30.752245Z DEBUG yamux::connection: new connection: 1cbe96fb (Server)    
2023-02-28T01:05:30.752291Z TRACE libp2p_core::upgrade::apply: Upgraded inbound stream to /yamux/1.0.0    
2023-02-28T01:05:30.752355Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.752391Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:05:30.752412Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:05:30.752431Z TRACE libp2p_noise::io::framed: read: frame len = 36    
2023-02-28T01:05:30.752448Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 36, off: 0 }    
2023-02-28T01:05:30.752469Z TRACE libp2p_pnet: read 36 bytes    
2023-02-28T01:05:30.752492Z TRACE libp2p_pnet: decrypted 36 bytes    
2023-02-28T01:05:30.752500Z TRACE libp2p_noise::io::framed: read: 36/36 bytes    
2023-02-28T01:05:30.752517Z TRACE libp2p_noise::io::framed: read: decrypting 36 bytes    
2023-02-28T01:05:30.752538Z TRACE libp2p_noise::io::framed: read: payload len = 20 bytes    
2023-02-28T01:05:30.752558Z TRACE libp2p_noise::io: read: copied 1/20 bytes    
2023-02-28T01:05:30.752577Z TRACE libp2p_noise::io: read: copied 20/20 bytes    
2023-02-28T01:05:30.752595Z TRACE libp2p_noise::io: read: frame consumed    
2023-02-28T01:05:30.752614Z TRACE multistream_select::protocol: Received message: Header(V1)    
2023-02-28T01:05:30.752634Z TRACE libp2p_noise::io::framed: read state: Ready    
2023-02-28T01:05:30.752652Z TRACE libp2p_noise::io::framed: read state: ReadLen { buf: [0, 0], off: 0 }    
2023-02-28T01:05:30.752674Z TRACE libp2p_pnet: read 2 bytes    
2023-02-28T01:05:30.752693Z TRACE libp2p_pnet: decrypted 2 bytes    
2023-02-28T01:05:30.752710Z TRACE libp2p_noise::io::framed: read: frame len = 30    
2023-02-28T01:05:30.752717Z TRACE libp2p_noise::io::framed: read state: ReadData { len: 30, off: 0 }    
2023-02-28T01:05:30.752736Z TRACE libp2p_pnet: read 30 bytes    
2023-02-28T01:05:30.752756Z TRACE libp2p_pnet: decrypted 30 bytes    
2023-02-28T01:05:30.752773Z TRACE libp2p_noise::io::framed: read: 30/30 bytes    
2023-02-28T01:05:30.752791Z TRACE libp2p_noise::io::framed: read: decrypting 30 bytes    
2023-02-28T01:05:30.752811Z TRACE libp2p_noise::io::framed: read: payload len = 14 bytes    
2023-02-28T01:05:30.752831Z TRACE libp2p_noise::io: read: copied 1/14 bytes    
2023-02-28T01:05:30.752851Z TRACE libp2p_noise::io: read: copied 14/14 bytes    
2023-02-28T01:05:30.752868Z TRACE libp2p_noise::io: read: frame consumed    
2023-02-28T01:05:30.752888Z TRACE multistream_select::protocol: Received message: Protocol(Protocol(b"/yamux/1.0.0"))    
2023-02-28T01:05:30.752909Z DEBUG multistream_select::dialer_select: Dialer: Received confirmation for protocol: /yamux/1.0.0    
2023-02-28T01:05:30.752931Z DEBUG yamux::connection: new connection: aef7edba (Client)    
2023-02-28T01:05:30.752957Z TRACE libp2p_core::upgrade::apply: Upgraded outbound stream to /yamux/1.0.0    
2023-02-28T01:05:30.753116Z DEBUG libp2p_swarm: Connection established: PeerId("12D3KooWAE4nQGeYGRJNfQzHrHVBzzBhbN3MRFYKVf9ixbheWnBE") Listener { local_addr: "/memory/18427787989218526450", send_back_addr: "/memory/11701347791046994603" }; Total (peer): 1.    
2023-02-28T01:05:30.753250Z DEBUG libp2p_swarm: Connection established: PeerId("12D3KooWJHDEL4Avjs3SbFaN2JrXR17MS3Uq2PGNavw6vKnXvzSd") Dialer { address: "/memory/18427787989218526450", role_override: Dialer }; Total (peer): 1.    
test can_establish_connection_memory ... ok

@hanabi1224
Copy link
Contributor Author

@thomaseizinger this is fixed by flushing the socket right after writing during the handshake

@hanabi1224 hanabi1224 changed the title test: pnet smoke tests test(pnet ): pnet smoke tests Feb 28, 2023
@hanabi1224 hanabi1224 changed the title test(pnet ): pnet smoke tests test(pnet): pnet smoke tests Feb 28, 2023
@thomaseizinger thomaseizinger changed the title test(pnet): pnet smoke tests fix(pnet): flush nonce in handshake Feb 28, 2023
thomaseizinger
thomaseizinger approved these changes Feb 28, 2023
View reviewed changes
Copy link
Contributor

@thomaseizinger thomaseizinger left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice work, thank you for the reproduction and the fix!

transports/pnet/CHANGELOG.md Outdated Show resolved Hide resolved
@mergify mergify bot merged commit 52a32ff into libp2p:master Feb 28, 2023
@hanabi1224 hanabi1224 deleted the pnet-ws-test branch February 28, 2023 04:47
@mxinden
Copy link
Member

mxinden commented Mar 6, 2023

Great catch @hanabi1224. Thank you for the patch.

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

@thomaseizinger thomaseizinger thomaseizinger approved these changes

Assignees
No one assigned
Labels
send-it
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

BUG: pnet does not work on websocket listen address
3 participants
@hanabi1224 @thomaseizinger @mxinden