search

hyperledger-iroha / iroha

Iroha - A simple, enterprise-grade decentralized ledger
https://wiki.hyperledger.org/display/iroha
Apache License 2.0
438 stars 280 forks source link

[BUG] Failure During New Peer Registration #4999

Closed alexstroke1 closed 2 months ago

alexstroke1 commented 2 months ago

OS and Environment

MacOS, Docker Hub

GIT commit hash

76dafdc

Minimum working example / Steps to reproduce

  1. Run Iroha and build the client CLI as per the standard setup instructions.
  2. Execute the following command to register a new peer: 
    ./iroha peer register --address=irohad4:1341 --key=ed0120259874FDC3707623AB54EBC370406F95FE6CEC6176AC81B369605784B71298BB

Actual result

Expected result

The new peer should be successfully registered and integrated into the network without errors.

Logs

Log contents ```plaintext 2024-08-22 09:20:58 irohad0-1 | libunwind: __unw_add_dynamic_fde: bad fde: FDE is really a CIE 2024-08-22 09:20:59 irohad0-1 | 2024-08-22T07:20:59.557313Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 prev_role=ProxyTail next_role=ValidatingPeer block_hash=605555895d4c8ded69c41e927969a2013d08ccb9d5efdac238589877d912a109 new_height=1 2024-08-22 09:20:59 irohad0-1 | 2024-08-22T07:20:59.557633Z INFO consensus: iroha_core::sumeragi::main_loop: Sumeragi initialized peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 role=ValidatingPeer 2024-08-22 09:21:02 irohad2-1 | libunwind: __unw_add_dynamic_fde: bad fde: FDE is really a CIE 2024-08-22 09:21:02 irohad1-1 | libunwind: __unw_add_dynamic_fde: bad fde: FDE is really a CIE 2024-08-22 09:21:02 irohad3-1 | libunwind: __unw_add_dynamic_fde: bad fde: FDE is really a CIE 2024-08-22 09:21:02 irohad1-1 | 2024-08-22T07:21:02.857659Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 prev_role=ValidatingPeer next_role=Leader block_hash=605555895d4c8ded69c41e927969a2013d08ccb9d5efdac238589877d912a109 new_height=1 2024-08-22 09:21:02 irohad1-1 | 2024-08-22T07:21:02.860517Z INFO consensus: iroha_core::sumeragi::main_loop: Sumeragi initialized peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 role=Leader 2024-08-22 09:21:02 irohad2-1 | 2024-08-22T07:21:02.917036Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10@@0.0.0.0:1339 prev_role=Leader next_role=ProxyTail block_hash=605555895d4c8ded69c41e927969a2013d08ccb9d5efdac238589877d912a109 new_height=1 2024-08-22 09:21:02 irohad2-1 | 2024-08-22T07:21:02.921382Z INFO consensus: iroha_core::sumeragi::main_loop: Sumeragi initialized peer_id=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10@@0.0.0.0:1339 role=ProxyTail 2024-08-22 09:21:03 irohad3-1 | 2024-08-22T07:21:03.049466Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 prev_role=ObservingPeer next_role=ObservingPeer block_hash=605555895d4c8ded69c41e927969a2013d08ccb9d5efdac238589877d912a109 new_height=1 2024-08-22 09:21:03 irohad3-1 | 2024-08-22T07:21:03.053165Z INFO consensus: iroha_core::sumeragi::main_loop: Sumeragi initialized peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 role=ObservingPeer 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.320696Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 role=ValidatingPeer 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.327636Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 role=ValidatingPeer 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.334294Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 role=ValidatingPeer 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.341411Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 role=ValidatingPeer 2024-08-22 09:21:26 irohad1-1 | 2024-08-22T07:21:26.625232Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 role=Leader 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.638909Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10@@0.0.0.0:1339 role=ProxyTail 2024-08-22 09:21:26 irohad3-1 | 2024-08-22T07:21:26.647785Z WARN consensus: iroha_core::sumeragi::main_loop: No block produced in due time, requesting view change... peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 role=ObservingPeer 2024-08-22 09:21:26 irohad3-1 | 2024-08-22T07:21:26.657364Z ERROR consensus: iroha_core::sumeragi::main_loop: Topology rotated n times peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 prev_role=ObservingPeer next_role=ProxyTail n=1 view_change_index=1 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.653924Z ERROR consensus: iroha_core::sumeragi::main_loop: Topology rotated n times peer_id=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10@@0.0.0.0:1339 prev_role=ProxyTail next_role=ValidatingPeer n=1 view_change_index=1 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.656786Z ERROR consensus: iroha_core::sumeragi::main_loop: Topology rotated n times peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 prev_role=ValidatingPeer next_role=Leader n=1 view_change_index=1 2024-08-22 09:21:26 irohad1-1 | 2024-08-22T07:21:26.660004Z INFO consensus: iroha_core::sumeragi::main_loop: Block created peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 block=672c1df7510ed6a5905ab8e04887b394a610b8a3f55e560deea88224b4ef8e35 view_change_index=0 txns=1 created_in_ms=3 2024-08-22 09:21:26 irohad1-1 | 2024-08-22T07:21:26.671114Z ERROR consensus: iroha_core::sumeragi::main_loop: Topology rotated n times peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 prev_role=Leader next_role=ObservingPeer n=1 view_change_index=1 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.696309Z INFO consensus: iroha_core::sumeragi::main_loop: Block created peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 block=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 view_change_index=1 txns=1 created_in_ms=18 2024-08-22 09:21:26 irohad3-1 | 2024-08-22T07:21:26.702775Z INFO consensus: iroha_core::sumeragi::main_loop: Block received peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 role=ProxyTail block=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 2024-08-22 09:21:26 irohad1-1 | 2024-08-22T07:21:26.711020Z INFO consensus: iroha_core::sumeragi::main_loop: Block signed and forwarded peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 role=ObservingPeer block=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 2024-08-22 09:21:26 irohad3-1 | 2024-08-22T07:21:26.728011Z INFO consensus: iroha_core::sumeragi::main_loop: Received block signatures peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 role=ProxyTail 2024-08-22 09:21:26 irohad3-1 | 2024-08-22T07:21:26.740449Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed0120CACF3A84B8DC8710CE9D6B968EE95EC7EE4C93C85858F026F3B4417F569592CE@@0.0.0.0:1340 prev_role=ProxyTail next_role=Leader block_hash=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 new_height=2 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.747047Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10@@0.0.0.0:1339 prev_role=ValidatingPeer next_role=ObservingPeer block_hash=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 new_height=2 2024-08-22 09:21:26 irohad1-1 | 2024-08-22T07:21:26.748302Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed01209897952D14BDFAEA780087C38FF3EB800CB20B882748FC95A575ADB9CD2CB21D@@0.0.0.0:1338 prev_role=ObservingPeer next_role=ValidatingPeer block_hash=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 new_height=2 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.751963Z INFO consensus: iroha_core::sumeragi::main_loop: Block committed peer_id=ed0120A98BAFB0663CE08D75EBD506FEC38A84E576A7C9B0897693ED4B04FD9EF2D18D@@0.0.0.0:1337 prev_role=Leader next_role=ProxyTail block_hash=112a6f3355b094065fbbf5eaf6bcec209780e5c2b0fdcb0a11cd1c22de424905 new_height=2 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.757642Z ERROR run{listen_addr=0.0.0.0:1339 public_key=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10}:run{conn_id=5}: iroha_p2p::peer::run: Failure during handshake. error=Failed IO operation 2024-08-22 09:21:26 irohad0-1 | 2024-08-22T07:21:26.763489Z ERROR iroha_torii: Failure during event streaming error=WebSocket error: WebSocket protocol error: Sending after closing is not allowed 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.772417Z ERROR run{listen_addr=0.0.0.0:1339 public_key=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10}:run{conn_id=6}: iroha_p2p::peer::run: Failure during handshake. error=Failed IO operation 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.871066Z ERROR run{listen_addr=0.0.0.0:1339 public_key=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10}:run{conn_id=7}: iroha_p2p::peer::run: Failure during handshake. error=Failed IO operation 2024-08-22 09:21:26 irohad2-1 | 2024-08-22T07:21:26.967513Z ERROR run{listen_addr=0.0.0.0:1339 public_key=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10}:run{conn_id=8}: iroha_p2p::peer::run: Failure during handshake. error=Failed IO operation 2024-08-22 09:21:27 irohad2-1 | 2024-08-22T07:21:27.085590Z ERROR run{listen_addr=0.0.0.0:1339 public_key=ed01204EE2FCD53E1730AF142D1E23951198678295047F9314B4006B0CB61850B1DB10}:run{conn_id=9}: iroha_p2p::peer::run: Failure during handshake. error=Failed IO operation ```

Who can help to reproduce?

@alexstroke1

Notes

No response

s8sato commented 2 months ago

This was not reproduced to me. I modified test_env.py to allow offline peers not included in bootstrap. It was observed that an offline peer joined the network successfully when it was registered. Try this:

git remote add sato https://github.com/s8sato/iroha.git
git fetch sato fix/4999
git checkout sato/fix/4999
cargo build
./scripts/test_env.py --peer-name-as-seed setup 5 1
cd test
curl http://127.0.0.1:8080/status
curl http://127.0.0.1:8084/status
./iroha peer register --address=127.0.0.1:1341 --key=ed0120800F1BFA6295601A2D5256EA3C40BD60D431EC2DE3BC491FC3927C5BFEFF34E2
curl http://127.0.0.1:8080/status
curl http://127.0.0.1:8084/status
alexstroke1 commented 2 months ago

@s8sato It was registered, but what about logs on peers?

alexstroke1 commented 2 months ago

image

s8sato commented 2 months ago

Observed no errors specific to registering peers. Instead, found common errors:

LOG_LEVEL=ERROR ./scripts/test_env.py setup
cd test
./iroha domain register --id kingdom

iroha0/log.txt

  2024-08-22T15:26:03.161900Z ERROR iroha_core::sumeragi::main_loop: Topology rotated n times, peer_id: ed012003415E0E516BE83870CE5A2165605E8719216B5ECCCE4AEDFB0B2B77862B3798@@127.0.0.1:1337, prev_role: ProxyTail, next_role: ValidatingPeer, n: 1, view_change_index: 1
    at core/src/sumeragi/main_loop.rs:915

  2024-08-22T15:26:03.287294Z ERROR iroha_torii: Failure during event streaming, error: WebSocket error: WebSocket protocol error: Sending after closing is not allowed
    at torii/src/lib.rs:215

iroha1/log.txt, the same for iroha2, iroha3

  2024-08-22T15:26:03.141593Z ERROR iroha_core::sumeragi::main_loop: Topology rotated n times, peer_id: ed01203DF52ED2B730A7AC1407AFE0B3F291501D4421035D6DC1E920FC000AA26EA4E1@@127.0.0.1:1340, prev_role: ObservingPeer, next_role: ProxyTail, n: 1, view_change_index: 1
    at core/src/sumeragi/main_loop.rs:915
s8sato commented 2 months ago

So I'd suggest to redefine the issue @alexstroke1

alexstroke1 commented 2 months ago

So I'd suggest to redefine the issue @alexstroke1

no objections

s8sato commented 2 months ago

Closed in favor of #5004 and #5005