diff --git a/.idea/db-forest-config.xml b/.idea/db-forest-config.xml new file mode 100644 index 000000000..d403b1c38 --- /dev/null +++ b/.idea/db-forest-config.xml @@ -0,0 +1,11 @@ + + + + . + ---------------------------------------- + 1:0:579f7449-1ec5-4c9b-9ff3-5e24fd48c3cc + 2:0:99bd9de8-674c-4635-b5f9-892f0d004e30 + 3:0:186934f8-36b9-4dca-9498-a9756747c2fb + . + + \ No newline at end of file diff --git a/masq_lib/src/logger.rs b/masq_lib/src/logger.rs index b5fe282c8..dd525fc66 100644 --- a/masq_lib/src/logger.rs +++ b/masq_lib/src/logger.rs @@ -317,8 +317,9 @@ impl Logger { level <= self.level_limit } - pub fn set_level_for_test(&mut self, level: Level) { - self.level_limit = level + pub fn set_test_log_level(mut self, level: Level) -> Self { + self.level_limit = level; + self } } diff --git a/node/src/accountant/logging_utils/accounting_msgs_debug.rs b/node/src/accountant/logging_utils/accounting_msgs_debug.rs index e6cb8eb52..ea7c82751 100644 --- a/node/src/accountant/logging_utils/accounting_msgs_debug.rs +++ b/node/src/accountant/logging_utils/accounting_msgs_debug.rs @@ -7,30 +7,32 @@ use std::fmt::{Display, Formatter}; use std::iter::once; use web3::types::Address; -// An attempt to provide somewhat useful debug stats for the accounting messages after we have -// decreased the log level for lots of them, and it drastically reduced the observability -// of the Accountant. +// Lightweight debug statistics intended to restore some observability lost after +// lowering the log level of frequently emitted accounting messages. +// +// The implementation avoids overhead when debug logging is disabled. Since trace logs +// already provide more detailed information, some debug and trace messages are mutually +// exclusive and do not use this utility. #[derive(Default)] -pub struct AccountingMessageTracker { - routing_provided_stats: AccountingMsgStats, - exit_provided_stats: AccountingMsgStats, - consumed_stats: AccountingMsgStats, +pub struct AccountingMsgTracker { + routing_provided_stats: AccountingMsgDebugStats, + exit_provided_stats: AccountingMsgDebugStats, + consumed_stats: AccountingMsgDebugStats, } -impl AccountingMessageTracker { - pub fn process_debug_stats( +impl AccountingMsgTracker { + pub fn process_another_msg( &mut self, msg_type: AccountingMsgType, new_charges: Vec, log_window_size: u16, - ) -> Option { - self.record_new_charges_by_msg_type(new_charges, msg_type); - - self.maybe_dump_stats_by_msg_type(log_window_size, msg_type) + ) -> Option { + self.record_charges_by_msg_type(new_charges, msg_type); + self.consider_logging(log_window_size, msg_type) } - fn record_new_charges_by_msg_type( + fn record_charges_by_msg_type( &mut self, new_charges: Vec, msg_type: AccountingMsgType, @@ -48,21 +50,21 @@ impl AccountingMessageTracker { } } - fn maybe_dump_stats_by_msg_type( + fn consider_logging( &mut self, log_window_size: u16, msg_type: AccountingMsgType, - ) -> Option { + ) -> Option { match msg_type { AccountingMsgType::RoutingServiceProvided => self .routing_provided_stats - .maybe_dump_stats(log_window_size, msg_type), - AccountingMsgType::ExitServiceProvided => self - .exit_provided_stats - .maybe_dump_stats(log_window_size, msg_type), - AccountingMsgType::ServicesConsumed => self - .consumed_stats - .maybe_dump_stats(log_window_size, msg_type), + .log_if(log_window_size, msg_type), + AccountingMsgType::ExitServiceProvided => { + self.exit_provided_stats.log_if(log_window_size, msg_type) + } + AccountingMsgType::ServicesConsumed => { + self.consumed_stats.log_if(log_window_size, msg_type) + } } } } @@ -71,58 +73,78 @@ impl AccountingMessageTracker { pub struct NewCharge { pub address: Address, pub amount_wei: u128, + pub bytes: usize, } impl NewCharge { - pub fn new(address: Address, amount_wei: u128) -> Self { + pub fn new(address: Address, amount_wei: u128, bytes: usize) -> Self { Self { address, amount_wei, + bytes, } } } #[derive(Debug, PartialEq, Eq)] -pub struct LoggableStats { +pub struct LoggableDebugStats { msg_type: AccountingMsgType, - accounting_msg_stats: HashMap, - log_window_in_pcs_of_msgs: u16, + accounting_msg_stats: HashMap, + log_window_size: u16, } -impl Display for LoggableStats { + +impl LoggableDebugStats { + pub fn stats(&self) -> Vec { + self.accounting_msg_stats + .iter() + .sorted_by(|(address_a, stats_a), (address_b, stats_b)| { + Ord::cmp(&stats_b.wei, &stats_a.wei).then(Ord::cmp(&address_b, &address_a)) + }) + .map(|(address, stats)| format!("{:?}: {} | {}", address, stats.wei, stats.bytes)) + .collect() + } +} + +impl Display for LoggableDebugStats { fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { - let label = format!( - "Total debits across last {} {:?} messages (wei):", - self.log_window_in_pcs_of_msgs, self.msg_type + let init_label = format!( + "Debits from last {} {:?} messages [wei | bytes]:", + self.log_window_size, self.msg_type ); - let stats = self - .accounting_msg_stats - .iter() - .sorted() - .map(|(address, sum)| format!("{:?}: {}", address, sum)) - .collect_vec(); - once(label).chain(stats).join("\n").fmt(f) + + let stats = self.stats(); + + once(init_label).chain(stats).join("\n").fmt(f) } } +#[derive(Default, Debug, PartialEq, Eq, PartialOrd, Ord)] +struct AddressStats { + bytes: usize, + wei: u128, +} + #[derive(Default)] -struct AccountingMsgStats { - stats: HashMap, +struct AccountingMsgDebugStats { + stats: HashMap, msg_count_since_last_logged: usize, } -impl AccountingMsgStats { - fn maybe_dump_stats( +impl AccountingMsgDebugStats { + fn log_if( &mut self, log_window_size: u16, msg_type: AccountingMsgType, - ) -> Option { + ) -> Option { if self.should_log_stats(log_window_size) { self.msg_count_since_last_logged = 0; - Some(LoggableStats { + let accounting_msg_stats = self.stats.drain().collect(); + + Some(LoggableDebugStats { msg_type, - accounting_msg_stats: self.stats.drain().collect(), - log_window_in_pcs_of_msgs: log_window_size, + accounting_msg_stats, + log_window_size, }) } else { None @@ -135,7 +157,9 @@ impl AccountingMsgStats { fn record_new_charges(&mut self, new_charges_vec: Vec) { new_charges_vec.iter().for_each(|new_charges| { - *self.stats.entry(new_charges.address).or_default() += new_charges.amount_wei; + let mut entry = self.stats.entry(new_charges.address).or_default(); + entry.wei += new_charges.amount_wei; + entry.bytes += new_charges.bytes; }); self.msg_count_since_last_logged += 1; } @@ -148,21 +172,23 @@ pub enum AccountingMsgType { ServicesConsumed, } -pub struct NewChargessDebugContainer { +pub struct NewChargesDebugContainer { debug_enabled: bool, + trace_enabled: bool, vec: Vec, } -impl NewChargessDebugContainer { +impl NewChargesDebugContainer { pub fn new(logger: &Logger) -> Self { Self { debug_enabled: logger.debug_enabled(), + trace_enabled: logger.trace_enabled(), vec: vec![], } } pub fn add_new_charge(mut self, new_charge_opt: Option) -> Self { - if self.debug_enabled { + if self.debug_enabled && !self.trace_enabled { if let Some(new_charge) = new_charge_opt { self.vec.push(new_charge); } @@ -171,8 +197,8 @@ impl NewChargessDebugContainer { } } -impl From for Vec { - fn from(postings: NewChargessDebugContainer) -> Self { +impl From for Vec { + fn from(postings: NewChargesDebugContainer) -> Self { postings.vec } } @@ -180,8 +206,8 @@ impl From for Vec { #[cfg(test)] mod tests { use super::{ - AccountingMessageTracker, AccountingMsgType, LoggableStats, NewCharge, - NewChargessDebugContainer, + AccountingMsgDebugStats, AccountingMsgTracker, AccountingMsgType, AddressStats, + LoggableDebugStats, NewCharge, NewChargesDebugContainer, }; use crate::blockchain::test_utils::make_address; use itertools::Itertools; @@ -191,54 +217,80 @@ mod tests { use web3::types::Address; #[test] - fn test_loggable_count_works_for_routing_service_provided() { - test_process_debug_stats(AccountingMsgType::RoutingServiceProvided, 6); + fn should_log_stats_when_one_msg_less() { + let log_window = 5; + let mut subject = AccountingMsgDebugStats::default(); + subject.msg_count_since_last_logged = 4; + + assert_eq!(subject.should_log_stats(log_window), false); + } + + #[test] + fn should_log_stats_when_equal() { + let log_window = 5; + let mut subject = AccountingMsgDebugStats::default(); + subject.msg_count_since_last_logged = 5; + + assert_eq!(subject.should_log_stats(log_window), true); + } + + #[test] + fn should_log_stats_when_one_over() { + // This situation is not expected in reality; just hardening + let log_window = 5; + let mut subject = AccountingMsgDebugStats::default(); + subject.msg_count_since_last_logged = 6; + + assert_eq!(subject.should_log_stats(log_window), true); } #[test] - fn test_loggable_count_works_for_exit_service_provided() { - test_process_debug_stats(AccountingMsgType::ExitServiceProvided, 3); + fn process_another_msg_works_for_routing_service_provided() { + test_process_another_msg(AccountingMsgType::RoutingServiceProvided, 6); } #[test] - fn test_loggable_count_works_for_services_consumed() { - test_process_debug_stats(AccountingMsgType::ServicesConsumed, 8); + fn process_another_msg_works_for_exit_service_provided() { + test_process_another_msg(AccountingMsgType::ExitServiceProvided, 3); } - fn test_process_debug_stats(msg_type: AccountingMsgType, log_window_size: u16) { - let mut new_charge_feeds_per_msg = - generate_new_charge_feeds_representing_msgs(log_window_size); - let expected_sorted_stats = - construct_expected_sorted_stats_from_generated_new_charges(&new_charge_feeds_per_msg); - let mut subject = AccountingMessageTracker::default(); + #[test] + fn process_another_msg_works_for_services_consumed() { + test_process_another_msg(AccountingMsgType::ServicesConsumed, 8); + } + + fn test_process_another_msg(msg_type: AccountingMsgType, log_window_size: u16) { + let mut msgs_with_charges = generate_msgs(log_window_size); + let expected_sorted_stats = derive_expected_sorted_stats(&msgs_with_charges); + let mut subject = AccountingMsgTracker::default(); + assert_empty_stats(&subject); - let charge_msg_matching_the_window_size = - new_charge_feeds_per_msg.remove(log_window_size as usize - 1 - 1); - let initial_charge_msgs = new_charge_feeds_per_msg; - test_msgs_of_count_window_size_minus_one( + let msg_matching_the_window_size = msgs_with_charges.remove(log_window_size as usize - 1); + let initial_few_charge_msgs = msgs_with_charges; + + assert_msg_window_size_minus_one( &mut subject, msg_type, log_window_size, - initial_charge_msgs, + initial_few_charge_msgs, ); - let result = subject - .process_debug_stats( - msg_type, - charge_msg_matching_the_window_size, - log_window_size, - ) - .expect("first try: expected stats dump"); + test_matching_the_log_window( + &mut subject, + msg_type, + msg_matching_the_window_size, + log_window_size, + expected_sorted_stats, + ); - assert_provided_loggable_stats(result, msg_type, log_window_size, expected_sorted_stats); assert_empty_stats(&subject); retest_after_emptied(&mut subject, msg_type); } - fn test_msgs_of_count_window_size_minus_one( - subject: &mut AccountingMessageTracker, + fn assert_msg_window_size_minus_one( + subject: &mut AccountingMsgTracker, msg_type: AccountingMsgType, log_window_size: u16, initial_charge_msgs: Vec>, @@ -247,7 +299,7 @@ mod tests { .into_iter() .enumerate() .for_each(|(idx, new_charges)| { - let result = subject.process_debug_stats(msg_type, new_charges, log_window_size); + let result = subject.process_another_msg(msg_type, new_charges, log_window_size); assert_eq!( result, @@ -260,7 +312,7 @@ mod tests { }); } - fn assert_empty_stats(subject: &AccountingMessageTracker) { + fn assert_empty_stats(subject: &AccountingMsgTracker) { assert!(subject.consumed_stats.stats.is_empty()); assert_eq!(subject.consumed_stats.msg_count_since_last_logged, 0); assert!(subject.exit_provided_stats.stats.is_empty()); @@ -272,35 +324,44 @@ mod tests { ) } - fn assert_provided_loggable_stats( - actual_loggable_stats: LoggableStats, + fn test_matching_the_log_window( + subject: &mut AccountingMsgTracker, msg_type: AccountingMsgType, + another_msg_with_charges: Vec, log_window_size: u16, - expected_sorted_stats: Vec<(Address, u128)>, + expected_sorted_stats: Vec<(Address, AddressStats)>, + ) { + let result = subject + .process_another_msg(msg_type, another_msg_with_charges, log_window_size) + .expect("first try: expected stats dump"); + + assert_produced_loggable_stats(result, msg_type, log_window_size, expected_sorted_stats); + } + + fn assert_produced_loggable_stats( + actual_loggable_stats: LoggableDebugStats, + msg_type: AccountingMsgType, + log_window_size: u16, + expected_sorted_stats: Vec<(Address, AddressStats)>, ) { assert_eq!(actual_loggable_stats.msg_type, msg_type); assert_eq!( actual_loggable_stats .accounting_msg_stats .into_iter() - .sorted() + .sorted_by_key(|(address, _)| *address) .collect_vec(), expected_sorted_stats ); - assert_eq!( - actual_loggable_stats.log_window_in_pcs_of_msgs, - log_window_size - ); + assert_eq!(actual_loggable_stats.log_window_size, log_window_size); } - fn retest_after_emptied(subject: &mut AccountingMessageTracker, msg_type: AccountingMsgType) { + fn retest_after_emptied(subject: &mut AccountingMsgTracker, msg_type: AccountingMsgType) { const QUICK_RETEST_WINDOW_SIZE: u16 = 2; - let mut new_charges_feeds_per_msg = - generate_new_charge_feeds_representing_msgs(QUICK_RETEST_WINDOW_SIZE); - let expected_sorted_stats = - construct_expected_sorted_stats_from_generated_new_charges(&new_charges_feeds_per_msg); + let mut new_charges_feeds_per_msg = generate_msgs(QUICK_RETEST_WINDOW_SIZE); + let expected_sorted_stats = derive_expected_sorted_stats(&new_charges_feeds_per_msg); - let result = subject.process_debug_stats( + let result = subject.process_another_msg( msg_type, new_charges_feeds_per_msg.remove(0), QUICK_RETEST_WINDOW_SIZE, @@ -309,14 +370,14 @@ mod tests { assert_eq!(result, None); let result = subject - .process_debug_stats( + .process_another_msg( msg_type, new_charges_feeds_per_msg.remove(0), QUICK_RETEST_WINDOW_SIZE, ) .expect("second try: expected stats dump"); - assert_provided_loggable_stats( + assert_produced_loggable_stats( result, msg_type, QUICK_RETEST_WINDOW_SIZE, @@ -324,98 +385,137 @@ mod tests { ); } - fn generate_new_charge_feeds_representing_msgs(log_window_size: u16) -> Vec> { + fn generate_msgs(log_window_size: u16) -> Vec> { (0..log_window_size) .map(|msg_number| { (0..msg_number) .map(|new_charge_idx| { - let address = make_address(new_charge_idx as u32); - let charge = (new_charge_idx as u128 + 1) * 1234567; - NewCharge::new(address, charge) + let discriminant = msg_number + new_charge_idx; + let address = make_address(discriminant as u32); + let charge = (discriminant as u128 + 1) * 1234567; + let bytes = (discriminant as usize + 1) * 321; + NewCharge::new(address, charge, bytes) }) .collect_vec() }) .collect_vec() } - fn construct_expected_sorted_stats_from_generated_new_charges( + fn derive_expected_sorted_stats( msg_batches: &[Vec], - ) -> Vec<(Address, u128)> { + ) -> Vec<(Address, AddressStats)> { msg_batches .iter() .flatten() .fold(HashMap::new(), |mut totals, posting| { - *totals.entry(posting.address).or_default() += posting.amount_wei; + let mut entry: &mut AddressStats = totals.entry(posting.address).or_default(); + entry.wei += posting.amount_wei; + entry.bytes += posting.bytes; totals }) .into_iter() - .sorted() + .sorted_by_key(|(address, _)| *address) .collect() } #[test] - fn new_posting_debug_container_for_debug_enabled() { - let mut logger = Logger::new("test"); - logger.set_level_for_test(Level::Debug); - let container = NewChargessDebugContainer::new(&logger); - let new_charge_1 = NewCharge::new(make_address(1), 1234567); - let new_charge_2 = NewCharge::new(make_address(2), 7654321); + fn new_charge_debug_container_when_debug_not_enabled() { + let logger = Logger::new("test").set_test_log_level(Level::Info); + let container = NewChargesDebugContainer::new(&logger); + let new_charge_1 = NewCharge::new(make_address(1), 1234567, 2323); + let new_charge_2 = NewCharge::new(make_address(2), 7654321, 4545); let container = container.add_new_charge(Some(NewCharge::new( new_charge_1.address, new_charge_1.amount_wei, - ))); - let container = container.add_new_charge(Some(NewCharge::new( - new_charge_1.address, - new_charge_1.amount_wei, + new_charge_1.bytes, ))); let container = container.add_new_charge(None); let container = container.add_new_charge(Some(NewCharge::new( new_charge_2.address, new_charge_2.amount_wei, + new_charge_2.bytes, ))); - let stats: Vec = container.into(); - assert_eq!(stats, vec![new_charge_1, new_charge_1, new_charge_2]); + let collected_charges: Vec = container.into(); + assert_eq!(collected_charges, vec![]); } #[test] - fn new_posting_debug_container_for_debug_not_enabled() { - let mut logger = Logger::new("test"); - logger.set_level_for_test(Level::Info); - let container = NewChargessDebugContainer::new(&logger); - let new_charge_1 = NewCharge::new(make_address(1), 1234567); - let new_charge_2 = NewCharge::new(make_address(2), 7654321); + fn new_charge_debug_container_when_debug_is_enabled_but_trace_is_not() { + let logger = Logger::new("test").set_test_log_level(Level::Debug); + let address_1 = make_address(1); + let address_2 = make_address(2); + let container = NewChargesDebugContainer::new(&logger); + let new_charge_1 = NewCharge::new(address_1, 1234567, 5432); + let new_charge_2 = NewCharge::new(address_1, 7654321, 7890); + let new_charge_3 = NewCharge::new(address_2, 3232323, 7890); let container = container.add_new_charge(Some(NewCharge::new( new_charge_1.address, new_charge_1.amount_wei, + new_charge_1.bytes, + ))); + let container = container.add_new_charge(Some(NewCharge::new( + new_charge_2.address, + new_charge_2.amount_wei, + new_charge_2.bytes, ))); + let container = container.add_new_charge(None); + let container = container.add_new_charge(Some(NewCharge::new( + new_charge_3.address, + new_charge_3.amount_wei, + new_charge_3.bytes, + ))); + + let collected_charges: Vec = container.into(); + assert_eq!( + collected_charges, + vec![new_charge_1, new_charge_2, new_charge_3] + ); + } + + #[test] + fn new_charge_debug_container_when_trace_is_enabled() { + let logger = Logger::new("test").set_test_log_level(Level::Trace); + let address_1 = make_address(1); + let address_2 = make_address(2); + let container = NewChargesDebugContainer::new(&logger); + let new_charge_1 = NewCharge::new(address_1, 1234567, 5432); + let new_charge_2 = NewCharge::new(address_2, 7654321, 7890); + let container = container.add_new_charge(Some(NewCharge::new( new_charge_1.address, new_charge_1.amount_wei, + new_charge_1.bytes, ))); - let container = container.add_new_charge(None); let container = container.add_new_charge(Some(NewCharge::new( new_charge_2.address, new_charge_2.amount_wei, + new_charge_2.bytes, ))); - let stats: Vec = container.into(); - assert_eq!(stats, vec![]); + let collected_charges: Vec = container.into(); + assert_eq!(collected_charges, vec![]); } #[test] fn display_loggable_stats() { - let loggable_stats = LoggableStats { + let accounting_msg_stats = hashmap!(make_address(1) => AddressStats {wei: 987654, bytes: 4567}, make_address(2) => AddressStats{wei: 123456, bytes: 1234}, make_address(3) => AddressStats {wei: 987654, bytes: 1111}); + let loggable_stats = LoggableDebugStats { msg_type: AccountingMsgType::RoutingServiceProvided, - accounting_msg_stats: hashmap!(make_address(1) => 1234567, make_address(2) => 7654321), - log_window_in_pcs_of_msgs: 15, + accounting_msg_stats, + log_window_size: 15, }; + + let result = format!("{}", loggable_stats); + + // Sorted first by the amount of wei, then by the address. Both in the descending order let expected_display = "\ - Total debits across last 15 RoutingServiceProvided messages (wei):\n\ - 0x0000000000000000000001000000001000000001: 1234567\n\ - 0x0000000000000000000002000000002000000002: 7654321"; - assert_eq!(format!("{}", loggable_stats), expected_display); + Debits from last 15 RoutingServiceProvided messages [wei | bytes]:\n\ + 0x0000000000000000000003000000003000000003: 987654 | 1111\n\ + 0x0000000000000000000001000000001000000001: 987654 | 4567\n\ + 0x0000000000000000000002000000002000000002: 123456 | 1234"; + assert_eq!(result, expected_display); } } diff --git a/node/src/accountant/logging_utils/mod.rs b/node/src/accountant/logging_utils/mod.rs index a64df97d7..7e58aa40b 100644 --- a/node/src/accountant/logging_utils/mod.rs +++ b/node/src/accountant/logging_utils/mod.rs @@ -3,15 +3,15 @@ pub mod accounting_msgs_debug; pub mod msg_id_generator; -use crate::accountant::logging_utils::accounting_msgs_debug::AccountingMessageTracker; +use crate::accountant::logging_utils::accounting_msgs_debug::AccountingMsgTracker; use crate::accountant::logging_utils::msg_id_generator::{ MessageIdGenerator, MessageIdGeneratorReal, }; -const ACCOUNTING_MSG_LOG_WINDOW: u16 = 50; +const ACCOUNTING_MSG_LOG_WINDOW: u16 = 200; pub struct LoggingUtils { - pub debug_stats: AccountingMessageTracker, + pub accounting_msg_tracker: AccountingMsgTracker, pub accounting_msg_log_window: u16, pub msg_id_generator: Box, } @@ -19,7 +19,7 @@ pub struct LoggingUtils { impl Default for LoggingUtils { fn default() -> Self { Self { - debug_stats: AccountingMessageTracker::default(), + accounting_msg_tracker: AccountingMsgTracker::default(), accounting_msg_log_window: ACCOUNTING_MSG_LOG_WINDOW, msg_id_generator: Box::new(MessageIdGeneratorReal::default()), } @@ -32,7 +32,7 @@ mod tests { #[test] fn constants_have_right_values() { - assert_eq!(ACCOUNTING_MSG_LOG_WINDOW, 50); + assert_eq!(ACCOUNTING_MSG_LOG_WINDOW, 200); } #[test] diff --git a/node/src/accountant/logging_utils/msg_id_generator.rs b/node/src/accountant/logging_utils/msg_id_generator.rs index 03069b353..a45e292e5 100644 --- a/node/src/accountant/logging_utils/msg_id_generator.rs +++ b/node/src/accountant/logging_utils/msg_id_generator.rs @@ -5,7 +5,6 @@ use std::sync::atomic::Ordering; pub trait MessageIdGenerator { fn new_id(&self) -> u32; - fn last_used_id(&self) -> u32; as_any_ref_in_trait!(); } @@ -16,17 +15,9 @@ impl MessageIdGenerator for MessageIdGeneratorReal { fn new_id(&self) -> u32 { MSG_ID_INCREMENTER.fetch_add(1, Ordering::Relaxed) } - fn last_used_id(&self) -> u32 { - MSG_ID_INCREMENTER.load(Ordering::Relaxed) - 1 - } as_any_ref_in_trait_impl!(); } -pub enum MsgIdRequested { - New, - LastUsed, -} - #[cfg(test)] mod tests { use crate::accountant::logging_utils::msg_id_generator::{ @@ -63,19 +54,4 @@ mod tests { assert_eq!(id, 0) } - - #[test] - fn msg_id_generator_last_used_id() { - let _guard = MSG_ID_GENERATOR_TEST_GUARD.lock().unwrap(); - let subject = MessageIdGeneratorReal::default(); - let new_id = subject.new_id(); - - let same_id_1 = subject.last_used_id(); - let same_id_2 = subject.last_used_id(); - let new_id_2 = subject.new_id(); - - assert_eq!(new_id, same_id_1); - assert_eq!(new_id, same_id_2); - assert_eq!(new_id_2, same_id_2 + 1); - } } diff --git a/node/src/accountant/mod.rs b/node/src/accountant/mod.rs index 9c2a8c849..4da644a88 100644 --- a/node/src/accountant/mod.rs +++ b/node/src/accountant/mod.rs @@ -24,9 +24,8 @@ use crate::accountant::financials::visibility_restricted_module::{ check_query_is_within_tech_limits, financials_entry_check, }; use crate::accountant::logging_utils::accounting_msgs_debug::{ - AccountingMsgType, NewCharge, NewChargessDebugContainer, + AccountingMsgType, NewCharge, NewChargesDebugContainer, }; -use crate::accountant::logging_utils::msg_id_generator::MsgIdRequested; use crate::accountant::logging_utils::LoggingUtils; use crate::accountant::scanners::payable_scanner::msgs::{ InitialTemplatesMessage, PricedTemplatesMessage, @@ -52,11 +51,8 @@ use crate::sub_lib::accountant::FinancialStatistics; use crate::sub_lib::accountant::ReportExitServiceProvidedMessage; use crate::sub_lib::accountant::ReportRoutingServiceProvidedMessage; use crate::sub_lib::accountant::ReportServicesConsumedMessage; -use crate::sub_lib::accountant::{ - AccountableServiceWithTraceLog, DaoFactories, MessageWithServicesProvided, - RoutingServiceConsumedTraceLogWrapper, ServiceProvided, -}; use crate::sub_lib::accountant::{AccountantSubs, DetailedScanType}; +use crate::sub_lib::accountant::{DaoFactories, ServiceProvided, ServiceProvidedMsg}; use crate::sub_lib::blockchain_bridge::OutboundPaymentsInstructions; use crate::sub_lib::neighborhood::{ConfigChange, ConfigChangeMsg}; use crate::sub_lib::peer_actors::{BindMessage, StartMessage}; @@ -644,7 +640,11 @@ impl Accountant { ), Err(e) => panic!("Was recording services provided for {} but hit a fatal database error: {:?}", wallet, e) } - Some(NewCharge::new(wallet.address(), total_charge)) + Some(NewCharge::new( + wallet.address(), + total_charge, + service.payload_size, + )) } else { warning!( self.logger, @@ -681,7 +681,7 @@ impl Accountant { ), Err(e) => panic!("Recording services consumed from {} but has hit fatal database error: {:?}", wallet, e) }; - Some(NewCharge::new(wallet.address(), total_charge)) + Some(NewCharge::new(wallet.address(), total_charge, payload_size)) } else { warning!( self.logger, @@ -744,22 +744,45 @@ impl Accountant { fn handle_report_service_provided_message(&mut self, msg: AccountingMessage) where - AccountingMessage: MessageWithServicesProvided, + AccountingMessage: ServiceProvidedMsg, { - let services_provided = &msg.services_provided(); + let services_provided = msg.services_provided(); let accounting_msg_type = msg.msg_type(); let trace_log_wrapper = msg.trace_log_wrapper(); + let msg_id = self.logging_utils.msg_id_generator.new_id(); - trace_log_wrapper.log_trace(self.logging_kit(MsgIdRequested::New)); + trace_log_wrapper.maybe_log_trace(&self.logger, msg_id); let charges = self.record_service_provided(services_provided); - self.consider_logging_debug_stats(accounting_msg_type, charges.into_iter().collect_vec()); + self.maybe_log_debug_stats(accounting_msg_type, charges.into_iter().collect_vec()); } fn handle_report_services_consumed_message(&mut self, msg: ReportServicesConsumedMessage) { - msg.exit.log_trace(self.logging_kit(MsgIdRequested::New)); + let msg_id = self.logging_utils.msg_id_generator.new_id(); + + let charge_container = NewChargesDebugContainer::new(&self.logger); + + trace!( + self.logger, + "Msg {}: Accruing debt to {} for consuming {} exited bytes", + msg_id, + msg.exit.earning_wallet, + msg.exit.payload_size + ); + let charge_container = self.handle_exit_service_consumed(&msg, charge_container); + let charge_container = + self.handle_routing_services_consumed(&msg, charge_container, msg_id); + + self.maybe_log_debug_stats(AccountingMsgType::ServicesConsumed, charge_container.into()); + } + + fn handle_exit_service_consumed( + &mut self, + msg: &ReportServicesConsumedMessage, + new_charges: NewChargesDebugContainer, + ) -> NewChargesDebugContainer { let exit_charge_opt = self.record_service_consumed( msg.exit.service_rate, msg.exit.byte_rate, @@ -768,34 +791,28 @@ impl Accountant { &msg.exit.earning_wallet, ); - let new_charges_container = - NewChargessDebugContainer::new(&self.logger).add_new_charge(exit_charge_opt); - - let new_charges_container = - self.handle_routing_services_consumed(&msg, new_charges_container); - - self.consider_logging_debug_stats( - AccountingMsgType::ServicesConsumed, - new_charges_container.into(), - ); + new_charges.add_new_charge(exit_charge_opt) } fn handle_routing_services_consumed( &mut self, msg: &ReportServicesConsumedMessage, - new_charges: NewChargessDebugContainer, - ) -> NewChargessDebugContainer { + charge_container: NewChargesDebugContainer, + msg_id: u32, + ) -> NewChargesDebugContainer { msg.routing .services .iter() - .fold(new_charges, |new_charges, routing_service| { - RoutingServiceConsumedTraceLogWrapper { - service: routing_service, - routing_payload_size: msg.routing.routing_payload_size, - } - .log_trace(self.logging_kit(MsgIdRequested::LastUsed)); + .fold(charge_container, |new_charges, routing_service| { + trace!( + self.logger, + "Msg {}: Accruing debt to {} for consuming {} routed bytes", + msg_id, + routing_service.earning_wallet, + msg.routing.routing_payload_size + ); - let new_charge = self.record_service_consumed( + let new_charge_opt = self.record_service_consumed( routing_service.service_rate, routing_service.byte_rate, msg.timestamp, @@ -803,37 +820,23 @@ impl Accountant { &routing_service.earning_wallet, ); - new_charges.add_new_charge(new_charge) + new_charges.add_new_charge(new_charge_opt) }) } - fn logging_kit(&self, msg_id_requested: MsgIdRequested) -> (&Logger, u32) { - ( - &self.logger, - match msg_id_requested { - MsgIdRequested::New => self.logging_utils.msg_id_generator.new_id(), - MsgIdRequested::LastUsed => self.logging_utils.msg_id_generator.last_used_id(), - }, - ) - } - - fn consider_logging_debug_stats( - &mut self, - msg_type: AccountingMsgType, - charges: Vec, - ) { + fn maybe_log_debug_stats(&mut self, msg_type: AccountingMsgType, charges: Vec) { if charges.is_empty() { return; } let log_window_size = self.logging_utils.accounting_msg_log_window; - if self.logger.debug_enabled() { - if let Some(loggable_stats) = self.logging_utils.debug_stats.process_debug_stats( - msg_type, - charges, - log_window_size, - ) { + if self.logger.debug_enabled() && !self.logger.trace_enabled() { + if let Some(loggable_stats) = self + .logging_utils + .accounting_msg_tracker + .process_another_msg(msg_type, charges, log_window_size) + { debug!(self.logger, "{}", loggable_stats); } } @@ -2870,7 +2873,7 @@ mod tests { let test_name = "accountant_scans_after_startup_and_does_not_detect_any_pending_payables"; let scan_params = ScanParams::default(); let notify_and_notify_later_params = NotifyAndNotifyLaterParams::default(); - let time_until_next_scan_params_arc = Arc::new(Mutex::new(vec![])); + let next_scan_timing_params_arc = Arc::new(Mutex::new(vec![])); let earning_wallet = make_wallet("earning"); let consuming_wallet = make_wallet("consuming"); let system = System::new(test_name); @@ -2892,7 +2895,7 @@ mod tests { configure_accountant_for_startup_with_preexisting_pending_payables( test_name, ¬ify_and_notify_later_params, - &time_until_next_scan_params_arc, + &next_scan_timing_params_arc, config, pending_payable_scanner, receivable_scanner, @@ -2920,7 +2923,7 @@ mod tests { assert_payable_scanner_for_no_pending_payable_found( &scan_params.payable_start_scan, ¬ify_and_notify_later_params, - time_until_next_scan_params_arc, + next_scan_timing_params_arc, new_payable_expected_computed_interval, ); assert_receivable_scanner( @@ -3095,7 +3098,7 @@ mod tests { fn configure_accountant_for_startup_with_preexisting_pending_payables( test_name: &str, notify_and_notify_later_params: &NotifyAndNotifyLaterParams, - time_until_next_scan_params_arc: &Arc>>, + next_scan_timing_params_arc: &Arc>>, config: BootstrapperConfig, pending_payable_scanner: ScannerMock< RequestTransactionReceipts, @@ -3141,8 +3144,8 @@ mod tests { subject.scan_schedulers.receivable.handle = Box::new(receivable_notify_later_handle_mock); subject.scan_schedulers.receivable.interval = receivable_scan_interval; let interval_computer = NewPayableScanIntervalComputerMock::default() - .time_until_next_scan_params(&time_until_next_scan_params_arc) - .time_until_next_scan_result(ScanTiming::WaitFor( + .next_scan_timing_params(&next_scan_timing_params_arc) + .next_scan_timing_result(ScanTiming::WaitFor( new_payable_expected_computed_interval, )); subject.scan_schedulers.payable.interval_computer = Box::new(interval_computer); @@ -4496,9 +4499,10 @@ mod tests { let receivable_dao_mock = ReceivableDaoMock::new() .more_money_receivable_parameters(&more_money_receivable_parameters_arc) .more_money_receivable_result(Ok(())); + let logger = Logger::new(test_name).set_test_log_level(Level::Debug); let mut subject = AccountantBuilder::default() .bootstrapper_config(bootstrapper_config) - .logger(Logger::new(test_name)) + .logger(logger) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .receivable_daos(vec![ForAccountantBody(receivable_dao_mock)]) .build(); @@ -4531,13 +4535,18 @@ mod tests { more_money_receivable_parameters[0], (now, make_wallet("booga"), (1 * 42) + (1234 * 24)) ); - TestLogHandler::new() - .exists_log_containing(&format!("DEBUG: {test_name}: Total debits across last ")); + TestLogHandler::new().exists_log_containing(&format!( + "DEBUG: {test_name}: \ + Debits from last 1 RoutingServiceProvided messages [wei | bytes]:\n\ + 0x000000000000000000000000000000626f6f6761: 29658 | 1234" + )); } #[test] fn report_routing_service_provided_message_is_received_from_our_consuming_wallet() { init_test_logging(); + let test_name = + "report_routing_service_provided_message_is_received_from_our_consuming_wallet"; let consuming_wallet = make_wallet("our consuming wallet"); let config = bc_from_wallets(consuming_wallet.clone(), make_wallet("our earning wallet")); let more_money_receivable_parameters_arc = Arc::new(Mutex::new(vec![])); @@ -4546,10 +4555,11 @@ mod tests { .more_money_receivable_parameters(&more_money_receivable_parameters_arc); let subject = AccountantBuilder::default() .bootstrapper_config(config) + .logger(Logger::new(test_name)) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .receivable_daos(vec![ForAccountantBody(receivable_dao_mock)]) .build(); - let system = System::new("report_routing_service_message_is_received"); + let system = System::new(test_name); let subject_addr: Addr = subject.start(); subject_addr .try_send(BindMessage { @@ -4577,7 +4587,7 @@ mod tests { .is_empty()); TestLogHandler::new().exists_log_containing(&format!( - "WARN: Accountant: Declining to record a receivable against our wallet {} for services we provided", + "WARN: {test_name}: Declining to record a receivable against our wallet {} for services we provided", consuming_wallet, )); } @@ -4585,6 +4595,8 @@ mod tests { #[test] fn report_routing_service_provided_message_is_received_from_our_earning_wallet() { init_test_logging(); + let test_name = + "report_routing_service_provided_message_is_received_from_our_earning_wallet"; let earning_wallet = make_wallet("our earning wallet"); let config = bc_from_earning_wallet(earning_wallet.clone()); let more_money_receivable_parameters_arc = Arc::new(Mutex::new(vec![])); @@ -4593,10 +4605,11 @@ mod tests { .more_money_receivable_parameters(&more_money_receivable_parameters_arc); let subject = AccountantBuilder::default() .bootstrapper_config(config) + .logger(Logger::new(test_name)) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .receivable_daos(vec![ForAccountantBody(receivable_dao_mock)]) .build(); - let system = System::new("report_routing_service_message_is_received"); + let system = System::new(test_name); let subject_addr: Addr = subject.start(); subject_addr .try_send(BindMessage { @@ -4624,7 +4637,7 @@ mod tests { .is_empty()); TestLogHandler::new().exists_log_containing(&format!( - "WARN: Accountant: Declining to record a receivable against our wallet {} for services we provided", + "WARN: {test_name}: Declining to record a receivable against our wallet {} for services we provided", earning_wallet, )); } @@ -4640,9 +4653,10 @@ mod tests { let receivable_dao_mock = ReceivableDaoMock::new() .more_money_receivable_parameters(&more_money_receivable_parameters_arc) .more_money_receivable_result(Ok(())); + let logger = Logger::new(test_name).set_test_log_level(Level::Debug); let mut subject = AccountantBuilder::default() .bootstrapper_config(config) - .logger(Logger::new(test_name)) + .logger(logger) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .receivable_daos(vec![ForAccountantBody(receivable_dao_mock)]) .build(); @@ -4675,13 +4689,18 @@ mod tests { more_money_receivable_parameters[0], (now, make_wallet("booga"), (1 * 42) + (1234 * 24)) ); - TestLogHandler::new() - .exists_log_containing(&format!("DEBUG: {test_name}: Total debits across last ")); + TestLogHandler::new().exists_log_containing(&format!( + "DEBUG: {test_name}: \ + Debits from last 1 ExitServiceProvided messages [wei | bytes]:\n\ + 0x000000000000000000000000000000626f6f6761: 29658 | 1234" + )); } #[test] fn report_exit_service_provided_message_is_received_from_our_consuming_wallet() { init_test_logging(); + let test_name = + "report_exit_service_provided_message_is_received_from_our_consuming_wallet"; let consuming_wallet = make_wallet("my consuming wallet"); let config = bc_from_wallets(consuming_wallet.clone(), make_wallet("my earning wallet")); let more_money_receivable_parameters_arc = Arc::new(Mutex::new(vec![])); @@ -4690,10 +4709,11 @@ mod tests { .more_money_receivable_parameters(&more_money_receivable_parameters_arc); let subject = AccountantBuilder::default() .bootstrapper_config(config) + .logger(Logger::new(test_name)) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .receivable_daos(vec![ForAccountantBody(receivable_dao_mock)]) .build(); - let system = System::new("report_exit_service_provided_message_is_received"); + let system = System::new(test_name); let subject_addr: Addr = subject.start(); subject_addr .try_send(BindMessage { @@ -4721,7 +4741,7 @@ mod tests { .is_empty()); TestLogHandler::new().exists_log_containing(&format!( - "WARN: Accountant: Declining to record a receivable against our wallet {} for services we provided", + "WARN: {test_name}: Declining to record a receivable against our wallet {} for services we provided", consuming_wallet )); } @@ -4729,6 +4749,7 @@ mod tests { #[test] fn report_exit_service_provided_message_is_received_from_our_earning_wallet() { init_test_logging(); + let test_name = "report_exit_service_provided_message_is_received_from_our_earning_wallet"; let earning_wallet = make_wallet("my earning wallet"); let config = bc_from_earning_wallet(earning_wallet.clone()); let more_money_receivable_parameters_arc = Arc::new(Mutex::new(vec![])); @@ -4737,10 +4758,11 @@ mod tests { .more_money_receivable_parameters(&more_money_receivable_parameters_arc); let subject = AccountantBuilder::default() .bootstrapper_config(config) + .logger(Logger::new(test_name)) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .receivable_daos(vec![ForAccountantBody(receivable_dao_mock)]) .build(); - let system = System::new("report_exit_service_provided_message_is_received"); + let system = System::new(test_name); let subject_addr: Addr = subject.start(); subject_addr .try_send(BindMessage { @@ -4768,7 +4790,7 @@ mod tests { .is_empty()); TestLogHandler::new().exists_log_containing(&format!( - "WARN: Accountant: Declining to record a receivable against our wallet {} for services we provided", + "WARN: {test_name}: Declining to record a receivable against our wallet {} for services we provided", earning_wallet, )); } @@ -4784,13 +4806,14 @@ mod tests { .more_money_payable_result(Ok(())) .more_money_payable_result(Ok(())) .more_money_payable_result(Ok(())); + let logger = Logger::new(test_name).set_test_log_level(Level::Debug); let mut subject = AccountantBuilder::default() .bootstrapper_config(config) - .logger(Logger::new(test_name)) + .logger(logger) .payable_daos(vec![ForAccountantBody(payable_dao_mock)]) .build(); subject.logging_utils.accounting_msg_log_window = 1; - let system = System::new("report_services_consumed_message_is_received"); + let system = System::new(test_name); let subject_addr: Addr = subject.start(); subject_addr .try_send(BindMessage { @@ -4851,8 +4874,13 @@ mod tests { ) ] ); - TestLogHandler::new() - .exists_log_containing(&format!("DEBUG: {test_name}: Total debits across last ")); + TestLogHandler::new().exists_log_containing(&format!( + "DEBUG: {test_name}: \ + Debits from last 1 ServicesConsumed messages [wei | bytes]:\n\ + 0x0000000000000000000000726f7574696e672032: 114100 | 3456\n\ + 0x0000000000000000000000726f7574696e672031: 82986 | 3456\n\ + 0x0000000000000000000000000000000065786974: 36120 | 1200" + )); } fn assert_that_we_do_not_charge_our_own_wallet_for_consumed_services( @@ -5575,7 +5603,7 @@ mod tests { let test_name = "accountant_confirms_all_pending_txs_and_schedules_new_payable_scanner_timely"; let finish_scan_params_arc = Arc::new(Mutex::new(vec![])); - let time_until_next_scan_params_arc = Arc::new(Mutex::new(vec![])); + let next_scan_timing_params_arc = Arc::new(Mutex::new(vec![])); let new_payable_notify_later_arc = Arc::new(Mutex::new(vec![])); let new_payable_notify_arc = Arc::new(Mutex::new(vec![])); let system = System::new("new_payable_scanner_timely"); @@ -5592,9 +5620,9 @@ mod tests { ))); let expected_computed_interval = Duration::from_secs(3); let interval_computer = NewPayableScanIntervalComputerMock::default() - .time_until_next_scan_params(&time_until_next_scan_params_arc) + .next_scan_timing_params(&next_scan_timing_params_arc) // This determines the test - .time_until_next_scan_result(ScanTiming::WaitFor(expected_computed_interval)); + .next_scan_timing_result(ScanTiming::WaitFor(expected_computed_interval)); subject.scan_schedulers.payable.interval_computer = Box::new(interval_computer); subject.scan_schedulers.payable.new_payable_notify_later = Box::new( NotifyLaterHandleMock::default().notify_later_params(&new_payable_notify_later_arc), @@ -5652,7 +5680,7 @@ mod tests { let test_name = "accountant_confirms_payable_txs_and_schedules_the_delayed_new_payable_scanner_asap"; let finish_scan_params_arc = Arc::new(Mutex::new(vec![])); - let time_until_next_scan_params_arc = Arc::new(Mutex::new(vec![])); + let next_scan_timing_params_arc = Arc::new(Mutex::new(vec![])); let new_payable_notify_later_arc = Arc::new(Mutex::new(vec![])); let new_payable_notify_arc = Arc::new(Mutex::new(vec![])); let mut subject = AccountantBuilder::default() @@ -5667,9 +5695,9 @@ mod tests { pending_payable_scanner, ))); let interval_computer = NewPayableScanIntervalComputerMock::default() - .time_until_next_scan_params(&time_until_next_scan_params_arc) + .next_scan_timing_params(&next_scan_timing_params_arc) // This determines the test - .time_until_next_scan_result(ScanTiming::ReadyNow); + .next_scan_timing_result(ScanTiming::ReadyNow); subject.scan_schedulers.payable.interval_computer = Box::new(interval_computer); subject.scan_schedulers.payable.new_payable_notify_later = Box::new( NotifyLaterHandleMock::default().notify_later_params(&new_payable_notify_later_arc), @@ -5704,8 +5732,8 @@ mod tests { "Should be empty but {:?}", finish_scan_params ); - let time_until_next_scan_params = time_until_next_scan_params_arc.lock().unwrap(); - assert_eq!(*time_until_next_scan_params, vec![()]); + let next_scan_timing_params = next_scan_timing_params_arc.lock().unwrap(); + assert_eq!(*next_scan_timing_params, vec![()]); let new_payable_notify_later = new_payable_notify_later_arc.lock().unwrap(); assert!( new_payable_notify_later.is_empty(), @@ -5756,7 +5784,7 @@ mod tests { }), }]); let left_side_bound = if let ScanTiming::WaitFor(interval) = - assertion_interval_computer.time_until_next_scan() + assertion_interval_computer.next_scan_timing() { interval } else { @@ -5770,7 +5798,7 @@ mod tests { let new_payable_notify_later = new_payable_notify_later_arc.lock().unwrap(); let (_, actual_interval) = new_payable_notify_later[0]; let right_side_bound = if let ScanTiming::WaitFor(interval) = - assertion_interval_computer.time_until_next_scan() + assertion_interval_computer.next_scan_timing() { interval } else { @@ -5949,7 +5977,7 @@ mod tests { let notify_later_params_arc = Arc::new(Mutex::new(vec![])); scan_schedulers.payable.interval_computer = Box::new( NewPayableScanIntervalComputerMock::default() - .time_until_next_scan_result(ScanTiming::WaitFor(Duration::from_secs(152))), + .next_scan_timing_result(ScanTiming::WaitFor(Duration::from_secs(152))), ); scan_schedulers.payable.new_payable_notify_later = Box::new( NotifyLaterHandleMock::default().notify_later_params(¬ify_later_params_arc), @@ -7028,81 +7056,72 @@ mod tests { } #[test] - fn accounts_stats_are_logged_only_if_debug_enabled() { + fn accounts_stats_are_not_logged_if_debug_is_not_enabled() { init_test_logging(); - let test_name = "accounts_stats_are_logged_only_if_debug_enabled"; - let mut logger = Logger::new(test_name); - logger.set_level_for_test(Level::Debug); + let test_name = "accounts_stats_are_not_logged_if_debug_is_not_enabled"; + let logger = Logger::new("test").set_test_log_level(Level::Info); let mut subject = AccountantBuilder::default().logger(logger).build(); subject.logging_utils.accounting_msg_log_window = 1; - let new_charge_1 = NewCharge::new(make_address(1), 1234567); - let new_charge_2 = NewCharge::new(make_address(2), 7654321); + let new_charge_1 = NewCharge::new(make_address(1), 1234567, 4444); + let new_charge_2 = NewCharge::new(make_address(2), 7654321, 5555); - subject.consider_logging_debug_stats( + subject.maybe_log_debug_stats( AccountingMsgType::ServicesConsumed, vec![new_charge_1, new_charge_2], ); - TestLogHandler::new() - .exists_log_containing(&format!("DEBUG: {test_name}: Total debits across last")); + TestLogHandler::new().exists_no_log_containing(&format!("DEBUG: {test_name}:")); } #[test] - fn accounts_stats_are_not_logged_if_debug_is_not_enabled() { + fn accounts_debug_stats_are_logged_if_debug_enabled_and_trace_not_enabled() { init_test_logging(); - let test_name = "accounts_stats_are_not_logged_if_debug_is_not_enabled"; - let mut logger = Logger::new("test"); - logger.set_level_for_test(Level::Info); + let test_name = "accounts_debug_stats_are_logged_if_debug_enabled_and_trace_not_enabled"; + let logger = Logger::new(test_name).set_test_log_level(Level::Debug); let mut subject = AccountantBuilder::default().logger(logger).build(); subject.logging_utils.accounting_msg_log_window = 1; - let new_charge_1 = NewCharge::new(make_address(1), 1234567); - let new_charge_2 = NewCharge::new(make_address(2), 7654321); + let new_charge_1 = NewCharge::new(make_address(1), 1234567, 444); + let new_charge_2 = NewCharge::new(make_address(2), 7654321, 555); - subject.consider_logging_debug_stats( + subject.maybe_log_debug_stats( AccountingMsgType::ServicesConsumed, vec![new_charge_1, new_charge_2], ); - TestLogHandler::new().exists_no_log_containing(&format!("DEBUG: {test_name}:")); + TestLogHandler::new() + .exists_log_containing(&format!("DEBUG: {test_name}: Debits from last")); } #[test] - fn accounts_stats_are_not_produced_for_empty_charges() { + fn accounts_debug_stats_are_not_logged_if_trace_enabled() { init_test_logging(); - let test_name = "accounts_stats_are_not_produced_for_empty_charges"; - let mut logger = Logger::new("test"); - logger.set_level_for_test(Level::Debug); + let test_name = "accounts_debug_stats_are_not_logged_if_trace_enabled"; + let logger = Logger::new(test_name).set_test_log_level(Level::Trace); let mut subject = AccountantBuilder::default().logger(logger).build(); subject.logging_utils.accounting_msg_log_window = 1; + let new_charge_1 = NewCharge::new(make_address(1), 1234567, 444); + let new_charge_2 = NewCharge::new(make_address(2), 7654321, 555); - subject.consider_logging_debug_stats(AccountingMsgType::ServicesConsumed, vec![]); + subject.maybe_log_debug_stats( + AccountingMsgType::ServicesConsumed, + vec![new_charge_1, new_charge_2], + ); - TestLogHandler::new().exists_no_log_containing(&format!("DEBUG: {test_name}:")); + TestLogHandler::new() + .exists_no_log_containing(&format!("DEBUG: {test_name}: Debits from last")); } #[test] - fn logging_kit_works() { - let test_name = "logging_kit_works"; - let subject = AccountantBuilder::default() - .logger(Logger::new(test_name)) - .build(); + fn accounts_stats_are_not_produced_for_empty_charges() { + init_test_logging(); + let test_name = "accounts_stats_are_not_produced_for_empty_charges"; + let logger = Logger::new("test").set_test_log_level(Level::Debug); + let mut subject = AccountantBuilder::default().logger(logger).build(); + subject.logging_utils.accounting_msg_log_window = 1; - let (logger_1, id_1) = subject.logging_kit(MsgIdRequested::New); - let (logger_2, id_2) = subject.logging_kit(MsgIdRequested::New); - let (logger_3, id_3) = subject.logging_kit(MsgIdRequested::LastUsed); - let (logger_4, id_4) = subject.logging_kit(MsgIdRequested::New); + subject.maybe_log_debug_stats(AccountingMsgType::ServicesConsumed, vec![]); - assert_ne!(id_1, id_2); - assert_eq!(id_2, id_3); - assert_ne!(id_3, id_4); - let test_log_handler = TestLogHandler::new(); - vec![logger_1, logger_2, logger_3, logger_4] - .into_iter() - .enumerate() - .for_each(|(idx, logger)| { - debug!(logger, "idx: {idx}"); - test_log_handler.exists_log_containing(&format!("DEBUG: {test_name}: idx: {idx}")); - }); + TestLogHandler::new().exists_no_log_containing(&format!("DEBUG: {test_name}:")); } #[test] diff --git a/node/src/accountant/scanners/payable_scanner/tx_templates/priced/new.rs b/node/src/accountant/scanners/payable_scanner/tx_templates/priced/new.rs index 6de54e4c9..47d9d6053 100644 --- a/node/src/accountant/scanners/payable_scanner/tx_templates/priced/new.rs +++ b/node/src/accountant/scanners/payable_scanner/tx_templates/priced/new.rs @@ -4,7 +4,7 @@ use crate::accountant::scanners::payable_scanner::tx_templates::initial::new::{ NewTxTemplate, NewTxTemplates, }; use crate::accountant::scanners::payable_scanner::tx_templates::BaseTxTemplate; -use crate::blockchain::blockchain_bridge::increase_gas_price_by_margin; +use crate::blockchain::blockchain_bridge::apply_gas_price_buffer; use masq_lib::logger::Logger; use std::ops::Deref; use thousands::Separable; @@ -63,7 +63,7 @@ impl PricedNewTxTemplates { ceil: u128, logger: &Logger, ) -> Self { - let computed_gas_price_wei = increase_gas_price_by_margin(latest_gas_price_wei); + let computed_gas_price_wei = apply_gas_price_buffer(latest_gas_price_wei); let safe_gas_price_wei = if computed_gas_price_wei > ceil { warning!( diff --git a/node/src/accountant/scanners/payable_scanner/tx_templates/priced/retry.rs b/node/src/accountant/scanners/payable_scanner/tx_templates/priced/retry.rs index 48e41f4b9..e6f8d70e9 100644 --- a/node/src/accountant/scanners/payable_scanner/tx_templates/priced/retry.rs +++ b/node/src/accountant/scanners/payable_scanner/tx_templates/priced/retry.rs @@ -4,7 +4,7 @@ use crate::accountant::scanners::payable_scanner::tx_templates::initial::retry:: RetryTxTemplate, RetryTxTemplates, }; use crate::accountant::scanners::payable_scanner::tx_templates::BaseTxTemplate; -use crate::blockchain::blockchain_bridge::increase_gas_price_by_margin; +use crate::blockchain::blockchain_bridge::apply_gas_price_buffer; use masq_lib::logger::Logger; use std::ops::{Deref, DerefMut}; use thousands::Separable; @@ -49,7 +49,7 @@ impl PricedRetryTxTemplate { fn compute_gas_price(latest_gas_price_wei: u128, prev_gas_price_wei: u128) -> u128 { let gas_price_wei = latest_gas_price_wei.max(prev_gas_price_wei); - increase_gas_price_by_margin(gas_price_wei) + apply_gas_price_buffer(gas_price_wei) } } diff --git a/node/src/accountant/scanners/scan_schedulers.rs b/node/src/accountant/scanners/scan_schedulers.rs index 97a3edd62..6825bbefe 100644 --- a/node/src/accountant/scanners/scan_schedulers.rs +++ b/node/src/accountant/scanners/scan_schedulers.rs @@ -99,7 +99,7 @@ impl PayableScanScheduler { } pub fn schedule_new_payable_scan(&self, ctx: &mut Context, logger: &Logger) { - if let ScanTiming::WaitFor(interval) = self.interval_computer.time_until_next_scan() { + if let ScanTiming::WaitFor(interval) = self.interval_computer.next_scan_timing() { debug!( logger, "Scheduling a new-payable scan in {}ms", @@ -153,7 +153,7 @@ impl PayableScanScheduler { } pub trait NewPayableScanIntervalComputer { - fn time_until_next_scan(&self) -> ScanTiming; + fn next_scan_timing(&self) -> ScanTiming; fn reset_last_scan_timestamp(&mut self); @@ -167,7 +167,7 @@ pub struct NewPayableScanIntervalComputerReal { } impl NewPayableScanIntervalComputer for NewPayableScanIntervalComputerReal { - fn time_until_next_scan(&self) -> ScanTiming { + fn next_scan_timing(&self) -> ScanTiming { let current_time = self.clock.now(); let time_since_last_scan = current_time .duration_since(self.last_scan_timestamp) @@ -469,7 +469,7 @@ mod tests { subject.scan_interval = standard_interval; subject.last_scan_timestamp = past_instant; - let result = subject.time_until_next_scan(); + let result = subject.next_scan_timing(); assert_eq!( result, @@ -504,7 +504,7 @@ mod tests { subject.scan_interval = standard_interval; subject.last_scan_timestamp = past_instant; - let result = subject.time_until_next_scan(); + let result = subject.next_scan_timing(); assert_eq!( result, @@ -524,7 +524,7 @@ mod tests { subject.scan_interval = Duration::from_secs(180); subject.clock = Box::new(SimpleClockMock::default().now_result(now)); - let result = subject.time_until_next_scan(); + let result = subject.next_scan_timing(); assert_eq!( result, @@ -570,7 +570,7 @@ mod tests { subject.clock = Box::new(SimpleClockMock::default().now_result(now)); subject.last_scan_timestamp = now.checked_add(Duration::from_secs(1)).unwrap(); - let _ = subject.time_until_next_scan(); + let _ = subject.next_scan_timing(); } #[test] diff --git a/node/src/accountant/scanners/test_utils.rs b/node/src/accountant/scanners/test_utils.rs index 08325dedc..139d8fb1b 100644 --- a/node/src/accountant/scanners/test_utils.rs +++ b/node/src/accountant/scanners/test_utils.rs @@ -336,15 +336,15 @@ impl ScannerMockMarker for ScannerMock>>, - time_until_next_scan_results: RefCell>, + next_scan_timing_params: Arc>>, + next_scan_timing_results: RefCell>, reset_last_scan_timestamp_params: Arc>>, } impl NewPayableScanIntervalComputer for NewPayableScanIntervalComputerMock { - fn time_until_next_scan(&self) -> ScanTiming { - self.time_until_next_scan_params.lock().unwrap().push(()); - self.time_until_next_scan_results.borrow_mut().remove(0) + fn next_scan_timing(&self) -> ScanTiming { + self.next_scan_timing_params.lock().unwrap().push(()); + self.next_scan_timing_results.borrow_mut().remove(0) } fn reset_last_scan_timestamp(&mut self) { @@ -358,13 +358,13 @@ impl NewPayableScanIntervalComputer for NewPayableScanIntervalComputerMock { } impl NewPayableScanIntervalComputerMock { - pub fn time_until_next_scan_params(mut self, params: &Arc>>) -> Self { - self.time_until_next_scan_params = params.clone(); + pub fn next_scan_timing_params(mut self, params: &Arc>>) -> Self { + self.next_scan_timing_params = params.clone(); self } - pub fn time_until_next_scan_result(self, result: ScanTiming) -> Self { - self.time_until_next_scan_results.borrow_mut().push(result); + pub fn next_scan_timing_result(self, result: ScanTiming) -> Self { + self.next_scan_timing_results.borrow_mut().push(result); self } diff --git a/node/src/accountant/test_utils.rs b/node/src/accountant/test_utils.rs index 8b9611910..ebda60222 100644 --- a/node/src/accountant/test_utils.rs +++ b/node/src/accountant/test_utils.rs @@ -1478,10 +1478,6 @@ impl MessageIdGenerator for MessageIdGeneratorMock { fn new_id(&self) -> u32 { self.ids.borrow_mut().remove(0) } - - fn last_used_id(&self) -> u32 { - todo!() - } } impl MessageIdGeneratorMock { diff --git a/node/src/blockchain/blockchain_agent/agent_web3.rs b/node/src/blockchain/blockchain_agent/agent_web3.rs index 66df08d57..f65813cfc 100644 --- a/node/src/blockchain/blockchain_agent/agent_web3.rs +++ b/node/src/blockchain/blockchain_agent/agent_web3.rs @@ -118,7 +118,7 @@ mod tests { BlockchainAgentWeb3, WEB3_MAXIMAL_GAS_LIMIT_MARGIN, }; use crate::blockchain::blockchain_agent::BlockchainAgent; - use crate::blockchain::blockchain_bridge::increase_gas_price_by_margin; + use crate::blockchain::blockchain_bridge::apply_gas_price_buffer; use crate::test_utils::make_wallet; use itertools::{Either, Itertools}; use masq_lib::blockchains::chains::Chain; @@ -155,7 +155,7 @@ mod tests { let result = subject.price_qualified_payables(Either::Left(new_tx_templates.clone())); - let gas_price_with_margin_wei = increase_gas_price_by_margin(rpc_gas_price_wei); + let gas_price_with_margin_wei = apply_gas_price_buffer(rpc_gas_price_wei); let expected_result = Either::Left(PricedNewTxTemplates::new( new_tx_templates, gas_price_with_margin_wei, @@ -206,11 +206,11 @@ mod tests { let expected_result = { let price_wei_for_accounts_from_1_to_5 = vec![ - increase_gas_price_by_margin(rpc_gas_price_wei), - increase_gas_price_by_margin(rpc_gas_price_wei), - increase_gas_price_by_margin(rpc_gas_price_wei + 1), - increase_gas_price_by_margin(rpc_gas_price_wei), - increase_gas_price_by_margin(rpc_gas_price_wei + 456_789), + apply_gas_price_buffer(rpc_gas_price_wei), + apply_gas_price_buffer(rpc_gas_price_wei), + apply_gas_price_buffer(rpc_gas_price_wei + 1), + apply_gas_price_buffer(rpc_gas_price_wei), + apply_gas_price_buffer(rpc_gas_price_wei + 456_789), ]; if price_wei_for_accounts_from_1_to_5.len() != retry_tx_templates.len() { panic!("Corrupted test") @@ -240,7 +240,7 @@ mod tests { // Adding just 1 didn't work, therefore 2 let rpc_gas_price_wei = ((ceiling_gas_price_wei * 100) / (DEFAULT_GAS_PRICE_MARGIN as u128 + 100)) + 2; - let check_value_wei = increase_gas_price_by_margin(rpc_gas_price_wei); + let check_value_wei = apply_gas_price_buffer(rpc_gas_price_wei); test_gas_price_must_not_break_through_ceiling_value_in_the_new_payable_mode( test_name, @@ -341,7 +341,7 @@ mod tests { // Adding just 1 didn't work, therefore 2 let rpc_gas_price_wei = (ceiling_gas_price_wei * 100) / (DEFAULT_GAS_PRICE_MARGIN as u128 + 100) + 2; - let check_value_wei = increase_gas_price_by_margin(rpc_gas_price_wei); + let check_value_wei = apply_gas_price_buffer(rpc_gas_price_wei); let template_1 = RetryTxTemplateBuilder::new() .payable_account(&account_1) .prev_gas_price_wei(rpc_gas_price_wei - 1) @@ -386,7 +386,7 @@ mod tests { let border_gas_price_wei = (ceiling_gas_price_wei * 100) / (DEFAULT_GAS_PRICE_MARGIN as u128 + 100) + 2; let rpc_gas_price_wei = border_gas_price_wei - 1; - let check_value_wei = increase_gas_price_by_margin(border_gas_price_wei); + let check_value_wei = apply_gas_price_buffer(border_gas_price_wei); let template_1 = RetryTxTemplateBuilder::new() .payable_account(&account_1) .prev_gas_price_wei(border_gas_price_wei) @@ -603,7 +603,7 @@ mod tests { assert_eq!( result, (2 * (77_777 + WEB3_MAXIMAL_GAS_LIMIT_MARGIN)) - * increase_gas_price_by_margin(444_555_666) + * apply_gas_price_buffer(444_555_666) ); } @@ -646,11 +646,11 @@ mod tests { let result = subject.estimate_transaction_fee_total(&priced_qualified_payables); let gas_prices_for_accounts_from_1_to_5 = vec![ - increase_gas_price_by_margin(rpc_gas_price_wei), - increase_gas_price_by_margin(rpc_gas_price_wei), - increase_gas_price_by_margin(rpc_gas_price_wei + 1), - increase_gas_price_by_margin(rpc_gas_price_wei), - increase_gas_price_by_margin(rpc_gas_price_wei + 456_789), + apply_gas_price_buffer(rpc_gas_price_wei), + apply_gas_price_buffer(rpc_gas_price_wei), + apply_gas_price_buffer(rpc_gas_price_wei + 1), + apply_gas_price_buffer(rpc_gas_price_wei), + apply_gas_price_buffer(rpc_gas_price_wei + 456_789), ]; let expected_result = gas_prices_for_accounts_from_1_to_5 .into_iter() diff --git a/node/src/blockchain/blockchain_bridge.rs b/node/src/blockchain/blockchain_bridge.rs index 183f58659..8e2327b95 100644 --- a/node/src/blockchain/blockchain_bridge.rs +++ b/node/src/blockchain/blockchain_bridge.rs @@ -538,7 +538,7 @@ struct PendingTxInfo { when_sent: SystemTime, } -pub fn increase_gas_price_by_margin(gas_price: u128) -> u128 { +pub fn apply_gas_price_buffer(gas_price: u128) -> u128 { (gas_price * (100 + DEFAULT_GAS_PRICE_MARGIN as u128)) / 100 } @@ -771,7 +771,7 @@ mod tests { let accountant_received_payment = accountant_recording_arc.lock().unwrap(); let blockchain_agent_with_context_msg_actual: &PricedTemplatesMessage = accountant_received_payment.get_record(0); - let computed_gas_price_wei = increase_gas_price_by_margin(0x230000000); + let computed_gas_price_wei = apply_gas_price_buffer(0x230000000); let expected_tx_templates = tx_templates .iter() .map(|tx_template| PricedNewTxTemplate { @@ -2224,8 +2224,8 @@ mod tests { } #[test] - fn increase_gas_price_by_margin_works() { - assert_eq!(increase_gas_price_by_margin(1_000_000_000), 1_300_000_000); - assert_eq!(increase_gas_price_by_margin(9_000_000_000), 11_700_000_000); + fn apply_gas_price_buffer_works() { + assert_eq!(apply_gas_price_buffer(1_000_000_000), 1_300_000_000); + assert_eq!(apply_gas_price_buffer(9_000_000_000), 11_700_000_000); } } diff --git a/node/src/blockchain/blockchain_interface/blockchain_interface_web3/mod.rs b/node/src/blockchain/blockchain_interface/blockchain_interface_web3/mod.rs index 9249c6ee0..48fe94ad8 100644 --- a/node/src/blockchain/blockchain_interface/blockchain_interface_web3/mod.rs +++ b/node/src/blockchain/blockchain_interface/blockchain_interface_web3/mod.rs @@ -469,7 +469,7 @@ mod tests { use super::*; use crate::accountant::scanners::pending_payable_scanner::utils::TxHashByTable; use crate::accountant::test_utils::make_payable_account; - use crate::blockchain::blockchain_bridge::increase_gas_price_by_margin; + use crate::blockchain::blockchain_bridge::apply_gas_price_buffer; use crate::blockchain::blockchain_interface::blockchain_interface_web3::{ BlockchainInterfaceWeb3, CONTRACT_ABI, REQUESTS_IN_PARALLEL, TRANSACTION_LITERAL, TRANSFER_METHOD_ID, @@ -884,7 +884,7 @@ mod tests { let gas_price_wei_from_rpc_u128_wei = u128::from_str_radix(&gas_price_wei_from_rpc_hex[2..], 16).unwrap(); let gas_price_wei_from_rpc_u128_wei_with_margin = - increase_gas_price_by_margin(gas_price_wei_from_rpc_u128_wei); + apply_gas_price_buffer(gas_price_wei_from_rpc_u128_wei); let expected_result = Either::Left(PricedNewTxTemplates::new( tx_templates.clone(), gas_price_wei_from_rpc_u128_wei_with_margin, @@ -919,11 +919,11 @@ mod tests { let retry_tx_templates = RetryTxTemplates(vec![retry_1.clone(), retry_2.clone(), retry_3.clone()]); let expected_retry_tx_templates = PricedRetryTxTemplates(vec![ - PricedRetryTxTemplate::new(retry_1, increase_gas_price_by_margin(gas_price_from_rpc)), - PricedRetryTxTemplate::new(retry_2, increase_gas_price_by_margin(gas_price_from_rpc)), + PricedRetryTxTemplate::new(retry_1, apply_gas_price_buffer(gas_price_from_rpc)), + PricedRetryTxTemplate::new(retry_2, apply_gas_price_buffer(gas_price_from_rpc)), PricedRetryTxTemplate::new( retry_3, - increase_gas_price_by_margin(gas_price_from_rpc + 1), + apply_gas_price_buffer(gas_price_from_rpc + 1), ), ]); diff --git a/node/src/blockchain/blockchain_interface_initializer.rs b/node/src/blockchain/blockchain_interface_initializer.rs index 04838f312..d7c1706df 100644 --- a/node/src/blockchain/blockchain_interface_initializer.rs +++ b/node/src/blockchain/blockchain_interface_initializer.rs @@ -47,7 +47,7 @@ mod tests { use crate::accountant::scanners::payable_scanner::tx_templates::initial::new::NewTxTemplates; use crate::accountant::scanners::payable_scanner::tx_templates::priced::new::PricedNewTxTemplates; use crate::accountant::test_utils::make_payable_account; - use crate::blockchain::blockchain_bridge::increase_gas_price_by_margin; + use crate::blockchain::blockchain_bridge::apply_gas_price_buffer; use crate::blockchain::blockchain_interface_initializer::BlockchainInterfaceInitializer; use crate::test_utils::make_wallet; use futures::Future; @@ -88,7 +88,7 @@ mod tests { .unwrap(); assert_eq!(blockchain_agent.consuming_wallet(), &payable_wallet); let result = blockchain_agent.price_qualified_payables(Either::Left(tx_templates.clone())); - let gas_price_with_margin = increase_gas_price_by_margin(1_000_000_000); + let gas_price_with_margin = apply_gas_price_buffer(1_000_000_000); let expected_result = Either::Left(PricedNewTxTemplates::new( tx_templates, gas_price_with_margin, diff --git a/node/src/sub_lib/accountant.rs b/node/src/sub_lib/accountant.rs index 4d23faaf8..3d9acf5c2 100644 --- a/node/src/sub_lib/accountant.rs +++ b/node/src/sub_lib/accountant.rs @@ -126,17 +126,10 @@ impl SubsFactory for AccountantSubsFactoryReal { } } -pub trait AccountableServiceWithTraceLog { - fn log_trace(&self, (logger, msg_id): (&Logger, u32)) { - logger.trace(|| self.trace_log_msg(msg_id)) - } - fn trace_log_msg(&self, msg_id: u32) -> String; -} - -pub trait MessageWithServicesProvided { +pub trait ServiceProvidedMsg { fn services_provided(&self) -> &ServiceProvided; fn msg_type(&self) -> AccountingMsgType; - fn trace_log_wrapper(&self) -> ServiceProvidedTraceLogWrapper<'_>; + fn trace_log_wrapper(&self) -> ServiceTraceLogWrapper<'_>; } #[derive(Clone, PartialEq, Eq, Debug, Message)] @@ -144,7 +137,7 @@ pub struct ReportExitServiceProvidedMessage { pub service: ServiceProvided, } -impl MessageWithServicesProvided for ReportExitServiceProvidedMessage { +impl ServiceProvidedMsg for ReportExitServiceProvidedMessage { fn services_provided(&self) -> &ServiceProvided { &self.service } @@ -153,8 +146,8 @@ impl MessageWithServicesProvided for ReportExitServiceProvidedMessage { AccountingMsgType::ExitServiceProvided } - fn trace_log_wrapper(&self) -> ServiceProvidedTraceLogWrapper<'_> { - ServiceProvidedTraceLogWrapper::ExitServiceProvided(&self.service) + fn trace_log_wrapper(&self) -> ServiceTraceLogWrapper<'_> { + ServiceTraceLogWrapper::Exit(&self.service) } } @@ -163,7 +156,7 @@ pub struct ReportRoutingServiceProvidedMessage { pub service: ServiceProvided, } -impl MessageWithServicesProvided for ReportRoutingServiceProvidedMessage { +impl ServiceProvidedMsg for ReportRoutingServiceProvidedMessage { fn services_provided(&self) -> &ServiceProvided { &self.service } @@ -172,31 +165,8 @@ impl MessageWithServicesProvided for ReportRoutingServiceProvidedMessage { AccountingMsgType::RoutingServiceProvided } - fn trace_log_wrapper(&self) -> ServiceProvidedTraceLogWrapper<'_> { - ServiceProvidedTraceLogWrapper::RoutingServiceProvided(&self.service) - } -} - -impl AccountableServiceWithTraceLog for ServiceProvidedTraceLogWrapper<'_> { - fn trace_log_msg(&self, msg_id: u32) -> String { - match self { - ServiceProvidedTraceLogWrapper::ExitServiceProvided(service) => { - format!( - "Msg {}: Charging exit service for {} bytes to wallet {} at {} per service and {} per byte", - msg_id, - service.payload_size, - service.paying_wallet, - service.service_rate, - service.byte_rate - ) - } - ServiceProvidedTraceLogWrapper::RoutingServiceProvided(service) => { - format!( - "Msg {}: Charging routing of {} bytes to wallet {}", - msg_id, service.payload_size, service.paying_wallet - ) - } - } + fn trace_log_wrapper(&self) -> ServiceTraceLogWrapper<'_> { + ServiceTraceLogWrapper::Routing(&self.service) } } @@ -216,24 +186,6 @@ pub struct ReportServicesConsumedMessage { pub routing: RoutingServicesConsumed, } -impl AccountableServiceWithTraceLog for ExitServiceConsumed { - fn trace_log_msg(&self, msg_id: u32) -> String { - format!( - "Msg {}: Accruing debt to {} for consuming {} exited bytes", - msg_id, self.earning_wallet, self.payload_size - ) - } -} - -impl<'a> AccountableServiceWithTraceLog for RoutingServiceConsumedTraceLogWrapper<'a> { - fn trace_log_msg(&self, msg_id: u32) -> String { - format!( - "Msg {}: Accruing debt to {} for consuming {} routed bytes", - msg_id, self.service.earning_wallet, self.routing_payload_size - ) - } -} - #[derive(Clone, PartialEq, Eq, Debug)] pub struct ExitServiceConsumed { pub earning_wallet: Wallet, @@ -255,9 +207,35 @@ pub struct RoutingServiceConsumed { pub byte_rate: u64, } -pub enum ServiceProvidedTraceLogWrapper<'a> { - ExitServiceProvided(&'a ServiceProvided), - RoutingServiceProvided(&'a ServiceProvided), +pub enum ServiceTraceLogWrapper<'a> { + Exit(&'a ServiceProvided), + Routing(&'a ServiceProvided), +} + +impl ServiceTraceLogWrapper<'_> { + pub fn maybe_log_trace(&self, logger: &Logger, msg_id: u32) { + logger.trace(|| self.compose_msg(msg_id)) + } + fn compose_msg(&self, msg_id: u32) -> String { + match self { + Self::Exit(service) => { + format!( + "Msg {}: Charging exit service for {} bytes to wallet {} at {} per service and {} per byte", + msg_id, + service.payload_size, + service.paying_wallet, + service.service_rate, + service.byte_rate + ) + } + Self::Routing(service) => { + format!( + "Msg {}: Charging routing of {} bytes to wallet {}", + msg_id, service.payload_size, service.paying_wallet + ) + } + } + } } pub struct RoutingServiceConsumedTraceLogWrapper<'a> { @@ -293,10 +271,10 @@ mod tests { use crate::accountant::test_utils::AccountantBuilder; use crate::accountant::{checked_conversion, Accountant}; use crate::sub_lib::accountant::{ - AccountableServiceWithTraceLog, AccountantSubsFactoryReal, DetailedScanType, - MessageWithServicesProvided, PaymentThresholds, ReportExitServiceProvidedMessage, - ReportRoutingServiceProvidedMessage, ScanIntervals, ServiceProvided, SubsFactory, - DEFAULT_EARNING_WALLET, DEFAULT_PAYMENT_THRESHOLDS, TEMPORARY_CONSUMING_WALLET, + AccountantSubsFactoryReal, DetailedScanType, PaymentThresholds, + ReportExitServiceProvidedMessage, ReportRoutingServiceProvidedMessage, ScanIntervals, + ServiceProvided, ServiceProvidedMsg, SubsFactory, DEFAULT_EARNING_WALLET, + DEFAULT_PAYMENT_THRESHOLDS, TEMPORARY_CONSUMING_WALLET, }; use crate::sub_lib::wallet::Wallet; use crate::test_utils::make_wallet; @@ -424,10 +402,10 @@ mod tests { AccountingMsgType::RoutingServiceProvided ); assert!(exit_service_provided_trace_log_wrapper - .trace_log_msg(1) + .compose_msg(1) .contains("Msg 1: Charging exit")); assert!(routing_service_provided_trace_log_wrapper - .trace_log_msg(2) + .compose_msg(2) .contains("Msg 2: Charging routing")); } } diff --git a/node/src/sub_lib/utils.rs b/node/src/sub_lib/utils.rs index 5bd7a655a..6065c8187 100644 --- a/node/src/sub_lib/utils.rs +++ b/node/src/sub_lib/utils.rs @@ -323,8 +323,8 @@ mod tests { #[test] fn handle_ui_crash_message_does_not_crash_if_not_crashable() { init_test_logging(); - let mut logger = Logger::new("handle_ui_crash_message_does_not_crash_if_not_crashable"); - logger.set_level_for_test(Level::Info); + let test_name = "handle_ui_crash_message_does_not_crash_if_not_crashable"; + let logger = Logger::new(test_name).set_test_log_level(Level::Info); let msg_body = UiCrashRequest { actor: "CRASHKEY".to_string(), panic_message: "Foiled again!".to_string(),