diff --git a/validator/impl/collator.cpp b/validator/impl/collator.cpp index 86ee1cf4..1d277048 100644 --- a/validator/impl/collator.cpp +++ b/validator/impl/collator.cpp @@ -106,7 +106,7 @@ Collator::Collator(ShardIdFull shard, bool is_hardfork, UnixTime min_ts, BlockId * The results of these queries are handled by corresponding callback functions. */ void Collator::start_up() { - LOG(DEBUG) << "Collator for shard " << shard_.to_str() << " started"; + LOG(WARNING) << "Collator for shard " << shard_.to_str() << " started"; LOG(DEBUG) << "Previous block #1 is " << prev_blocks.at(0).to_str(); if (prev_blocks.size() > 1) { LOG(DEBUG) << "Previous block #2 is " << prev_blocks.at(1).to_str(); @@ -554,7 +554,7 @@ bool Collator::preprocess_prev_mc_state() { * @param res The retreived masterchain state. */ void Collator::after_get_mc_state(td::Result, BlockIdExt>> res) { - LOG(DEBUG) << "in Collator::after_get_mc_state()"; + LOG(WARNING) << "in Collator::after_get_mc_state()"; --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -589,7 +589,7 @@ void Collator::after_get_mc_state(td::Result, Bl * @param res The retrieved shard state. */ void Collator::after_get_shard_state(int idx, td::Result> res) { - LOG(DEBUG) << "in Collator::after_get_shard_state(" << idx << ")"; + LOG(WARNING) << "in Collator::after_get_shard_state(" << idx << ")"; --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -820,7 +820,6 @@ bool Collator::request_out_msg_queue_size() { * @param res The obtained outbound queue. */ void Collator::got_neighbor_out_queue(int i, td::Result> res) { - LOG(DEBUG) << "obtained outbound queue for neighbor #" << i; --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -828,6 +827,7 @@ void Collator::got_neighbor_out_queue(int i, td::Result> res) } Ref outq_descr = res.move_as_ok(); block::McShardDescr& descr = neighbors_.at(i); + LOG(WARNING) << "obtained outbound queue for neighbor #" << i << " : " << descr.shard().to_str(); if (outq_descr->get_block_id() != descr.blk_) { LOG(DEBUG) << "outq_descr->id = " << outq_descr->get_block_id().to_str() << " ; descr.id = " << descr.blk_.to_str(); fatal_error( @@ -893,7 +893,7 @@ void Collator::got_out_queue_size(size_t i, td::Result res) { return; } td::uint32 size = res.move_as_ok(); - LOG(DEBUG) << "got outbound queue size from prev block #" << i << ": " << size; + LOG(WARNING) << "got outbound queue size from prev block #" << i << ": " << size; out_msg_queue_size_ += size; check_pending(); } @@ -1762,7 +1762,7 @@ bool Collator::register_shard_block_creators(std::vector creator_li */ bool Collator::try_collate() { if (!preinit_complete) { - LOG(DEBUG) << "running do_preinit()"; + LOG(WARNING) << "running do_preinit()"; if (!do_preinit()) { return fatal_error(-667, "error preinitializing data required by collator"); } @@ -2062,7 +2062,7 @@ bool Collator::do_collate() { // After do_collate started it will not be interrupted by timeout alarm_timestamp() = td::Timestamp::never(); - LOG(DEBUG) << "do_collate() : start"; + LOG(WARNING) << "do_collate() : start"; if (!fetch_config_params()) { return fatal_error("cannot fetch required configuration parameters from masterchain state"); } @@ -2276,8 +2276,8 @@ bool Collator::out_msg_queue_cleanup() { } return !delivered; }); - LOG(INFO) << "deleted " << deleted << " messages from out_msg_queue after merge, remaining queue size is " - << out_msg_queue_size_; + LOG(WARNING) << "deleted " << deleted << " messages from out_msg_queue after merge, remaining queue size is " + << out_msg_queue_size_; if (res < 0) { return fatal_error("error scanning/updating OutMsgQueue"); } @@ -2352,8 +2352,8 @@ bool Collator::out_msg_queue_cleanup() { std::swap(queue_parts[i], queue_parts.back()); queue_parts.pop_back(); } - LOG(INFO) << "deleted " << deleted << " messages from out_msg_queue, remaining queue size is " - << out_msg_queue_size_; + LOG(WARNING) << "deleted " << deleted << " messages from out_msg_queue, remaining queue size is " + << out_msg_queue_size_; } if (verbosity >= 2) { auto rt = out_msg_queue_->get_root(); @@ -5035,7 +5035,7 @@ void Collator::return_block_candidate(td::Result saved) { fatal_error(std::move(err)); } else { CHECK(block_candidate); - LOG(INFO) << "sending new BlockCandidate to Promise"; + LOG(WARNING) << "sending new BlockCandidate to Promise"; main_promise(block_candidate->clone()); busy_ = false; stop(); @@ -5133,6 +5133,8 @@ void Collator::after_get_external_messages(td::Resulthash()); } } + LOG(WARNING) << "got " << vect.size() << " external messages from mempool, " << bad_ext_msgs_.size() + << " bad messages"; check_pending(); } diff --git a/validator/impl/fabric.cpp b/validator/impl/fabric.cpp index 23a03482..ede8d36d 100644 --- a/validator/impl/fabric.cpp +++ b/validator/impl/fabric.cpp @@ -202,10 +202,12 @@ void run_validate_query(ShardIdFull shard, UnixTime min_ts, BlockIdExt min_maste seqno = p.seqno(); } } - td::actor::create_actor( - PSTRING() << (is_fake ? "fakevalidate" : "validateblock") << shard.to_str() << ":" << (seqno + 1), shard, min_ts, - min_masterchain_block_id, std::move(prev), std::move(candidate), std::move(validator_set), std::move(manager), - timeout, std::move(promise), is_fake) + static std::atomic idx; + td::actor::create_actor(PSTRING() << (is_fake ? "fakevalidate" : "validateblock") << shard.to_str() + << ":" << (seqno + 1) << "#" << idx.fetch_add(1), + shard, min_ts, min_masterchain_block_id, std::move(prev), std::move(candidate), + std::move(validator_set), std::move(manager), timeout, std::move(promise), + is_fake) .release(); } diff --git a/validator/impl/validate-query.cpp b/validator/impl/validate-query.cpp index d9d03207..d5f489a3 100644 --- a/validator/impl/validate-query.cpp +++ b/validator/impl/validate-query.cpp @@ -234,6 +234,7 @@ bool ValidateQuery::fatal_error(std::string err_msg, int err_code) { */ void ValidateQuery::finish_query() { if (main_promise) { + LOG(WARNING) << "validate query done"; main_promise.set_result(now_); } stop(); @@ -252,7 +253,7 @@ void ValidateQuery::finish_query() { * Then the function also sends requests to the ValidatorManager to fetch blocks and shard stated. */ void ValidateQuery::start_up() { - LOG(INFO) << "validate query for " << block_candidate.id.to_str() << " started"; + LOG(WARNING) << "validate query for " << block_candidate.id.to_str() << " started"; alarm_timestamp() = timeout; rand_seed_.set_zero(); created_by_ = block_candidate.pubkey; @@ -667,7 +668,7 @@ bool ValidateQuery::extract_collated_data() { * @param res The result of the retrieval of the latest masterchain state. */ void ValidateQuery::after_get_latest_mc_state(td::Result, BlockIdExt>> res) { - LOG(DEBUG) << "in ValidateQuery::after_get_latest_mc_state()"; + LOG(WARNING) << "in ValidateQuery::after_get_latest_mc_state()"; --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -708,7 +709,7 @@ void ValidateQuery::after_get_latest_mc_state(td::Result> res) { - LOG(DEBUG) << "in ValidateQuery::after_get_mc_state() for " << mc_blkid_.to_str(); + LOG(WARNING) << "in ValidateQuery::after_get_mc_state() for " << mc_blkid_.to_str(); --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -752,7 +753,7 @@ void ValidateQuery::got_mc_handle(td::Result res) { * @param res The result of the shard state retrieval. */ void ValidateQuery::after_get_shard_state(int idx, td::Result> res) { - LOG(DEBUG) << "in ValidateQuery::after_get_shard_state(" << idx << ")"; + LOG(WARNING) << "in ValidateQuery::after_get_shard_state(" << idx << ")"; --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -1495,7 +1496,6 @@ bool ValidateQuery::request_neighbor_queues() { * @param res The obtained outbound queue. */ void ValidateQuery::got_neighbor_out_queue(int i, td::Result> res) { - LOG(DEBUG) << "obtained outbound queue for neighbor #" << i; --pending; if (res.is_error()) { fatal_error(res.move_as_error()); @@ -1503,6 +1503,7 @@ void ValidateQuery::got_neighbor_out_queue(int i, td::Result> } Ref outq_descr = res.move_as_ok(); block::McShardDescr& descr = neighbors_.at(i); + LOG(WARNING) << "obtained outbound queue for neighbor #" << i << " : " << descr.shard().to_str(); if (outq_descr->get_block_id() != descr.blk_) { LOG(DEBUG) << "outq_descr->id = " << outq_descr->get_block_id().to_str() << " ; descr.id = " << descr.blk_.to_str(); fatal_error( @@ -6187,6 +6188,7 @@ bool ValidateQuery::try_validate() { } try { if (!stage_) { + LOG(WARNING) << "try_validate stage 0"; if (!compute_prev_state()) { return fatal_error(-666, "cannot compute previous state"); } @@ -6216,6 +6218,7 @@ bool ValidateQuery::try_validate() { return true; } } + LOG(WARNING) << "try_validate stage 1"; LOG(INFO) << "running automated validity checks for block candidate " << id_.to_str(); if (!block::gen::t_Block.validate_ref(10000000, block_root_)) { return reject_query("block "s + id_.to_str() + " failed to pass automated validity checks"); diff --git a/validator/manager.cpp b/validator/manager.cpp index 54d272bc..4bac4a74 100644 --- a/validator/manager.cpp +++ b/validator/manager.cpp @@ -784,6 +784,8 @@ void ValidatorManagerImpl::wait_block_message_queue_short(BlockIdExt block_id, t void ValidatorManagerImpl::get_external_messages(ShardIdFull shard, td::Promise>> promise) { + td::Timer t; + size_t processed = 0, deleted = 0; std::vector> res; MessageId left{AccountIdPrefixFull{shard.workchain, shard.shard & (shard.shard - 1)}, Bits256::zero()}; auto it = ext_messages_.lower_bound(left); @@ -792,10 +794,12 @@ void ValidatorManagerImpl::get_external_messages(ShardIdFull shard, if (!shard_contains(shard, s.dst)) { break; } + ++processed; if (it->second->expired()) { ext_addr_messages_[it->second->address()].erase(it->first.hash); ext_messages_hashes_.erase(it->first.hash); it = ext_messages_.erase(it); + ++deleted; continue; } if (it->second->is_active()) { @@ -803,6 +807,9 @@ void ValidatorManagerImpl::get_external_messages(ShardIdFull shard, } it++; } + LOG(WARNING) << "get_external_messages to shard " << shard.to_str() << " : time=" << t.elapsed() + << " result_size=" << res.size() << " processed=" << processed << " expired=" << deleted + << " total_size=" << ext_messages_.size(); promise.set_value(std::move(res)); } @@ -1356,7 +1363,18 @@ td::Ref ValidatorManagerImpl::do_get_last_liteserver_state() { if (last_masterchain_state_.is_null()) { return {}; } - if (last_liteserver_state_.is_null() || last_liteserver_state_->get_unix_time() < td::Clocks::system() - 30) { + if (last_liteserver_state_.is_null()) { + last_liteserver_state_ = last_masterchain_state_; + return last_liteserver_state_; + } + if (last_liteserver_state_->get_seqno() == last_masterchain_state_->get_seqno()) { + return last_liteserver_state_; + } + // If liteserver seqno (i.e. shard client) lags then use last masterchain state for liteserver + // Allowed lag depends on the block rate + double time_per_block = double(last_masterchain_state_->get_unix_time() - last_liteserver_state_->get_unix_time()) / + double(last_masterchain_state_->get_seqno() - last_liteserver_state_->get_seqno()); + if (td::Clocks::system() - double(last_liteserver_state_->get_unix_time()) > std::min(time_per_block * 8, 180.0)) { last_liteserver_state_ = last_masterchain_state_; } return last_liteserver_state_; @@ -2356,15 +2374,15 @@ void ValidatorManagerImpl::alarm() { } if (log_status_at_.is_in_past()) { if (last_masterchain_block_handle_) { - LOG(INFO) << "STATUS: last_masterchain_block_ago=" - << td::format::as_time(td::Clocks::system() - last_masterchain_block_handle_->unix_time()) - << " last_known_key_block_ago=" - << td::format::as_time(td::Clocks::system() - (last_known_key_block_handle_->inited_unix_time() - ? last_known_key_block_handle_->unix_time() - : 0)) - << " shard_client_ago=" - << td::format::as_time(td::Clocks::system() - - (shard_client_handle_ ? shard_client_handle_->unix_time() : 0)); + LOG(ERROR) << "STATUS: last_masterchain_block_ago=" + << td::format::as_time(td::Clocks::system() - last_masterchain_block_handle_->unix_time()) + << " last_known_key_block_ago=" + << td::format::as_time(td::Clocks::system() - (last_known_key_block_handle_->inited_unix_time() + ? last_known_key_block_handle_->unix_time() + : 0)) + << " shard_client_ago=" + << td::format::as_time(td::Clocks::system() - + (shard_client_handle_ ? shard_client_handle_->unix_time() : 0)); } log_status_at_ = td::Timestamp::in(60.0); } diff --git a/validator/validator-group.cpp b/validator/validator-group.cpp index c1f4f38a..7baf0f05 100644 --- a/validator/validator-group.cpp +++ b/validator/validator-group.cpp @@ -136,7 +136,7 @@ void ValidatorGroup::accept_block_candidate(td::uint32 round_id, PublicKeyHash s std::vector approve_signatures, validatorsession::ValidatorSessionStats stats, td::Promise promise) { - if (round_id >= last_known_round_id_) { + if (round_id >= last_known_round_id_) { last_known_round_id_ = round_id + 1; } auto sig_set = create_signature_set(std::move(signatures)); @@ -150,6 +150,7 @@ void ValidatorGroup::accept_block_candidate(td::uint32 round_id, PublicKeyHash s return; } auto next_block_id = create_next_block_id(root_hash, file_hash); + LOG(WARNING) << "Accepted block " << next_block_id; td::actor::send_closure(manager_, &ValidatorManager::log_validator_session_stats, next_block_id, std::move(stats)); auto block = block_data.size() > 0 ? create_block(next_block_id, std::move(block_data)).move_as_ok() : td::Ref{};