From e377339f0420422658917addea1b4edfc40fb4ef Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Fri, 3 Mar 2023 07:10:23 -0600 Subject: [PATCH 1/4] GH-768 Move subjective bill log to all level of producer_plugin logger. --- plugins/producer_plugin/producer_plugin.cpp | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 491cf682ff..9711582960 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -41,6 +41,13 @@ using std::vector; using std::deque; using boost::signals2::scoped_connection; +// in release/3.2+ move to fc logger.hpp +#define fc_tlog( LOGGER, FORMAT, ... ) \ + FC_MULTILINE_MACRO_BEGIN \ + if( (LOGGER).is_enabled( fc::log_level::all ) ) \ + (LOGGER).log( FC_LOG_MESSAGE( all, FORMAT, __VA_ARGS__ ) ); \ + FC_MULTILINE_MACRO_END + #undef FC_LOG_AND_DROP #define LOG_AND_DROP() \ catch ( const guard_exception& e ) { \ @@ -696,7 +703,7 @@ class producer_plugin_impl : public std::enable_shared_from_thisbilled_cpu_time_us; auto trace = chain.push_transaction( trx, block_deadline, max_trx_time, prev_billed_cpu_time_us, false, sub_bill ); - fc_dlog( _trx_failed_trace_log, "Subjective bill for ${a}: ${b} elapsed ${t}us", ("a",first_auth)("b",sub_bill)("t",trace->elapsed)); + fc_tlog( _log, "Subjective bill for ${a}: ${b} elapsed ${t}us", ("a",first_auth)("b",sub_bill)("t",trace->elapsed)); if( trace->except ) { if( exception_is_exhausted( *trace->except ) ) { _unapplied_transactions.add_incoming( trx, persist_until_expired, return_failure_traces, next ); @@ -2049,7 +2056,7 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin || trx->read_only; auto trace = chain.push_transaction( trx, deadline, max_trx_time, prev_billed_cpu_time_us, false, sub_bill ); - fc_dlog( _trx_failed_trace_log, "Subjective unapplied bill for ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)); + fc_tlog( _log, "Subjective unapplied bill for ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)); if( trace->except ) { if( exception_is_exhausted( *trace->except ) ) { if( block_is_exhausted() ) { @@ -2058,7 +2065,7 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin break; } } else { - fc_dlog( _trx_failed_trace_log, "Subjective unapplied bill for failed ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)); + fc_tlog( _log, "Subjective unapplied bill for failed ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)); 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 @@ -2077,7 +2084,7 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin continue; } } else { - fc_dlog( _trx_successful_trace_log, "Subjective unapplied bill for success ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)); + fc_tlog( _log, "Subjective unapplied bill for success ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)); // if db_read_mode SPECULATIVE then trx is in the pending block and not immediately reverted if (!disable_subjective_billing) _subjective_billing.subjective_bill( trx->id(), trx->packed_trx()->expiration(), first_auth, trace->elapsed, From 0046163ad76f68e99f2643735de0e603c151ecd5 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Sat, 4 Mar 2023 13:52:06 -0600 Subject: [PATCH 2/4] GH-768 Move fc_tlog to logger.hpp --- libraries/libfc/include/fc/log/logger.hpp | 6 ++++++ plugins/producer_plugin/producer_plugin.cpp | 7 ------- 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/libraries/libfc/include/fc/log/logger.hpp b/libraries/libfc/include/fc/log/logger.hpp index 803a2de0a8..0d61b691a8 100644 --- a/libraries/libfc/include/fc/log/logger.hpp +++ b/libraries/libfc/include/fc/log/logger.hpp @@ -74,6 +74,12 @@ namespace fc # define FC_MULTILINE_MACRO_END } while (0) #endif +#define fc_tlog( LOGGER, FORMAT, ... ) \ + FC_MULTILINE_MACRO_BEGIN \ + if( (LOGGER).is_enabled( fc::log_level::all ) ) \ + (LOGGER).log( FC_LOG_MESSAGE( all, FORMAT, __VA_ARGS__ ) ); \ + FC_MULTILINE_MACRO_END + #define fc_dlog( LOGGER, FORMAT, ... ) \ FC_MULTILINE_MACRO_BEGIN \ if( (LOGGER).is_enabled( fc::log_level::debug ) ) \ diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index a88cefca1b..97c2b4a4af 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -40,13 +40,6 @@ using std::string; using std::vector; using boost::signals2::scoped_connection; -// in release/3.2+ move to fc logger.hpp -#define fc_tlog( LOGGER, FORMAT, ... ) \ - FC_MULTILINE_MACRO_BEGIN \ - if( (LOGGER).is_enabled( fc::log_level::all ) ) \ - (LOGGER).log( FC_LOG_MESSAGE( all, FORMAT, __VA_ARGS__ ) ); \ - FC_MULTILINE_MACRO_END - #undef FC_LOG_AND_DROP #define LOG_AND_DROP() \ catch ( const guard_exception& e ) { \ From 83307587a276cf62ca126bdb70d2f4723e31e2e8 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Sat, 4 Mar 2023 14:01:23 -0600 Subject: [PATCH 3/4] GH-768 Log non TRX_TRACE trx logging to all (trace) level logger of producer_plugin. --- plugins/producer_plugin/producer_plugin.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 97c2b4a4af..e232e4975b 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -560,7 +560,7 @@ class producer_plugin_impl : public std::enable_shared_from_this_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) ); + fc_tlog( _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 ); @@ -2043,14 +2043,14 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline, pr.failed = true; auto failure_code = trace->except->code(); if( failure_code != tx_duplicate::code_value ) { - fc_dlog( _trx_failed_trace_log, "Subjective bill for failed ${a}: ${b} elapsed ${t}us, time ${r}us", + fc_tlog( _log, "Subjective bill for failed ${a}: ${b} elapsed ${t}us, time ${r}us", ("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 ); // 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}", + fc_tlog( _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 ) @@ -2066,7 +2066,7 @@ 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", + 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)); _account_fails.add_success_time(end - start); log_trx_results( trx, trace, start ); From a0ff189eab22f57b90a75c4c665349c21a0af680 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 6 Mar 2023 08:01:08 -0600 Subject: [PATCH 4/4] kick ci/cd