diff --git a/engine/runtime/action-log/src/action.rs b/engine/runtime/action-log/src/action.rs index cf9dfd921..19290603d 100644 --- a/engine/runtime/action-log/src/action.rs +++ b/engine/runtime/action-log/src/action.rs @@ -3,8 +3,7 @@ use std::path::PathBuf; use std::sync::Mutex; use once_cell::sync::Lazy; -use slog::{Drain, Logger, OwnedKVList, Record}; -use slog_term::Decorator; +use slog::Logger; use sloggers::file::FileLoggerBuilder; use sloggers::null::NullLoggerBuilder; use sloggers::types::Severity; @@ -12,6 +11,8 @@ use sloggers::{Build, BuildWithCustomFormat}; use reearth_flow_common::str::{is_boolean, parse_boolean}; +use crate::json::Json; + static ACTION_LOG_DISABLE: Lazy>> = Lazy::new(|| Mutex::new(env::var("ACTION_LOG_DISABLE").ok())); @@ -22,84 +23,11 @@ pub(crate) fn action_logger(root_path: PathBuf, action: &str) -> Logger { NullLoggerBuilder.build().unwrap() } _ => { - let mut builder = FileLoggerBuilder::new(format!( - "{}/{}.log", - root_path.to_str().unwrap_or_default(), - action - )); + let mut builder = FileLoggerBuilder::new(root_path.join(format!("{}.log", action))); builder.level(Severity::Info); builder - .build_with_custom_format(|decorator| Ok(CustomFormat::new(decorator))) + .build_with_custom_format(|decorator| Ok(Json::new(decorator))) .unwrap() } } } - -pub struct CustomFormat -where - D: Decorator, -{ - decorator: D, -} - -impl Drain for CustomFormat -where - D: Decorator, -{ - type Ok = (); - type Err = std::io::Error; - - fn log( - &self, - record: &Record, - values: &OwnedKVList, - ) -> std::result::Result { - self.format_custom(record, values) - } -} - -const TIMESTAMP_FORMAT: &[time::format_description::FormatItem] = time::macros::format_description!( - "[year]/[month]/[day] [hour]:[minute]:[second] [offset_hour]:[offset_minute]" -); - -impl CustomFormat -where - D: Decorator, -{ - pub fn new(decorator: D) -> Self { - CustomFormat { decorator } - } - - fn format_custom(&self, record: &Record, values: &OwnedKVList) -> std::io::Result<()> { - self.decorator.with_record(record, values, |decorator| { - decorator.start_level()?; - write!(decorator, "[{:?}]", record.level())?; - - decorator.start_whitespace()?; - write!(decorator, " ")?; - - decorator.start_timestamp()?; - let now: time::OffsetDateTime = std::time::SystemTime::now().into(); - write!( - decorator, - "{}", - now.format(TIMESTAMP_FORMAT) - .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e))? - )?; - - decorator.start_whitespace()?; - write!(decorator, " ")?; - - decorator.start_whitespace()?; - write!(decorator, " ")?; - - decorator.start_msg()?; - write!(decorator, "{}", record.msg())?; - - writeln!(decorator)?; - decorator.flush()?; - - Ok(()) - }) - } -} diff --git a/engine/runtime/action-log/src/json.rs b/engine/runtime/action-log/src/json.rs new file mode 100644 index 000000000..f0edca3e5 --- /dev/null +++ b/engine/runtime/action-log/src/json.rs @@ -0,0 +1,257 @@ +use serde::ser::SerializeMap; +use serde::serde_if_integer128; +use slog::o; +use slog::Key; +use slog::Record; +use slog::{FnValue, PushFnValue}; +use slog::{OwnedKVList, SendSyncRefUnwindSafeKV, KV}; +use slog_term::Decorator; +use std::{fmt, io, result}; + +use std::cell::RefCell; +use std::fmt::Write; + +thread_local! { + static TL_BUF: RefCell = RefCell::new(String::with_capacity(128)) +} + +pub(crate) struct SerdeSerializer { + /// Current state of map serializing: `serde::Serializer::MapState` + ser_map: S::SerializeMap, +} + +impl SerdeSerializer { + /// Start serializing map of values + fn start(ser: S, len: Option) -> result::Result { + let ser_map = ser.serialize_map(len).map_err(|e| { + io::Error::new( + io::ErrorKind::Other, + format!("serde serialization error: {}", e), + ) + })?; + Ok(SerdeSerializer { ser_map }) + } + + /// Finish serialization, and return the serializer + fn end(self) -> result::Result { + self.ser_map.end() + } +} + +macro_rules! impl_m( + ($s:expr, $key:expr, $val:expr) => ({ + let k_s: &str = $key.as_ref(); + $s.ser_map.serialize_entry(k_s, $val) + .map_err(|e| io::Error::new(io::ErrorKind::Other, format!("serde serialization error: {}", e)))?; + Ok(()) + }); +); + +impl slog::Serializer for SerdeSerializer +where + S: serde::Serializer, +{ + fn emit_bool(&mut self, key: Key, val: bool) -> slog::Result { + impl_m!(self, key, &val) + } + + fn emit_unit(&mut self, key: Key) -> slog::Result { + impl_m!(self, key, &()) + } + + fn emit_char(&mut self, key: Key, val: char) -> slog::Result { + impl_m!(self, key, &val) + } + + fn emit_none(&mut self, key: Key) -> slog::Result { + let val: Option<()> = None; + impl_m!(self, key, &val) + } + fn emit_u8(&mut self, key: Key, val: u8) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_i8(&mut self, key: Key, val: i8) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_u16(&mut self, key: Key, val: u16) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_i16(&mut self, key: Key, val: i16) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_usize(&mut self, key: Key, val: usize) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_isize(&mut self, key: Key, val: isize) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_u32(&mut self, key: Key, val: u32) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_i32(&mut self, key: Key, val: i32) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_f32(&mut self, key: Key, val: f32) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_u64(&mut self, key: Key, val: u64) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_i64(&mut self, key: Key, val: i64) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_f64(&mut self, key: Key, val: f64) -> slog::Result { + impl_m!(self, key, &val) + } + serde_if_integer128! { + fn emit_u128(&mut self, key: Key, val: u128) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_i128(&mut self, key: Key, val: i128) -> slog::Result { + impl_m!(self, key, &val) + } + } + fn emit_str(&mut self, key: Key, val: &str) -> slog::Result { + impl_m!(self, key, &val) + } + fn emit_arguments(&mut self, key: Key, val: &fmt::Arguments) -> slog::Result { + TL_BUF.with(|buf| { + let mut buf = buf.borrow_mut(); + + buf.write_fmt(*val).unwrap(); + + let res = { || impl_m!(self, key, &*buf) }(); + buf.clear(); + res + }) + } +} + +/// Json `Drain` +/// +/// Each record will be printed as a Json map +/// to a given `io` +pub(crate) struct Json +where + D: Decorator, +{ + decorator: D, + values: Vec, +} + +impl Json +where + D: Decorator, +{ + pub fn new(decorator: D) -> Json { + JsonBuilder::new(decorator).add_default_keys().build() + } + + fn log_impl( + &self, + serializer: &mut serde_json::ser::Serializer<&mut W, F>, + rinfo: &Record, + logger_values: &OwnedKVList, + ) -> io::Result<()> + where + W: io::Write, + F: serde_json::ser::Formatter, + { + let mut serializer = SerdeSerializer::start(&mut *serializer, None)?; + + for kv in &self.values { + kv.serialize(rinfo, &mut serializer)?; + } + + logger_values.serialize(rinfo, &mut serializer)?; + + rinfo.kv().serialize(rinfo, &mut serializer)?; + + let res = serializer.end(); + + res.map_err(|e| io::Error::new(io::ErrorKind::Other, e))?; + + Ok(()) + } +} + +impl slog::Drain for Json +where + D: Decorator, +{ + type Ok = (); + type Err = io::Error; + fn log(&self, record: &Record, values: &OwnedKVList) -> io::Result<()> { + self.decorator.with_record(record, values, |decorator| { + let mut buffer = Vec::new(); + let mut serializer = serde_json::Serializer::new(&mut buffer); + self.log_impl(&mut serializer, record, values)?; + serializer.into_inner(); + let json_str = String::from_utf8(buffer).unwrap(); + write!(decorator, "{}", json_str)?; + writeln!(decorator)?; + decorator.flush()?; + Ok(()) + }) + } +} + +/// Json `Drain` builder +/// +/// Create with `Json::new`. +pub struct JsonBuilder { + values: Vec, + decorator: D, +} + +impl JsonBuilder +where + D: Decorator, +{ + pub(crate) fn new(decorator: D) -> Self { + JsonBuilder { + values: vec![], + decorator, + } + } + + /// Build `Json` `Drain` + /// + /// This consumes the builder. + pub fn build(self) -> Json { + Json { + values: self.values, + decorator: self.decorator, + } + } + + /// Add custom values to be printed with this formatter + pub fn add_key_value(mut self, value: slog::OwnedKV) -> Self + where + T: SendSyncRefUnwindSafeKV + 'static, + { + self.values.push(value.into()); + self + } + + /// Add default key-values: + /// + /// * `ts` - timestamp + /// * `level` - record logging level name + /// * `msg` - msg - formatted logging message + pub fn add_default_keys(self) -> Self { + self.add_key_value(o!( + "ts" => FnValue(move |_ : &Record| { + time::OffsetDateTime::now_utc() + .format(&time::format_description::well_known::Rfc3339) + .ok() + }), + "level" => FnValue(move |rinfo : &Record| { + rinfo.level().as_short_str() + }), + "msg" => PushFnValue(move |record : &Record, ser| { + ser.emit(record.msg()) + }), + )) + } +} diff --git a/engine/runtime/action-log/src/lib.rs b/engine/runtime/action-log/src/lib.rs index 4b3766833..400df0a74 100644 --- a/engine/runtime/action-log/src/lib.rs +++ b/engine/runtime/action-log/src/lib.rs @@ -1,5 +1,6 @@ mod action; pub mod factory; +pub(crate) mod json; mod split; pub use slog::error as slog_error;