Connection handshake failure for TCP connections

[Lederstrumpf]

Classify the bug
Put x in the boxes below:

• Build issue
• Test failing
• Runtime panic
• Incorrect results
• Unexpected/undocumented behaviour /

Describe the problem
lnp-node peers don't perform the connection handshake either in the 0.5 release cycle nor with 0.6.0-beta.1.

To Reproduce
Steps to reproduce the behavior:

1. Operating system: NixOS 2.3.16 & Debian 11
2. Rust compiler version: 1.56.1
3. On peer A: lnp-cli -c 127.0.0.1:$RPC_PEER_A listen
4. On peer B: lnp-cli -c 127.0.0.1:$RPC_PEER_B connect $PEER_ID_PEER_A@$IP_PEER_A:9735

Expected behavior
A clear and concise description of what you expected to happen.

Logs
Log excerpt from peer A:

[2022-03-24T12:32:58Z DEBUG microservices::peer::peer_connection] Awaiting incoming messages from the remote peer
[2022-03-24T12:32:58Z DEBUG microservices::esb::controller] Creating ESB session for service RPC located at tcp://127.0.0.1:62962 with identity 'peerd<036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735)>'
[2022-03-24T12:32:58Z DEBUG microservices::esb::controller] Creating ESB session for service MSG located at ipc:///root/.lnp_node/testnet/msg with identity 'peerd<036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735)>'
[2022-03-24T12:32:58Z DEBUG microservices::esb::controller] Creating ESB session for service BRIDGE
[2022-03-24T12:32:58Z TRACE microservices::peer::peer_connection] Incoming data from the remote peer: [254, 12, 162]
[2022-03-24T12:32:58Z TRACE microservices::peer] Peer connection generated peer interface error: LNP message with unknown even type #65036
[2022-03-24T12:32:58Z ERROR lnp_node::peerd::runtime] Unrecoverable peer interface error: LNP message with unknown even type #65036, halting
[2022-03-24T12:32:58Z DEBUG zmq] socket dropped
thread '<unnamed>' panicked at 'peerd-listener run loop has failed with peer interface error: LNP message with unknown even type #65036', /root/.cargo/git/checkouts/rust-microservices-ce46943afbcc9892/d0e0baa/src/[node.rs:37](http://node.rs:37/):17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[2022-03-24T12:32:59Z TRACE microservices::esb::controller] Sending hello() from peerd<036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735)> to lnpd via router lnpd
[2022-03-24T12:32:59Z INFO  lnp_node::service] peerd<036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735)> started
[2022-03-24T12:32:59Z TRACE microservices::esb::controller] Awaiting for ESB request from 4 service buses...
[2022-03-24T12:32:59Z TRACE microservices::esb::controller] Received ESB request from 1 service busses...
[2022-03-24T12:32:59Z DEBUG microservices::esb::controller] peerd<036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735)> -> lnpd: hello()
[2022-03-24T12:32:59Z INFO  lnp_node::lnpd::runtime] peerd<036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735)> daemon is connected
[2022-03-24T12:32:59Z INFO  lnp_node::lnpd::runtime] Connection 036e56033677e86c5e6af030b6483202d33f0a7ad7cc292b45f44e9e44d6c128ac[@0.0.0.0:9735](https://matrix.to/#/@0.0.0.0:9735) is registered; total 1 connections are known
[2022-03-24T12:32:59Z TRACE microservices::esb::controller] request processing complete

Additional context
Peers connected via TCP

Other links
Please provide links and references to the affected repositories, code samples etc.

[dr-orlovsky]

It looks like they fail to do proper BOLT-8 handshake. I tested handshakes in LNP Node <-> c-lightning combination, and not with two LNP Nodes. Will check and try to fix

[Lederstrumpf]

Thanks Maxim.
Just did a bisection and can confirm it's commit 270f5c1acda004ee343b2e6fc06f850cb90a3549: c-lightning connectivity for the first time that introduces a breaking change (sometimes unknown data type in LNP message, sometimes LNP message with unknown even value), i.e. indeed the c-lightning integration.

Listener's log at this revision:

[2022-04-04T12:40:39Z DEBUG peerd] Awaiting for incoming connections...
[2022-04-04T12:40:40Z TRACE microservices::peer::peer_connection] Incoming data from the remote peer: [118, 49, 28]
[2022-04-04T12:40:40Z TRACE microservices::peer] Peer connection generated Peer interface error: unknown data type in LNP message
[2022-04-04T12:40:40Z DEBUG lnp_node::peerd::runtime] Underlying peer interface requested to handle Peer interface error: unknown data type in LNP message
[2022-04-04T12:40:40Z ERROR lnp_node::peerd::runtime] Unrecoverable peer error Peer interface error: unknown data type in LNP message, halting
[2022-04-04T12:40:40Z DEBUG zmq] socket dropped
thread '<unnamed>' panicked at 'peerd-listener run loop has failed with error Peer interface error: unknown data type in LNP message', /root/.cargo/registry/src/git.luolix.top-1ecc6299db9ec823/microservices-0.5.2/src/node.rs:37:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[2022-04-04T12:40:40Z TRACE microservices::esb::controller] Routing: sending hello() from peerd<02345562c5f9308d2a0c89837e3fafb2704f2c4c4fc8308406e780a096c08be016@0.0.0.0:9735> to lnpd via lnpd
[2022-04-04T12:40:40Z TRACE microservices::esb::controller] Routing: sending hello() from peerd<02345562c5f9308d2a0c89837e3fafb2704f2c4c4fc8308406e780a096c08be016@0.0.0.0:9735> to lnpd via lnpd
[2022-04-04T12:40:40Z TRACE microservices::esb::controller] Received ESB request from 1 service busses...

[dr-orlovsky]

Ok, found the reason: the accepting part does not initiates encrypted brontide connection. Working on the solution.

[dr-orlovsky]

Glad to report that the issue is fixed now. Al you have to do is to update to the v0.6.1 of both internet2 and microservices crates as I did here in 1244ec9

The problem was caused by Brontide API inconsistency.