Improved Logging, track blocks missed by witnesses

libraries/app/application.cpp

@@ -380,8 +380,13 @@ namespace detail {
       virtual bool handle_block(const graphene::net::block_message& blk_msg, bool sync_mode,
                                 std::vector<fc::uint160_t>& contained_transaction_message_ids) override
       { try {
+         auto latency = graphene::time::now() - blk_msg.block.timestamp;
          if (!sync_mode || blk_msg.block.block_num() % 10000 == 0)
-            ilog("Got block #${n} from network", ("n", blk_msg.block.block_num()));
+         {
+            const auto& witness = blk_msg.block.witness(*_chain_db);
+            const auto& witness_account = witness.witness_account(*_chain_db);
+            ilog("Got block #${n} from network with latency of ${l} ms from ${w}", ("n", blk_msg.block.block_num())("l", (latency.count()/1000))("w",witness_account.name)   );
+         }
 
          try {
             // TODO: in the case where this block is valid but on a fork that's too old for us to switch to,
@@ -498,7 +503,7 @@ namespace detail {
        */
       virtual message get_item(const item_id& id) override
       { try {
-         ilog("Request for item ${id}", ("id", id));
+        // ilog("Request for item ${id}", ("id", id));
          if( id.item_type == graphene::net::block_message_type )
          {
             auto opt_block = _chain_db->fetch_block_by_id(id.item_hash);

libraries/chain/db_update.cpp

@@ -40,6 +40,18 @@ void database::update_global_dynamic_data( const signed_block& b )
    uint32_t missed_blocks = get_slot_at_time( b.timestamp );
    assert( missed_blocks != 0 );
    missed_blocks--;
+   if( missed_blocks < 20 ) {
+      for( uint32_t i = 0; i < missed_blocks; ++i ) {
+         const auto& witness_missed = get_scheduled_witness( i+1 )(*this);
+         if(  witness_missed.id != b.witness ) {
+            const auto& witness_account = witness_missed.witness_account(*this); 
+            wlog( "Witness ${name} missed block ${n} around ${t}", ("name",witness_account.name)("n",b.block_num())("t",b.timestamp) );
+            modify( witness_missed, [&]( witness_object& w ) {
+              w.total_missed++;
+            });
+         } 
+      }
+   }
 
    // dynamic global properties updating
    modify( _dgp, [&]( dynamic_global_property_object& dgp ){

libraries/chain/fork_database.cpp

@@ -56,6 +56,7 @@ shared_ptr<fork_item>  fork_database::push_block(const signed_block& b)
    {
       wlog( "Pushing block to fork database that failed to link: ${id}, ${num}", ("id",b.id())("num",b.block_num()) );
       wlog( "Head: ${num}, ${id}", ("num",_head->data.block_num())("id",_head->data.id()) );
+      throw;
       _unlinked_index.insert( item );
    }
    return _head;

libraries/chain/include/graphene/chain/witness_object.hpp

@@ -38,6 +38,7 @@ namespace graphene { namespace chain {
          vote_id_type     vote_id;
          uint64_t         total_votes = 0;
          string           url;
+         int64_t          total_missed = 0;     
 
          witness_object() : vote_id(vote_id_type::witness) {}
    };
@@ -69,4 +70,6 @@ FC_REFLECT_DERIVED( graphene::chain::witness_object, (graphene::db::object),
                     (pay_vb)
                     (vote_id)
                     (total_votes)
-                    (url) )
+                    (url) 
+                    (total_missed)
+                  )

libraries/plugins/witness/witness.cpp

@@ -147,7 +147,7 @@ void witness_plugin::schedule_production_loop()
    // If we would wait less than 200ms, wait for the whole second.
    fc::time_point now = graphene::time::now();
    fc::time_point_sec next_second( now + fc::microseconds( 1200000 ) );
-   wdump( (now.time_since_epoch().count())(next_second) );
+   //wdump( (now.time_since_epoch().count())(next_second) );
    _block_production_task = fc::schedule([this]{block_production_loop();},
                                          next_second, "Witness Block Production");
 }
@@ -183,7 +183,7 @@ block_production_condition::block_production_condition_enum witness_plugin::bloc
          ilog("Not producing block because it isn't my turn");
          break;
       case block_production_condition::not_time_yet:
-         ilog("Not producing block because slot has not yet arrived");
+         // ilog("Not producing block because slot has not yet arrived");
          break;
       case block_production_condition::no_private_key:
          ilog("Not producing block because I don't have the private key for ${scheduled_key}", (capture) );

programs/full_web_node/BlockChain.cpp

@@ -40,7 +40,7 @@ void BlockChain::start()
          QString dataDir = QStandardPaths::writableLocation(QStandardPaths::AppDataLocation);
          QDir(dataDir).mkpath(".");
          boost::program_options::variables_map map;
-         map.insert({"rpc-endpoint",boost::program_options::variable_value(std::string("127.0.0.1:8090"), false)});
+         map.insert({"rpc-endpoint",boost::program_options::variable_value(std::string("127.0.0.1:8091"), false)});
          map.insert({"seed-node",boost::program_options::variable_value(std::vector<std::string>{("104.200.28.117:61705")}, false)});
          grapheneApp->initialize(dataDir.toStdString(), map);
          grapheneApp->initialize_plugins(map);