add forking test to chain_tester

libraries/chain/controller.cpp

@@ -437,7 +437,8 @@ struct controller_impl {
    void start_block( block_timestamp_type when ) {
      FC_ASSERT( !pending );
 
-     FC_ASSERT( db.revision() == head->block_num );
+     FC_ASSERT( db.revision() == head->block_num, "",
+                ("db_head_block", db.revision())("controller_head_block", head->block_num)("fork_db_head_block", fork_db.head()->block_num) );
 
      pending = db.start_undo_session(true);
      pending->_pending_block_state = std::make_shared<block_state>( *head, when );
@@ -506,6 +507,8 @@ struct controller_impl {
             throw;
          }
       } else if( new_head->id != head->id ) {
+         wlog("switching forks from ${current_head_id} (block number ${current_head_num}) to ${new_head_id} (block number ${new_head_num})",
+              ("current_head_id", head->id)("current_head_num", head->block_num)("new_head_id", new_head->id)("new_head_num", new_head->block_num) );
          auto branches = fork_db.fetch_branch_from( new_head->id, head->id );
 
          for( auto itr = branches.second.begin(); itr != branches.second.end(); ++itr ) {
@@ -546,6 +549,7 @@ struct controller_impl {
                throw *except;
             } // end if exception
          } /// end for each block in branch
+         wlog("successfully switched fork to new head ${head_id}", ("new_head_id", new_head->id));
       }
    } /// push_block
 
@@ -584,13 +588,15 @@ struct controller_impl {
 
    void finalize_block()
    { try {
-      ilog( "finalize block ${p} ${t} schedule_version: ${v} lib: ${lib} ${np}  ${signed}",
-            ("p",pending->_pending_block_state->header.producer)
+      ilog( "finalize block ${n} (${id}) at ${t} by ${p} (${signing_key}); schedule_version: ${v} lib: ${lib} ${np}",
+            ("n",pending->_pending_block_state->block_num)
+            ("id",pending->_pending_block_state->header.id())
             ("t",pending->_pending_block_state->header.timestamp)
+            ("p",pending->_pending_block_state->header.producer)
+            ("signing_key", pending->_pending_block_state->block_signing_key)
             ("v",pending->_pending_block_state->header.schedule_version)
             ("lib",pending->_pending_block_state->dpos_last_irreversible_blocknum)
             ("np",pending->_pending_block_state->header.new_producers)
-            ("signed", pending->_pending_block_state->block_signing_key)
             );
 
       set_action_merkle();

libraries/chain/fork_database.cpp

@@ -123,7 +123,7 @@ namespace eosio { namespace chain {
       FC_ASSERT( existing == by_id_idx.end(), "we already know about this block" );
 
       auto prior = by_id_idx.find( b->previous );
-      FC_ASSERT( prior != by_id_idx.end(), "unlinkable block" );
+      FC_ASSERT( prior != by_id_idx.end(), "unlinkable block", ("id", b->id())("previous", b->previous) );
 
       auto result = std::make_shared<block_state>( **prior, move(b) );
       return add(result);

libraries/testing/test.cpp

@@ -44,16 +44,71 @@ int main( int argc, char** argv ) {
 
 
       tester c2;
-      wlog( "push to c2" );
+      wlog( "push c1 blocks to c2" );
       while( c2.control->head_block_num() < c.control->head_block_num() ) {
          auto fb = c.control->fetch_block_by_number( c2.control->head_block_num()+1 );
          c2.control->push_block( fb );
       }
+      wlog( "end push c1 blocks to c2" );
 
+      wlog( "c1 blocks:" );
+      c.produce_blocks(3);
+      signed_block_ptr b;
+      b = c.produce_block();
+      account_name expected_producer = N(dan);
+      FC_ASSERT( b->producer == expected_producer,
+                 "expected block ${n} to be produced by ${expected_producer} but was instead produced by ${actual_producer}",
+                ("n", b->block_num())("expected_producer", expected_producer.to_string())("actual_producer", b->producer.to_string()) );
 
+      b = c.produce_block();
+      expected_producer = N(sam);
+      FC_ASSERT( b->producer == expected_producer,
+                 "expected block ${n} to be produced by ${expected_producer} but was instead produced by ${actual_producer}",
+                ("n", b->block_num())("expected_producer", expected_producer.to_string())("actual_producer", b->producer.to_string()) );
+      c.produce_blocks(11);
+      // The next block should be produced by pam.
+
+      // Sync second chain with first chain.
+      wlog( "push c1 blocks to c2" );
+      while( c2.control->head_block_num() < c.control->head_block_num() ) {
+         auto fb = c.control->fetch_block_by_number( c2.control->head_block_num()+1 );
+         c2.control->push_block( fb );
+      }
+      wlog( "end push c1 blocks to c2" );
+
+      // Now sam and pam go on their own fork while dan is producing blocks by himself.
+
+      wlog( "sam and pam go off on their own fork on c2 while dan produces blocks by himself in c1" );
+      auto fork_block_num = c.control->head_block_num();
+
+      wlog( "c2 blocks:" );
+      c2.produce_blocks(12); // pam produces 12 blocks
+      b = c2.produce_block( fc::milliseconds(config::block_interval_ms * 13) ); // sam skips over dan's blocks
+      expected_producer = N(sam);
+      FC_ASSERT( b->producer == expected_producer,
+                 "expected block ${n} to be produced by ${expected_producer} but was instead produced by ${actual_producer}",
+                ("n", b->block_num())("expected_producer", expected_producer.to_string())("actual_producer", b->producer.to_string()) );
+      c2.produce_blocks(11 + 12);
+
+
+      wlog( "c1 blocks:" );
+      b = c.produce_block( fc::milliseconds(config::block_interval_ms * 13) ); // dan skips over pam's blocks
+      expected_producer = N(dan);
+      FC_ASSERT( b->producer == expected_producer,
+                 "expected block ${n} to be produced by ${expected_producer} but was instead produced by ${actual_producer}",
+                ("n", b->block_num())("expected_producer", expected_producer.to_string())("actual_producer", b->producer.to_string()) );
+      c.produce_blocks(11);
+
+      // dan on chain 1 now gets all of the blocks from chain 2 which should cause fork switch
+      wlog( "push c2 blocks to c1" );
+      for( uint32_t start = fork_block_num + 1, end = c2.control->head_block_num(); start <= end; ++start ) {
+         auto fb = c2.control->fetch_block_by_number( start );
+         c.control->push_block( fb );
+      }
+      wlog( "end push c2 blocks to c1" );
 
 
-   } FC_CAPTURE_AND_RETHROW() 
+   } FC_CAPTURE_AND_RETHROW()
    } catch ( const fc::exception& e ) {
       edump((e.to_detail_string()));
    }

libraries/testing/tester.cpp

@@ -103,8 +103,13 @@ namespace eosio { namespace testing {
       auto head_time = control->head_block_time();
       auto next_time = head_time + skip_time;
 
-      if( !control->pending_block_state() )
+      if( !control->pending_block_state() ) {
+         control->start_block( next_time );
+      } else if( control->pending_block_state()->header.timestamp != next_time ) {
+         control->abort_block();
          control->start_block( next_time );
+         // TODO: Schedule all transactions in unapplied_transactions and deferred ones?
+      }
 
       control->finalize_block();
       control->sign_block( [&]( digest_type d ) {