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

net_plugin handshake storm #588

Closed
heifner opened this issue Dec 21, 2022 · 1 comment
Closed

net_plugin handshake storm #588

heifner opened this issue Dec 21, 2022 · 1 comment
Assignees
@heifner
Labels
actionable bug Something isn't working 👍 lgtm OCI Work exclusive to OCI team

Comments

@heifner
Copy link
Member

heifner commented Dec 21, 2022

Observed in recent test failure logs: https://github.com/AntelopeIO/leap/actions/runs/3752991593/jobs/6375833496

debug 2022-12-21T21:55:32.974 net-0     net_plugin.cpp:811            operator()           ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] handle handshake_message
debug 2022-12-21T21:55:32.974 net-0     net_plugin.cpp:2766           handle_message       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] received handshake_message
debug 2022-12-21T21:55:32.974 net-0     net_plugin.cpp:2773           handle_message       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] received handshake gen 2893, lib 507, head 832
debug 2022-12-21T21:55:32.974 net-0     net_plugin.cpp:1790           recv_handshake       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] Network latency is 1ms, 0 blocks discrepancy by network latency, 1 blocks discrepancy expected once message received
info  2022-12-21T21:55:32.974 net-0     net_plugin.cpp:1849           recv_handshake       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] handshake lib 507, head 832, head id 981d8f9df4e25435.. sync 4
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:811            operator()           ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] handle handshake_message
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:2766           handle_message       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] received handshake_message
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:2773           handle_message       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] received handshake gen 2894, lib 507, head 832
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:1790           recv_handshake       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] Network latency is 1ms, 0 blocks discrepancy by network latency, 1 blocks discrepancy expected once message received
info  2022-12-21T21:55:32.974 net-1     net_plugin.cpp:1849           recv_handshake       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] handshake lib 507, head 832, head id 981d8f9df4e25435.. sync 4
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:811            operator()           ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] handle handshake_message
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:2766           handle_message       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] received handshake_message
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:2773           handle_message       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] received handshake gen 2895, lib 507, head 832
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:1790           recv_handshake       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] Network latency is 1ms, 0 blocks discrepancy by network latency, 1 blocks discrepancy expected once message received
info  2022-12-21T21:55:32.974 net-1     net_plugin.cpp:1849           recv_handshake       ] ["localhost:9878 - f9bdaf6" - 4 127.0.0.1:36386] handshake lib 507, head 832, head id 981d8f9df4e25435.. sync 4

Logs on the peer:

debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:835            operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] handle notice_message
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:2990           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] received notice_message
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:3024           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] this is a catch up notice with 833 blocks
debug 2022-12-21T21:55:32.974 net-1     net_plugin.cpp:1930           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] sync_manager got catch up block notice
info  2022-12-21T21:55:32.974 net-1     net_plugin.cpp:1938           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] notice_message, pending 833, blk_num 833, id 2c240056d06a1829...
info  2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1138           operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] Sending handshake generation 2898, lib 507, head 832, id 981d8f9df4e25435
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:835            operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] handle notice_message
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:2990           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] received notice_message
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:3024           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] this is a catch up notice with 833 blocks
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1930           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] sync_manager got catch up block notice
info  2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1938           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] notice_message, pending 833, blk_num 833, id 2c240056d06a1829...
info  2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1138           operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] Sending handshake generation 2899, lib 507, head 832, id 981d8f9df4e25435
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:835            operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] handle notice_message
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:2990           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] received notice_message
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:3024           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] this is a catch up notice with 833 blocks
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1930           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] sync_manager got catch up block notice
info  2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1938           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] notice_message, pending 833, blk_num 833, id 2c240056d06a1829...
info  2022-12-21T21:55:32.974 net-2     net_plugin.cpp:1138           operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] Sending handshake generation 2900, lib 507, head 832, id 981d8f9df4e25435
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:835            operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] handle notice_message
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:2990           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] received notice_message
debug 2022-12-21T21:55:32.974 net-2     net_plugin.cpp:3024           handle_message       ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] this is a catch up notice with 833 blocks
debug 2022-12-21T21:55:32.975 net-2     net_plugin.cpp:1930           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] sync_manager got catch up block notice
info  2022-12-21T21:55:32.975 net-2     net_plugin.cpp:1938           sync_recv_notice     ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] notice_message, pending 833, blk_num 833, id 2c240056d06a1829...
info  2022-12-21T21:55:32.975 net-2     net_plugin.cpp:1138           operator()           ] ["localhost:9876 - 9379f72" - 3 127.0.0.1:9876] Sending handshake generation 2901, lib 507, head 832, id 981d8f9df4e25435

It looks like our network latency calculation is wrong as there should not be any block discrepancy when network latency is 0ms or 1ms. In any rate, we should not get caught in this type of loop.
@enf-ci-bot enf-ci-bot moved this to Todo in Team Backlog Dec 21, 2022
@heifner heifner added bug Something isn't working actionable and removed triage labels Dec 21, 2022
@heifner heifner self-assigned this Jan 26, 2023
@heifner heifner added the OCI Work exclusive to OCI team label Jan 26, 2023
heifner added a commit that referenced this issue Jan 31, 2023
@heifner
GH-588 Remove +1 to number of blocks latency calculation. With it 0 l…
5ec82ac 
…atency indicates 1 block latency.
heifner added a commit that referenced this issue Jan 31, 2023
@heifner
GH-588 Remove +1 to number of blocks latency calculation. With it 0 l…
55578c4 
…atency indicates 1 block latency.
heifner added a commit that referenced this issue Jan 31, 2023
@heifner
Merge branch 'main' into GH-588-handshake-3.1
3ad8767
heifner added a commit that referenced this issue Jan 31, 2023
@heifner
GH-588 Remove +1 to number of blocks latency calculation. With it 0 l…
3db765e 
…atency indicates 1 block latency.
@heifner heifner mentioned this issue Jan 31, 2023
Merged
@stephenpdeos stephenpdeos moved this from Todo to In Progress in Team Backlog Jan 31, 2023
heifner added a commit that referenced this issue Feb 1, 2023
@heifner
GH-588 Add additional logging that would be helpful for debugging
f347ab5
heifner added a commit that referenced this issue Feb 1, 2023
@heifner
GH-588 Round using lround instead of the original hardcoded +1
ec27d3d
heifner added a commit that referenced this issue Feb 2, 2023
@heifner
Merge pull request #676 from AntelopeIO/GH-588-handshake-3.1
343596a 
[3.1] net_plugin improve block latency calculation
heifner added a commit that referenced this issue Feb 2, 2023
@heifner
Merge remote-tracking branch 'origin/release/3.1' into GH-588-handsha…
b1f187c 
…ke-3.2
@heifner heifner mentioned this issue Feb 2, 2023
Merged
@stephenpdeos stephenpdeos moved this from In Progress to Awaiting Review in Team Backlog Feb 2, 2023
heifner added a commit that referenced this issue Feb 2, 2023
@heifner
Merge pull request #681 from AntelopeIO/GH-588-handshake-3.2
8feca18 
[3.1 -> 3.2] net_plugin improve block latency calculation
heifner added a commit that referenced this issue Feb 2, 2023
@heifner
Merge remote-tracking branch 'origin/release/3.2' into GH-588-handsha…
1b5efcf 
…ke-main
@heifner heifner mentioned this issue Feb 2, 2023
Merged
heifner added a commit that referenced this issue Feb 3, 2023
@heifner
Merge pull request #682 from AntelopeIO/GH-588-handshake-main
02e4cc5 
[3.2 -> main] net_plugin improve block latency calculation
@heifner
Copy link
Member Author

heifner commented Feb 3, 2023

Fixed by #590

@heifner heifner closed this as completed Feb 3, 2023
@github-project-automation github-project-automation bot moved this from Awaiting Review to Done in Team Backlog Feb 3, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@heifner heifner

Labels
actionable bug Something isn't working 👍 lgtm OCI Work exclusive to OCI team
Projects
Team Backlog
Archived in project
Milestone
No milestone
Development

No branches or pull requests
3 participants
@heifner @stephenpdeos @enf-ci-bot