diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 7a4f6a635e..640beb2522 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -145,6 +145,21 @@ class account_failures { max_failures_per_account = max_failures; } + void add_idle_time( const fc::microseconds& idle ) { + block_idle_time += idle; + } + + void add_fail_time( const fc::microseconds& fail_time ) { + 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( const account_name& n, int64_t exception_code ) { auto& fa = failed_accounts[n]; ++fa.num_failures; @@ -162,9 +177,14 @@ class account_failures { return false; } - void report() const { + void report( const fc::time_point& idle_trx_time ) { 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 trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, other: ${o}us", + ("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) ); for( const auto& e : failed_accounts ) { std::string reason; if( e.second.is_deadline() ) reason += "deadline"; @@ -189,6 +209,9 @@ class account_failures { void clear() { failed_accounts.clear(); + block_idle_time = trx_fail_time = trx_success_time = fc::microseconds{}; + trx_fail_num = trx_success_num = 0; + clear_time = fc::time_point::now(); } private: @@ -226,6 +249,12 @@ class account_failures { std::map failed_accounts; uint32_t max_failures_per_account = 3; + fc::microseconds block_idle_time; + uint32_t trx_success_num = 0; + uint32_t trx_fail_num = 0; + fc::microseconds trx_success_time; + fc::microseconds trx_fail_time; + fc::time_point clear_time{fc::time_point::now()}; const eosio::subjective_billing& subjective_billing; }; @@ -291,7 +320,7 @@ class producer_plugin_impl : public std::enable_shared_from_this _protocol_features_to_activate; bool _protocol_features_signaled = false; // to mark whether it has been signaled in start_block @@ -386,8 +415,13 @@ class producer_plugin_impl : public std::enable_shared_from_thischain(); + if( chain.is_building_block() ) { + _account_fails.report( _idle_trx_time ); + } _unapplied_transactions.add_aborted( chain.abort_block() ); _subjective_billing.abort_block(); + _account_fails.clear(); + _idle_trx_time = fc::time_point::now(); } bool on_incoming_block(const signed_block_ptr& block, const std::optional& block_id) { @@ -453,18 +487,19 @@ class producer_plugin_impl : public std::enable_shared_from_thisheader.timestamp.next().to_time_point() >= fc::time_point::now() ) { + auto now = fc::time_point::now(); + if( hbs->header.timestamp.next().to_time_point() >= now ) { _production_enabled = true; } - if( fc::time_point::now() - block->timestamp < fc::minutes(5) || (blk_num % 1000 == 0) ) { + if( now - block->timestamp < fc::minutes(5) || (blk_num % 1000 == 0) ) { ilog("Received block ${id}... #${n} @ ${t} signed by ${p} " "[trxs: ${count}, lib: ${lib}, conf: ${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, latency: ${latency} ms]", ("p",block->producer)("id",id.str().substr(8,16))("n",blk_num)("t",block->timestamp) ("count",block->transactions.size())("lib",chain.last_irreversible_block_num()) ("confs", block->confirmed)("net", br.total_net_usage)("cpu", br.total_cpu_usage_us) ("elapsed", br.total_elapsed_time)("time", br.total_time) - ("latency", (fc::time_point::now() - block->timestamp).count()/1000 ) ); + ("latency", (now - block->timestamp).count()/1000 ) ); if( chain.get_read_mode() != db_read_mode::IRREVERSIBLE && hbs->id != id && hbs->block != nullptr ) { // not applied to head ilog("Block not applied to head ${id}... #${n} @ ${t} signed by ${p} " "[trxs: ${count}, dpos: ${dpos}, conf: ${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, latency: ${latency} ms]", @@ -472,7 +507,7 @@ class producer_plugin_impl : public std::enable_shared_from_thisblock->transactions.size())("dpos", hbs->dpos_irreversible_blocknum) ("confs", hbs->block->confirmed)("net", br.total_net_usage)("cpu", br.total_cpu_usage_us) ("elapsed", br.total_elapsed_time)("time", br.total_time) - ("latency", (fc::time_point::now() - hbs->block->timestamp).count()/1000 ) ); + ("latency", (now - hbs->block->timestamp).count()/1000 ) ); } } @@ -481,8 +516,9 @@ class producer_plugin_impl : public std::enable_shared_from_thischain(); + // abort the pending block - _unapplied_transactions.add_aborted( chain.abort_block() ); + abort_block(); schedule_production_loop(); } @@ -521,9 +557,17 @@ class producer_plugin_impl : public std::enable_shared_from_thislog_trx_results( trx, nullptr, ex, 0, fc::time_point::now() ); + auto start = fc::time_point::now(); + auto idle_time = start - self->_idle_trx_time; + self->_account_fails.add_idle_time( idle_time ); + fc_dlog( _trx_successful_trace_log, "Time since last trx: ${t}us", ("t", idle_time) ); + + auto exception_handler = [self, &next, trx{std::move(trx)}, &start](fc::exception_ptr ex) { + self->_account_fails.add_idle_time( start - self->_idle_trx_time ); + self->log_trx_results( trx, nullptr, ex, 0, start ); next( std::move(ex) ); + self->_idle_trx_time = fc::time_point::now(); + self->_account_fails.add_fail_time(self->_idle_trx_time - start); }; try { auto result = future.get(); @@ -534,6 +578,7 @@ class producer_plugin_impl : public std::enable_shared_from_thisrestart_speculative_block(); } } + self->_idle_trx_time = fc::time_point::now(); } CATCH_AND_CALL(exception_handler); } ); } @@ -546,7 +591,6 @@ class producer_plugin_impl : public std::enable_shared_from_this next) { bool exhausted = false; chain::controller& chain = chain_plug->chain(); - try { const auto& id = trx->id(); @@ -593,7 +637,6 @@ class producer_plugin_impl : public std::enable_shared_from_this next ) { auto start = fc::time_point::now(); - fc_dlog( _trx_successful_trace_log, "Time since last trx: ${t}us", ("t", start - _idle_trx_time) ); + + bool disable_subjective_enforcement = (persist_until_expired && _disable_subjective_api_billing) + || (!persist_until_expired && _disable_subjective_p2p_billing) + || trx->read_only; auto first_auth = trx->packed_trx()->get_transaction().first_authorizer(); - if( _pending_block_mode == pending_block_mode::producing && _account_fails.failure_limit( first_auth ) ) { + if( !disable_subjective_enforcement && _account_fails.failure_limit( first_auth ) ) { if( next ) { auto except_ptr = std::static_pointer_cast( std::make_shared( FC_LOG_MESSAGE( error, "transaction ${id} exceeded failure limit for account ${a}", @@ -1883,7 +1928,7 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, log_trx_results( trx, except_ptr ); next( except_ptr ); } - _idle_trx_time = fc::time_point::now(); + _account_fails.add_fail_time(fc::time_point::now() - start); return push_result{.failed = true}; } @@ -1892,9 +1937,7 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, if( max_trx_time.count() < 0 ) max_trx_time = fc::microseconds::maximum(); bool disable_subjective_billing = ( _pending_block_mode == pending_block_mode::producing ) - || ( persist_until_expired && _disable_subjective_api_billing ) - || ( !persist_until_expired && _disable_subjective_p2p_billing ) - || trx->read_only; + || disable_subjective_enforcement; int64_t sub_bill = 0; if( !disable_subjective_billing ) @@ -1910,8 +1953,10 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, } auto trace = chain.push_transaction( trx, block_deadline, max_trx_time, prev_billed_cpu_time_us, false, sub_bill ); + auto end = fc::time_point::now(); push_result pr; if( trace->except ) { + _account_fails.add_fail_time(end - start); 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 ", @@ -1924,20 +1969,19 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, } else { pr.failed = true; fc_dlog( _trx_failed_trace_log, "Subjective bill for failed ${a}: ${b} elapsed ${t}us, time ${r}us", - ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", fc::time_point::now() - start)); + ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", end - start)); if (!disable_subjective_billing) _subjective_billing.subjective_bill_failure( first_auth, trace->elapsed, fc::time_point::now() ); log_trx_results( trx, trace, start ); - if( _pending_block_mode == pending_block_mode::producing ) { - auto failure_code = trace->except->code(); - if( failure_code != tx_duplicate::code_value ) { - // this failed our configured maximum transaction time, we don't want to replay it - fc_dlog( _log, "Failed ${c} trx, auth: ${a}, prev billed: ${p}us, ran: ${r}us, id: ${id}", - ("c", failure_code)("a", first_auth)("p", prev_billed_cpu_time_us) - ( "r", fc::time_point::now() - start )( "id", trx->id() ) ); + auto failure_code = trace->except->code(); + if( failure_code != tx_duplicate::code_value ) { + // this failed our configured maximum transaction time, we don't want to replay it + fc_dlog( _trx_failed_trace_log, "Failed ${c} trx, auth: ${a}, prev billed: ${p}us, ran: ${r}us, id: ${id}", + ("c", failure_code)("a", first_auth)("p", prev_billed_cpu_time_us) + ( "r", end - start )( "id", trx->id() ) ); + if( !disable_subjective_enforcement ) _account_fails.add( first_auth, failure_code ); - } } if( next ) { if( return_failure_trace ) { @@ -1950,7 +1994,8 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, } } else { fc_dlog( _trx_successful_trace_log, "Subjective bill for success ${a}: ${b} elapsed ${t}us, time ${r}us", - ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", fc::time_point::now() - start)); + ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", end - start)); + _account_fails.add_success_time(end - start); log_trx_results( trx, trace, start ); if( persist_until_expired && !_disable_persist_until_expired ) { // if this trx didn't fail/soft-fail and the persist flag is set @@ -1966,7 +2011,6 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, if( next ) next( trace ); } - _idle_trx_time = fc::time_point::now(); return pr; } @@ -2063,7 +2107,6 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p num_processed++; - _idle_trx_time = fc::time_point::now(); // configurable ratio of incoming txns vs deferred txns while (incoming_trx_weight >= 1.0 && itr != end ) { if (deadline <= fc::time_point::now()) { @@ -2110,7 +2153,9 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p if( max_trx_time.count() < 0 ) max_trx_time = fc::microseconds::maximum(); auto trace = chain.push_scheduled_transaction(trx_id, deadline, max_trx_time, 0, false); + auto end = fc::time_point::now(); if (trace->except) { + _account_fails.add_fail_time(end - start); if (exception_is_exhausted(*trace->except)) { if( block_is_exhausted() ) { exhausted = true; @@ -2120,7 +2165,7 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p fc_dlog(_trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${txid}, time: ${r}, auth: ${a} : ${details}", ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer()) - ("txid", trx_id)("r", fc::time_point::now() - start)("a", get_first_authorizer(trace)) + ("txid", trx_id)("r", end - start)("a", get_first_authorizer(trace)) ("details", get_detailed_contract_except_info(nullptr, trace, nullptr))); fc_dlog(_trx_trace_failure_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${entire_trace}", ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer()) @@ -2130,10 +2175,11 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p num_failed++; } } else { + _account_fails.add_success_time(end - start); 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()) - ("txid", trx_id)("r", fc::time_point::now() - start)("a", get_first_authorizer(trace)) + ("txid", trx_id)("r", end - start)("a", get_first_authorizer(trace)) ("cpu", trace->receipt ? trace->receipt->cpu_usage_us : 0)); fc_dlog(_trx_trace_success_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${entire_trace}", ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer()) @@ -2160,7 +2206,6 @@ bool producer_plugin_impl::process_incoming_trxs( const fc::time_point& deadline bool exhausted = false; auto end = _unapplied_transactions.incoming_end(); if( itr != end ) { - _idle_trx_time = fc::time_point::now(); size_t processed = 0; fc_dlog( _log, "Processing ${n} pending transactions", ("n", _unapplied_transactions.incoming_size()) ); while( itr != end ) { @@ -2214,6 +2259,8 @@ void producer_plugin_impl::schedule_production_loop() { auto result = start_block(); + _idle_trx_time = fc::time_point::now(); + if (result == start_block_result::failed) { elog("Failed to start a pending block, will try again later"); _timer.expires_from_now( boost::posix_time::microseconds( config::block_interval_us / 10 )); @@ -2397,7 +2444,7 @@ void producer_plugin_impl::produce_block() { block_state_ptr new_bs = chain.head_block_state(); - _account_fails.report(); + _account_fails.report(_idle_trx_time); _account_fails.clear(); controller::block_report br; diff --git a/programs/cleos/main.cpp b/programs/cleos/main.cpp index 3d0cf920e5..53b127eabb 100644 --- a/programs/cleos/main.cpp +++ b/programs/cleos/main.cpp @@ -166,6 +166,7 @@ const fc::microseconds abi_serializer_max_time = fc::seconds(10); // No risk to string tx_ref_block_num_or_id; bool tx_force_unique = false; bool tx_dont_broadcast = false; +bool tx_unpack_data = false; bool tx_return_packed = false; bool tx_skip_sign = false; bool tx_print_json = false; @@ -226,6 +227,7 @@ void add_standard_transaction_options(CLI::App* cmd, string default_permission = cmd->add_flag("-j,--json", tx_print_json, localized("Print result as JSON")); cmd->add_option("--json-file", tx_json_save_file, localized("Save result in JSON format into a file")); cmd->add_flag("-d,--dont-broadcast", tx_dont_broadcast, localized("Don't broadcast transaction to the network (just print to stdout)")); + cmd->add_flag("-u,--unpack-action-data", tx_unpack_data, localized("Unpack all action data within transaction, needs interaction with ${n} unless --abi-file. Used in conjunction with --dont-broadcast.", ("n", node_executable_name))); cmd->add_flag("--return-packed", tx_return_packed, localized("Used in conjunction with --dont-broadcast to get the packed transaction")); cmd->add_option("-r,--ref-block", tx_ref_block_num_or_id, (localized("Set the reference block num or block id used for TAPOS (Transaction as Proof-of-Stake)"))); cmd->add_flag("--use-old-rpc", tx_use_old_rpc, localized("Use old RPC push_transaction, rather than new RPC send_transaction")); @@ -499,14 +501,15 @@ fc::variant push_transaction( signed_transaction& trx, const std::vector(python3 -c 'import json,sys; print(str(json.load(sys.stdin)["debug"]).lower());') &> /dev/null) +TDIR=$(mktemp -d || exit 1) +NODEOS_DEBUG=$(programs/nodeos/nodeos --config-dir "${TDIR}" --data-dir "${TDIR}" --extract-build-info >(python3 -c 'import json,sys; print(str(json.load(sys.stdin)["debug"]).lower());') &> /dev/null) +#avoiding an rm -rf out of paranoia, but with the tradeoff this could change somehow in the future +rm "${TDIR}/config.ini" || exit 1 +rmdir "${TDIR}" || exit 1 if [[ "${NODEOS_DEBUG}" == 'false' ]]; then echo 'PASS: Debug flag is not set.' echo '' diff --git a/tutorials/bios-boot-tutorial/genesis.json b/tutorials/bios-boot-tutorial/genesis.json index 6e27e3cd87..f0f77b4fbb 100644 --- a/tutorials/bios-boot-tutorial/genesis.json +++ b/tutorials/bios-boot-tutorial/genesis.json @@ -19,6 +19,5 @@ "max_inline_action_size": 4096, "max_inline_action_depth": 4, "max_authority_depth": 6 - }, - "initial_chain_id": "0000000000000000000000000000000000000000000000000000000000000000" + } }