Adjust allowed time lag for last_liteserver_state + more verbose logs (…

…ton-blockchain#836) * Add logs to collator and validator * More logs to get_ext_messages, decrease verbosity level * Adjust allowed time lag for last_liteserver_state * Change verbosity of STATUS message --------- Co-authored-by: SpyCheese <mikle98@yandex.ru>
dungeon-master-666 · Mar 4, 2024 · 3217710 · 3217710
1 parent 4e83ac3
commit 3217710
Show file tree

Hide file tree

Showing 5 changed files with 58 additions and 32 deletions.
diff --git 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<std::pair<Ref<MasterchainState>, 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<std::pair<Ref<MasterchainState>, Bl
  * @param res The retrieved shard state.
  */
 void Collator::after_get_shard_state(int idx, td::Result<Ref<ShardState>> 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,14 +820,14 @@ bool Collator::request_out_msg_queue_size() {
  * @param res The obtained outbound queue.
  */
 void Collator::got_neighbor_out_queue(int i, td::Result<Ref<MessageQueue>> res) {
-  LOG(DEBUG) << "obtained outbound queue for neighbor #" << i;
   --pending;
   if (res.is_error()) {
     fatal_error(res.move_as_error());
     return;
   }
   Ref<MessageQueue> 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<td::uint32> 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<td::Bits256> 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<td::Unit> 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::Result<std::vector<Ref<ExtMessage
       bad_ext_msgs_.emplace_back(ext_msg->hash());
     }
   }
+  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
@@ -202,10 +202,12 @@ void run_validate_query(ShardIdFull shard, UnixTime min_ts, BlockIdExt min_maste
       seqno = p.seqno();
     }
   }
-  td::actor::create_actor<ValidateQuery>(
-      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<size_t> idx;
+  td::actor::create_actor<ValidateQuery>(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
@@ -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<std::pair<Ref<MasterchainState>, 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<std::pair<Ref<Mastercha
  * @param res The result of the masterchain state retrieval.
  */
 void ValidateQuery::after_get_mc_state(td::Result<Ref<ShardState>> 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<BlockHandle> res) {
  * @param res The result of the shard state retrieval.
  */
 void ValidateQuery::after_get_shard_state(int idx, td::Result<Ref<ShardState>> 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,14 +1496,14 @@ bool ValidateQuery::request_neighbor_queues() {
  * @param res The obtained outbound queue.
  */
 void ValidateQuery::got_neighbor_out_queue(int i, td::Result<Ref<MessageQueue>> res) {
-  LOG(DEBUG) << "obtained outbound queue for neighbor #" << i;
   --pending;
   if (res.is_error()) {
     fatal_error(res.move_as_error());
     return;
   }
   Ref<MessageQueue> 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
@@ -784,6 +784,8 @@ void ValidatorManagerImpl::wait_block_message_queue_short(BlockIdExt block_id, t
 
 void ValidatorManagerImpl::get_external_messages(ShardIdFull shard,
                                                  td::Promise<std::vector<td::Ref<ExtMessage>>> promise) {
+  td::Timer t;
+  size_t processed = 0, deleted = 0;
   std::vector<td::Ref<ExtMessage>> res;
   MessageId<ExtMessage> left{AccountIdPrefixFull{shard.workchain, shard.shard & (shard.shard - 1)}, Bits256::zero()};
   auto it = ext_messages_.lower_bound(left);
@@ -792,17 +794,22 @@ 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()) {
       res.push_back(it->second->message());
     }
     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<MasterchainState> 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
@@ -136,7 +136,7 @@ void ValidatorGroup::accept_block_candidate(td::uint32 round_id, PublicKeyHash s
                                             std::vector<BlockSignature> approve_signatures,
                                             validatorsession::ValidatorSessionStats stats,
                                             td::Promise<td::Unit> 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<BlockData>{};