diff options
Diffstat (limited to '')
| -rw-r--r-- | src/cryptonote_protocol/cryptonote_protocol_handler.inl | 788 |
1 files changed, 613 insertions, 175 deletions
diff --git a/src/cryptonote_protocol/cryptonote_protocol_handler.inl b/src/cryptonote_protocol/cryptonote_protocol_handler.inl index 01f70cba1..61a211094 100644 --- a/src/cryptonote_protocol/cryptonote_protocol_handler.inl +++ b/src/cryptonote_protocol/cryptonote_protocol_handler.inl @@ -42,17 +42,24 @@ #include "cryptonote_basic/cryptonote_format_utils.h" #include "profile_tools.h" #include "net/network_throttle-detail.hpp" +#include "common/pruning.h" #undef MONERO_DEFAULT_LOG_CATEGORY #define MONERO_DEFAULT_LOG_CATEGORY "net.cn" #define MLOG_P2P_MESSAGE(x) MCINFO("net.p2p.msg", context << x) +#define MLOG_PEER_STATE(x) \ + MCINFO(MONERO_DEFAULT_LOG_CATEGORY, context << "[" << epee::string_tools::to_string_hex(context.m_pruning_seed) << "] state: " << x << " in state " << cryptonote::get_protocol_state_string(context.m_state)) -#define BLOCK_QUEUE_NBLOCKS_THRESHOLD 10 // chunks of N blocks +#define BLOCK_QUEUE_NSPANS_THRESHOLD 10 // chunks of N blocks #define BLOCK_QUEUE_SIZE_THRESHOLD (100*1024*1024) // MB -#define REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD (5 * 1000000) // microseconds +#define BLOCK_QUEUE_FORCE_DOWNLOAD_NEAR_BLOCKS 1000 +#define REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD_STANDBY (5 * 1000000) // microseconds +#define REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD (30 * 1000000) // microseconds #define IDLE_PEER_KICK_TIME (600 * 1000000) // microseconds #define PASSIVE_PEER_KICK_TIME (60 * 1000000) // microseconds +#define DROP_ON_SYNC_WEDGE_THRESHOLD (30 * 1000000000ull) // nanoseconds +#define LAST_ACTIVITY_STALL_THRESHOLD (2.0f) // seconds namespace cryptonote { @@ -75,6 +82,19 @@ namespace cryptonote template<class t_core> bool t_cryptonote_protocol_handler<t_core>::init(const boost::program_options::variables_map& vm) { + m_sync_timer.pause(); + m_sync_timer.reset(); + m_add_timer.pause(); + m_add_timer.reset(); + m_last_add_end_time = 0; + m_sync_spans_downloaded = 0; + m_sync_old_spans_downloaded = 0; + m_sync_bad_spans_downloaded = 0; + m_sync_download_chain_size = 0; + m_sync_download_objects_size = 0; + + m_block_download_max_size = command_line::get_arg(vm, cryptonote::arg_block_download_max_size); + return true; } //------------------------------------------------------------------------------------------------------------------------ @@ -103,9 +123,12 @@ namespace cryptonote if(context.m_state == cryptonote_connection_context::state_synchronizing) { NOTIFY_REQUEST_CHAIN::request r = boost::value_initialized<NOTIFY_REQUEST_CHAIN::request>(); + context.m_needed_objects.clear(); m_core.get_short_chain_history(r.block_ids); - LOG_PRINT_CCONTEXT_L2("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() ); + handler_request_blocks_history( r.block_ids ); // change the limit(?), sleep(?) + MLOG_P2P_MESSAGE("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() ); post_notify<NOTIFY_REQUEST_CHAIN>(r, context); + MLOG_PEER_STATE("requesting chain"); } else if(context.m_state == cryptonote_connection_context::state_standby) { @@ -247,6 +270,7 @@ namespace cryptonote cnx.connection_id = epee::string_tools::pod_to_hex(cntxt.m_connection_id); cnx.height = cntxt.m_remote_blockchain_height; + cnx.pruning_seed = cntxt.m_pruning_seed; connections.push_back(cnx); @@ -279,7 +303,23 @@ namespace cryptonote } } + // reject weird pruning schemes + if (hshd.pruning_seed) + { + const uint32_t log_stripes = tools::get_pruning_log_stripes(hshd.pruning_seed); + if (log_stripes != CRYPTONOTE_PRUNING_LOG_STRIPES || tools::get_pruning_stripe(hshd.pruning_seed) > (1u << log_stripes)) + { + MWARNING(context << " peer claim unexpected pruning seed " << epee::string_tools::to_string_hex(hshd.pruning_seed) << ", disconnecting"); + return false; + } + } + context.m_remote_blockchain_height = hshd.current_height; + context.m_pruning_seed = hshd.pruning_seed; +#ifdef CRYPTONOTE_PRUNING_DEBUG_SPOOF_SEED + context.m_pruning_seed = tools::make_pruning_seed(1 + (context.m_remote_address.as<epee::net_utils::ipv4_network_address>().ip()) % (1 << CRYPTONOTE_PRUNING_LOG_STRIPES), CRYPTONOTE_PRUNING_LOG_STRIPES); + LOG_INFO_CC(context, "New connection posing as pruning seed " << epee::string_tools::to_string_hex(context.m_pruning_seed) << ", seed address " << &context.m_pruning_seed); +#endif uint64_t target = m_core.get_target_blockchain_height(); if (target == 0) @@ -298,7 +338,6 @@ namespace cryptonote /* As I don't know if accessing hshd from core could be a good practice, I prefer pushing target height to the core at the same time it is pushed to the user. Nz. */ - m_core.set_target_blockchain_height((hshd.current_height)); int64_t diff = static_cast<int64_t>(hshd.current_height) - static_cast<int64_t>(m_core.get_current_blockchain_height()); uint64_t abs_diff = std::abs(diff); uint64_t max_block_height = std::max(hshd.current_height,m_core.get_current_blockchain_height()); @@ -309,14 +348,31 @@ namespace cryptonote << (0 <= diff ? std::string("behind") : std::string("ahead")) << "] " << ENDL << "SYNCHRONIZATION started"); if (hshd.current_height >= m_core.get_current_blockchain_height() + 5) // don't switch to unsafe mode just for a few blocks + { m_core.safesyncmode(false); + } + if (m_core.get_target_blockchain_height() == 0) // only when sync starts + { + m_sync_timer.resume(); + m_sync_timer.reset(); + m_add_timer.pause(); + m_add_timer.reset(); + m_last_add_end_time = 0; + m_sync_spans_downloaded = 0; + m_sync_old_spans_downloaded = 0; + m_sync_bad_spans_downloaded = 0; + m_sync_download_chain_size = 0; + m_sync_download_objects_size = 0; + } + m_core.set_target_blockchain_height((hshd.current_height)); } - LOG_PRINT_L1("Remote blockchain height: " << hshd.current_height << ", id: " << hshd.top_id); + MINFO(context << "Remote blockchain height: " << hshd.current_height << ", id: " << hshd.top_id); context.m_state = cryptonote_connection_context::state_synchronizing; //let the socket to send response to handshake, but request callback, to let send request data after response LOG_PRINT_CCONTEXT_L2("requesting callback"); ++context.m_callback_request_count; m_p2p->request_callback(context); + MLOG_PEER_STATE("requesting callback"); return true; } //------------------------------------------------------------------------------------------------------------------------ @@ -327,6 +383,7 @@ namespace cryptonote hshd.top_version = m_core.get_ideal_hard_fork_version(hshd.current_height); hshd.cumulative_difficulty = m_core.get_block_cumulative_difficulty(hshd.current_height); hshd.current_height +=1; + hshd.pruning_seed = m_core.get_blockchain_pruning_seed(); return true; } //------------------------------------------------------------------------------------------------------------------------ @@ -389,11 +446,14 @@ namespace cryptonote relay_block(arg, context); }else if(bvc.m_marked_as_orphaned) { + context.m_needed_objects.clear(); context.m_state = cryptonote_connection_context::state_synchronizing; NOTIFY_REQUEST_CHAIN::request r = boost::value_initialized<NOTIFY_REQUEST_CHAIN::request>(); m_core.get_short_chain_history(r.block_ids); - LOG_PRINT_CCONTEXT_L2("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() ); + handler_request_blocks_history( r.block_ids ); // change the limit(?), sleep(?) + MLOG_P2P_MESSAGE("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() ); post_notify<NOTIFY_REQUEST_CHAIN>(r, context); + MLOG_PEER_STATE("requesting chain"); } return 1; @@ -616,6 +676,7 @@ namespace cryptonote missing_tx_req.missing_tx_indices = std::move(need_tx_indices); m_core.resume_mine(); + MLOG_P2P_MESSAGE("-->>NOTIFY_REQUEST_FLUFFY_MISSING_TX: missing_tx_indices.size()=" << missing_tx_req.missing_tx_indices.size() ); post_notify<NOTIFY_REQUEST_FLUFFY_MISSING_TX>(missing_tx_req, context); } else // whoo-hoo we've got em all .. @@ -656,11 +717,14 @@ namespace cryptonote } else if( bvc.m_marked_as_orphaned ) { + context.m_needed_objects.clear(); context.m_state = cryptonote_connection_context::state_synchronizing; NOTIFY_REQUEST_CHAIN::request r = boost::value_initialized<NOTIFY_REQUEST_CHAIN::request>(); m_core.get_short_chain_history(r.block_ids); - LOG_PRINT_CCONTEXT_L2("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() ); + handler_request_blocks_history( r.block_ids ); // change the limit(?), sleep(?) + MLOG_P2P_MESSAGE("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() ); post_notify<NOTIFY_REQUEST_CHAIN>(r, context); + MLOG_PEER_STATE("requesting chain"); } } } @@ -747,7 +811,7 @@ namespace cryptonote fluffy_response.b.txs.push_back(t_serializable_object_to_blob(tx)); } - LOG_PRINT_CCONTEXT_L2 + MLOG_P2P_MESSAGE ( "-->>NOTIFY_RESPONSE_FLUFFY_MISSING_TX: " << ", txs.size()=" << fluffy_response.b.txs.size() @@ -811,7 +875,7 @@ namespace cryptonote drop_connection(context, false, false); return 1; } - LOG_PRINT_CCONTEXT_L2("-->>NOTIFY_RESPONSE_GET_OBJECTS: blocks.size()=" << rsp.blocks.size() << ", txs.size()=" << rsp.txs.size() + MLOG_P2P_MESSAGE("-->>NOTIFY_RESPONSE_GET_OBJECTS: blocks.size()=" << rsp.blocks.size() << ", txs.size()=" << rsp.txs.size() << ", rsp.m_current_blockchain_height=" << rsp.current_blockchain_height << ", missed_ids.size()=" << rsp.missed_ids.size()); post_notify<NOTIFY_RESPONSE_GET_OBJECTS>(rsp, context); //handler_response_blocks_now(sizeof(rsp)); // XXX @@ -834,11 +898,14 @@ namespace cryptonote return avg / m_avg_buffer.size(); } - template<class t_core> int t_cryptonote_protocol_handler<t_core>::handle_response_get_objects(int command, NOTIFY_RESPONSE_GET_OBJECTS::request& arg, cryptonote_connection_context& context) { MLOG_P2P_MESSAGE("Received NOTIFY_RESPONSE_GET_OBJECTS (" << arg.blocks.size() << " blocks, " << arg.txs.size() << " txes)"); + MLOG_PEER_STATE("received objects"); + + boost::posix_time::ptime request_time = context.m_last_request_time; + context.m_last_request_time = boost::date_time::not_a_date_time; // calculate size of request size_t size = 0; @@ -860,6 +927,8 @@ namespace cryptonote CRITICAL_REGION_LOCAL(m_buffer_mutex); m_avg_buffer.push_back(size); } + ++m_sync_spans_downloaded; + m_sync_download_objects_size += size; MDEBUG(context << " downloaded " << size << " bytes worth of blocks"); /*using namespace boost::chrono; @@ -874,6 +943,7 @@ namespace cryptonote LOG_ERROR_CCONTEXT("sent wrong NOTIFY_HAVE_OBJECTS: arg.m_current_blockchain_height=" << arg.current_blockchain_height << " < m_last_response_height=" << context.m_last_response_height << ", dropping connection"); drop_connection(context, false, false); + ++m_sync_bad_spans_downloaded; return 1; } @@ -898,6 +968,7 @@ namespace cryptonote LOG_ERROR_CCONTEXT("sent wrong block: failed to parse and validate block: " << epee::string_tools::buff_to_hex_nodelimer(block_entry.block) << ", dropping connection"); drop_connection(context, false, false); + ++m_sync_bad_spans_downloaded; return 1; } if (b.miner_tx.vin.size() != 1 || b.miner_tx.vin.front().type() != typeid(txin_gen)) @@ -905,6 +976,7 @@ namespace cryptonote LOG_ERROR_CCONTEXT("sent wrong block: block: miner tx does not have exactly one txin_gen input" << epee::string_tools::buff_to_hex_nodelimer(block_entry.block) << ", dropping connection"); drop_connection(context, false, false); + ++m_sync_bad_spans_downloaded; return 1; } if (start_height == std::numeric_limits<uint64_t>::max()) @@ -917,6 +989,7 @@ namespace cryptonote LOG_ERROR_CCONTEXT("sent wrong NOTIFY_RESPONSE_GET_OBJECTS: block with id=" << epee::string_tools::pod_to_hex(get_blob_hash(block_entry.block)) << " wasn't requested, dropping connection"); drop_connection(context, false, false); + ++m_sync_bad_spans_downloaded; return 1; } if(b.tx_hashes.size() != block_entry.txs.size()) @@ -924,6 +997,7 @@ namespace cryptonote LOG_ERROR_CCONTEXT("sent wrong NOTIFY_RESPONSE_GET_OBJECTS: block with id=" << epee::string_tools::pod_to_hex(get_blob_hash(block_entry.block)) << ", tx_hashes.size()=" << b.tx_hashes.size() << " mismatch with block_complete_entry.m_txs.size()=" << block_entry.txs.size() << ", dropping connection"); drop_connection(context, false, false); + ++m_sync_bad_spans_downloaded; return 1; } @@ -931,34 +1005,27 @@ namespace cryptonote block_hashes.push_back(block_hash); } - if(context.m_requested_objects.size()) + if(!context.m_requested_objects.empty()) { - MERROR("returned not all requested objects (context.m_requested_objects.size()=" + MERROR(context << "returned not all requested objects (context.m_requested_objects.size()=" << context.m_requested_objects.size() << "), dropping connection"); drop_connection(context, false, false); + ++m_sync_bad_spans_downloaded; return 1; } - // get the last parsed block, which should be the highest one - const crypto::hash last_block_hash = cryptonote::get_block_hash(b); - if(m_core.have_block(last_block_hash)) - { - const uint64_t subchain_height = start_height + arg.blocks.size(); - LOG_DEBUG_CC(context, "These are old blocks, ignoring: blocks " << start_height << " - " << (subchain_height-1) << ", blockchain height " << m_core.get_current_blockchain_height()); - m_block_queue.remove_spans(context.m_connection_id, start_height); - goto skip; - } - { MLOG_YELLOW(el::Level::Debug, context << " Got NEW BLOCKS inside of " << __FUNCTION__ << ": size: " << arg.blocks.size() - << ", blocks: " << start_height << " - " << (start_height + arg.blocks.size() - 1)); + << ", blocks: " << start_height << " - " << (start_height + arg.blocks.size() - 1) << + " (pruning seed " << epee::string_tools::to_string_hex(context.m_pruning_seed) << ")"); // add that new span to the block queue - const boost::posix_time::time_duration dt = now - context.m_last_request_time; + const boost::posix_time::time_duration dt = now - request_time; const float rate = size * 1e6 / (dt.total_microseconds() + 1); - MDEBUG(context << " adding span: " << arg.blocks.size() << " at height " << start_height << ", " << dt.total_microseconds()/1e6 << " seconds, " << (rate/1e3) << " kB/s, size now " << (m_block_queue.get_data_size() + blocks_size) / 1048576.f << " MB"); + MDEBUG(context << " adding span: " << arg.blocks.size() << " at height " << start_height << ", " << dt.total_microseconds()/1e6 << " seconds, " << (rate/1024) << " kB/s, size now " << (m_block_queue.get_data_size() + blocks_size) / 1048576.f << " MB"); m_block_queue.add_blocks(start_height, arg.blocks, context.m_connection_id, rate, blocks_size); + const crypto::hash last_block_hash = cryptonote::get_block_hash(b); context.m_last_known_hash = last_block_hash; if (!m_core.get_test_drop_download() || !m_core.get_test_drop_download_height()) { // DISCARD BLOCKS for testing @@ -966,7 +1033,6 @@ namespace cryptonote } } -skip: try_add_next_blocks(context); return 1; } @@ -983,15 +1049,22 @@ skip: const boost::unique_lock<boost::mutex> sync{m_sync_lock, boost::try_to_lock}; if (!sync.owns_lock()) { - MINFO("Failed to lock m_sync_lock, going back to download"); + MINFO(context << "Failed to lock m_sync_lock, going back to download"); goto skip; } MDEBUG(context << " lock m_sync_lock, adding blocks to chain..."); + MLOG_PEER_STATE("adding blocks"); { m_core.pause_mine(); - epee::misc_utils::auto_scope_leave_caller scope_exit_handler = epee::misc_utils::create_scope_leave_handler( - boost::bind(&t_core::resume_mine, &m_core)); + m_add_timer.resume(); + bool starting = true; + epee::misc_utils::auto_scope_leave_caller scope_exit_handler = epee::misc_utils::create_scope_leave_handler([this, &starting]() { + m_add_timer.pause(); + m_core.resume_mine(); + if (!starting) + m_last_add_end_time = tools::get_tick_count(); + }); while (1) { @@ -1004,22 +1077,38 @@ skip: MDEBUG(context << " no next span found, going back to download"); break; } - MDEBUG(context << " next span in the queue has blocks " << start_height << "-" << (start_height + blocks.size() - 1) - << ", we need " << previous_height); if (blocks.empty()) { - MERROR("Next span has no blocks"); + MERROR(context << "Next span has no blocks"); m_block_queue.remove_spans(span_connection_id, start_height); - break; + continue; } + MDEBUG(context << " next span in the queue has blocks " << start_height << "-" << (start_height + blocks.size() - 1) + << ", we need " << previous_height); + block new_block; + if (!parse_and_validate_block_from_blob(blocks.back().block, new_block)) + { + MERROR(context << "Failed to parse block, but it should already have been parsed"); + m_block_queue.remove_spans(span_connection_id, start_height); + continue; + } + const crypto::hash last_block_hash = cryptonote::get_block_hash(new_block); + if (m_core.have_block(last_block_hash)) + { + const uint64_t subchain_height = start_height + blocks.size(); + LOG_DEBUG_CC(context, "These are old blocks, ignoring: blocks " << start_height << " - " << (subchain_height-1) << ", blockchain height " << m_core.get_current_blockchain_height()); + m_block_queue.remove_spans(span_connection_id, start_height); + ++m_sync_old_spans_downloaded; + continue; + } if (!parse_and_validate_block_from_blob(blocks.front().block, new_block)) { - MERROR("Failed to parse block, but it should already have been parsed"); + MERROR(context << "Failed to parse block, but it should already have been parsed"); m_block_queue.remove_spans(span_connection_id, start_height); - break; + continue; } bool parent_known = m_core.have_block(new_block.prev_id); if (!parent_known) @@ -1032,6 +1121,24 @@ skip: bool parent_requested = m_block_queue.requested(new_block.prev_id); if (!parent_requested) { + // we might be able to ask for that block directly, as we now can request out of order, + // otherwise we continue out of order, unless this block is the one we need, in which + // case we request block hashes, though it might be safer to disconnect ? + if (start_height > previous_height) + { + if (should_drop_connection(context, get_next_needed_pruning_stripe().first)) + { + MDEBUG(context << "Got block with unknown parent which was not requested, but peer does not have that block - dropping connection"); + if (!context.m_is_income) + m_p2p->add_used_stripe_peer(context); + drop_connection(context, false, true); + return 1; + } + MDEBUG(context << "Got block with unknown parent which was not requested, but peer does not have that block - back to download"); + + goto skip; + } + // this can happen if a connection was sicced onto a late span, if it did not have those blocks, // since we don't know that at the sic time LOG_ERROR_CCONTEXT("Got block with unknown parent which was not requested - querying block hashes"); @@ -1047,7 +1154,17 @@ skip: } const boost::posix_time::ptime start = boost::posix_time::microsec_clock::universal_time(); - context.m_last_request_time = start; + + if (starting) + { + starting = false; + if (m_last_add_end_time) + { + const uint64_t tnow = tools::get_tick_count(); + const uint64_t ns = tools::ticks_to_ns(tnow - m_last_add_end_time); + MINFO("Restarting adding block after idle for " << ns/1e9 << " seconds"); + } + } m_core.prepare_handle_incoming_blocks(blocks); @@ -1150,7 +1267,7 @@ skip: } // each download block - MCINFO("sync-info", "Block process time (" << blocks.size() << " blocks, " << num_txs << " txs): " << block_process_time_full + transactions_process_time_full << " (" << transactions_process_time_full << "/" << block_process_time_full << ") ms"); + MDEBUG(context << "Block process time (" << blocks.size() << " blocks, " << num_txs << " txs): " << block_process_time_full + transactions_process_time_full << " (" << transactions_process_time_full << "/" << block_process_time_full << ") ms"); if (!m_core.cleanup_handle_incoming_blocks()) { @@ -1160,40 +1277,54 @@ skip: m_block_queue.remove_spans(span_connection_id, start_height); - if (m_core.get_current_blockchain_height() > previous_height) + const uint64_t current_blockchain_height = m_core.get_current_blockchain_height(); + if (current_blockchain_height > previous_height) { + const uint64_t target_blockchain_height = m_core.get_target_blockchain_height(); const boost::posix_time::time_duration dt = boost::posix_time::microsec_clock::universal_time() - start; + std::string progress_message = ""; + if (current_blockchain_height < target_blockchain_height) + { + uint64_t completion_percent = (current_blockchain_height * 100 / target_blockchain_height); + if (completion_percent == 100) // never show 100% if not actually up to date + completion_percent = 99; + progress_message = " (" + std::to_string(completion_percent) + "%, " + + std::to_string(target_blockchain_height - current_blockchain_height) + " left)"; + } + const uint32_t previous_stripe = tools::get_pruning_stripe(previous_height, target_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES); + const uint32_t current_stripe = tools::get_pruning_stripe(current_blockchain_height, target_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES); std::string timing_message = ""; if (ELPP->vRegistry()->allowed(el::Level::Info, "sync-info")) timing_message = std::string(" (") + std::to_string(dt.total_microseconds()/1e6) + " sec, " - + std::to_string((m_core.get_current_blockchain_height() - previous_height) * 1e6 / dt.total_microseconds()) - + " blocks/sec), " + std::to_string(m_block_queue.get_data_size() / 1048576.f) + " MB queued"; + + std::to_string((current_blockchain_height - previous_height) * 1e6 / dt.total_microseconds()) + + " blocks/sec), " + std::to_string(m_block_queue.get_data_size() / 1048576.f) + " MB queued in " + + std::to_string(m_block_queue.get_num_filled_spans()) + " spans, stripe " + + std::to_string(previous_stripe) + " -> " + std::to_string(current_stripe); if (ELPP->vRegistry()->allowed(el::Level::Debug, "sync-info")) - timing_message += std::string(": ") + m_block_queue.get_overview(); - if(m_core.get_target_blockchain_height() == 0){ - MGINFO_YELLOW(context << " Synced " << m_core.get_current_blockchain_height() << "/" << m_core.get_target_blockchain_height() - << timing_message); - } else { - const int completition_percent = (m_core.get_current_blockchain_height() * 100 / m_core.get_target_blockchain_height()); - if(completition_percent < 99) {//printing completion percent only if % is < of 99 cause for 99 >= this is useless - MGINFO_YELLOW(context << " Synced " << m_core.get_current_blockchain_height() << "/" << m_core.get_target_blockchain_height() - << " (" << completition_percent << "% " << (m_core.get_target_blockchain_height() - m_core.get_current_blockchain_height()) - << " blocks remaining)" << timing_message); - } else { - MGINFO_YELLOW(context << " Synced " << m_core.get_current_blockchain_height() << "/" << m_core.get_target_blockchain_height() - << timing_message); - } - } + timing_message += std::string(": ") + m_block_queue.get_overview(current_blockchain_height); + MGINFO_YELLOW("Synced " << current_blockchain_height << "/" << target_blockchain_height + << progress_message << timing_message); + if (previous_stripe != current_stripe) + notify_new_stripe(context, current_stripe); } } } - if (should_download_next_span(context)) + MLOG_PEER_STATE("stopping adding blocks"); + + if (should_download_next_span(context, false)) { - context.m_needed_objects.clear(); - context.m_last_response_height = 0; force_next_span = true; } + else if (should_drop_connection(context, get_next_needed_pruning_stripe().first)) + { + if (!context.m_is_income) + { + m_p2p->add_used_stripe_peer(context); + drop_connection(context, false, false); + } + return 1; + } } skip: @@ -1207,6 +1338,28 @@ skip: } //------------------------------------------------------------------------------------------------------------------------ template<class t_core> + void t_cryptonote_protocol_handler<t_core>::notify_new_stripe(cryptonote_connection_context& cntxt, uint32_t stripe) + { + m_p2p->for_each_connection([&](cryptonote_connection_context& context, nodetool::peerid_type peer_id, uint32_t support_flags)->bool + { + if (cntxt.m_connection_id == context.m_connection_id) + return true; + if (context.m_state == cryptonote_connection_context::state_normal) + { + const uint32_t peer_stripe = tools::get_pruning_stripe(context.m_pruning_seed); + if (stripe && peer_stripe && peer_stripe != stripe) + return true; + context.m_state = cryptonote_connection_context::state_synchronizing; + LOG_PRINT_CCONTEXT_L2("requesting callback"); + ++context.m_callback_request_count; + m_p2p->request_callback(context); + MLOG_PEER_STATE("requesting callback"); + } + return true; + }); + } + //------------------------------------------------------------------------------------------------------------------------ + template<class t_core> bool t_cryptonote_protocol_handler<t_core>::on_idle() { m_idle_peer_kicker.do_call(boost::bind(&t_cryptonote_protocol_handler<t_core>::kick_idle_peers, this)); @@ -1218,30 +1371,24 @@ skip: bool t_cryptonote_protocol_handler<t_core>::kick_idle_peers() { MTRACE("Checking for idle peers..."); - std::vector<boost::uuids::uuid> kick_connections; m_p2p->for_each_connection([&](cryptonote_connection_context& context, nodetool::peerid_type peer_id, uint32_t support_flags)->bool { - if (context.m_state == cryptonote_connection_context::state_synchronizing || context.m_state == cryptonote_connection_context::state_before_handshake) + if (context.m_state == cryptonote_connection_context::state_synchronizing && context.m_last_request_time != boost::date_time::not_a_date_time) { - const bool passive = context.m_state == cryptonote_connection_context::state_before_handshake; const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time(); const boost::posix_time::time_duration dt = now - context.m_last_request_time; - const int64_t threshold = passive ? PASSIVE_PEER_KICK_TIME : IDLE_PEER_KICK_TIME; - if (dt.total_microseconds() > threshold) + if (dt.total_microseconds() > IDLE_PEER_KICK_TIME) { - MINFO(context << " kicking " << (passive ? "passive" : "idle") << " peer"); - kick_connections.push_back(context.m_connection_id); + MINFO(context << " kicking idle peer, last update " << (dt.total_microseconds() / 1.e6) << " seconds ago"); + LOG_PRINT_CCONTEXT_L2("requesting callback"); + context.m_last_request_time = boost::date_time::not_a_date_time; + context.m_state = cryptonote_connection_context::state_standby; // we'll go back to adding, then (if we can't), download + ++context.m_callback_request_count; + m_p2p->request_callback(context); } } return true; }); - for (const boost::uuids::uuid &conn_id: kick_connections) - { - m_p2p->for_connection(conn_id, [this](cryptonote_connection_context& context, nodetool::peerid_type peer_id, uint32_t support_flags) { - drop_connection(context, false, false); - return true; - }); - } return true; } //------------------------------------------------------------------------------------------------------------------------ @@ -1272,75 +1419,174 @@ skip: drop_connection(context, false, false); return 1; } - LOG_PRINT_CCONTEXT_L2("-->>NOTIFY_RESPONSE_CHAIN_ENTRY: m_start_height=" << r.start_height << ", m_total_height=" << r.total_height << ", m_block_ids.size()=" << r.m_block_ids.size()); + MLOG_P2P_MESSAGE("-->>NOTIFY_RESPONSE_CHAIN_ENTRY: m_start_height=" << r.start_height << ", m_total_height=" << r.total_height << ", m_block_ids.size()=" << r.m_block_ids.size()); post_notify<NOTIFY_RESPONSE_CHAIN_ENTRY>(r, context); return 1; } //------------------------------------------------------------------------------------------------------------------------ template<class t_core> - bool t_cryptonote_protocol_handler<t_core>::should_download_next_span(cryptonote_connection_context& context) const + bool t_cryptonote_protocol_handler<t_core>::should_download_next_span(cryptonote_connection_context& context, bool standby) { std::vector<crypto::hash> hashes; boost::uuids::uuid span_connection_id; boost::posix_time::ptime request_time; + boost::uuids::uuid connection_id; std::pair<uint64_t, uint64_t> span; + bool filled; - span = m_block_queue.get_start_gap_span(); - if (span.second > 0) - { - MDEBUG(context << " we should download it as there is a gap"); - return true; - } - - // if the next span is not scheduled (or there is none) - span = m_block_queue.get_next_span_if_scheduled(hashes, span_connection_id, request_time); - if (span.second == 0) + const uint64_t blockchain_height = m_core.get_current_blockchain_height(); + if (context.m_remote_blockchain_height <= blockchain_height) + return false; + const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time(); + const bool has_next_block = tools::has_unpruned_block(blockchain_height, context.m_remote_blockchain_height, context.m_pruning_seed); + if (has_next_block) { - // we might be in a weird case where there is a filled next span, - // but it starts higher than the current height - uint64_t height; - std::vector<cryptonote::block_complete_entry> bcel; - if (!m_block_queue.get_next_span(height, bcel, span_connection_id, true)) - return false; - if (height > m_core.get_current_blockchain_height()) + if (!m_block_queue.has_next_span(blockchain_height, filled, request_time, connection_id)) { - MDEBUG(context << " we should download it as the next block isn't scheduled"); + MDEBUG(context << " we should download it as no peer reserved it"); return true; } + if (!filled) + { + const long dt = (now - request_time).total_microseconds(); + if (dt >= REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD) + { + MDEBUG(context << " we should download it as it's not been received yet after " << dt/1e6); + return true; + } + + // in standby, be ready to double download early since we're idling anyway + // let the fastest peer trigger first + long threshold; + const double dl_speed = context.m_max_speed_down; + if (standby && dt >= REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD_STANDBY && dl_speed > 0) + { + bool download = false; + if (m_p2p->for_connection(connection_id, [&](cryptonote_connection_context& ctx, nodetool::peerid_type peer_id, uint32_t f)->bool{ + const time_t nowt = time(NULL); + const time_t time_since_last_recv = nowt - ctx.m_last_recv; + const float last_activity = std::min((float)time_since_last_recv, dt/1e6f); + const bool stalled = last_activity > LAST_ACTIVITY_STALL_THRESHOLD; + if (stalled) + { + MDEBUG(context << " we should download it as the downloading peer is stalling for " << nowt - ctx.m_last_recv << " seconds"); + download = true; + return true; + } + + // estimate the standby peer can give us 80% of its max speed + // and let it download if that speed is > N times as fast as the current one + // N starts at 10 after REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD_STANDBY, + // decreases to 1.25 at REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD, + // so that at times goes without the download being done, a retry becomes easier + const float max_multiplier = 10.f; + const float min_multiplier = 1.25f; + float multiplier = max_multiplier; + if (dt/1e6 >= REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD_STANDBY) + { + multiplier = max_multiplier - (dt/1e6-REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD_STANDBY) * (max_multiplier - min_multiplier) / (REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD - REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD_STANDBY); + multiplier = std::min(max_multiplier, std::max(min_multiplier, multiplier)); + } + if (dl_speed * .8f > ctx.m_current_speed_down * multiplier) + { + MDEBUG(context << " we should download it as we are substantially faster (" << dl_speed << " vs " + << ctx.m_current_speed_down << ", multiplier " << multiplier << " after " << dt/1e6 << " seconds)"); + download = true; + return true; + } + return true; + })) + { + if (download) + return true; + } + else + { + MWARNING(context << " we should download it as the downloading peer is unexpectedly not known to us"); + return true; + } + } + } + } + + return false; + } + //------------------------------------------------------------------------------------------------------------------------ + template<class t_core> + bool t_cryptonote_protocol_handler<t_core>::should_drop_connection(cryptonote_connection_context& context, uint32_t next_stripe) + { + if (context.m_anchor) + { + MDEBUG(context << "This is an anchor peer, not dropping"); return false; } - // if it was scheduled by this particular peer - if (span_connection_id == context.m_connection_id) + if (context.m_pruning_seed == 0) + { + MDEBUG(context << "This peer is not striped, not dropping"); return false; + } - float span_speed = m_block_queue.get_speed(span_connection_id); - float speed = m_block_queue.get_speed(context.m_connection_id); - MDEBUG(context << " next span is scheduled for " << span_connection_id << ", speed " << span_speed << ", ours " << speed); - - // we try for that span too if: - // - we're substantially faster, or: - // - we're the fastest and the other one isn't (avoids a peer being waaaay slow but yet unmeasured) - // - the other one asked at least 5 seconds ago - if (span_speed < .25 && speed > .75f) + const uint32_t peer_stripe = tools::get_pruning_stripe(context.m_pruning_seed); + if (next_stripe == peer_stripe) { - MDEBUG(context << " we should download it as we're substantially faster"); - return true; + MDEBUG(context << "This peer has needed stripe " << peer_stripe << ", not dropping"); + return false; } - if (speed == 1.0f && span_speed != 1.0f) + + if (!context.m_needed_objects.empty()) { - MDEBUG(context << " we should download it as we're the fastest peer"); - return true; + const uint64_t next_available_block_height = context.m_last_response_height - context.m_needed_objects.size() + 1; + if (tools::has_unpruned_block(next_available_block_height, context.m_remote_blockchain_height, context.m_pruning_seed)) + { + MDEBUG(context << "This peer has unpruned next block at height " << next_available_block_height << ", not dropping"); + return false; + } } - const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time(); - if ((now - request_time).total_microseconds() > REQUEST_NEXT_SCHEDULED_SPAN_THRESHOLD) + + if (next_stripe > 0) { - MDEBUG(context << " we should download it as this span was requested long ago"); - return true; + unsigned int n_out_peers = 0, n_peers_on_next_stripe = 0; + m_p2p->for_each_connection([&](cryptonote_connection_context& ctx, nodetool::peerid_type peer_id, uint32_t support_flags)->bool{ + if (!ctx.m_is_income) + ++n_out_peers; + if (ctx.m_state >= cryptonote_connection_context::state_synchronizing && tools::get_pruning_stripe(ctx.m_pruning_seed) == next_stripe) + ++n_peers_on_next_stripe; + return true; + }); + const uint32_t distance = (peer_stripe + (1<<CRYPTONOTE_PRUNING_LOG_STRIPES) - next_stripe) % (1<<CRYPTONOTE_PRUNING_LOG_STRIPES); + if ((n_out_peers >= m_max_out_peers && n_peers_on_next_stripe == 0) || (distance > 1 && n_peers_on_next_stripe <= 2) || distance > 2) + { + MDEBUG(context << "we want seed " << next_stripe << ", and either " << n_out_peers << " is at max out peers (" + << m_max_out_peers << ") or distance " << distance << " from " << next_stripe << " to " << peer_stripe << + " is too large and we have only " << n_peers_on_next_stripe << " peers on next seed, dropping connection to make space"); + return true; + } } + MDEBUG(context << "End of checks, not dropping"); return false; } //------------------------------------------------------------------------------------------------------------------------ template<class t_core> + void t_cryptonote_protocol_handler<t_core>::skip_unneeded_hashes(cryptonote_connection_context& context, bool check_block_queue) const + { + // take out blocks we already have + size_t skip = 0; + while (skip < context.m_needed_objects.size() && (m_core.have_block(context.m_needed_objects[skip]) || (check_block_queue && m_block_queue.have(context.m_needed_objects[skip])))) + { + // if we're popping the last hash, record it so we can ask again from that hash, + // this prevents never being able to progress on peers we get old hash lists from + if (skip + 1 == context.m_needed_objects.size()) + context.m_last_known_hash = context.m_needed_objects[skip]; + ++skip; + } + if (skip > 0) + { + MDEBUG(context << "skipping " << skip << "/" << context.m_needed_objects.size() << " blocks"); + context.m_needed_objects = std::vector<crypto::hash>(context.m_needed_objects.begin() + skip, context.m_needed_objects.end()); + } + } + //------------------------------------------------------------------------------------------------------------------------ + template<class t_core> bool t_cryptonote_protocol_handler<t_core>::request_missing_objects(cryptonote_connection_context& context, bool check_having_blocks, bool force_next_span) { // flush stale spans @@ -1357,47 +1603,102 @@ skip: { do { - size_t nblocks = m_block_queue.get_num_filled_spans(); + size_t nspans = m_block_queue.get_num_filled_spans(); size_t size = m_block_queue.get_data_size(); - if (nblocks < BLOCK_QUEUE_NBLOCKS_THRESHOLD || size < BLOCK_QUEUE_SIZE_THRESHOLD) + const uint64_t bc_height = m_core.get_current_blockchain_height(); + const auto next_needed_pruning_stripe = get_next_needed_pruning_stripe(); + const uint32_t add_stripe = tools::get_pruning_stripe(bc_height, context.m_remote_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES); + const uint32_t peer_stripe = tools::get_pruning_stripe(context.m_pruning_seed); + const size_t block_queue_size_threshold = m_block_download_max_size ? m_block_download_max_size : BLOCK_QUEUE_SIZE_THRESHOLD; + bool queue_proceed = nspans < BLOCK_QUEUE_NSPANS_THRESHOLD || size < block_queue_size_threshold; + // get rid of blocks we already requested, or already have + skip_unneeded_hashes(context, true); + uint64_t next_needed_height = m_block_queue.get_next_needed_height(bc_height); + uint64_t next_block_height; + if (context.m_needed_objects.empty()) + next_block_height = next_needed_height; + else + next_block_height = context.m_last_response_height - context.m_needed_objects.size() + 1; + bool stripe_proceed_main = (add_stripe == 0 || peer_stripe == 0 || add_stripe == peer_stripe) && (next_block_height < bc_height + BLOCK_QUEUE_FORCE_DOWNLOAD_NEAR_BLOCKS || next_needed_height < bc_height + BLOCK_QUEUE_FORCE_DOWNLOAD_NEAR_BLOCKS); + bool stripe_proceed_secondary = tools::has_unpruned_block(next_block_height, context.m_remote_blockchain_height, context.m_pruning_seed); + bool proceed = stripe_proceed_main || (queue_proceed && stripe_proceed_secondary); + if (!stripe_proceed_main && !stripe_proceed_secondary && should_drop_connection(context, tools::get_pruning_stripe(next_block_height, context.m_remote_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES))) + { + if (!context.m_is_income) + m_p2p->add_used_stripe_peer(context); + return false; // drop outgoing connections + } + + MDEBUG(context << "proceed " << proceed << " (queue " << queue_proceed << ", stripe " << stripe_proceed_main << "/" << + stripe_proceed_secondary << "), " << next_needed_pruning_stripe.first << "-" << next_needed_pruning_stripe.second << + " needed, bc add stripe " << add_stripe << ", we have " << peer_stripe << "), bc_height " << bc_height); + MDEBUG(context << " - next_block_height " << next_block_height << ", seed " << epee::string_tools::to_string_hex(context.m_pruning_seed) << + ", next_needed_height "<< next_needed_height); + MDEBUG(context << " - last_response_height " << context.m_last_response_height << ", m_needed_objects size " << context.m_needed_objects.size()); + + // if we're waiting for next span, try to get it before unblocking threads below, + // or a runaway downloading of future spans might happen + if (stripe_proceed_main && should_download_next_span(context, true)) + { + MDEBUG(context << " we should try for that next span too, we think we could get it faster, resuming"); + force_next_span = true; + MLOG_PEER_STATE("resuming"); + break; + } + + if (proceed) { if (context.m_state != cryptonote_connection_context::state_standby) { - LOG_DEBUG_CC(context, "Block queue is " << nblocks << " and " << size << ", resuming"); + LOG_DEBUG_CC(context, "Block queue is " << nspans << " and " << size << ", resuming"); + MLOG_PEER_STATE("resuming"); } break; } // this one triggers if all threads are in standby, which should not happen, // but happened at least once, so we unblock at least one thread if so - const boost::unique_lock<boost::mutex> sync{m_sync_lock, boost::try_to_lock}; + boost::unique_lock<boost::mutex> sync{m_sync_lock, boost::try_to_lock}; if (sync.owns_lock()) { - LOG_DEBUG_CC(context, "No other thread is adding blocks, resuming"); - break; - } + bool filled = false; + boost::posix_time::ptime time; + boost::uuids::uuid connection_id; + if (m_block_queue.has_next_span(m_core.get_current_blockchain_height(), filled, time, connection_id) && filled) + { + LOG_DEBUG_CC(context, "No other thread is adding blocks, and next span needed is ready, resuming"); + MLOG_PEER_STATE("resuming"); + context.m_state = cryptonote_connection_context::state_standby; + ++context.m_callback_request_count; + m_p2p->request_callback(context); + return true; + } + else + { + sync.unlock(); - if (should_download_next_span(context)) - { - MDEBUG(context << " we should try for that next span too, we think we could get it faster, resuming"); - force_next_span = true; - break; + // if this has gone on for too long, drop incoming connection to guard against some wedge state + if (!context.m_is_income) + { + const uint64_t now = tools::get_tick_count(); + const uint64_t dt = now - m_last_add_end_time; + if (tools::ticks_to_ns(dt) >= DROP_ON_SYNC_WEDGE_THRESHOLD) + { + MDEBUG(context << "Block addition seems to have wedged, dropping connection"); + return false; + } + } + } } if (context.m_state != cryptonote_connection_context::state_standby) { - LOG_DEBUG_CC(context, "Block queue is " << nblocks << " and " << size << ", pausing"); + if (!queue_proceed) + LOG_DEBUG_CC(context, "Block queue is " << nspans << " and " << size << ", pausing"); + else if (!stripe_proceed_main && !stripe_proceed_secondary) + LOG_DEBUG_CC(context, "We do not have the stripe required to download another block, pausing"); context.m_state = cryptonote_connection_context::state_standby; - } - - // this needs doing after we went to standby, so the callback knows what to do - bool filled; - if (m_block_queue.has_next_span(context.m_connection_id, filled) && !filled) - { - MDEBUG(context << " we have the next span, and it is scheduled, resuming"); - ++context.m_callback_request_count; - m_p2p->request_callback(context); - return true; + MLOG_PEER_STATE("pausing"); } return true; @@ -1405,7 +1706,9 @@ skip: context.m_state = cryptonote_connection_context::state_synchronizing; } - MDEBUG(context << " request_missing_objects: check " << check_having_blocks << ", force_next_span " << force_next_span << ", m_needed_objects " << context.m_needed_objects.size() << " lrh " << context.m_last_response_height << ", chain " << m_core.get_current_blockchain_height()); + MDEBUG(context << " request_missing_objects: check " << check_having_blocks << ", force_next_span " << force_next_span + << ", m_needed_objects " << context.m_needed_objects.size() << " lrh " << context.m_last_response_height << ", chain " + << m_core.get_current_blockchain_height() << ", pruning seed " << epee::string_tools::to_string_hex(context.m_pruning_seed)); if(context.m_needed_objects.size() || force_next_span) { //we know objects that we need, request this objects @@ -1414,28 +1717,6 @@ skip: size_t count = 0; const size_t count_limit = m_core.get_block_sync_size(m_core.get_current_blockchain_height()); std::pair<uint64_t, uint64_t> span = std::make_pair(0, 0); - { - MDEBUG(context << " checking for gap"); - span = m_block_queue.get_start_gap_span(); - if (span.second > 0) - { - const uint64_t first_block_height_known = context.m_last_response_height - context.m_needed_objects.size() + 1; - const uint64_t last_block_height_known = context.m_last_response_height; - const uint64_t first_block_height_needed = span.first; - const uint64_t last_block_height_needed = span.first + std::min(span.second, (uint64_t)count_limit) - 1; - MDEBUG(context << " gap found, span: " << span.first << " - " << span.first + span.second - 1 << " (" << last_block_height_needed << ")"); - MDEBUG(context << " current known hashes from " << first_block_height_known << " to " << last_block_height_known); - if (first_block_height_needed < first_block_height_known || last_block_height_needed > last_block_height_known) - { - MDEBUG(context << " we are missing some of the necessary hashes for this gap, requesting chain again"); - context.m_needed_objects.clear(); - context.m_last_response_height = 0; - start_from_current_chain = true; - goto skip; - } - MDEBUG(context << " we have the hashes for this gap"); - } - } if (force_next_span) { if (span.second == 0) @@ -1452,6 +1733,7 @@ skip: req.blocks.push_back(hash); context.m_requested_objects.insert(hash); } + m_block_queue.reset_next_span_time(); } } } @@ -1465,22 +1747,20 @@ skip: context.m_last_response_height = 0; goto skip; } - // take out blocks we already have - size_t skip = 0; - while (skip < context.m_needed_objects.size() && m_core.have_block(context.m_needed_objects[skip])) - { - // if we're popping the last hash, record it so we can ask again from that hash, - // this prevents never being able to progress on peers we get old hash lists from - if (skip + 1 == context.m_needed_objects.size()) - context.m_last_known_hash = context.m_needed_objects[skip]; - ++skip; - } - if (skip > 0) - context.m_needed_objects = std::vector<crypto::hash>(context.m_needed_objects.begin() + skip, context.m_needed_objects.end()); + skip_unneeded_hashes(context, false); const uint64_t first_block_height = context.m_last_response_height - context.m_needed_objects.size() + 1; - span = m_block_queue.reserve_span(first_block_height, context.m_last_response_height, count_limit, context.m_connection_id, context.m_needed_objects); + span = m_block_queue.reserve_span(first_block_height, context.m_last_response_height, count_limit, context.m_connection_id, context.m_pruning_seed, context.m_remote_blockchain_height, context.m_needed_objects); MDEBUG(context << " span from " << first_block_height << ": " << span.first << "/" << span.second); + if (span.second > 0) + { + const uint32_t stripe = tools::get_pruning_stripe(span.first, context.m_remote_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES); + if (context.m_pruning_seed && stripe != tools::get_pruning_stripe(context.m_pruning_seed)) + { + MDEBUG(context << " starting early on next seed (" << span.first << " with stripe " << stripe << + ", context seed " << epee::string_tools::to_string_hex(context.m_pruning_seed) << ")"); + } + } } if (span.second == 0 && !force_next_span) { @@ -1489,6 +1769,8 @@ skip: boost::uuids::uuid span_connection_id; boost::posix_time::ptime time; span = m_block_queue.get_next_span_if_scheduled(hashes, span_connection_id, time); + if (span.second > 0 && !tools::has_unpruned_block(span.first, context.m_remote_blockchain_height, context.m_pruning_seed)) + span = std::make_pair(0, 0); if (span.second > 0) { is_next = true; @@ -1534,17 +1816,67 @@ skip: } context.m_last_request_time = boost::posix_time::microsec_clock::universal_time(); - LOG_PRINT_CCONTEXT_L1("-->>NOTIFY_REQUEST_GET_OBJECTS: blocks.size()=" << req.blocks.size() << ", txs.size()=" << req.txs.size() + MLOG_P2P_MESSAGE("-->>NOTIFY_REQUEST_GET_OBJECTS: blocks.size()=" << req.blocks.size() << ", txs.size()=" << req.txs.size() << "requested blocks count=" << count << " / " << count_limit << " from " << span.first << ", first hash " << req.blocks.front()); //epee::net_utils::network_throttle_manager::get_global_throttle_inreq().logger_handle_net("log/dr-monero/net/req-all.data", sec, get_avg_block_size()); post_notify<NOTIFY_REQUEST_GET_OBJECTS>(req, context); + MLOG_PEER_STATE("requesting objects"); + return true; + } + + // if we're still around, we might be at a point where the peer is pruned, so we could either + // drop it to make space for other peers, or ask for a span further down the line + const uint32_t next_stripe = get_next_needed_pruning_stripe().first; + const uint32_t peer_stripe = tools::get_pruning_stripe(context.m_pruning_seed); + if (next_stripe && peer_stripe && next_stripe != peer_stripe) + { + // at this point, we have to either close the connection, or start getting blocks past the + // current point, or become dormant + MDEBUG(context << "this peer is pruned at seed " << epee::string_tools::to_string_hex(context.m_pruning_seed) << + ", next stripe needed is " << next_stripe); + if (!context.m_is_income) + { + if (should_drop_connection(context, next_stripe)) + { + m_p2p->add_used_stripe_peer(context); + return false; // drop outgoing connections + } + } + // we'll get back stuck waiting for the go ahead + context.m_state = cryptonote_connection_context::state_normal; + MLOG_PEER_STATE("Nothing to do for now, switching to normal state"); return true; } } skip: context.m_needed_objects.clear(); + + // we might have been called from the "received chain entry" handler, and end up + // here because we can't use any of those blocks (maybe because all of them are + // actually already requested). In this case, if we can add blocks instead, do so + if (m_core.get_current_blockchain_height() < m_core.get_target_blockchain_height()) + { + const boost::unique_lock<boost::mutex> sync{m_sync_lock, boost::try_to_lock}; + if (sync.owns_lock()) + { + uint64_t start_height; + std::vector<cryptonote::block_complete_entry> blocks; + boost::uuids::uuid span_connection_id; + bool filled = false; + if (m_block_queue.get_next_span(start_height, blocks, span_connection_id, filled) && filled) + { + LOG_DEBUG_CC(context, "No other thread is adding blocks, resuming"); + MLOG_PEER_STATE("will try to add blocks next"); + context.m_state = cryptonote_connection_context::state_standby; + ++context.m_callback_request_count; + m_p2p->request_callback(context); + return true; + } + } + } + if(context.m_last_response_height < context.m_remote_blockchain_height-1) {//we have to fetch more objects ids, request blockchain entry @@ -1567,8 +1899,9 @@ skip: //LOG_PRINT_CCONTEXT_L1("r = " << 200); context.m_last_request_time = boost::posix_time::microsec_clock::universal_time(); - LOG_PRINT_CCONTEXT_L1("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() << ", start_from_current_chain " << start_from_current_chain); + MLOG_P2P_MESSAGE("-->>NOTIFY_REQUEST_CHAIN: m_block_ids.size()=" << r.block_ids.size() << ", start_from_current_chain " << start_from_current_chain); post_notify<NOTIFY_REQUEST_CHAIN>(r, context); + MLOG_PEER_STATE("requesting chain"); }else { CHECK_AND_ASSERT_MES(context.m_last_response_height == context.m_remote_blockchain_height-1 @@ -1608,9 +1941,25 @@ skip: << ENDL << "Use the \"help\" command to see the list of available commands." << ENDL << "**********************************************************************"); + m_sync_timer.pause(); + if (ELPP->vRegistry()->allowed(el::Level::Info, "sync-info")) + { + const uint64_t sync_time = m_sync_timer.value(); + const uint64_t add_time = m_add_timer.value(); + if (sync_time && add_time) + { + MCLOG_YELLOW(el::Level::Info, "sync-info", "Sync time: " << sync_time/1e9/60 << " min, idle time " << + (100.f * (1.0f - add_time / (float)sync_time)) << "%" << ", " << + (10 * m_sync_download_objects_size / 1024 / 1024) / 10.f << " + " << + (10 * m_sync_download_chain_size / 1024 / 1024) / 10.f << " MB downloaded, " << + 100.0f * m_sync_old_spans_downloaded / m_sync_spans_downloaded << "% old spans, " << + 100.0f * m_sync_bad_spans_downloaded / m_sync_spans_downloaded << "% bad spans"); + } + } m_core.on_synchronized(); } m_core.safesyncmode(true); + m_p2p->clear_used_stripe_peers(); return true; } //------------------------------------------------------------------------------------------------------------------------ @@ -1631,6 +1980,11 @@ skip: { MLOG_P2P_MESSAGE("Received NOTIFY_RESPONSE_CHAIN_ENTRY: m_block_ids.size()=" << arg.m_block_ids.size() << ", m_start_height=" << arg.start_height << ", m_total_height=" << arg.total_height); + MLOG_PEER_STATE("received chain"); + + context.m_last_request_time = boost::date_time::not_a_date_time; + + m_sync_download_chain_size += arg.m_block_ids.size() * sizeof(crypto::hash); if(!arg.m_block_ids.size()) { @@ -1644,7 +1998,14 @@ skip: drop_connection(context, true, false); return 1; } + MDEBUG(context << "first block hash " << arg.m_block_ids.front() << ", last " << arg.m_block_ids.back()); + if (arg.total_height >= CRYPTONOTE_MAX_BLOCK_NUMBER || arg.m_block_ids.size() >= CRYPTONOTE_MAX_BLOCK_NUMBER) + { + LOG_ERROR_CCONTEXT("sent wrong NOTIFY_RESPONSE_CHAIN_ENTRY, with total_height=" << arg.total_height << " and block_ids=" << arg.m_block_ids.size()); + drop_connection(context, false, false); + return 1; + } context.m_remote_blockchain_height = arg.total_height; context.m_last_response_height = arg.start_height + arg.m_block_ids.size()-1; if(context.m_last_response_height > context.m_remote_blockchain_height) @@ -1664,6 +2025,7 @@ skip: return 1; } + context.m_needed_objects.clear(); uint64_t added = 0; for(auto& bl_id: arg.m_block_ids) { @@ -1773,10 +2135,85 @@ skip: } //------------------------------------------------------------------------------------------------------------------------ template<class t_core> + std::string t_cryptonote_protocol_handler<t_core>::get_peers_overview() const + { + std::stringstream ss; + const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time(); + m_p2p->for_each_connection([&](const connection_context &ctx, nodetool::peerid_type peer_id, uint32_t support_flags) { + const uint32_t stripe = tools::get_pruning_stripe(ctx.m_pruning_seed); + char state_char = cryptonote::get_protocol_state_char(ctx.m_state); + ss << stripe + state_char; + if (ctx.m_last_request_time != boost::date_time::not_a_date_time) + ss << (((now - ctx.m_last_request_time).total_microseconds() > IDLE_PEER_KICK_TIME) ? "!" : "?"); + ss << + " "; + return true; + }); + return ss.str(); + } + //------------------------------------------------------------------------------------------------------------------------ + template<class t_core> + std::pair<uint32_t, uint32_t> t_cryptonote_protocol_handler<t_core>::get_next_needed_pruning_stripe() const + { + const uint64_t want_height_from_blockchain = m_core.get_current_blockchain_height(); + const uint64_t want_height_from_block_queue = m_block_queue.get_next_needed_height(want_height_from_blockchain); + const uint64_t want_height = std::max(want_height_from_blockchain, want_height_from_block_queue); + uint64_t blockchain_height = m_core.get_target_blockchain_height(); + // if we don't know the remote chain size yet, assume infinitely large so we get the right stripe if we're not near the tip + if (blockchain_height == 0) + blockchain_height = CRYPTONOTE_MAX_BLOCK_NUMBER; + const uint32_t next_pruning_stripe = tools::get_pruning_stripe(want_height, blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES); + if (next_pruning_stripe == 0) + return std::make_pair(0, 0); + // if we already have a few peers on this stripe, but none on next one, try next one + unsigned int n_next = 0, n_subsequent = 0, n_others = 0; + const uint32_t subsequent_pruning_stripe = 1 + next_pruning_stripe % (1<<CRYPTONOTE_PRUNING_LOG_STRIPES); + m_p2p->for_each_connection([&](const connection_context &context, nodetool::peerid_type peer_id, uint32_t support_flags) { + if (context.m_state >= cryptonote_connection_context::state_synchronizing) + { + if (context.m_pruning_seed == 0 || tools::get_pruning_stripe(context.m_pruning_seed) == next_pruning_stripe) + ++n_next; + else if (tools::get_pruning_stripe(context.m_pruning_seed) == subsequent_pruning_stripe) + ++n_subsequent; + else + ++n_others; + } + return true; + }); + const bool use_next = (n_next > m_max_out_peers / 2 && n_subsequent <= 1) || (n_next > 2 && n_subsequent == 0); + const uint32_t ret_stripe = use_next ? subsequent_pruning_stripe: next_pruning_stripe; + MIDEBUG(const std::string po = get_peers_overview(), "get_next_needed_pruning_stripe: want height " << want_height << " (" << + want_height_from_blockchain << " from blockchain, " << want_height_from_block_queue << " from block queue), stripe " << + next_pruning_stripe << " (" << n_next << "/" << m_max_out_peers << " on it and " << n_subsequent << " on " << + subsequent_pruning_stripe << ", " << n_others << " others) -> " << ret_stripe << " (+" << + (ret_stripe - next_pruning_stripe + (1 << CRYPTONOTE_PRUNING_LOG_STRIPES)) % (1 << CRYPTONOTE_PRUNING_LOG_STRIPES) << + "), current peers " << po); + return std::make_pair(next_pruning_stripe, ret_stripe); + } + //------------------------------------------------------------------------------------------------------------------------ + template<class t_core> + bool t_cryptonote_protocol_handler<t_core>::needs_new_sync_connections() const + { + const uint64_t target = m_core.get_target_blockchain_height(); + const uint64_t height = m_core.get_current_blockchain_height(); + if (target && target <= height) + return false; + size_t n_out_peers = 0; + m_p2p->for_each_connection([&](cryptonote_connection_context& ctx, nodetool::peerid_type peer_id, uint32_t support_flags)->bool{ + if (!ctx.m_is_income) + ++n_out_peers; + return true; + }); + if (n_out_peers >= m_max_out_peers) + return false; + return true; + } + //------------------------------------------------------------------------------------------------------------------------ + template<class t_core> void t_cryptonote_protocol_handler<t_core>::drop_connection(cryptonote_connection_context &context, bool add_fail, bool flush_all_spans) { - LOG_DEBUG_CC(context, "dropping connection id " << context.m_connection_id << - ", add_fail " << add_fail << ", flush_all_spans " << flush_all_spans); + LOG_DEBUG_CC(context, "dropping connection id " << context.m_connection_id << " (pruning seed " << + epee::string_tools::to_string_hex(context.m_pruning_seed) << + "), add_fail " << add_fail << ", flush_all_spans " << flush_all_spans); if (add_fail) m_p2p->add_host_fail(context.m_remote_address); @@ -1803,6 +2240,7 @@ skip: } m_block_queue.flush_spans(context.m_connection_id, false); + MLOG_PEER_STATE("closed"); } //------------------------------------------------------------------------------------------------------------------------ |