Merge pull request #63 from AntelopeIO/GH-8-finalizer-log

IF: Missing vote logging and Prometheus logging of votes

libraries/chain/block.cpp

@@ -1,6 +1,6 @@
 #include <eosio/chain/block.hpp>
 
-namespace eosio { namespace chain {
+namespace eosio::chain {
    void additional_block_signatures_extension::reflector_init() {
       static_assert( fc::raw::has_feature_reflector_init_on_unpacked_reflected_types,
                      "additional_block_signatures_extension expects FC to support reflector_init" );
@@ -63,7 +63,42 @@ namespace eosio { namespace chain {
       }
 
       return results;
+   }
+
+   // Does not validate ordering, assumes validate_and_extract_extensions() has been called in verify_qc_claim()
+   std::optional<block_extension> signed_block::extract_extension(uint16_t extension_id)const {
+      using decompose_t = block_extension_types::decompose_t;
+
+      assert(std::ranges::is_sorted(block_extensions)); // currently all extensions are unique so default compare works
+
+      for( size_t i = 0; i < block_extensions.size(); ++i ) {
+         const auto& e = block_extensions[i];
+         auto id = e.first;
+
+         if (id > extension_id)
+            break;
+         if (id != extension_id)
+            continue;
+
+         std::optional<block_extension> ext;
+         ext.emplace();
+
+         auto match = decompose_t::extract<block_extension>( id, e.second, *ext );
+         EOS_ASSERT( match, invalid_block_extension,
+                     "Block extension with id type ${id} is not supported",
+                     ("id", id)
+         );
+
+         return ext;
+      }
+
+      return {};
+   }
 
+   bool signed_block::contains_extension(uint16_t extension_id)const {
+      return std::any_of(block_extensions.cbegin(), block_extensions.cend(), [&](const auto& p) {
+         return p.first == extension_id;
+      });
    }
 
-} } /// namespace eosio::chain
+} /// namespace eosio::chain

libraries/chain/block_header.cpp

@@ -65,13 +65,18 @@ namespace eosio { namespace chain {
       return results;
    }
 
+   // Does not validate ordering, assumes validate_and_extract_header_extensions() has been called in block_state creation
    std::optional<block_header_extension> block_header::extract_header_extension(uint16_t extension_id)const {
       using decompose_t = block_header_extension_types::decompose_t;
 
+      assert(std::ranges::is_sorted(header_extensions)); // currently all extensions are unique so default compare works
+
       for( size_t i = 0; i < header_extensions.size(); ++i ) {
          const auto& e = header_extensions[i];
          auto id = e.first;
 
+         if (id > extension_id)
+            break;
          if (id != extension_id)
             continue;
 

libraries/chain/controller.cpp

@@ -4054,7 +4054,7 @@ struct controller_impl {
             if( switch_fork ) {
                auto head_fork_comp_str = apply<std::string>(chain_head, [](auto& head) -> std::string { return log_fork_comparison(*head); });
                ilog("switching forks from ${chid} (block number ${chn}) ${c} to ${nhid} (block number ${nhn}) ${n}",
-                    ("chid", chain_head.id())("chn}", chain_head.block_num())("nhid", new_head->id())("nhn", new_head->block_num())
+                    ("chid", chain_head.id())("chn", chain_head.block_num())("nhid", new_head->id())("nhn", new_head->block_num())
                     ("c", head_fork_comp_str)("n", log_fork_comparison(*new_head)));
 
                // not possible to log transaction specific info when switching forks
@@ -5313,6 +5313,12 @@ const producer_authority_schedule* controller::next_producers()const {
    return my->pending->next_producers();
 }
 
+finalizer_policy_ptr controller::head_active_finalizer_policy()const {
+   return apply_s<finalizer_policy_ptr>(my->chain_head, [](const auto& head) {
+      return head->active_finalizer_policy;
+   });
+}
+
 bool controller::light_validation_allowed() const {
    return my->light_validation_allowed();
 }

libraries/chain/include/eosio/chain/block.hpp

@@ -79,7 +79,8 @@ namespace eosio { namespace chain {
    }
 
    using block_extension_types = detail::block_extension_types<
-         additional_block_signatures_extension, quorum_certificate_extension
+         additional_block_signatures_extension,
+         quorum_certificate_extension
    >;
 
    using block_extension = block_extension_types::block_extension_t;
@@ -101,6 +102,12 @@ namespace eosio { namespace chain {
       extensions_type               block_extensions;
 
       flat_multimap<uint16_t, block_extension> validate_and_extract_extensions()const;
+      std::optional<block_extension> extract_extension(uint16_t extension_id)const;
+      template<typename Ext> Ext extract_extension()const {
+         assert(contains_extension(Ext::extension_id()));
+         return std::get<Ext>(*extract_extension(Ext::extension_id()));
+      }
+      bool contains_extension(uint16_t extension_id)const;
    };
    using signed_block_ptr = std::shared_ptr<signed_block>;
 

libraries/chain/include/eosio/chain/controller.hpp

@@ -265,6 +265,9 @@ namespace eosio::chain {
          // post-instant-finality this always returns nullptr
          const producer_authority_schedule*         pending_producers_legacy()const;
 
+         // returns nullptr pre-savanna
+         finalizer_policy_ptr                       head_active_finalizer_policy()const;
+
          void set_if_irreversible_block_id(const block_id_type& id);
          uint32_t if_irreversible_block_num() const;
 

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,93 @@ 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(const signed_block_ptr& block, 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)) {
+         if (fc::time_point::now() - block->timestamp < fc::minutes(5) || (block->block_num() % 1000 == 0)) {
+            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, "Local finalizer ${f} did not vote on block ${n}:${id}",
+                                ("f", finalizers[i].description)("n", block->block_num())("id", id.str().substr(8,16)));
+                     }
+                  }
+               }
+            }
+            if (!not_voted.empty()) {
+               fc_ilog(vote_logger, "Block ${n}:${id} has no votes from finalizers: ${v}",
+                       ("n", block->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) {
+            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);
+               }
+            }
+         };
+         if (qc._strong_votes) {
+            add_votes(*qc._strong_votes, m.strong_votes);
+         }
+         if (qc._weak_votes) {
+            add_votes(*qc._weak_votes, m.weak_votes);
+         }
+         if (m.strong_votes.size() + m.weak_votes.size() != active_finalizer_policy->finalizers.size()) {
+            fc::dynamic_bitset not_voted(active_finalizer_policy->finalizers.size());
+            if (qc._strong_votes) {
+               not_voted = *qc._strong_votes;
+            }
+            if (qc._weak_votes) {
+               assert(not_voted.size() == qc._weak_votes->size());
+               not_voted |= *qc._weak_votes;
+            }
+            not_voted.flip();
+            add_votes(not_voted, m.no_votes);
+         }
+         _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, 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 +1209,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 +1422,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 +2988,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, 0 no vote")}
+       }
        , 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)); });
+          });
    }
 };