search

paritytech / litep2p

Peer-to-peer networking library
MIT License
67 stars 9 forks source link

The ignored_validation_open_substream test of websocket and tcp failed on a local PC #101

Closed Ma233 closed 4 months ago

Ma233 commented 4 months ago

Hi, I tried to run the tests of this project on my Macbook and got two failed tests -- ignored_validation_open_substream_tcp and ignored_validation_open_substream_websocket.

The log of failed test `ignored_validation_open_substream_tcp`. ``` litep2p on ī‚  master is šŸ“¦ v0.3.0 via šŸ¦€ v1.77.2 took 12s āÆ RUST_LOG=debug cargo nextest run --nocapture -- ignored_validation_open_substream_tcp warning: use of deprecated module `libp2p::quic`: `quic` is only in alpha status. Please depend on `libp2p-quic` directly and don't ues the `quic` feature of `libp2p`. --> tests/conformance/rust/quic_ping.rs:25:21 | 25 | identity, ping, quic, | ^^^^ | = note: `#[warn(deprecated)]` on by default warning: `litep2p` (test "mod") generated 1 warning Finished test [unoptimized + debuginfo] target(s) in 0.24s Starting 1 test across 7 binaries (479 skipped; run ID: abbf75d5-8771-44a1-b319-db8899fb75d9, nextest profile: default) START litep2p::mod protocol::notification::ignored_validation_open_substream_tcp running 1 test 2024-05-06T08:47:53.671368Z DEBUG litep2p: enable notification protocol protocol=Static("/notif/1") 2024-05-06T08:47:53.671498Z DEBUG litep2p::tcp: start tcp transport listen_addresses=["/ip4/0.0.0.0/tcp/0", "/ip6/::/tcp/0"] 2024-05-06T08:47:53.673437Z DEBUG litep2p::transport-manager: register transport transport=Tcp 2024-05-06T08:47:53.673524Z DEBUG litep2p: enable notification protocol protocol=Static("/notif/1") 2024-05-06T08:47:53.673575Z DEBUG litep2p::tcp: start tcp transport listen_addresses=["/ip4/0.0.0.0/tcp/0", "/ip6/::/tcp/0"] 2024-05-06T08:47:53.675304Z DEBUG litep2p::transport-manager: register transport transport=Tcp 2024-05-06T08:47:53.675452Z DEBUG litep2p::notification: starting notification event loop 2024-05-06T08:47:53.675503Z DEBUG litep2p::notification: starting notification event loop 2024-05-06T08:47:53.675585Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(0) addresses={"/ip4/192.168.50.145/tcp/60625/p2p/12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2": AddressRecord { score: 0, address: "/ip4/192.168.50.145/tcp/60625/p2p/12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2", connection_id: None }} 2024-05-06T08:47:53.676046Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /noise 2024-05-06T08:47:53.676138Z DEBUG litep2p::tcp::connection: accept connection address=192.168.50.145:60623 2024-05-06T08:47:53.676229Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /noise 2024-05-06T08:47:53.676247Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /noise 2024-05-06T08:47:53.676263Z DEBUG litep2p::crypto::noise: start noise handshake role=Listener 2024-05-06T08:47:53.677106Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /noise 2024-05-06T08:47:53.677116Z DEBUG litep2p::crypto::noise: start noise handshake role=Dialer 2024-05-06T08:47:53.680026Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /yamux/1.0.0 2024-05-06T08:47:53.680474Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /yamux/1.0.0 2024-05-06T08:47:53.680490Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /yamux/1.0.0 2024-05-06T08:47:53.680506Z DEBUG litep2p::yamux: new connection: a0a504e9 (Server) 2024-05-06T08:47:53.680590Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWNgwXfQWo8NTkjADu23YDCvvsB8V7QAGU5iFfMKzp6Szv") protocol=/notif/1 endpoint=Listener { address: "/ip4/192.168.50.145/tcp/60623", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-05-06T08:47:53.680661Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /yamux/1.0.0 2024-05-06T08:47:53.680671Z DEBUG litep2p::yamux: new connection: 38cd7f9e (Client) 2024-05-06T08:47:53.680708Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2") protocol=/notif/1 endpoint=Dialer { address: "/ip4/192.168.50.145/tcp/60625", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-05-06T08:47:53.680759Z DEBUG litep2p::tcp::connection: open substream protocol=Static("/notif/1") substream_id=SubstreamId(0) 2024-05-06T08:47:53.680786Z DEBUG litep2p::yamux: 38cd7f9e: new outbound (Stream 38cd7f9e/1) of (Connection 38cd7f9e Client (streams 0)) 2024-05-06T08:47:53.680819Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /notif/1 2024-05-06T08:47:53.680917Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /notif/1 2024-05-06T08:47:53.680926Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /notif/1 2024-05-06T08:47:53.680940Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWNgwXfQWo8NTkjADu23YDCvvsB8V7QAGU5iFfMKzp6Szv") direction=Inbound 2024-05-06T08:47:53.680986Z DEBUG litep2p::notification: handle inbound substream peer=PeerId("12D3KooWNgwXfQWo8NTkjADu23YDCvvsB8V7QAGU5iFfMKzp6Szv") protocol=/notif/1 fallback=None state=Closed { pending_open: None } 2024-05-06T08:47:53.681075Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /notif/1 2024-05-06T08:47:53.681091Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2") direction=Outbound(SubstreamId(0)) 2024-05-06T08:47:53.681120Z DEBUG litep2p::notification: handle outbound substream peer=PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2") protocol=Allocated("/notif/1") substream_id=SubstreamId(0) 2024-05-06T08:48:03.686747Z DEBUG litep2p::notification: failed to negotiate substream peer=PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2") protocol=/notif/1 direction=Outbound state=Validating { protocol: Allocated("/notif/1"), fallback: None, outbound: Negotiating, inbound: Closed, direction: Outbound } 2024-05-06T08:48:03.687346Z DEBUG litep2p::tcp::connection: protocols have disconnected, closing connection 2024-05-06T08:48:03.689619Z DEBUG litep2p::tcp::connection: connection closed with error peer=PeerId("12D3KooWNgwXfQWo8NTkjADu23YDCvvsB8V7QAGU5iFfMKzp6Szv") error=Decode(Io(Kind(UnexpectedEof))) 2024-05-06T08:48:03.689741Z DEBUG litep2p::notification: connection closed while validation pending peer=PeerId("12D3KooWNgwXfQWo8NTkjADu23YDCvvsB8V7QAGU5iFfMKzp6Szv") protocol=/notif/1 2024-05-06T08:48:05.690620Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(1) addresses={"/ip4/192.168.50.145/tcp/60625/p2p/12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2": AddressRecord { score: 100, address: "/ip4/192.168.50.145/tcp/60625/p2p/12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2", connection_id: None }} 2024-05-06T08:48:05.691859Z DEBUG litep2p::tcp: failed to open connection connection_id=ConnectionId(1) error=IoError(AddrInUse) 2024-05-06T08:48:05.692310Z DEBUG litep2p::notification: failed to dial peer peer=PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2") protocol=/notif/1 address="" thread 'protocol::notification::ignored_validation_open_substream_tcp' panicked at tests/protocol/notification.rs:3975:5: assertion `left == right` failed left: NotificationStreamOpenFailure { peer: PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2"), error: DialFailure } right: NotificationStreamOpenFailure { peer: PeerId("12D3KooWMYtg5ir8HefjfMwpAapRL3Nr39Yy4KfuA5CTsB5b5bB2"), error: Rejected } note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace test protocol::notification::ignored_validation_open_substream_tcp ... FAILED failures: failures: protocol::notification::ignored_validation_open_substream_tcp test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 217 filtered out; finished in 12.04s ```
The log of failed test `ignored_validation_open_substream_websocket`. ``` litep2p on ī‚  master is šŸ“¦ v0.3.0 via šŸ¦€ v1.77.2 āÆ RUST_LOG=debug cargo nextest run --nocapture -- ignored_validation_open_substream_websocket warning: use of deprecated module `libp2p::quic`: `quic` is only in alpha status. Please depend on `libp2p-quic` directly and don't ues the `quic` feature of `libp2p`. --> tests/conformance/rust/quic_ping.rs:25:21 | 25 | identity, ping, quic, | ^^^^ | = note: `#[warn(deprecated)]` on by default warning: `litep2p` (test "mod") generated 1 warning Finished test [unoptimized + debuginfo] target(s) in 0.27s Starting 1 test across 7 binaries (479 skipped; run ID: 7466ceee-37a0-4401-a465-b87fd5b165c6, nextest profile: default) START litep2p::mod protocol::notification::ignored_validation_open_substream_websocket running 1 test 2024-05-06T08:51:24.766446Z DEBUG litep2p: enable notification protocol protocol=Static("/notif/1") 2024-05-06T08:51:24.767963Z DEBUG litep2p::websocket: start websocket transport listen_addresses=["/ip4/0.0.0.0/tcp/0/ws", "/ip6/::/tcp/0/ws"] 2024-05-06T08:51:24.770367Z DEBUG litep2p::transport-manager: register transport transport=WebSocket 2024-05-06T08:51:24.770449Z DEBUG litep2p: enable notification protocol protocol=Static("/notif/1") 2024-05-06T08:51:24.770501Z DEBUG litep2p::websocket: start websocket transport listen_addresses=["/ip4/0.0.0.0/tcp/0/ws", "/ip6/::/tcp/0/ws"] 2024-05-06T08:51:24.772357Z DEBUG litep2p::transport-manager: register transport transport=WebSocket 2024-05-06T08:51:24.772534Z DEBUG litep2p::notification: starting notification event loop 2024-05-06T08:51:24.772588Z DEBUG litep2p::notification: starting notification event loop 2024-05-06T08:51:24.772694Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(0) addresses={"/ip4/127.0.0.1/tcp/61321/ws/p2p/12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe": AddressRecord { score: 0, address: "/ip4/127.0.0.1/tcp/61321/ws/p2p/12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe", connection_id: None }} 2024-05-06T08:51:24.777553Z DEBUG tungstenite::handshake::server: Server handshake done. 2024-05-06T08:51:24.777650Z DEBUG tungstenite::handshake::client: Client handshake done. 2024-05-06T08:51:24.777866Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /noise 2024-05-06T08:51:24.778415Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /noise 2024-05-06T08:51:24.778431Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /noise 2024-05-06T08:51:24.778456Z DEBUG litep2p::crypto::noise: start noise handshake role=Listener 2024-05-06T08:51:24.779300Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /noise 2024-05-06T08:51:24.779308Z DEBUG litep2p::crypto::noise: start noise handshake role=Dialer 2024-05-06T08:51:24.782368Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /yamux/1.0.0 2024-05-06T08:51:24.783008Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /yamux/1.0.0 2024-05-06T08:51:24.783037Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /yamux/1.0.0 2024-05-06T08:51:24.783058Z DEBUG litep2p::yamux: new connection: 687d40a8 (Server) 2024-05-06T08:51:24.783229Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWFeDW7SKfjmerpV6EKCpZKZwMHwEnZMhw5C3QMx9eiFxd") protocol=/notif/1 endpoint=Listener { address: "/ip4/127.0.0.1/tcp/61319/ws/p2p/12D3KooWFeDW7SKfjmerpV6EKCpZKZwMHwEnZMhw5C3QMx9eiFxd", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-05-06T08:51:24.783342Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /yamux/1.0.0 2024-05-06T08:51:24.783353Z DEBUG litep2p::yamux: new connection: cfb1739e (Client) 2024-05-06T08:51:24.783403Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe") protocol=/notif/1 endpoint=Dialer { address: "/ip4/127.0.0.1/tcp/61321/ws/p2p/12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-05-06T08:51:24.783707Z DEBUG litep2p::websocket::connection: open substream protocol=Static("/notif/1") substream_id=SubstreamId(0) 2024-05-06T08:51:24.783759Z DEBUG litep2p::yamux: cfb1739e: new outbound (Stream cfb1739e/1) of (Connection cfb1739e Client (streams 0)) 2024-05-06T08:51:24.783956Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /notif/1 2024-05-06T08:51:24.784166Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /notif/1 2024-05-06T08:51:24.784180Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /notif/1 2024-05-06T08:51:24.784200Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWFeDW7SKfjmerpV6EKCpZKZwMHwEnZMhw5C3QMx9eiFxd") direction=Inbound 2024-05-06T08:51:24.784277Z DEBUG litep2p::notification: handle inbound substream peer=PeerId("12D3KooWFeDW7SKfjmerpV6EKCpZKZwMHwEnZMhw5C3QMx9eiFxd") protocol=/notif/1 fallback=None state=Closed { pending_open: None } 2024-05-06T08:51:24.784396Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /notif/1 2024-05-06T08:51:24.784413Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe") direction=Outbound(SubstreamId(0)) 2024-05-06T08:51:24.784449Z DEBUG litep2p::notification: handle outbound substream peer=PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe") protocol=Allocated("/notif/1") substream_id=SubstreamId(0) 2024-05-06T08:51:34.788716Z DEBUG litep2p::notification: failed to negotiate substream peer=PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe") protocol=/notif/1 direction=Outbound state=Validating { protocol: Allocated("/notif/1"), fallback: None, outbound: Negotiating, inbound: Closed, direction: Outbound } 2024-05-06T08:51:34.790176Z DEBUG litep2p::websocket::connection: protocols have exited, shutting down connection 2024-05-06T08:51:34.792884Z DEBUG litep2p::websocket::connection: connection closed with error peer=PeerId("12D3KooWFeDW7SKfjmerpV6EKCpZKZwMHwEnZMhw5C3QMx9eiFxd") error=Decode(Io(Kind(UnexpectedEof))) 2024-05-06T08:51:34.793165Z DEBUG litep2p::notification: connection closed while validation pending peer=PeerId("12D3KooWFeDW7SKfjmerpV6EKCpZKZwMHwEnZMhw5C3QMx9eiFxd") protocol=/notif/1 2024-05-06T08:51:36.795172Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(1) addresses={"/ip4/127.0.0.1/tcp/61321/ws/p2p/12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe": AddressRecord { score: 100, address: "/ip4/127.0.0.1/tcp/61321/ws/p2p/12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe", connection_id: None }} 2024-05-06T08:51:36.798518Z DEBUG litep2p::websocket: failed to open connection connection_id=ConnectionId(1) error=Other("Address already in use (os error 48)") 2024-05-06T08:51:36.798741Z DEBUG litep2p::notification: failed to dial peer peer=PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe") protocol=/notif/1 address="" thread 'protocol::notification::ignored_validation_open_substream_websocket' panicked at tests/protocol/notification.rs:3975:5: assertion `left == right` failed left: NotificationStreamOpenFailure { peer: PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe"), error: DialFailure } right: NotificationStreamOpenFailure { peer: PeerId("12D3KooWPo398izdNsxxNCXj3YTqok6J7d7hPsCmXGzL98oz6EJe"), error: Rejected } note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace test protocol::notification::ignored_validation_open_substream_websocket ... FAILED failures: failures: protocol::notification::ignored_validation_open_substream_websocket test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 217 filtered out; finished in 12.04s FAIL [ 12.045s] litep2p::mod protocol::notification::ignored_validation_open_substream_websocket Canceling due to test failure ------------ Summary [ 12.046s] 1 test run: 0 passed, 1 failed, 479 skipped FAIL [ 12.045s] litep2p::mod protocol::notification::ignored_validation_open_substream_websocket error: test run failed ``` 
tcp:
2024-05-06T08:43:56.463654Z DEBUG litep2p::tcp: failed to open connection connection_id=ConnectionId(1) error=IoError(AddrInUse)

websocket:
2024-05-06T08:51:36.798518Z DEBUG litep2p::websocket: failed to open connection connection_id=ConnectionId(1) error=Other("Address already in use (os error 48)")

According to the logs, it looks like the connection was not closed as expected, and when a new connection was created, the same port was used.

The `ignored_validation_open_substream_quic` test is passed because it use a new port when dial. ``` litep2p on ī‚  master is šŸ“¦ v0.3.0 via šŸ¦€ v1.77.2 took 12s āÆ RUST_LOG=debug cargo nextest run --nocapture -- ignored_validation_open_substream_quic warning: use of deprecated module `libp2p::quic`: `quic` is only in alpha status. Please depend on `libp2p-quic` directly and don't ues the `quic` feature of `libp2p`. --> tests/conformance/rust/quic_ping.rs:25:21 | 25 | identity, ping, quic, | ^^^^ | = note: `#[warn(deprecated)]` on by default warning: `litep2p` (test "mod") generated 1 warning Finished test [unoptimized + debuginfo] target(s) in 0.24s Starting 1 test across 7 binaries (479 skipped; run ID: c92f722d-14c6-463d-b0e4-c80a72cbf7ae, nextest profile: default) START litep2p::mod protocol::notification::ignored_validation_open_substream_quic running 1 test 2024-05-06T09:03:29.579396Z DEBUG litep2p: enable notification protocol protocol=Static("/notif/1") 2024-05-06T09:03:29.579586Z INFO litep2p::quic: start quic transport config=Config { listen_addresses: ["/ip4/127.0.0.1/udp/0/quic-v1"], connection_open_timeout: 10s, substream_open_timeout: 5s } 2024-05-06T09:03:29.580550Z DEBUG litep2p::transport-manager: register transport transport=Quic 2024-05-06T09:03:29.580613Z DEBUG litep2p: enable notification protocol protocol=Static("/notif/1") 2024-05-06T09:03:29.580649Z INFO litep2p::quic: start quic transport config=Config { listen_addresses: ["/ip4/127.0.0.1/udp/0/quic-v1"], connection_open_timeout: 10s, substream_open_timeout: 5s } 2024-05-06T09:03:29.581270Z DEBUG litep2p::transport-manager: register transport transport=Quic 2024-05-06T09:03:29.581424Z DEBUG litep2p::notification: starting notification event loop 2024-05-06T09:03:29.581476Z DEBUG litep2p::notification: starting notification event loop 2024-05-06T09:03:29.581852Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(0) addresses={"/ip4/127.0.0.1/udp/62090/quic-v1/p2p/12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ": AddressRecord { score: 0, address: "/ip4/127.0.0.1/udp/62090/quic-v1/p2p/12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ", connection_id: None }} 2024-05-06T09:03:29.582563Z DEBUG rustls::client::hs: No cached session for DnsName(DnsName(DnsName("l"))) 2024-05-06T09:03:29.582658Z DEBUG rustls::client::hs: Not resuming any session 2024-05-06T09:03:29.583730Z DEBUG rustls::server::hs: decided upon suite TLS13_CHACHA20_POLY1305_SHA256 2024-05-06T09:03:29.584074Z DEBUG rustls::server::hs: Chosen ALPN protocol [108, 105, 98, 112, 50, 112] 2024-05-06T09:03:29.584658Z DEBUG drive{id=0}: rustls::client::hs: Using ciphersuite TLS13_CHACHA20_POLY1305_SHA256 2024-05-06T09:03:29.584676Z DEBUG drive{id=0}: rustls::client::tls13: Not resuming 2024-05-06T09:03:29.584921Z DEBUG drive{id=0}: rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([6c6962703270]), ServerNameAck, TransportParameters([1, 2, 103, 16, 3, 2, 69, 200, 4, 8, 255, 255, 255, 255, 255, 255, 255, 255, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 64, 100, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 2, 16, 7, 194, 118, 157, 211, 71, 214, 254, 176, 20, 129, 223, 243, 236, 168, 91, 32, 4, 128, 0, 255, 255, 0, 20, 74, 164, 186, 85, 224, 221, 31, 63, 244, 242, 240, 206, 18, 211, 24, 143, 206, 165, 139, 224, 15, 8, 75, 248, 183, 85, 148, 83, 214, 56, 106, 178, 0])] 2024-05-06T09:03:29.584945Z DEBUG drive{id=0}: rustls::client::hs: ALPN protocol is Some(b"libp2p") 2024-05-06T09:03:29.584962Z DEBUG drive{id=0}: rustls::client::tls13: Got CertificateRequest CertificateRequestPayloadTLS13 { context: , extensions: [SignatureAlgorithms([ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256])] } 2024-05-06T09:03:29.585140Z DEBUG drive{id=0}: rustls::client::common: Attempting client auth 2024-05-06T09:03:29.587273Z DEBUG litep2p::quic: connection established connection_id=ConnectionId(0) success=true 2024-05-06T09:03:29.587385Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") protocol=/notif/1 endpoint=Listener { address: "/ip4/127.0.0.1/udp/62090/quic-v1", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-05-06T09:03:29.587491Z DEBUG litep2p::quic::connection: open substream protocol=Static("/notif/1") substream_id=SubstreamId(0) 2024-05-06T09:03:29.587518Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /notif/1 2024-05-06T09:03:29.589844Z DEBUG litep2p::quic: connection established connection_id=ConnectionId(0) success=true 2024-05-06T09:03:29.589980Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 endpoint=Listener { address: "/ip4/127.0.0.1/udp/50240/quic-v1", connection_id: ConnectionId(0) } connection_id=ConnectionId(0) 2024-05-06T09:03:29.590069Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /notif/1 2024-05-06T09:03:29.590079Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /notif/1 2024-05-06T09:03:29.590099Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") direction=Inbound 2024-05-06T09:03:29.590144Z DEBUG litep2p::notification: handle inbound substream peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 fallback=None state=Closed { pending_open: None } 2024-05-06T09:03:29.590306Z DEBUG drive{id=0}: rustls::client::tls13: Ticket saved 2024-05-06T09:03:29.590393Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /notif/1 2024-05-06T09:03:29.590406Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") direction=Outbound(SubstreamId(0)) 2024-05-06T09:03:29.590457Z DEBUG litep2p::notification: handle outbound substream peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") protocol=Allocated("/notif/1") substream_id=SubstreamId(0) 2024-05-06T09:03:39.593973Z DEBUG litep2p::notification: failed to negotiate substream peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") protocol=/notif/1 direction=Outbound state=Validating { protocol: Allocated("/notif/1"), fallback: None, outbound: Negotiating, inbound: Closed, direction: Outbound } 2024-05-06T09:03:39.594639Z DEBUG litep2p::quic::connection: protocols have dropped connection peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") connection_id=ConnectionId(0) 2024-05-06T09:03:39.595546Z DEBUG litep2p::quic::connection: failed to accept substream peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") error=TimedOut 2024-05-06T09:03:39.596047Z DEBUG litep2p::notification: connection closed while validation pending peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 2024-05-06T09:03:41.599320Z DEBUG litep2p::transport-manager: dial remote peer connection_id=ConnectionId(1) addresses={"/ip4/127.0.0.1/udp/62090/quic-v1/p2p/12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ": AddressRecord { score: 100, address: "/ip4/127.0.0.1/udp/62090/quic-v1/p2p/12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ", connection_id: None }} 2024-05-06T09:03:41.601796Z DEBUG rustls::client::hs: No cached session for DnsName(DnsName(DnsName("l"))) 2024-05-06T09:03:41.602002Z DEBUG rustls::client::hs: Not resuming any session 2024-05-06T09:03:41.603856Z DEBUG rustls::server::hs: decided upon suite TLS13_CHACHA20_POLY1305_SHA256 2024-05-06T09:03:41.604572Z DEBUG rustls::server::hs: Chosen ALPN protocol [108, 105, 98, 112, 50, 112] 2024-05-06T09:03:41.605881Z DEBUG drive{id=0}: rustls::client::hs: Using ciphersuite TLS13_CHACHA20_POLY1305_SHA256 2024-05-06T09:03:41.605924Z DEBUG drive{id=0}: rustls::client::tls13: Not resuming 2024-05-06T09:03:41.606427Z DEBUG drive{id=0}: rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([6c6962703270]), ServerNameAck, TransportParameters([1, 2, 103, 16, 3, 2, 69, 200, 4, 8, 255, 255, 255, 255, 255, 255, 255, 255, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 64, 100, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 2, 16, 181, 245, 24, 131, 222, 249, 87, 123, 71, 217, 79, 117, 175, 245, 204, 88, 32, 4, 128, 0, 255, 255, 0, 20, 48, 207, 31, 79, 128, 90, 139, 29, 231, 35, 251, 40, 254, 185, 115, 118, 151, 43, 244, 126, 15, 8, 113, 81, 25, 75, 108, 190, 9, 205, 106, 178, 0])] 2024-05-06T09:03:41.606475Z DEBUG drive{id=0}: rustls::client::hs: ALPN protocol is Some(b"libp2p") 2024-05-06T09:03:41.606509Z DEBUG drive{id=0}: rustls::client::tls13: Got CertificateRequest CertificateRequestPayloadTLS13 { context: , extensions: [SignatureAlgorithms([ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256])] } 2024-05-06T09:03:41.606536Z DEBUG drive{id=0}: rustls::client::common: Attempting client auth 2024-05-06T09:03:41.610373Z DEBUG litep2p::quic: connection established connection_id=ConnectionId(1) success=true 2024-05-06T09:03:41.610583Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") protocol=/notif/1 endpoint=Listener { address: "/ip4/127.0.0.1/udp/62090/quic-v1", connection_id: ConnectionId(1) } connection_id=ConnectionId(1) 2024-05-06T09:03:41.610707Z DEBUG litep2p::quic::connection: open substream protocol=Static("/notif/1") substream_id=SubstreamId(1) 2024-05-06T09:03:41.610746Z DEBUG litep2p::multistream-select: Dialer: Proposed protocol: /notif/1 2024-05-06T09:03:41.614146Z DEBUG litep2p::quic: connection established connection_id=ConnectionId(1) success=true 2024-05-06T09:03:41.614394Z DEBUG litep2p::transport-service: connection established peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 endpoint=Listener { address: "/ip4/127.0.0.1/udp/49800/quic-v1", connection_id: ConnectionId(1) } connection_id=ConnectionId(1) 2024-05-06T09:03:41.614451Z DEBUG litep2p::notification: new connection established while validation still pending peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 2024-05-06T09:03:41.614552Z DEBUG litep2p::multistream_select::listener_select: Listener: confirming protocol: /notif/1 2024-05-06T09:03:41.614565Z DEBUG litep2p::multistream_select::listener_select: Listener: sent confirmed protocol: /notif/1 2024-05-06T09:03:41.614589Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") direction=Inbound 2024-05-06T09:03:41.614636Z DEBUG litep2p::notification: handle inbound substream peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 fallback=None state=ValidationPending { state: Open } 2024-05-06T09:03:41.614670Z DEBUG litep2p::notification: validation for previous substream still pending peer=PeerId("12D3KooWBUheK6qz7DPxVVscNNLdAtr9ZTZYU6MWZafhKKTrNsLD") protocol=/notif/1 fallback=None state=ValidationPending { state: Open } 2024-05-06T09:03:41.614845Z DEBUG drive{id=0}: rustls::client::tls13: Ticket saved 2024-05-06T09:03:41.615056Z DEBUG litep2p::multistream-select: Dialer: Received confirmation for protocol: /notif/1 2024-05-06T09:03:41.615078Z DEBUG litep2p::protocol-set: substream opened protocol=/notif/1 peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") direction=Outbound(SubstreamId(1)) 2024-05-06T09:03:41.615121Z DEBUG litep2p::notification: handle outbound substream peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") protocol=Allocated("/notif/1") substream_id=SubstreamId(1) 2024-05-06T09:03:41.615193Z DEBUG litep2p::notification: failed to negotiate substream peer=PeerId("12D3KooWDCBddrUDd3V1RsxcNYCjyuyQac3zL3K2VX2DbwRT9QvJ") protocol=/notif/1 direction=Outbound state=Validating { protocol: Allocated("/notif/1"), fallback: None, outbound: Negotiating, inbound: Closed, direction: Outbound } test protocol::notification::ignored_validation_open_substream_quic ... ok test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 217 filtered out; finished in 12.05s PASS [ 12.052s] litep2p::mod protocol::notification::ignored_validation_open_substream_quic ------------ Summary [ 12.052s] 1 test run: 1 passed, 479 skipped ```
Ma233 commented 4 months ago

I tried to increase the time of wait a moment to allow the connection to close but it didn't help. I also ran the two tests in the test container of github action, and they passed in container.

lexnv commented 4 months ago

Hi, thanks for raising this issue!

I can reproduce the issue on my MacOS, however this works perfectly on my linux machine (ubuntu).

Linux implementation of SO_REUSEPORT diverged from the MacOS (BSD):

We currently offer support for linux machines, which are used by substrate nodes. In the meantime, you could ignore these tests on MacOs (unless you plan to deploy the litep2p on a mac machine).

There's not much we can do here, please reopen this if need be šŸ™