Merge pull request EOSIO#1034 from EOSIO/MHB-hotfix-Dawn397-gh1024

Addressing the MHB issue

libraries/chain/chain_controller.cpp

@@ -901,9 +901,10 @@ void chain_controller::process_message(const transaction& trx, account_name code
                                        apply_context* parent_context, int depth,
                                        const fc::time_point& start_time ) {
    const blockchain_configuration& chain_configuration = get_global_properties().configuration;
+   auto us_duration = (fc::time_point::now() - start_time).count();
    if( is_producing() ) {
-      EOS_ASSERT((fc::time_point::now() - start_time).count() < chain_configuration.max_trx_runtime, checktime_exceeded,
-         "Transaction message exceeded maximum total transaction time of ${limit}ms", ("limit", chain_configuration.max_trx_runtime));
+      EOS_ASSERT(us_duration < chain_configuration.max_trx_runtime, checktime_exceeded,
+                  "Transaction message exceeded maximum total transaction time of ${limit}ms, took ${duration}ms", ("limit", chain_configuration.max_trx_runtime/1000)("dur",us_duration/1000));
    }
    EOS_ASSERT(depth < chain_configuration.in_depth_limit, msg_resource_exhausted,
      "Message processing exceeded maximum inline recursion depth of ${limit}", ("limit", chain_configuration.in_depth_limit));
@@ -977,7 +978,17 @@ void chain_controller::apply_message(apply_context& context)
              : _skip_flags & created_block
                ? _create_block_txn_execution_time
                : _txn_execution_time;
-       wasm_interface::get().apply(context, execution_time, is_producing() );
+       try {
+          wasm_interface::get().apply(context, execution_time, is_producing() );
+       } catch (const fc::exception &ex) {
+          // The particular exception that is causing havoc is generated in the wasm layer, and is
+          // Runtime::Exception::Cause::integerDivideByZeroOrIntegerOverflow)
+          if (!is_producing()) {
+             wlog ("apply_message ignoring exception while not producing");
+          }
+          else
+             throw;
+       }
     }
 
 } FC_CAPTURE_AND_RETHROW((context.msg)) }
@@ -999,7 +1010,7 @@ typename T::processed chain_controller::process_transaction( const T& trx, int d
 { try {
    const blockchain_configuration& chain_configuration = get_global_properties().configuration;
    EOS_ASSERT((fc::time_point::now() - start_time).count() < chain_configuration.max_trx_runtime, checktime_exceeded,
-      "Transaction exceeded maximum total transaction time of ${limit}ms", ("limit", chain_configuration.max_trx_runtime));
+      "Transaction exceeded maximum total transaction time of ${limit}ms", ("limit", chain_configuration.max_trx_runtime/1000));
 
    EOS_ASSERT(depth < chain_configuration.in_depth_limit, tx_resource_exhausted,
       "Transaction exceeded maximum inline recursion depth of ${limit}", ("limit", chain_configuration.in_depth_limit));
@@ -1030,7 +1041,7 @@ const producer_object& chain_controller::validate_block_header(uint32_t skip, co
               ("head_block_id",head_block_id())("next.prev",next_block.previous));
    EOS_ASSERT(head_block_time() < next_block.timestamp, block_validate_exception, "",
               ("head_block_time",head_block_time())("next",next_block.timestamp)("blocknum",next_block.block_num()));
-   if (next_block.timestamp > head_block_time() + block_interval()) {
+   if (is_producing() && next_block.timestamp > head_block_time() + block_interval()) {
       elog("head_block_time ${h}, next_block ${t}, block_interval ${bi}",
            ("h", head_block_time())("t", next_block.timestamp)("bi", block_interval()));
       elog("Did not produce block within block_interval ${bi}, took ${t}ms)",

libraries/chain/include/eos/chain/chain_controller.hpp

@@ -109,7 +109,8 @@ namespace eosio { namespace chain {
             skip_output_check           = 1 << 13, ///< used to skip checks for outputs in block exactly matching those created from apply
             pushed_transaction          = 1 << 14, ///< used to indicate that the origination of the call was from a push_transaction, to determine time allotment
             created_block               = 1 << 15, ///< used to indicate that the origination of the call was for creating a block, to determine time allotment
-            received_block              = 1 << 16  ///< used to indicate that the origination of the call was for a received block, to determine time allotment
+            received_block              = 1 << 16, ///< used to indicate that the origination of the call was for a received block, to determine time allotment
+            irreversible                = 1 << 17  ///< indicates the block was received while catching up and is already considered irreversible.
          };
 
          /**
@@ -269,8 +270,11 @@ namespace eosio { namespace chain {
          chainbase::database& get_mutable_database() { return _db; }
 
          bool should_check_scope()const                      { return !(_skip_flags&skip_scope_check);                     }
-         bool is_producing()const                            { return _skip_flags & (received_block | pushed_transaction); }
 
+         // returns true to indicate that the caller should interpret the current block or transaction
+         // as one that is being produced, or otherwise validated. This is never true if the block is
+         // received as part of catching up with the rest of the chain, and is known to be irreversible.
+         bool is_producing()const                            { return (_skip_flags & (received_block | pushed_transaction)) && !(_skip_flags & irreversible); }
 
          const deque<signed_transaction>&  pending()const { return _pending_transactions; }
 

libraries/chain/wasm_interface.cpp

@@ -143,7 +143,7 @@ DEFINE_INTRINSIC_FUNCTION0(env,checktime,checktime,none) {
 
       char* value = memoryArrayPtr<char>( wasm.current_memory, valueptr, valuelen );
       KeyType*  keys = reinterpret_cast<KeyType*>(value);
-      
+
       valuelen -= keylen;
       value    += keylen;
 
@@ -270,7 +270,7 @@ DEFINE_INTRINSIC_FUNCTION0(env,checktime,checktime,none) {
 
 DEFINE_RECORD_UPDATE_FUNCTIONS(i64, key_value_index, 8);
 DEFINE_RECORD_READ_FUNCTIONS(i64,,key_value_index, by_scope_primary);
-      
+
 DEFINE_RECORD_UPDATE_FUNCTIONS(i128i128, key128x128_value_index, 32);
 DEFINE_RECORD_READ_FUNCTIONS(i128i128, primary_,   key128x128_value_index, by_scope_primary);
 DEFINE_RECORD_READ_FUNCTIONS(i128i128, secondary_, key128x128_value_index, by_scope_secondary);
@@ -537,7 +537,7 @@ DEFINE_INTRINSIC_FUNCTION1(env,sbrk,sbrk,i32,i32,num_bytes) {
 /**
  * transaction C API implementation
  * @{
- */ 
+ */
 
 DEFINE_INTRINSIC_FUNCTION0(env,transaction_create,transaction_create,i32) {
    auto& ptrx = wasm_interface::get().current_apply_context->create_pending_transaction();
@@ -592,7 +592,7 @@ DEFINE_INTRINSIC_FUNCTION1(env,transaction_drop,transaction_drop,none,i32,handle
 DEFINE_INTRINSIC_FUNCTION4(env,message_create,message_create,i32,i64,code,i64,type,i32,data,i32,length) {
    auto& wasm  = wasm_interface::get();
    auto  mem   = wasm.current_memory;
-   
+
    EOS_ASSERT( length >= 0, tx_unknown_argument,
       "Pushing a message with a negative length" );
 
@@ -638,7 +638,7 @@ DEFINE_INTRINSIC_FUNCTION1(env,message_drop,message_drop,none,i32,handle) {
 
 /**
  * @} transaction C API implementation
- */ 
+ */
 
 
 
@@ -985,7 +985,7 @@ DEFINE_INTRINSIC_FUNCTION2(env,account_balance_get,account_balance_get,i32,i32,c
           const auto llvm_time = fc::time_point::now();
 
           current_memory = Runtime::getDefaultMemory(state.instance);
-            
+
           char* memstart = &memoryRef<char>( current_memory, 0 );
          // state.init_memory.resize(1<<16); /// TODO: actually get memory size
           const auto allocated_memory = Runtime::getDefaultMemorySize(state.instance);
@@ -1019,8 +1019,8 @@ DEFINE_INTRINSIC_FUNCTION2(env,account_balance_get,account_balance_get,i32,i32,c
                 state.table_key_types.emplace(std::make_pair(table.table_name, key_type));
              }
           }
-          ilog("wasm_interface::load times llvm:${llvm} ms, init:${init} ms, abi:${abi} ms",
-               ("llvm",(llvm_time-start).count()/1000)("init",(init_time-llvm_time).count()/1000)("abi",(fc::time_point::now()-init_time).count()/1000));
+          ilog("wasm_interface::load name = ${n} times llvm:${llvm} ms, init:${init} ms, abi:${abi} ms",
+               ("n",name)("llvm",(llvm_time-start).count()/1000)("init",(init_time-llvm_time).count()/1000)("abi",(fc::time_point::now()-init_time).count()/1000));
         }
         catch(Serialization::FatalSerializationException exception)
         {

plugins/chain_plugin/chain_plugin.cpp

@@ -212,7 +212,7 @@ void chain_plugin::plugin_initialize(const variables_map& options) {
    chain::wasm_interface::get().row_overhead_db_limit_bytes = options.at("row-overhead-db-limit-bytes").as<uint32_t>();
 }
 
-void chain_plugin::plugin_startup() 
+void chain_plugin::plugin_startup()
 { try {
    auto& db = app().get_plugin<database_plugin>().db();
    eosio::chain::applied_irreverisable_block_func applied_func;
@@ -223,8 +223,8 @@ void chain_plugin::plugin_startup()
       }
    }
 
-   FC_ASSERT( fc::exists( my->genesis_file ), 
-              "unable to find genesis file '${f}', check --genesis-json argument", 
+   FC_ASSERT( fc::exists( my->genesis_file ),
+              "unable to find genesis file '${f}', check --genesis-json argument",
               ("f",my->genesis_file.generic_string()) );
 
    auto genesis = fc::json::from_file(my->genesis_file).as<native_contract::genesis_state_type>();
@@ -272,7 +272,10 @@ bool chain_plugin::accept_block(const chain::signed_block& block, bool currently
            ("p", block.producer));
    }
 
-   return chain().push_block(block, my->skip_flags);
+   // note that currently_syncing is true when the p2p layer is catching up to the current last
+   // irreversible block and so it is reasonable to use it as an indication that timing and exception
+   // handling should be relaxed for this block.
+   return chain().push_block(block, my->skip_flags | (currently_syncing ? chain_controller::irreversible : 0) );
 }
 
 void chain_plugin::accept_transaction(const chain::signed_transaction& trx) {
@@ -355,7 +358,7 @@ read_only::get_table_rows_result read_only::get_table_rows( const read_only::get
       return get_table_rows_ex<chain::key_value_index, chain::by_scope_primary>(p,abi);
    } else if( table_type == KEYstr ) {
       return get_table_rows_ex<chain::keystr_value_index, chain::by_scope_primary>(p,abi);
-   } else if( table_type == KEYi128i128 ) { 
+   } else if( table_type == KEYi128i128 ) {
       if( table_key == PRIMARY )
          return get_table_rows_ex<chain::key128x128_value_index, chain::by_scope_primary>(p,abi);
       if( table_key == SECONDARY )
@@ -404,9 +407,9 @@ read_write::push_transactions_results read_write::push_transactions(const read_w
    result.reserve(params.size());
    for( const auto& item : params ) {
       try {
-        result.emplace_back( push_transaction( item ) ); 
+        result.emplace_back( push_transaction( item ) );
       } catch ( const fc::exception& e ) {
-        result.emplace_back( read_write::push_transaction_results{ chain::transaction_id_type(), 
+        result.emplace_back( read_write::push_transaction_results{ chain::transaction_id_type(),
                           fc::mutable_variant_object( "error", e.to_detail_string() ) } );
       }
    }
@@ -448,16 +451,16 @@ read_only::get_account_results read_only::get_account( const get_account_params&
    const auto& permissions = d.get_index<permission_index,by_owner>();
    auto perm = permissions.lower_bound( boost::make_tuple( params.account_name ) );
    while( perm != permissions.end() && perm->owner == params.account_name ) {
-      /// TODO: lookup perm->parent name 
+      /// TODO: lookup perm->parent name
       name parent;
 
       // Don't lookup parent if null
       if( perm->parent._id ) {
          const auto* p = d.find<permission_object,by_id>( perm->parent );
          if( p ) {
             FC_ASSERT(perm->owner == p->owner, "Invalid parent");
-            parent = p->name; 
-         } 
+            parent = p->name;
+         }
       }
 
       result.permissions.push_back( permission{ perm->name, parent, perm->auth.to_authority() } );

plugins/net_plugin/net_plugin.cpp

@@ -849,21 +849,33 @@ namespace eosio {
           conn->write_depth--;
 
           if(ec) {
-            elog("Error sending to connection: ${i}", ("i", ec.message()));
+            string pname = conn ? conn->peer_name() : "no connection name";
+            if( ec.value() != boost::asio::error::eof) {
+              elog("Error sending to peer ${p}: ${i}", ("p",pname)("i", ec.message()));
+            }
+            else {
+              ilog("connection closure detected on write to ${p}",("p",pname));
+            }
             my_impl->close(conn);
             return;
           }
           conn->write_queue.pop_front();
           conn->do_queue_write();
         }
         catch(const std::exception &ex) {
-          elog("Exception in do_queue_write ${s}", ("s",ex.what()));
+          auto conn = c.lock();
+          string pname = conn ? conn->peer_name() : "no connection name";
+          elog("Exception in do_queue_write to ${p} ${s}", ("p",pname)("s",ex.what()));
         }
         catch(const fc::exception &ex) {
-          elog("Exception in do_queue_write ${s}", ("s",ex.to_string()));
+          auto conn = c.lock();
+          string pname = conn ? conn->peer_name() : "no connection name";
+          elog("Exception in do_queue_write to ${p} ${s}", ("p",pname)("s",ex.to_string()));
         }
         catch(...) {
-          elog("Exception in do_queue_write");
+          auto conn = c.lock();
+          string pname = conn ? conn->peer_name() : "no connection name";
+          elog("Exception in do_queue_write to ${p}", ("p",pname) );
         }
       });
   }
@@ -1400,26 +1412,35 @@ namespace eosio {
                 }
                 start_read_message(conn);
               } else {
-                elog( "Error reading message from connection: ${m}",( "m", ec.message() ) );
+                auto pname = conn->peer_name();
+                if (ec.value() != boost::asio::error::eof) {
+                  elog( "Error reading message from ${p}: ${m}",("p",pname)( "m", ec.message() ) );
+                } else {
+                  ilog( "Peer ${p} closed connection",("p",pname) );
+                }
                 close( conn );
               }
             }
             catch(const std::exception &ex) {
-              elog("Exception in handling read data ${s}", ("s",ex.what()));
+              string pname = conn ? conn->peer_name() : "no connection name";
+              elog("Exception in handling read data from ${p} ${s}",("p",pname)("s",ex.what()));
               close( conn );
             }
             catch(const fc::exception &ex) {
-              elog("Exception in handling read data ${s}", ("s",ex.to_string()));
+              string pname = conn ? conn->peer_name() : "no connection name";
+              elog("Exception in handling read data ${s}", ("p",pname)("s",ex.to_string()));
               close( conn );
             }
             catch (...) {
-              elog( "Undefined exception hanlding the read data from connection: ${m}",( "m", ec.message() ) );
+              string pname = conn ? conn->peer_name() : "no connection name";
+              elog( "Undefined exception hanlding the read data from connection ${p}",( "p",pname));
               close( conn );
             }
           }
         );
       } catch (...) {
-        elog( "Undefined exception handling reading" );
+        string pname = conn ? conn->peer_name() : "no connection name";
+        elog( "Undefined exception handling reading ${p}",("p",pname) );
         close( conn );
       }
     }
@@ -1604,6 +1625,7 @@ namespace eosio {
 
   void net_plugin_impl::handle_message( connection_ptr c, const go_away_message &msg ) {
     string rsn = reason_str( msg.reason );
+    ilog( "received a go away message, reason = ${r}",("r",rsn));
     c->no_retry = msg.reason;
     if(msg.reason == go_away_reason::duplicate ) {
       c->node_id = msg.node_id;