diff --git a/chainsight-cdk-macros/src/lib.rs b/chainsight-cdk-macros/src/lib.rs index d5e77793..23becf59 100644 --- a/chainsight-cdk-macros/src/lib.rs +++ b/chainsight-cdk-macros/src/lib.rs @@ -147,6 +147,11 @@ pub fn define_get_ethereum_address(input: TokenStream) -> TokenStream { web3::define_get_ethereum_address(input) } +#[proc_macro] +pub fn define_logger(input: TokenStream) -> TokenStream { + utils::define_logger(input) +} + #[proc_macro_derive(ContractEvent)] pub fn contract_event_derive(input: TokenStream) -> TokenStream { web3::contract_event_derive(input) diff --git a/chainsight-cdk-macros/src/snapshots/chainsight_cdk_macros__utils__tests__snapshot__define_logger.snap b/chainsight-cdk-macros/src/snapshots/chainsight_cdk_macros__utils__tests__snapshot__define_logger.snap new file mode 100644 index 00000000..7f8668ba --- /dev/null +++ b/chainsight-cdk-macros/src/snapshots/chainsight_cdk_macros__utils__tests__snapshot__define_logger.snap @@ -0,0 +1,41 @@ +--- +source: chainsight-cdk-macros/src/utils.rs +expression: formatted +--- +use chainsight_cdk::log::{Logger, LoggerImpl}; +#[candid::candid_method(query)] +#[ic_cdk::query] +fn tail_logs(rows: usize) -> Vec { + _logger().tail(rows) +} +#[candid::candid_method(update)] +#[ic_cdk::update] +#[chainsight_cdk_macros::only_controller] +fn drain_logs(rows: usize) -> Vec { + _logger().drain(rows) +} +#[ic_cdk::init] +fn init_logger() { + schedule_cleanup(); +} +#[ic_cdk::post_upgrade] +fn post_upgrade_logger() { + schedule_cleanup(); +} +fn schedule_cleanup() { + ic_cdk_timers::set_timer_interval(std::time::Duration::from_secs(86400u64), || { + ic_cdk::spawn(async { + _logger().sweep(7u8); + }) + }); + _logger().info( + format!( + "cleanup sheduled: interval = {} sec. retention days = {}", + 86400u64, 7u8 + ) + .as_str(), + ); +} +fn _logger() -> LoggerImpl { + LoggerImpl::new(Some("Logger")) +} diff --git a/chainsight-cdk-macros/src/utils.rs b/chainsight-cdk-macros/src/utils.rs index d5945836..584cb91d 100644 --- a/chainsight-cdk-macros/src/utils.rs +++ b/chainsight-cdk-macros/src/utils.rs @@ -1,6 +1,9 @@ use proc_macro::TokenStream; use quote::quote; -use syn::{parse_macro_input, DeriveInput}; +use syn::{ + parse::{Parse, ParseStream}, + parse_macro_input, DeriveInput, LitInt, Result, +}; pub fn chainsight_common(_input: TokenStream) -> TokenStream { chainsight_common_internal().into() @@ -14,6 +17,83 @@ fn chainsight_common_internal() -> proc_macro2::TokenStream { } } +#[derive(Default)] +struct DefineLoggerArgs { + retention_days: Option, + cleanup_interval_days: Option, +} +impl Parse for DefineLoggerArgs { + fn parse(input: ParseStream) -> Result { + if input.is_empty() { + return Ok(DefineLoggerArgs { + retention_days: None, + cleanup_interval_days: None, + }); + } + let retention_days: Option = input.parse()?; + let retention_days = retention_days.map(|x| x.base10_parse::().unwrap()); + if input.parse::().is_err() { + return Ok(DefineLoggerArgs { + retention_days, + cleanup_interval_days: None, + }); + } + let cleanup_interval_days: Option = input.parse()?; + Ok(DefineLoggerArgs { + retention_days, + cleanup_interval_days: cleanup_interval_days.map(|x| x.base10_parse().unwrap()), + }) + } +} +pub fn define_logger(input: TokenStream) -> TokenStream { + let args = parse_macro_input!(input as DefineLoggerArgs); + define_logger_internal(args).into() +} + +fn define_logger_internal(args: DefineLoggerArgs) -> proc_macro2::TokenStream { + let retention_days = args.retention_days.unwrap_or(7); + let cleanup_interval = args.cleanup_interval_days.unwrap_or(1) as u64 * 86400; + quote! { + use chainsight_cdk::log::{Logger, LoggerImpl}; + + #[candid::candid_method(query)] + #[ic_cdk::query] + fn tail_logs(rows: usize) -> Vec { + _logger().tail(rows) + } + + #[candid::candid_method(update)] + #[ic_cdk::update] + #[chainsight_cdk_macros::only_controller] + fn drain_logs(rows: usize) -> Vec { + _logger().drain(rows) + } + + #[ic_cdk::init] + fn init_logger() { + schedule_cleanup(); + } + + #[ic_cdk::post_upgrade] + fn post_upgrade_logger() { + schedule_cleanup(); + } + + fn schedule_cleanup() { + ic_cdk_timers::set_timer_interval(std::time::Duration::from_secs(#cleanup_interval), || { + ic_cdk::spawn(async { + _logger().sweep(#retention_days); + }) + }); + _logger().info(format!("cleanup sheduled: interval = {} sec. retention days = {}", #cleanup_interval, #retention_days).as_str()); + } + + fn _logger() -> LoggerImpl { + LoggerImpl::new(Some("Logger")) + } + } +} + pub fn did_export(input: TokenStream) -> TokenStream { let args = parse_macro_input!(input as syn::LitStr); did_export_internal(args).into() @@ -76,6 +156,15 @@ mod tests { assert_snapshot!("snapshot__chainsight_common", formatted); } + #[test] + fn test_snapshot_define_logger() { + let generated = define_logger_internal(Default::default()); + let formatted = RustFmt::default() + .format_str(generated.to_string()) + .expect("rustfmt failed"); + assert_snapshot!("snapshot__define_logger", formatted); + } + #[test] fn test_snapshot_did_export() { let input = quote! {"sample_component"}; diff --git a/chainsight-cdk/Cargo.toml b/chainsight-cdk/Cargo.toml index 49d25065..036dc0d1 100644 --- a/chainsight-cdk/Cargo.toml +++ b/chainsight-cdk/Cargo.toml @@ -27,6 +27,8 @@ derive_more = "0.99.17" lazy_static = "1.4.0" primitive-types = "0.12.1" Inflector = "0.11.4" +time = "0.3.37" +ic-cdk-timers = "0.11.0" [dev-dependencies] insta = { version = "1.33.0", features = ["yaml"] } diff --git a/chainsight-cdk/src/core/mod.rs b/chainsight-cdk/src/core/mod.rs index 43b6d445..0dfd1087 100644 --- a/chainsight-cdk/src/core/mod.rs +++ b/chainsight-cdk/src/core/mod.rs @@ -1,4 +1,5 @@ mod env; +mod time; pub use core::*; pub use env::*; pub use time::*; diff --git a/chainsight-cdk/src/lib.rs b/chainsight-cdk/src/lib.rs index 6f671da3..11a5e676 100644 --- a/chainsight-cdk/src/lib.rs +++ b/chainsight-cdk/src/lib.rs @@ -5,6 +5,7 @@ pub mod core; pub mod indexer; pub mod initializer; pub mod lens; +pub mod log; pub mod metric; pub mod rpc; pub mod storage; diff --git a/chainsight-cdk/src/log/logger.rs b/chainsight-cdk/src/log/logger.rs new file mode 100644 index 00000000..48b64362 --- /dev/null +++ b/chainsight-cdk/src/log/logger.rs @@ -0,0 +1,293 @@ +use anyhow::Error; +use std::{cmp::min, collections::HashMap}; + +use super::types::{LogLevel, Logger}; + +const DAY_IN_NANOS: u64 = 86400 * 1_000_000_000; + +thread_local! { + static LOGS: std::cell::RefCell>> = std::cell::RefCell::new(HashMap::new()); +} + +#[derive(Default)] +pub struct LoggerImpl { + ctx: String, +} + +impl Logger for LoggerImpl { + fn info(&self, s: &str) { + self.log(&LogLevel::Info, s, ic_cdk::api::time()); + } + + fn err(&self, err: &Error) { + self.log( + &LogLevel::Error, + &Self::format_err(err), + ic_cdk::api::time(), + ); + } + + fn err_with_msg(&self, err: &Error, msg: &str) { + self.log( + &LogLevel::Error, + &Self::format_err_with_msg(err, msg), + ic_cdk::api::time(), + ); + } +} + +impl LoggerImpl { + pub fn new(ctx: Option<&str>) -> Self { + if let Some(ctx) = ctx { + Self { + ctx: format!("[{}] ", ctx), + } + } else { + Self::default() + } + } + + pub fn drain(&self, rows: usize) -> Vec { + let exported = self._drain(rows); + self.info(format!("Drained {} logs.", exported.len()).as_str()); + exported + } + + pub fn tail(&self, rows: usize) -> Vec { + let keys = Self::keys(); + let mut res = Vec::new(); + LOGS.with_borrow(|logs| { + for key in keys.iter().rev() { + if res.len() >= rows { + break; + } + let logs = logs.get(key).unwrap(); + let tail_from = logs.len().saturating_sub(rows - res.len()); + let mut logs = logs[tail_from..].to_vec(); + logs.extend(res.clone()); + res = logs; + } + }); + res + } + + pub fn sweep(&self, retention_days: u8) { + let until = (ic_cdk::api::time() / DAY_IN_NANOS - retention_days as u64) * DAY_IN_NANOS; + self._sweep(until); + self.info(format!("Sweeped logs before {}.", Self::format_timestamp(until)).as_str()); + } + + fn _drain(&self, rows: usize) -> Vec { + let keys = Self::keys(); + let mut drained = Vec::new(); + for key in keys.iter() { + if drained.len() >= rows { + break; + } + LOGS.with_borrow_mut(|logs| { + let logs = logs.get_mut(key).unwrap(); + let to_drain = min(rows - drained.len(), logs.len()); + drained.extend(logs.drain(..to_drain)); + }); + } + drained + } + + fn _sweep(&self, until: u64) { + let keys = Self::keys(); + let key = Self::key(until); + LOGS.with_borrow_mut(|logs| { + keys.iter().filter(|k| **k < key).for_each(|k| { + logs.remove(k); + }); + }); + } + + fn key(ts: u64) -> u64 { + ts / (DAY_IN_NANOS) + } + + fn keys() -> Vec { + let mut keys = LOGS.with_borrow(|logs| logs.keys().cloned().collect::>()); + keys.sort(); + keys + } + + fn log(&self, level: &LogLevel, s: &str, ts: u64) { + let key = Self::key(ts); + LOGS.with_borrow_mut(|logs| { + if logs.get(&key).is_none() { + logs.insert(key, Vec::new()); + } + let log = logs.get_mut(&key).unwrap(); + log.push(self.format_log(level, s, ts)); + }); + } + + fn format_log(&self, level: &LogLevel, s: &str, ts: u64) -> String { + format!( + "[{}]: [{}] {}{}", + Self::format_timestamp(ts), + level, + self.ctx, + s + ) + } + + fn format_timestamp(ts: u64) -> String { + let datetime = time::OffsetDateTime::from_unix_timestamp_nanos(ts.into()); + if datetime.is_err() { + return format!("{}", ts); + } + let datetime = datetime.unwrap(); + let time = datetime.time(); + format!( + "{} {:02}:{:02}:{:02}.{:09} UTC", + datetime.date(), + time.hour(), + time.minute(), + time.second(), + time.nanosecond() + ) + } + + fn format_err(err: &Error) -> String { + let bt = err.backtrace(); + if bt.status() == std::backtrace::BacktraceStatus::Captured { + format!("{}\nstack backtrace:\n{}", err, err.backtrace()) + } else { + format!("{}", err) + } + } + + fn format_err_with_msg(err: &Error, msg: &str) -> String { + format!("{} err: {}", msg, Self::format_err(err)) + } +} + +#[cfg(test)] +mod test { + + use super::*; + + #[test] + fn test_format() { + let ts = i64::MAX as u64; + assert_eq!( + LoggerImpl::default().format_log(&LogLevel::Info, "test", ts), + "[2262-04-11 23:47:16.854775807 UTC]: [INFO] test" + ); + } + + #[test] + fn test_format_with_ctx() { + let ts = i64::MAX as u64; + assert_eq!( + LoggerImpl::new(Some("Test")).format_log(&LogLevel::Info, "test", ts), + "[2262-04-11 23:47:16.854775807 UTC]: [INFO] [Test] test" + ); + } + + #[test] + fn test_format_err() { + let err = anyhow::anyhow!("test error"); + assert!(LoggerImpl::format_err(&err).contains("test error")); + } + + #[test] + fn test_format_err_with_msg() { + let err = anyhow::anyhow!("test error"); + assert!(LoggerImpl::format_err_with_msg(&err, "msg.").contains("msg. err: test error")); + } + + #[test] + fn test_log() { + let logger = LoggerImpl::default(); + let ts = i64::MAX as u64; + logger.log(&LogLevel::Error, "test", ts); + LOGS.with(|log| { + assert_eq!( + log.borrow() + .get(&LoggerImpl::key(ts)) + .unwrap() + .last() + .unwrap(), + "[2262-04-11 23:47:16.854775807 UTC]: [ERROR] test" + ); + }); + } + + #[test] + fn test_drain() { + let logger = LoggerImpl::default(); + logger.log(&LogLevel::Info, "test", 1); + logger.log(&LogLevel::Info, "test", 2); + logger.log(&LogLevel::Info, "test", DAY_IN_NANOS); + logger.log(&LogLevel::Info, "test", DAY_IN_NANOS + 1); + logger.log(&LogLevel::Info, "test", DAY_IN_NANOS + 2); + + let logs = logger._drain(3); + assert_eq!(logs.len(), 3); + assert_eq!(logs[0], "[1970-01-01 00:00:00.000000001 UTC]: [INFO] test"); + assert_eq!(logs[2], "[1970-01-02 00:00:00.000000000 UTC]: [INFO] test"); + LOGS.with_borrow(|logs| { + let logs_1 = logs.get(&LoggerImpl::key(0)).unwrap(); + assert_eq!(logs_1.len(), 0); + let logs_2 = logs.get(&LoggerImpl::key(DAY_IN_NANOS)).unwrap(); + assert_eq!(logs_2.len(), 2); + assert_eq!( + logs_2[0], + "[1970-01-02 00:00:00.000000001 UTC]: [INFO] test" + ); + assert_eq!( + logs_2[1], + "[1970-01-02 00:00:00.000000002 UTC]: [INFO] test" + ); + }); + } + + #[test] + fn test_drain_overflow() { + let logger = LoggerImpl::default(); + logger.log(&LogLevel::Info, "test", 1); + logger.log(&LogLevel::Info, "test", 2); + + let logs = logger._drain(3); + assert_eq!(logs.len(), 2); + LOGS.with_borrow(|logs| { + assert_eq!(logs.len(), 1); + }); + } + + #[test] + fn test_tail() { + let logger = LoggerImpl::default(); + logger.log(&LogLevel::Info, "test", 1); + logger.log(&LogLevel::Info, "test", 2); + logger.log(&LogLevel::Info, "test", 3); + logger.log(&LogLevel::Info, "test", 4); + logger.log(&LogLevel::Info, "test", 5); + logger.log(&LogLevel::Info, "test", DAY_IN_NANOS); + + let logs = logger.tail(3); + assert_eq!(logs.len(), 3); + assert_eq!(logs[0], "[1970-01-01 00:00:00.000000004 UTC]: [INFO] test"); + assert_eq!(logs[2], "[1970-01-02 00:00:00.000000000 UTC]: [INFO] test"); + } + + #[test] + fn test_sweep() { + let logger = LoggerImpl::default(); + logger.log(&LogLevel::Info, "test", 1); + logger.log(&LogLevel::Info, "test", 2); + logger.log(&LogLevel::Info, "test", 3); + logger.log(&LogLevel::Info, "test", 4); + logger.log(&LogLevel::Info, "test", 5); + logger.log(&LogLevel::Info, "test", DAY_IN_NANOS); + + logger._sweep(DAY_IN_NANOS); + let logs = logger.tail(usize::MAX); + assert_eq!(logs.len(), 1); + assert_eq!(logs[0], "[1970-01-02 00:00:00.000000000 UTC]: [INFO] test"); + } +} diff --git a/chainsight-cdk/src/log/mod.rs b/chainsight-cdk/src/log/mod.rs new file mode 100644 index 00000000..14d9c6a6 --- /dev/null +++ b/chainsight-cdk/src/log/mod.rs @@ -0,0 +1,4 @@ +mod logger; +mod types; +pub use logger::*; +pub use types::*; diff --git a/chainsight-cdk/src/log/types.rs b/chainsight-cdk/src/log/types.rs new file mode 100644 index 00000000..67d0e674 --- /dev/null +++ b/chainsight-cdk/src/log/types.rs @@ -0,0 +1,22 @@ +use anyhow::Error; +use std::fmt::Display; + +pub trait Logger { + fn info(&self, s: &str); + fn err(&self, e: &Error); + fn err_with_msg(&self, e: &Error, msg: &str); +} + +pub enum LogLevel { + Info, + Error, +} + +impl Display for LogLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + LogLevel::Info => write!(f, "INFO"), + LogLevel::Error => write!(f, "ERROR"), + } + } +}