Table of Contents proposal

[4.0 -> main] Add time summary logging for transient trx processing and read-only threads

README.md

@@ -1,4 +1,11 @@
 # Leap
+
+1. [Branches](#branches)
+2. [Supported Operating Systems](#supported-operating-systems)
+3. [Binary Installation](#binary-installation)
+4. [Build and Install from Source](#build-and-install-from-source)
+5. [Bash Autocomplete](#bash-autocomplete)
+
 Leap is a C++ implementation of the [Antelope](https://github.com/AntelopeIO) protocol. It contains blockchain node software and supporting tools for developers and node operators.
 
 ## Branches
@@ -258,3 +265,10 @@ It is also possible to install using `make` instead:
 ```bash
 sudo make install
 ```
+
+## Bash Autocomplete
+`cleos` and `leap-util` offer a substantial amount of functionality. Consider using bash's autocompletion support which makes it easier to discover all their various options.
+
+For our provided `.deb` packages simply install Ubuntu's `bash-completion` package: `apt-get install bash-completion` (you may need to log out/in after installing).
+
+If building from source install the `build/programs/cleos/bash-completion/completions/cleos` and `build/programs/leap-util/bash-completion/completions/leap-util` files to your bash-completion directory. Refer to [bash-complete's documentation](https://github.com/scop/bash-completion#faq) on the possible install locations.

libraries/chain/controller.cpp

@@ -2680,7 +2680,7 @@ struct controller_impl {
    // only called from non-main threads (read-only trx execution threads)
    // when producer_plugin starts them
    void init_thread_local_data() {
-      EOS_ASSERT( !is_main_thread(), misc_exception, "init_thread_local_data called on the main thread");
+      EOS_ASSERT( !is_on_main_thread(), misc_exception, "init_thread_local_data called on the main thread");
 #ifdef EOSIO_EOS_VM_OC_RUNTIME_ENABLED
       if ( is_eos_vm_oc_enabled() )
          // EOSVMOC needs further initialization of its thread local data
@@ -2691,10 +2691,10 @@ struct controller_impl {
          wasmif_thread_local = std::make_unique<wasm_interface>( conf.wasm_runtime, conf.eosvmoc_tierup, db, conf.state_dir, conf.eosvmoc_config, !conf.profile_accounts.empty());
    }
 
-   bool is_main_thread() { return main_thread_id == std::this_thread::get_id(); };
+   bool is_on_main_thread() { return main_thread_id == std::this_thread::get_id(); };
 
    wasm_interface& get_wasm_interface() {
-      if ( is_main_thread()
+      if ( is_on_main_thread()
 #ifdef EOSIO_EOS_VM_OC_RUNTIME_ENABLED
           || is_eos_vm_oc_enabled()
 #endif
@@ -3686,6 +3686,10 @@ void controller::init_thread_local_data() {
    my->init_thread_local_data();
 }
 
+bool controller::is_on_main_thread() const {
+  return my->is_on_main_thread();
+}
+
 /// Protocol feature activation handlers:
 
 template<>

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

@@ -373,6 +373,7 @@ namespace eosio { namespace chain {
       void set_db_read_only_mode();
       void unset_db_read_only_mode();
       void init_thread_local_data();
+      bool is_on_main_thread() const;
 
       private:
          friend class apply_context;

libraries/wasm-jit/Include/IR/Operators.h

@@ -679,16 +679,16 @@ namespace IR
 }
 
 //paranoia for future platforms
-static_assert(sizeof(IR::OpcodeAndImm<IR::NoImm>) == 2);
-static_assert(sizeof(IR::OpcodeAndImm<IR::MemoryImm>) == 2);
-static_assert(sizeof(IR::OpcodeAndImm<IR::ControlStructureImm>) == 3);
-static_assert(sizeof(IR::OpcodeAndImm<IR::BranchImm>) == 6);
-static_assert(sizeof(IR::OpcodeAndImm<IR::BranchTableImm>) == 18);
-static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<I32>>) == 6);
-static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<I64>>) == 10);
-static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<F32>>) == 6);
-static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<F64>>) == 10);
-static_assert(sizeof(IR::OpcodeAndImm<IR::GetOrSetVariableImm<false>>) == 6);
-static_assert(sizeof(IR::OpcodeAndImm<IR::CallImm>) == 6);
-static_assert(sizeof(IR::OpcodeAndImm<IR::CallIndirectImm>) == 6);
-static_assert(sizeof(IR::OpcodeAndImm<IR::LoadOrStoreImm<0>>) == 10);
+static_assert(sizeof(IR::OpcodeAndImm<IR::NoImm>) == 2, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::MemoryImm>) == 2, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::ControlStructureImm>) == 3, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::BranchImm>) == 6, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::BranchTableImm>) == 18, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<I32>>) == 6, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<I64>>) == 10, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<F32>>) == 6, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::LiteralImm<F64>>) == 10, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::GetOrSetVariableImm<false>>) == 6, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::CallImm>) == 6, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::CallIndirectImm>) == 6, "unexpected size");
+static_assert(sizeof(IR::OpcodeAndImm<IR::LoadOrStoreImm<0>>) == 10, "unexpected size");

plugins/producer_plugin/producer_plugin.cpp

@@ -256,39 +256,53 @@ struct block_time_tracker {
       block_idle_time += idle;
    }
 
-   void add_fail_time( const fc::microseconds& fail_time ) {
-      trx_fail_time += fail_time;
-      ++trx_fail_num;
+   void add_fail_time( const fc::microseconds& fail_time, bool is_transient ) {
+      if( is_transient ) {
+         // transient time includes both success and fail time
+         transient_trx_time += fail_time;
+         ++transient_trx_num;
+      } else {
+         trx_fail_time += fail_time;
+         ++trx_fail_num;
+      }
    }
 
-   void add_success_time( const fc::microseconds& time ) {
-      trx_success_time += time;
-      ++trx_success_num;
+   void add_success_time( const fc::microseconds& time, bool is_transient ) {
+      if( is_transient ) {
+         transient_trx_time += time;
+         ++transient_trx_num;
+      } else {
+         trx_success_time += time;
+         ++trx_success_num;
+      }
    }
 
    void report( const fc::time_point& idle_trx_time, uint32_t block_num ) {
       if( _log.is_enabled( fc::log_level::debug ) ) {
          auto now = fc::time_point::now();
          add_idle_time( now - idle_trx_time );
-         fc_dlog( _log, "Block #${n} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, other: ${o}us",
+         fc_dlog( _log, "Block #${n} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, transient: ${tn}, ${t}us, other: ${o}us",
                   ("n", block_num)
                   ("i", block_idle_time)("t", now - clear_time)("sn", trx_success_num)("s", trx_success_time)
                   ("fn", trx_fail_num)("f", trx_fail_time)
-                  ("o", (now - clear_time) - block_idle_time - trx_success_time - trx_fail_time) );
+                  ("tn", transient_trx_num)("t", transient_trx_time)
+                  ("o", (now - clear_time) - block_idle_time - trx_success_time - trx_fail_time - transient_trx_time) );
       }
    }
 
    void clear() {
-      block_idle_time = trx_fail_time = trx_success_time = fc::microseconds{};
-      trx_fail_num = trx_success_num = 0;
+      block_idle_time = trx_fail_time = trx_success_time = transient_trx_time = fc::microseconds{};
+      trx_fail_num = trx_success_num = transient_trx_num = 0;
       clear_time = fc::time_point::now();
    }
 
    fc::microseconds block_idle_time;
    uint32_t trx_success_num = 0;
    uint32_t trx_fail_num = 0;
+   uint32_t transient_trx_num = 0;
    fc::microseconds trx_success_time;
    fc::microseconds trx_fail_time;
+   fc::microseconds transient_trx_time;
    fc::time_point clear_time{fc::time_point::now()};
 };
 
@@ -429,11 +443,13 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
       fc::microseconds                _ro_read_window_time_us{ 60000 };
       static constexpr fc::microseconds _ro_read_window_minimum_time_us{ 10000 };
       fc::microseconds                _ro_read_window_effective_time_us{ 0 }; // calculated during option initialization
+      std::atomic<int64_t>            _ro_all_threads_exec_time_us; // total time spent by all threads executing transactions. use atomic for simplicity and performance
+      fc::time_point                  _ro_read_window_start_time;
       boost::asio::deadline_timer     _ro_write_window_timer;
       boost::asio::deadline_timer     _ro_read_window_timer;
       fc::microseconds                _ro_max_trx_time_us{ 0 }; // calculated during option initialization
       ro_trx_queue_t                  _ro_trx_queue;
-      std::atomic<uint32_t>            _ro_num_active_trx_exec_tasks{ 0 };
+      std::atomic<uint32_t>           _ro_num_active_trx_exec_tasks{ 0 };
       std::vector<std::future<bool>>  _ro_trx_exec_tasks_fut;
 
       void start_write_window();
@@ -688,7 +704,8 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
                      self->log_trx_results( trx, nullptr, ex, 0, start, is_transient );
                      next( std::move(ex) );
                      self->_idle_trx_time = fc::time_point::now();
-                     self->_time_tracker.add_fail_time(self->_idle_trx_time - start);
+                     auto dur = self->_idle_trx_time - start;
+                     self->_time_tracker.add_fail_time(dur, is_transient);
                   };
                   try {
                      auto result = future.get();
@@ -2214,7 +2231,7 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline,
          log_trx_results( trx, except_ptr );
          next( except_ptr );
       }
-      _time_tracker.add_fail_time(fc::time_point::now() - start);
+      _time_tracker.add_fail_time(fc::time_point::now() - start, trx->is_transient());
       return push_result{.failed = true};
    }
 
@@ -2261,8 +2278,10 @@ producer_plugin_impl::handle_push_result( const transaction_metadata_ptr& trx,
    auto end = fc::time_point::now();
    push_result pr;
    if( trace->except ) {
-      if ( !trx->is_read_only() )
-         _time_tracker.add_fail_time(end - start);
+      if ( chain.is_on_main_thread() ) {
+         auto dur = end - start;
+         _time_tracker.add_fail_time(dur, trx->is_transient());
+      }
       if( exception_is_exhausted( *trace->except ) ) {
          if( _pending_block_mode == pending_block_mode::producing ) {
             fc_dlog(_trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} COULD NOT FIT, tx: ${txid} RETRYING ",
@@ -2302,8 +2321,10 @@ producer_plugin_impl::handle_push_result( const transaction_metadata_ptr& trx,
    } else {
       fc_tlog( _log, "Subjective bill for success ${a}: ${b} elapsed ${t}us, time ${r}us",
                ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", end - start));
-      if ( !trx->is_read_only() )
-         _time_tracker.add_success_time(end - start);
+      if ( chain.is_on_main_thread() ) {
+         auto dur = end - start;
+         _time_tracker.add_success_time(dur, trx->is_transient());
+      }
       log_trx_results( trx, trace, start );
       // if producing then trx is in objective cpu account billing
       if (!disable_subjective_enforcement && _pending_block_mode != pending_block_mode::producing) {
@@ -2446,7 +2467,7 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
          auto trace = chain.push_scheduled_transaction(trx_id, deadline, max_trx_time, 0, false);
          auto end = fc::time_point::now();
          if (trace->except) {
-            _time_tracker.add_fail_time(end - start);
+            _time_tracker.add_fail_time(end - start, false); // delayed transaction cannot be transient
             if (exception_is_exhausted(*trace->except)) {
                if( block_is_exhausted() ) {
                   exhausted = true;
@@ -2466,7 +2487,7 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
                num_failed++;
             }
          } else {
-            _time_tracker.add_success_time(end - start);
+            _time_tracker.add_success_time(end - start, false); // delayed transaction cannot be transient
             fc_dlog(_trx_successful_trace_log,
                     "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${txid}, time: ${r}, auth: ${a}, cpu: ${cpu}",
                     ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
@@ -2766,6 +2787,14 @@ void producer_plugin::log_failed_transaction(const transaction_id_type& trx_id,
 
 // Called from app thread
 void producer_plugin_impl::switch_to_write_window() {
+   if ( _log.is_enabled( fc::log_level::debug ) ) {
+      auto now = fc::time_point::now();
+      fc_dlog( _log, "Read-only threads ${n}, read window ${r}us, total all threads ${t}us",
+               ("n", _ro_thread_pool_size)
+               ("r", now - _ro_read_window_start_time)
+               ("t", _ro_all_threads_exec_time_us.load()));
+   }
+
    // this method can be called from multiple places. it is possible
    // we are already in write window.
    if ( app().executor().is_write_window() ) {
@@ -2819,6 +2848,8 @@ void producer_plugin_impl::switch_to_read_window() {
    app().executor().set_to_read_window();
    chain_plug->chain().set_db_read_only_mode();
    _received_block = false;
+   _ro_read_window_start_time = fc::time_point::now();
+   _ro_all_threads_exec_time_us = 0;
 
    // start a read-only transaction execution task in each thread in the thread pool
    _ro_num_active_trx_exec_tasks = _ro_thread_pool_size;
@@ -2933,7 +2964,12 @@ bool producer_plugin_impl::push_read_only_transaction(
       auto remaining_time_in_read_window_us = _ro_read_window_time_us - time_used_in_read_window_us;
       // Ensure the trx to finish by the end of read-window.
       auto window_deadline = std::min( start + remaining_time_in_read_window_us, block_deadline );
+
       auto trace = chain.push_transaction( trx, window_deadline, _ro_max_trx_time_us, 0, false, 0 );
+      if ( _log.is_enabled( fc::log_level::debug ) ) {
+         auto dur = fc::time_point::now() - start;
+         _ro_all_threads_exec_time_us += dur.count();
+      }
       auto pr = handle_push_result(trx, next, start, chain, trace, true /*return_failure_trace*/, true /*disable_subjective_enforcement*/, {} /*first_auth*/, 0 /*sub_bill*/, 0 /*prev_billed_cpu_time_us*/);
       // If a transaction was exhausted, that indicates we are close to
       // the end of read window. Retry in next round.

plugins/state_history_plugin/include/eosio/state_history_plugin/session.hpp

@@ -103,7 +103,7 @@ public:
    void pop_entry(bool call_send = true) {
       send_queue.erase(send_queue.begin());
       sending = false;
-      if (call_send)
+      if (call_send || !send_queue.empty())
          send();
    }
 

tests/TestHarness/Cluster.py

@@ -22,8 +22,11 @@ from .Node import BlockType
 from .Node import Node
 from .WalletMgr import WalletMgr
 from .launch_transaction_generators import TransactionGeneratorsLauncher, TpsTrxGensConfig
-from .libc import unshare, CLONE_NEWNET
-from .interfaces import getInterfaceFlags, setInterfaceUp, IFF_LOOPBACK
+try:
+    from .libc import unshare, CLONE_NEWNET
+    from .interfaces import getInterfaceFlags, setInterfaceUp, IFF_LOOPBACK
+except:
+    pass
 
 # Protocol Feature Setup Policy
 class PFSetupPolicy:
@@ -1727,4 +1730,7 @@ class Cluster(object):
                 for line in f:
                     firstTrxs.append(line.rstrip('\n'))
         Utils.Print(f"first transactions: {firstTrxs}")
-        node.waitForTransactionsInBlock(firstTrxs)
+        status = node.waitForTransactionsInBlock(firstTrxs)
+        if status is None:
+            Utils.Print('ERROR: Failed to spin up transaction generators: never received first transactions')
+        return status

tests/TestHarness/Node.py

@@ -61,7 +61,7 @@ class Node(Transactions):
             self.fetchBlock = lambda blockNum: self.processUrllibRequest("trace_api", "get_block", {"block_num":blockNum}, silentErrors=False, exitOnError=True)
             self.fetchKeyCommand = lambda: "[transaction][transaction_header][ref_block_num]"
             self.fetchRefBlock = lambda trans: trans["transaction_header"]["ref_block_num"]
-            self.cleosLimit = "--time-limit 99999"
+            self.cleosLimit = "--time-limit 999"
             self.fetchHeadBlock = lambda node, headBlock: node.processUrllibRequest("chain", "get_block_info", {"block_num":headBlock}, silentErrors=False, exitOnError=True)
 
     def __str__(self):

tests/TestHarness/queries.py

@@ -118,10 +118,10 @@ class NodeosQueries:
         # could be a transaction response
         if cntxt.hasKey("processed"):
             cntxt.add("processed")
-            cntxt.add("action_traces")
-            cntxt.index(0)
             if not cntxt.isSectionNull("except"):
                 return "no_block"
+            cntxt.add("action_traces")
+            cntxt.index(0)
             return cntxt.add("block_num")
 
         # or what the trace api plugin returns
@@ -242,7 +242,7 @@ class NodeosQueries:
         assert(isinstance(transId, str))
         exitOnErrorForDelayed=not delayedRetry and exitOnError
         timeout=3
-        cmdDesc="get transaction_trace"
+        cmdDesc=self.fetchTransactionCommand()
         cmd="%s %s" % (cmdDesc, transId)
         msg="(transaction id=%s)" % (transId);
         for i in range(0,(int(60/timeout) - 1)):
@@ -295,8 +295,8 @@ class NodeosQueries:
         refBlockNum=None
         key=""
         try:
-            key="[transaction][transaction_header][ref_block_num]"
-            refBlockNum=trans["transaction_header"]["ref_block_num"]
+            key = self.fetchKeyCommand()
+            refBlockNum = self.fetchRefBlock(trans)
             refBlockNum=int(refBlockNum)+1
         except (TypeError, ValueError, KeyError) as _:
             Utils.Print("transaction%s not found. Transaction: %s" % (key, trans))
@@ -347,8 +347,8 @@ class NodeosQueries:
 
     def getTable(self, contract, scope, table, exitOnError=False):
         cmdDesc = "get table"
-        cmd="%s %s %s %s" % (cmdDesc, contract, scope, table)
-        msg="contract=%s, scope=%s, table=%s" % (contract, scope, table);
+        cmd=f"{cmdDesc} {self.cleosLimit} {contract} {scope} {table}"
+        msg=f"contract={contract}, scope={scope}, table={table}"
         return self.processCleosCmd(cmd, cmdDesc, exitOnError=exitOnError, exitMsg=msg)
 
     def getTableAccountBalance(self, contract, scope):
@@ -529,7 +529,7 @@ class NodeosQueries:
             return m.group(1)
         except subprocess.CalledProcessError as ex:
             end=time.perf_counter()
-            msg=ex.output.decode("utf-8")
+            msg=ex.stderr.decode("utf-8")
             Utils.Print("ERROR: Exception during code hash retrieval.  cmd Duration: %.3f sec.  %s" % (end-start, msg))
             return None
 
@@ -580,8 +580,9 @@ class NodeosQueries:
         except subprocess.CalledProcessError as ex:
             if not silentErrors:
                 end=time.perf_counter()
-                msg=ex.output.decode("utf-8")
-                errorMsg="Exception during \"%s\". Exception message: %s.  cmd Duration=%.3f sec. %s" % (cmdDesc, msg, end-start, exitMsg)
+                out=ex.output.decode("utf-8")
+                msg=ex.stderr.decode("utf-8")
+                errorMsg="Exception during \"%s\". Exception message: %s.  stdout: %s.  cmd Duration=%.3f sec. %s" % (cmdDesc, msg, out, end-start, exitMsg)
                 if exitOnError:
                     Utils.cmdError(errorMsg)
                     Utils.errorExit(errorMsg)

tests/TestHarness/transactions.py

@@ -107,7 +107,7 @@ class Transactions(NodeosQueries):
                 self.trackCmdTransaction(trans, reportStatus=reportStatus)
         except subprocess.CalledProcessError as ex:
             end=time.perf_counter()
-            msg=ex.output.decode("utf-8")
+            msg=ex.stderr.decode("utf-8")
             Utils.Print("ERROR: Exception during funds transfer.  cmd Duration: %.3f sec.  %s" % (end-start, msg))
             if exitOnError:
                 Utils.cmdError("could not transfer \"%s\" from %s to %s" % (amountStr, source, destination))
@@ -131,7 +131,7 @@ class Transactions(NodeosQueries):
                 Utils.Print("cmd Duration: %.3f sec" % (end-start))
         except subprocess.CalledProcessError as ex:
             end=time.perf_counter()
-            msg=ex.output.decode("utf-8")
+            msg=ex.stderr.decode("utf-8")
             Utils.Print("ERROR: Exception during spawn of funds transfer.  cmd Duration: %.3f sec.  %s" % (end-start, msg))
             if exitOnError:
                 Utils.cmdError("could not transfer \"%s\" from %s to %s" % (amountStr, source, destination))
@@ -158,15 +158,15 @@ class Transactions(NodeosQueries):
         except subprocess.CalledProcessError as ex:
             if not shouldFail:
                 end=time.perf_counter()
-                msg=ex.output.decode("utf-8")
-                Utils.Print("ERROR: Exception during set contract.  cmd Duration: %.3f sec.  %s" % (end-start, msg))
+                out=ex.output.decode("utf-8")
+                msg=ex.stderr.decode("utf-8")
+                Utils.Print("ERROR: Exception during set contract. stderr: %s.  stdout: %s.  cmd Duration: %.3f sec." % (msg, out, end-start))
                 return None
             else:
                 retMap={}
                 retMap["returncode"]=ex.returncode
                 retMap["cmd"]=ex.cmd
                 retMap["output"]=ex.output
-                retMap["stdout"]=ex.stdout
                 retMap["stderr"]=ex.stderr
                 return retMap
 
@@ -213,7 +213,7 @@ class Transactions(NodeosQueries):
                 Utils.Print("cmd Duration: %.3f sec" % (end-start))
             return (NodeosQueries.getTransStatus(retTrans) == 'executed', retTrans)
         except subprocess.CalledProcessError as ex:
-            msg=ex.output.decode("utf-8")
+            msg=ex.stderr.decode("utf-8")
             if not silentErrors:
                 end=time.perf_counter()
                 Utils.Print("ERROR: Exception during push transaction.  cmd Duration=%.3f sec.  %s" % (end - start, msg))
@@ -245,7 +245,6 @@ class Transactions(NodeosQueries):
         except subprocess.CalledProcessError as ex:
             msg=ex.stderr.decode("utf-8")
             output=ex.output.decode("utf-8")
-            msg=ex.output.decode("utf-8")
             if not silentErrors:
                 end=time.perf_counter()
                 Utils.Print("ERROR: Exception during push message. stderr: %s. stdout: %s.  cmd Duration=%.3f sec." % (msg, output, end - start))

tests/cli_test.py

@@ -352,7 +352,7 @@ def abi_file_with_nodeos_test():
         os.makedirs(data_dir, exist_ok=True)
         walletMgr = WalletMgr(True)
         walletMgr.launch()
-        node = Node('localhost', 8888, nodeId, cmd="./programs/nodeos/nodeos -e -p eosio --plugin eosio::trace_api_plugin --trace-no-abis --plugin eosio::producer_plugin --plugin eosio::producer_api_plugin --plugin eosio::chain_api_plugin --plugin eosio::chain_plugin --plugin eosio::http_plugin --access-control-allow-origin=* --http-validate-host=false --resource-monitor-not-shutdown-on-threshold-exceeded " + "--data-dir " + data_dir + " --config-dir " + data_dir, walletMgr=walletMgr)
+        node = Node('localhost', 8888, nodeId, cmd="./programs/nodeos/nodeos -e -p eosio --plugin eosio::trace_api_plugin --trace-no-abis --plugin eosio::producer_plugin --plugin eosio::producer_api_plugin --plugin eosio::chain_api_plugin --plugin eosio::chain_plugin --plugin eosio::http_plugin --access-control-allow-origin=* --http-validate-host=false --max-transaction-time=-1 --resource-monitor-not-shutdown-on-threshold-exceeded " + "--data-dir " + data_dir + " --config-dir " + data_dir, walletMgr=walletMgr)
         node.verifyAlive() # Setting node state to not alive
         node.relaunch(newChain=True, cachePopen=True)
         node.waitForBlock(1)

tests/nodeos_snapshot_diff_test.py

@@ -126,13 +126,15 @@ try:
     waitForBlock(node0, blockNum, blockType=BlockType.lib)
 
     Print("Configure and launch txn generators")
+    
     targetTpsPerGenerator = 10
     testTrxGenDurationSec=60*30
     cluster.launchTrxGenerators(contractOwnerAcctName=cluster.eosioAccount.name, acctNamesList=[account1Name, account2Name],
                                 acctPrivKeysList=[account1PrivKey,account2PrivKey], nodeId=snapshotNodeId, tpsPerGenerator=targetTpsPerGenerator,
                                 numGenerators=trxGeneratorCnt, durationSec=testTrxGenDurationSec, waitToComplete=False)
 
-    cluster.waitForTrxGeneratorsSpinup(nodeId=snapshotNodeId, numGenerators=trxGeneratorCnt)
+    status = cluster.waitForTrxGeneratorsSpinup(nodeId=snapshotNodeId, numGenerators=trxGeneratorCnt)
+    assert status is not None, "ERROR: Failed to spinup Transaction Generators"
 
     blockNum=node0.getBlockNum(BlockType.head)
     timePerBlock=500
@@ -156,12 +158,8 @@ try:
     minReqPctLeeway=0.60
     minRequiredTransactions=minReqPctLeeway*transactionsPerBlock
     assert steadyStateAvg>=minRequiredTransactions, "Expected to at least receive %s transactions per block, but only getting %s" % (minRequiredTransactions, steadyStateAvg)
-
-    Print("Create snapshot")
-    blockNumSnap=nodeSnap.getBlockNum(BlockType.head)
-    ret = nodeProg.scheduleSnapshotAt(blockNumSnap)
-    assert ret is not None, "Snapshot creation failed"
     
+    Print("Create snapshot (node 0)")
     ret = nodeSnap.createSnapshot()
     assert ret is not None, "Snapshot creation failed"
     ret_head_block_num = ret["payload"]["head_block_num"]
@@ -178,6 +176,29 @@ try:
     Utils.processLeapUtilCmd("snapshot to-json --input-file {}".format(snapshotFile), "snapshot to-json", silentErrors=False)
     snapshotFile = snapshotFile + ".json"
 
+    Print("Trim programmable blocklog to snapshot head block num and relaunch programmable node")
+    nodeProg.kill(signal.SIGTERM)
+    output=cluster.getBlockLog(progNodeId, blockLogAction=BlockLogAction.trim, first=0, last=ret_head_block_num, throwException=True)
+    removeState(progNodeId)
+    Utils.rmFromFile(Utils.getNodeConfigDir(progNodeId, "config.ini"), "p2p-peer-address")
+    isRelaunchSuccess = nodeProg.relaunch(chainArg="--replay", addSwapFlags={}, timeout=relaunchTimeout, cachePopen=True)
+    assert isRelaunchSuccess, "Failed to relaunch programmable node"
+
+    Print("Schedule snapshot (node 2)")
+    ret = nodeProg.scheduleSnapshotAt(ret_head_block_num)
+    assert ret is not None, "Snapshot scheduling failed"
+
+    Print("Wait for programmable node lib to advance")
+    waitForBlock(nodeProg, ret_head_block_num+1, blockType=BlockType.lib)
+
+    Print("Kill programmable node")
+    nodeProg.kill(signal.SIGTERM)
+
+    Print("Convert snapshot to JSON")
+    progSnapshotFile = getLatestSnapshot(progNodeId)
+    Utils.processLeapUtilCmd("snapshot to-json --input-file {}".format(progSnapshotFile), "snapshot to-json", silentErrors=False)
+    progSnapshotFile = progSnapshotFile + ".json"
+
     Print("Trim irreversible blocklog to snapshot head block num")
     nodeIrr.kill(signal.SIGTERM)
     output=cluster.getBlockLog(irrNodeId, blockLogAction=BlockLogAction.trim, first=0, last=ret_head_block_num, throwException=True)
@@ -205,15 +226,6 @@ try:
     irrSnapshotFile = irrSnapshotFile + ".json"
 
     assert Utils.compareFiles(snapshotFile, irrSnapshotFile), f"Snapshot files differ {snapshotFile} != {irrSnapshotFile}"
-  
-    Print("Kill programmable node")
-    nodeProg.kill(signal.SIGTERM)
-
-    Print("Convert snapshot to JSON")
-    progSnapshotFile = getLatestSnapshot(progNodeId)
-    Utils.processLeapUtilCmd("snapshot to-json --input-file {}".format(progSnapshotFile), "snapshot to-json", silentErrors=False)
-    progSnapshotFile = progSnapshotFile + ".json"
-
     assert Utils.compareFiles(progSnapshotFile, irrSnapshotFile), f"Snapshot files differ {progSnapshotFile} != {irrSnapshotFile}"
 
     testSuccessful=True

tests/nodeos_startup_catchup.py

@@ -118,7 +118,8 @@ try:
                                 tpsPerGenerator=targetTpsPerGenerator, numGenerators=trxGeneratorCnt, durationSec=testTrxGenDurationSec,
                                 waitToComplete=False)
 
-    cluster.waitForTrxGeneratorsSpinup(nodeId=node0.nodeId, numGenerators=trxGeneratorCnt)
+    status = cluster.waitForTrxGeneratorsSpinup(nodeId=node0.nodeId, numGenerators=trxGeneratorCnt)
+    assert status is not None, "ERROR: Failed to spinup Transaction Generators"
 
     blockNum=head(node0)
     timePerBlock=500

tests/plugin_http_api_test.py

@@ -56,7 +56,7 @@ class PluginHttpTest(unittest.TestCase):
                         "http_plugin", "db_size_api_plugin", "prometheus_plugin"]
         nodeos_plugins = "--plugin eosio::" +  " --plugin eosio::".join(plugin_names)
         nodeos_flags = (" --data-dir=%s --config-dir=%s --trace-dir=%s --trace-no-abis --access-control-allow-origin=%s "
-                        "--contracts-console --http-validate-host=%s --verbose-http-errors --abi-serializer-max-time-ms 30000 --http-max-response-time-ms 30000 "
+                        "--contracts-console --http-validate-host=%s --verbose-http-errors --max-transaction-time -1 --abi-serializer-max-time-ms 30000 --http-max-response-time-ms 30000 "
                         "--p2p-peer-address localhost:9011 --resource-monitor-not-shutdown-on-threshold-exceeded ") % (self.data_dir, self.config_dir, self.data_dir, "\'*\'", "false")
         start_nodeos_cmd = ("%s -e -p eosio %s %s ") % (Utils.EosServerPath, nodeos_plugins, nodeos_flags)
         self.nodeos.launchCmd(start_nodeos_cmd, self.node_id)