GH-8 Info log missing votes in block and warn log missing vote for co…

…nfigured finalizer

plugins/producer_plugin/include/eosio/producer_plugin/producer_plugin.hpp

@@ -145,6 +145,13 @@ class producer_plugin : public appbase::plugin<producer_plugin> {
 
    static void set_test_mode(bool m) { test_mode_ = m; }
 
+   struct vote_block_metrics {
+      uint32_t block_num = 0;
+      std::vector<std::string> strong_votes;
+      std::vector<std::string> weak_votes;
+      std::vector<std::string> no_votes;
+   };
+
    struct speculative_block_metrics {
       account_name block_producer{};
       uint32_t     block_num             = 0;
@@ -188,6 +195,7 @@ class producer_plugin : public appbase::plugin<producer_plugin> {
    void register_update_produced_block_metrics(std::function<void(produced_block_metrics)>&&);
    void register_update_speculative_block_metrics(std::function<void(speculative_block_metrics)>&&);
    void register_update_incoming_block_metrics(std::function<void(incoming_block_metrics)>&&);
+   void register_update_vote_block_metrics(std::function<void(vote_block_metrics&&)>&&);
 
    inline static bool test_mode_{false}; // to be moved into appbase (application_base)
 

plugins/producer_plugin/producer_plugin.cpp

@@ -494,6 +494,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
    using signature_provider_type = signature_provider_plugin::signature_provider_type;
    std::map<chain::public_key_type, signature_provider_type> _signature_providers;
    chain::bls_pub_priv_key_map_t                     _finalizer_keys; // public, private
+   std::set<bls_public_key>                          _finalizers;
    std::set<chain::account_name>                     _producers;
    boost::asio::deadline_timer                       _timer;
    block_timing_util::producer_watermarks            _producer_watermarks;
@@ -550,6 +551,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
    std::function<void(producer_plugin::produced_block_metrics)> _update_produced_block_metrics;
    std::function<void(producer_plugin::speculative_block_metrics)> _update_speculative_block_metrics;
    std::function<void(producer_plugin::incoming_block_metrics)> _update_incoming_block_metrics;
+   std::function<void(producer_plugin::vote_block_metrics&&)> _update_vote_block_metrics;
 
    // ro for read-only
    struct ro_trx_t {
@@ -626,14 +628,91 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
                                ((_produce_block_cpu_effort.count() / 1000) * config::producer_repetitions) );
    }
 
-   void on_block(const signed_block_ptr& block) {
+   void log_missing_votes(block_num_type block_num, const block_id_type& id,
+                          const finalizer_policy_ptr& active_finalizer_policy,
+                          const valid_quorum_certificate& qc ) {
+      if (vote_logger.is_enabled(fc::log_level::info)) {
+         std::vector<std::string> not_voted;
+
+         auto check_weak = [](const auto& weak_votes, size_t i) {
+            return weak_votes && (*weak_votes)[i];
+         };
+
+         if (qc._strong_votes) {
+            const auto& votes = *qc._strong_votes;
+            auto& finalizers = active_finalizer_policy->finalizers;
+            assert(votes.size() == finalizers.size());
+            for (size_t i = 0; i < votes.size(); ++i) {
+               if (!votes[i] && !check_weak(qc._weak_votes, i)) {
+                  not_voted.push_back(finalizers[i].description);
+                  if (_finalizers.contains(finalizers[i].public_key)) {
+                     fc_wlog(vote_logger, "Block ${n}:${id} has no votes from our finalizer: ${v}",
+                             ("n", block_num)("id", id.str().substr(8,16))("v", finalizers[i].description));
+                  }
+               }
+            }
+         }
+         if (!not_voted.empty()) {
+            fc_ilog(vote_logger, "Block ${n}:${id} has no votes for: ${v}",
+                    ("n", block_num)("id", id.str().substr(8,16))("v", not_voted));
+         }
+      }
+   }
+
+   void update_vote_block_metrics(block_num_type block_num,
+                                  const finalizer_policy_ptr& active_finalizer_policy,
+                                  const valid_quorum_certificate& qc ) {
+      if (_update_vote_block_metrics) {
+         producer_plugin::vote_block_metrics m;
+         m.block_num = block_num;
+         auto add_votes = [&](const auto& votes, std::vector<string>& desc, std::set<size_t>& not_voted) {
+            assert(votes.size() == active_finalizer_policy->finalizers.size());
+            for (size_t i = 0; i < votes.size(); ++i) {
+               if (votes[i]) {
+                  desc.push_back(active_finalizer_policy->finalizers[i].description);
+               } else {
+                  not_voted.insert(i);
+               }
+            }
+         };
+         std::set<size_t> not_voted;
+         if (qc._strong_votes) {
+            add_votes(*qc._strong_votes, m.strong_votes, not_voted);
+         }
+         if (qc._weak_votes) {
+            std::set<size_t> not_voted_weak;
+            add_votes(*qc._weak_votes, m.weak_votes, not_voted_weak);
+            std::set<size_t> no_votes;
+            std::ranges::set_intersection(not_voted, not_voted_weak, std::inserter(no_votes, no_votes.end()));
+            not_voted.swap(no_votes);
+         }
+         if (!not_voted.empty()) {
+            for (auto i : not_voted) {
+               m.no_votes.push_back(active_finalizer_policy->finalizers.at(i).description);
+            }
+         }
+         _update_vote_block_metrics(std::move(m));
+      }
+   }
+
+   void on_block(const signed_block_ptr& block, const block_id_type& id) {
       auto& chain  = chain_plug->chain();
       auto  before = _unapplied_transactions.size();
       _unapplied_transactions.clear_applied(block);
       chain.get_mutable_subjective_billing().on_block(_log, block, fc::time_point::now());
       if (before > 0) {
          fc_dlog(_log, "Removed applied transactions before: ${before}, after: ${after}", ("before", before)("after", _unapplied_transactions.size()));
       }
+      if (vote_logger.is_enabled(fc::log_level::info) || _update_vote_block_metrics) {
+         if (block->contains_extension(quorum_certificate_extension::extension_id())) {
+            if (const auto& active_finalizers = chain.head_active_finalizer_policy()) {
+               const auto& qc_ext = block->extract_extension<quorum_certificate_extension>();
+               const auto& qc = qc_ext.qc.qc;
+               log_missing_votes(block->block_num(), id, active_finalizers, qc);
+               update_vote_block_metrics(block->block_num(), active_finalizers, qc);
+            }
+         }
+      }
    }
 
    void on_block_header(const signed_block_ptr& block) {
@@ -1128,6 +1207,7 @@ void producer_plugin_impl::plugin_initialize(const boost::program_options::varia
             if (bls) {
                const auto& [pubkey, privkey] = *bls;
                _finalizer_keys[pubkey.to_string()] = privkey.to_string();
+               _finalizers.insert(pubkey);
             }
          } catch(secure_enclave_exception& e) {
             elog("Error with Secure Enclave signature provider: ${e}; ignoring ${val}", ("e", e.top_message())("val", key_spec_pair));
@@ -1340,8 +1420,8 @@ void producer_plugin_impl::plugin_startup() {
          chain.set_node_finalizer_keys(_finalizer_keys);
 
          _accepted_block_connection.emplace(chain.accepted_block().connect([this](const block_signal_params& t) {
-            const auto& [ block, _ ] = t;
-            on_block(block);
+            const auto& [ block, id ] = t;
+            on_block(block, id);
           }));
          _accepted_block_header_connection.emplace(chain.accepted_block_header().connect([this](const block_signal_params& t) {
             const auto& [ block, _ ] = t;
@@ -2906,4 +2986,8 @@ void producer_plugin::register_update_incoming_block_metrics(std::function<void(
    my->_update_incoming_block_metrics = std::move(fun);
 }
 
+void producer_plugin::register_update_vote_block_metrics(std::function<void(producer_plugin::vote_block_metrics&&)>&& fun) {
+   my->_update_vote_block_metrics = std::move(fun);
+}
+
 } // namespace eosio

plugins/prometheus_plugin/metrics.hpp

@@ -65,6 +65,12 @@ struct catalog_type {
    p2p_connection_metrics p2p_metrics;
 
    // producer plugin
+   struct vote_metrics {
+      Gauge& block_num;
+      prometheus::Family<Gauge>& voted;
+   };
+   vote_metrics block_votes;
+
    prometheus::Family<Counter>& cpu_usage_us;
    prometheus::Family<Counter>& net_usage_us;
 
@@ -140,6 +146,10 @@ struct catalog_type {
             , .connection_start_time{family<Gauge>("nodeos_p2p_connection_start_time", "time of last connection to peer")}
             , .peer_addr{family<Gauge>("nodeos_p2p_peer_addr", "peer address")}
          }
+       , block_votes{
+            .block_num{build<Gauge>("nodeos_block_num", "current block number")}
+          , .voted{family<Gauge>("nodeos_block_votes", "votes incorporated into a block, -1 weak, 1 strong")}
+       }
        , cpu_usage_us(family<Counter>("nodeos_cpu_usage_us_total", "total cpu usage in microseconds for blocks"))
        , net_usage_us(family<Counter>("nodeos_net_usage_us_total", "total net usage in microseconds for blocks"))
        , last_irreversible(build<Gauge>("nodeos_last_irreversible", "last irreversible block number"))
@@ -234,6 +244,25 @@ struct catalog_type {
       }
    }
 
+   void update(const producer_plugin::vote_block_metrics&& metrics) {
+      block_votes.block_num.Set(metrics.block_num);
+
+      auto add_and_set_gauge = [&](auto& fam, const auto& prod, const auto& value) {
+         auto& gauge = fam.Add({{"producer", prod}});
+         gauge.Set(value);
+      };
+
+      for (const auto& v : metrics.strong_votes) {
+         add_and_set_gauge(block_votes.voted, v, 1);
+      }
+      for (const auto& v : metrics.weak_votes) {
+         add_and_set_gauge(block_votes.voted, v, -1);
+      }
+      for (const auto& v : metrics.no_votes) {
+         add_and_set_gauge(block_votes.voted, v, 0);
+      }
+   }
+
    void update(block_metrics& blk_metrics, const producer_plugin::speculative_block_metrics& metrics) {
       blk_metrics.num_blocks_created.Increment(1);
       blk_metrics.current_block_num.Set(metrics.block_num);
@@ -323,6 +352,10 @@ struct catalog_type {
           [&strand, this](const producer_plugin::incoming_block_metrics& metrics) {
              strand.post([metrics, this]() { update(metrics); });
           });
+      producer.register_update_vote_block_metrics(
+          [&strand, this](const producer_plugin::vote_block_metrics&& metrics) {
+             strand.post([metrics{std::move(metrics)}, this]() mutable { update(std::move(metrics)); });
+          });
    }
 };