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.

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

Suspicious P2P log messages when system clock is behind #2428

Closed
1 of 17 tasks
abitmore opened this issue Apr 27, 2021 · 3 comments
Closed
1 of 17 tasks

Suspicious P2P log messages when system clock is behind #2428

abitmore opened this issue Apr 27, 2021 · 3 comments

Comments

@abitmore
Copy link
Member

abitmore commented Apr 27, 2021

This log message is normal when the system clock is behind

p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] disconnecting client x.x.x.x:xxxxx because it offered us the rejected block
Failed to push sync block ... client rejected sync block sent by peer: {"code":90007,"name":"block_timestamp_in_future_exception","message":"block timestamp in the future"

But then got this, which is suspicious

p2p:message read_loop on_item_not_availabl ] Peer doesn't have the requested sync item. This really shouldn't happen

Then this, which is fine

p2p:terminate_inactive_connections_loop terminate_inactive_c ] Forcibly disconnecting peer x.x.x.x:xxxxx who failed to close their connection in a timely manner

Then lots of this, seems fine at a glance, but does it really make sense to just keep-alive without doing anything?

p2p:terminate_inactive_connections_loop terminate_inactive_c ] Sending a keepalive message to peer y.y.y.y:yyyyy who hasn't sent us any messages in the last 15 seconds

Then the node is stuck until trying to connect to a new peer for some reason. It is fine though. If the system clock goes back to normal, in the end the node would recover, although we could probably optimized the code to reduce the time needed to recover. I thought it would try to reconnect (due to the 3-hour-interval update_seed_nodes_task) and recover but it hasn't done. It's been several hours.

In logs I found my node had failed to connect due to this

p2p:connect_to_task connect_to ] error connecting to peer x.x.x.x:1776: 0 exception: unspecified
Cannot assign requested address
{"message":"Cannot assign requested address"}
fc::asio worker #0 asio.cpp:62 error_handler peer_connection.cpp:263

Another node admin encountered this (probably not related to the clock issue)

tcp_socket.cpp:169 bind ] Exception binding outgoing connection to desired local endpoint 0.0.0.0:1776: bind: Bad file descriptor

Impacts
Describe which portion(s) of BitShares Core may be impacted by this bug. Please tick at least one box.

  • API (the application programming interface)
  • Build (the build process or something prior to compiled code)
  • CLI (the command line wallet)
  • Deployment (the deployment process after building such as Docker, Travis, etc.)
  • DEX (the Decentralized EXchange, market engine, etc.)
  • P2P (the peer-to-peer network for transaction/block propagation)
  • Performance (system or user efficiency, etc.)
  • Protocol (the blockchain logic, consensus, validation, etc.)
  • Security (the security of system or user data, etc.)
  • UX (the User Experience)
  • Other (please add below)

CORE TEAM TASK LIST

  • Evaluate / Prioritize Bug Report
  • Refine User Stories / Requirements
  • Define Test Cases
  • Design / Develop Solution
  • Perform QA/Testing
  • Update Documentation
@abitmore abitmore added this to the Future Feature Release milestone Apr 27, 2021
@abitmore
Copy link
Member Author

Stack backtrace:

Thread 18 (Thread 0x7fff83fff700 (LWP 18990)):
#0  0x00000000057736d3 in graphene::net::detail::node_impl::have_already_received_sync_item(fc::ripemd160 const&) ()
#1  0x00000000057ac324 in graphene::net::detail::node_impl::fetch_sync_items_loop() ()
#2  0x00000000057ad1bc in fc::detail::void_functor_run<graphene::net::detail::node_impl::connect_to_p2p_network()::{lambda()#3}>::run(void*, fc::detail::void_functor_run<graphene::net::detail::node_impl::connect_to_p2p_network()::{lambda()#3}>) ()
#3  0x000000000563f864 in fc::task_base::run_impl() ()
#4  0x000000000563d12f in fc::thread_d::process_tasks() ()
#5  0x000000000563d88c in fc::thread_d::start_process_tasks(long) ()
#6  0x00000000063694c1 in make_fcontext ()
#7  0x0000000000000000 in ?? ()

@abitmore
Copy link
Member Author

By the way, found similar log messages in https://github.com/abitmore/bitshares-core/runs/2458242069 :

node.cpp:2370 on_item_not_availabl ] Peer doesn't have the requested sync item. This really shouldn't happen

It's syncing a new node, just the beginning, should be unrelated to the clock issue.

@abitmore
Copy link
Member Author

abitmore commented May 2, 2021

Duplicate of #2434. Closing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant