diff --git a/Cargo.toml b/Cargo.toml index d1a5d95..54cb708 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "bp3d-logger" -version = "1.1.0" +version = "2.0.0-rc.1.0.0" authors = ["Yuri Edward "] edition = "2021" description = "A flexible Log implementation intended to be used with BP3D software." @@ -14,12 +14,11 @@ categories = [] [dependencies] log = "0.4.14" -bp3d-fs = "1.0.0" +bp3d-os = { version = "1.0.0-rc.1.2.1", features=["dirs", "time"] } crossbeam-channel = "0.5.2" +crossbeam-queue = "0.3.8" once_cell = "1.10.0" -time = { version = "0.3.7", features = ["formatting", "macros"] } -time-tz = { version = "0.3.1", features = ["system"] } +time = { version = "0.3.0", features = ["formatting", "macros"] } termcolor = "1.1.3" -atty = "0.2.14" [features] diff --git a/src/backend.rs b/src/backend.rs index b3d7331..196465b 100644 --- a/src/backend.rs +++ b/src/backend.rs @@ -1,4 +1,4 @@ -// Copyright (c) 2021, BlockProject 3D +// Copyright (c) 2023, BlockProject 3D // // All rights reserved. // @@ -28,13 +28,12 @@ use crate::easy_termcolor::{color, EasyTermColor}; use crate::Colors; -use atty::Stream; use log::Level; use std::collections::HashMap; use std::fmt::Display; use std::fmt::Formatter; use std::fs::{File, OpenOptions}; -use std::io::{BufWriter, Write}; +use std::io::{BufWriter, IsTerminal, Write}; use std::path::PathBuf; use std::sync::atomic::{AtomicBool, Ordering}; use termcolor::{ColorChoice, ColorSpec, StandardStream}; @@ -72,11 +71,25 @@ fn write_msg(stream: StandardStream, target: &str, msg: &str, level: Level) { .color(color(level)) .write(level) .reset() - .write(']') - .write(format!(" {}", msg)) + .write("] ") + .write(msg) .lf(); } +enum Stream { + Stdout, + Stderr, +} + +impl Stream { + pub fn isatty(&self) -> bool { + match self { + Stream::Stdout => std::io::stdout().is_terminal(), + Stream::Stderr => std::io::stderr().is_terminal(), + } + } +} + impl StdBackend { pub fn new(smart_stderr: bool, colors: Colors) -> StdBackend { StdBackend { @@ -108,7 +121,7 @@ impl Backend for StdBackend { let use_termcolor = match self.colors { Colors::Disabled => false, Colors::Enabled => true, - Colors::Auto => atty::is(stream), + Colors::Auto => stream.isatty(), }; match use_termcolor { true => { diff --git a/src/internal.rs b/src/internal.rs index 9f8c091..1bf22b2 100644 --- a/src/internal.rs +++ b/src/internal.rs @@ -1,4 +1,4 @@ -// Copyright (c) 2021, BlockProject 3D +// Copyright (c) 2023, BlockProject 3D // // All rights reserved. // @@ -28,20 +28,28 @@ use crate::backend::Backend; use crate::{LogMsg, Logger}; +use bp3d_os::time::LocalOffsetDateTime; use crossbeam_channel::{bounded, Receiver, Sender}; +use crossbeam_queue::ArrayQueue; use log::{Level, Log, Metadata, Record}; +use std::fmt::Write; use std::sync::atomic::{AtomicBool, Ordering}; -use std::sync::Mutex; +use std::sync::{Arc, Mutex}; use time::macros::format_description; use time::OffsetDateTime; -use time_tz::OffsetDateTimeExt; -const BUF_SIZE: usize = 128; // The maximum count of log messages in the channel. +const BUF_SIZE: usize = 16; // The maximum count of log messages in the channel. +//Disable large_enum_variant as using a Box will inevitably cause a small allocation on a critical path, +//allocating in a critical code path will most likely result in degraded performance. +//And yes, logging is a critical path when using bp3d-tracing. +#[allow(clippy::large_enum_variant)] enum Command { Flush, Log(LogMsg), Terminate, + EnableLogBuffer, + DisableLogBuffer, } fn log( @@ -57,58 +65,99 @@ fn log( } } -fn exec_commad(cmd: Command, logger: &mut Logger) -> bool { - match cmd { - Command::Terminate => true, - Command::Flush => { - if let Some(file) = &mut logger.file { - if let Err(e) = file.flush() { +struct Thread { + logger: Logger, + recv_ch: Receiver, + enable_log_buffer: bool, + log_buffer: Arc>, +} + +impl Thread { + pub fn new( + logger: Logger, + recv_ch: Receiver, + log_buffer: Arc>, + ) -> Thread { + Thread { + logger, + recv_ch, + enable_log_buffer: false, + log_buffer, + } + } + + fn exec_commad(&mut self, cmd: Command) -> bool { + match cmd { + Command::Terminate => true, + Command::Flush => { + if let Some(file) = &mut self.logger.file { + if let Err(e) = file.flush() { + let _ = log( + self.logger.std.as_mut(), + "bp3d-logger", + &format!("Could not flush file backend: {}", e), + Level::Error, + ); + } + } + false + } + Command::Log(buffer) => { + let target = buffer.target(); + let msg = buffer.msg(); + let level = buffer.level(); + if let Err(e) = log(self.logger.file.as_mut(), target, msg, level) { let _ = log( - logger.std.as_mut(), + self.logger.std.as_mut(), "bp3d-logger", - &format!("Could not flush file backend: {}", e), + &format!("Could not write to file backend: {}", e), Level::Error, ); } + let _ = log(self.logger.std.as_mut(), target, msg, level); + if self.enable_log_buffer { + self.log_buffer.force_push(buffer); + } + false + } + Command::EnableLogBuffer => { + self.enable_log_buffer = true; + false + } + Command::DisableLogBuffer => { + self.enable_log_buffer = false; + false } - false } - Command::Log(LogMsg { target, msg, level }) => { - if let Err(e) = log(logger.file.as_mut(), &target, &msg, level) { - let _ = log( - logger.std.as_mut(), - "bp3d-logger", - &format!("Could not write to file backend: {}", e), - Level::Error, - ); + } + + pub fn run(mut self) { + while let Ok(v) = self.recv_ch.recv() { + let flag = self.exec_commad(v); + if flag { + // The thread has requested to exit itself; drop out of the main loop. + break; } - let _ = log(logger.std.as_mut(), &target, &msg, level); - false } } } pub struct LoggerImpl { - thread: Mutex>>, send_ch: Sender, - recv_ch: Receiver, - log_buffer_send_ch: Sender, - log_buffer_recv_ch: Receiver, - enable_log_buffer: AtomicBool, enabled: AtomicBool, + recv_ch: Receiver, + log_buffer: Arc>, + thread: Mutex>>, } impl LoggerImpl { pub fn new() -> LoggerImpl { let (send_ch, recv_ch) = bounded(BUF_SIZE); - let (log_buffer_send_ch, log_buffer_recv_ch) = bounded(BUF_SIZE); LoggerImpl { thread: Mutex::new(None), send_ch, recv_ch, - log_buffer_send_ch, - log_buffer_recv_ch, - enable_log_buffer: AtomicBool::new(false), + log_buffer: Arc::new(ArrayQueue::new(BUF_SIZE)), enabled: AtomicBool::new(false), } } @@ -118,15 +167,27 @@ impl LoggerImpl { } pub fn enable_log_buffer(&self, flag: bool) { - self.enable_log_buffer.store(flag, Ordering::Release); + unsafe { + if flag { + self.send_ch + .send(Command::EnableLogBuffer) + .unwrap_unchecked(); + } else { + self.send_ch + .send(Command::DisableLogBuffer) + .unwrap_unchecked(); + } + } } + #[inline] pub fn clear_log_buffer(&self) { - while self.log_buffer_recv_ch.try_recv().is_ok() {} //Clear the entire log buffer. + while self.log_buffer.pop().is_some() {} //Clear the entire log buffer. } - pub fn get_log_buffer(&self) -> Receiver { - self.log_buffer_recv_ch.clone() + #[inline] + pub fn read_log(&self) -> Option { + self.log_buffer.pop() } pub fn terminate(&self) { @@ -160,15 +221,10 @@ impl LoggerImpl { } } let recv_ch = self.recv_ch.clone(); + let log_buffer = self.log_buffer.clone(); *thread = Some(std::thread::spawn(move || { - let mut logger = logger; - while let Ok(v) = recv_ch.recv() { - let flag = exec_commad(v, &mut logger); - if flag { - // The thread has requested to exit itself; drop out of the main loop. - break; - } - } + let thread = Thread::new(logger, recv_ch, log_buffer); + thread.run(); })); } if flag { @@ -177,35 +233,27 @@ impl LoggerImpl { // This cannot panic as send_ch is owned by LoggerImpl which is intended // to be statically allocated. self.send_ch - .send(Command::Log(LogMsg { - level: Level::Error, - msg: "The logging thread has panicked!".into(), - target: "bp3d-logger".into(), - })) + .send(Command::Log(LogMsg::from_msg( + "bp3d-logger", + Level::Error, + "The logging thread has panicked!", + ))) .unwrap_unchecked(); } } } - pub fn low_level_log(&self, msg: LogMsg) { - if self.enable_log_buffer.load(Ordering::Acquire) { - unsafe { - // This cannot panic as both send_ch and log_buffer_send_ch are owned by LoggerImpl - // which is intended to be statically allocated. - self.send_ch - .send(Command::Log(msg.clone())) - .unwrap_unchecked(); - self.log_buffer_send_ch.send(msg).unwrap_unchecked(); - } - } else { - unsafe { - // This cannot panic as send_ch is owned by LoggerImpl which is intended - // to be statically allocated. - self.send_ch.send(Command::Log(msg)).unwrap_unchecked(); - } + pub fn low_level_log(&self, msg: &LogMsg) { + unsafe { + // This cannot panic as send_ch is owned by LoggerImpl which is intended + // to be statically allocated. + self.send_ch + .send(Command::Log(msg.clone())) + .unwrap_unchecked(); } } + #[inline] pub fn is_enabled(&self) -> bool { self.enabled.load(Ordering::Acquire) } @@ -232,26 +280,21 @@ impl Log for LoggerImpl { return; } let (target, module) = extract_target_module(record); - //In the future attempt to not update all the time https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=17c218f318826f55ab64535bfcd28ec6 - let system_tz = - time_tz::system::get_timezone().unwrap_or(time_tz::timezones::db::us::CENTRAL); + let time = OffsetDateTime::now_local(); let format = format_description!("[weekday repr:short] [month repr:short] [day] [hour repr:12]:[minute]:[second] [period case:upper]"); - // is very unlikely to occur (only possibility is a weird io error). - let formatted = OffsetDateTime::now_utc() - .to_timezone(system_tz) + let formatted = time + .unwrap_or_else(OffsetDateTime::now_utc) .format(format) - .unwrap_or_else(|_| "".into()); - let msg = LogMsg { - msg: format!( - "({}) {}: {}", - formatted, - module.unwrap_or("main"), - record.args() - ), - target: target.into(), - level: record.level(), - }; - self.low_level_log(msg); + .unwrap_or_default(); + let mut msg = LogMsg::new(target, record.level()); + let _ = write!( + msg, + "({}) {}: {}", + formatted, + module.unwrap_or("main"), + record.args() + ); + self.low_level_log(&msg); } fn flush(&self) { diff --git a/src/lib.rs b/src/lib.rs index d4ff517..a704bcd 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,4 +1,4 @@ -// Copyright (c) 2021, BlockProject 3D +// Copyright (c) 2023, BlockProject 3D // // All rights reserved. // @@ -29,36 +29,29 @@ // The reason why this is needed is because the 3 examples of usage of the Logger struct requires // some context to not make it confusing. #![allow(clippy::needless_doctest_main)] +#![warn(missing_docs)] + +//! An async flexible Log implementation intended to be used with BP3D software. mod backend; mod easy_termcolor; mod internal; +mod log_msg; use crate::backend::ENABLE_STDOUT; -use bp3d_fs::dirs::App; +use bp3d_os::dirs::App; use crossbeam_channel::Receiver; -use log::{Level, Log}; +use log::Log; use once_cell::sync::Lazy; use std::path::PathBuf; use std::sync::atomic::Ordering; -/// Represents a log message in the [LogBuffer](crate::LogBuffer). -#[derive(Clone)] -pub struct LogMsg { - /// The message string. - pub msg: String, - - /// The crate name that issued this log. - pub target: String, - - /// The log level. - pub level: Level, -} +pub use log_msg::LogMsg; /// The log buffer type. pub type LogBuffer = Receiver; -/// Trait to allow getting a log directory from either a bp3d_fs::dirs::App or a String. +/// Trait to allow getting a log directory from either a bp3d_os::dirs::App or a String. pub trait GetLogs { /// Gets the log directory as a PathBuf. /// @@ -74,14 +67,14 @@ impl<'a> GetLogs for &'a String { impl<'a, 'b> GetLogs for &'a App<'b> { fn get_logs(self) -> Option { - self.get_logs().map(|v| v.into()).ok() + self.get_logs().map(|v| v.create())?.ok().map(|v| v.into()) } } impl<'a> GetLogs for &'a str { fn get_logs(self) -> Option { let app = App::new(self); - app.get_logs().map(|v| v.into()).ok() + app.get_logs().map(|v| v.create())?.ok().map(|v| v.into()) } } @@ -153,8 +146,10 @@ impl Default for Colors { /// bp3d_logger::enable_log_buffer(); // Enable log redirect pump into application channel. /// //... application code with log redirect pump. /// info!("Example message"); -/// let l = bp3d_logger::get_log_buffer().recv().unwrap();// Capture the last log message. -/// println!("Last log message: {}", l.msg); +/// bp3d_logger::flush(); +/// let l = bp3d_logger::read_log().unwrap();// Capture the last log message. +/// //We can't test for equality because log messages contains a timestamp... +/// assert!(l.msg().ends_with("Example message")); /// bp3d_logger::disable_log_buffer(); /// //... application code without log redirect pump. /// } @@ -207,7 +202,7 @@ impl Logger { /// Enables file logging to the given application. /// - /// The application is given as a reference to [GetLogs](crate::GetLogs) to allow obtaining + /// The application is given as a reference to [GetLogs](GetLogs) to allow obtaining /// a log directory from various sources. /// /// If the log directory could not be found the function prints an error to stderr. @@ -288,18 +283,18 @@ pub fn disable_stdout() { ENABLE_STDOUT.store(false, Ordering::Release); } -/// Returns the buffer from the log redirect pump. -pub fn get_log_buffer() -> LogBuffer { - BP3D_LOGGER.get_log_buffer() +/// Attempts to extract one log message from the buffer. +pub fn read_log() -> Option { + BP3D_LOGGER.read_log() } /// Low-level log function. This injects log messages directly into the logging thread channel. /// /// This function applies basic formatting depending on the backend: -/// - For stdout/stderr backend the format is \[level\] msg +/// - For stdout/stderr backend the format is \ \[level\] msg /// - For file backend the format is \[level\] msg and the message is recorded in the file /// corresponding to the log target. -pub fn raw_log(msg: LogMsg) { +pub fn raw_log(msg: &LogMsg) { BP3D_LOGGER.low_level_log(msg) } diff --git a/src/log_msg.rs b/src/log_msg.rs new file mode 100644 index 0000000..f13b6b1 --- /dev/null +++ b/src/log_msg.rs @@ -0,0 +1,237 @@ +// Copyright (c) 2023, BlockProject 3D +// +// All rights reserved. +// +// Redistribution and use in source and binary forms, with or without modification, +// are permitted provided that the following conditions are met: +// +// * Redistributions of source code must retain the above copyright notice, +// this list of conditions and the following disclaimer. +// * Redistributions in binary form must reproduce the above copyright notice, +// this list of conditions and the following disclaimer in the documentation +// and/or other materials provided with the distribution. +// * Neither the name of BlockProject 3D nor the names of its contributors +// may be used to endorse or promote products derived from this software +// without specific prior written permission. +// +// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR +// CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, +// EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, +// PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR +// PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF +// LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING +// NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS +// SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + +use log::Level; +use std::fmt::{Error, Write}; +use std::mem::MaybeUninit; + +// Limit the size of the target string to 16 bytes. +const LOG_TARGET_SIZE: usize = 16; +// Size of the control fields of the log message structure: +// sizeof msg_len + 1 byte for target_len + 1 byte for level +const LOG_CONTROL_SIZE: usize = std::mem::size_of::() + 2; +// Limit the size of the log message string so that the size of the log structure is LOG_BUFFER_SIZE +const LOG_MSG_SIZE: usize = LOG_BUFFER_SIZE - LOG_TARGET_SIZE - LOG_CONTROL_SIZE; +const LOG_BUFFER_SIZE: usize = 1024; + +#[inline] +fn log_to_u8(level: Level) -> u8 { + match level { + Level::Error => 0, + Level::Warn => 1, + Level::Info => 2, + Level::Debug => 3, + Level::Trace => 4, + } +} + +#[inline] +fn u8_to_log(l: u8) -> Level { + match l { + 0 => Level::Error, + 1 => Level::Warn, + 3 => Level::Debug, + 4 => Level::Trace, + _ => Level::Info, + } +} + +/// A log message. +/// +/// This structure uses a large 1K buffer which stores the entire log message to improve +/// performance. +/// +/// The repr(C) is used to force the control fields (msg_len, level and target_len) to be before +/// the message buffer and avoid large movs when setting control fields. +/// +/// # Examples +/// +/// ``` +/// use log::Level; +/// use bp3d_logger::LogMsg; +/// use std::fmt::Write; +/// let mut msg = LogMsg::new("test", Level::Info); +/// let _ = write!(msg, "This is a formatted message {}", 42); +/// assert_eq!(msg.msg(), "This is a formatted message 42"); +/// ``` +#[derive(Clone)] +#[repr(C)] +pub struct LogMsg { + msg_len: u32, + level: u8, + target_len: u8, + buffer: [MaybeUninit; LOG_MSG_SIZE + LOG_TARGET_SIZE], +} + +impl LogMsg { + /// Creates a new instance of log message buffer. + /// + /// # Arguments + /// + /// * `target`: the target name this log comes from. + /// * `level`: the [Level](Level) of the log message. + /// + /// returns: LogMsg + /// + /// # Examples + /// + /// ``` + /// use log::Level; + /// use bp3d_logger::LogMsg; + /// let msg = LogMsg::new("test", Level::Info); + /// assert_eq!(msg.target(), "test"); + /// assert_eq!(msg.level(), Level::Info); + /// ``` + pub fn new(target: &str, level: Level) -> LogMsg { + let len = std::cmp::min(LOG_TARGET_SIZE, target.as_bytes().len()); + let mut buffer = LogMsg { + buffer: unsafe { MaybeUninit::uninit().assume_init() }, + target_len: len as _, + msg_len: len as _, + level: log_to_u8(level), + }; + unsafe { + std::ptr::copy_nonoverlapping( + target.as_bytes().as_ptr(), + std::mem::transmute(buffer.buffer.as_mut_ptr()), + len, + ); + } + buffer + } + + /// Clears the log message but keep the target and the level. + /// + /// # Examples + /// + /// ``` + /// use log::Level; + /// use bp3d_logger::LogMsg; + /// let mut msg = LogMsg::from_msg("test", Level::Info, "this is a test"); + /// msg.clear(); + /// assert_eq!(msg.msg(), ""); + /// assert_eq!(msg.target(), "test"); + /// assert_eq!(msg.level(), Level::Info); + /// ``` + #[inline] + pub fn clear(&mut self) { + self.msg_len = self.target_len as _; + } + + /// Auto-creates a new log message with a pre-defined string message. + /// + /// This function is the same as calling [write](LogMsg::write) after [new](LogMsg::new). + /// + /// # Arguments + /// + /// * `target`: the target name this log comes from. + /// * `level`: the [Level](Level) of the log message. + /// * `msg`: the message string. + /// + /// returns: LogMsg + /// + /// # Examples + /// + /// ``` + /// use log::Level; + /// use bp3d_logger::LogMsg; + /// let mut msg = LogMsg::from_msg("test", Level::Info, "this is a test"); + /// assert_eq!(msg.target(), "test"); + /// assert_eq!(msg.level(), Level::Info); + /// assert_eq!(msg.msg(), "this is a test"); + /// ``` + pub fn from_msg(target: &str, level: Level, msg: &str) -> LogMsg { + let mut ads = Self::new(target, level); + unsafe { ads.write(msg.as_bytes()) }; + ads + } + + /// Appends a raw byte buffer at the end of the message buffer. + /// + /// Returns the number of bytes written. + /// + /// # Arguments + /// + /// * `buf`: the raw byte buffer to append. + /// + /// returns: usize + /// + /// # Safety + /// + /// * [LogMsg](LogMsg) contains only valid UTF-8 strings so buf must contain only valid UTF-8 + /// bytes. + /// * If buf contains invalid UTF-8 bytes, further operations on the log message buffer may + /// result in UB. + pub unsafe fn write(&mut self, buf: &[u8]) -> usize { + let len = std::cmp::min(buf.len(), LOG_MSG_SIZE - self.msg_len as usize); + if len > 0 { + std::ptr::copy_nonoverlapping( + buf.as_ptr(), + std::mem::transmute(self.buffer.as_mut_ptr().offset(self.msg_len as _)), + len, + ); + self.msg_len += len as u32; //The length is always less than 2^32. + } + len + } + + /// Returns the target name this log comes from. + #[inline] + pub fn target(&self) -> &str { + // SAFEY: This is always safe because BufLogMsg is always UTF-8. + unsafe { + std::str::from_utf8_unchecked(std::mem::transmute(&self.buffer[..self.target_len as _])) + } + } + + /// Returns the log message as a string. + #[inline] + pub fn msg(&self) -> &str { + // SAFEY: This is always safe because BufLogMsg is always UTF-8. + unsafe { + std::str::from_utf8_unchecked(std::mem::transmute( + &self.buffer[self.target_len as _..self.msg_len as _], + )) + } + } + + /// Returns the level of this log message. + #[inline] + pub fn level(&self) -> Level { + u8_to_log(self.level) + } +} + +impl Write for LogMsg { + fn write_str(&mut self, s: &str) -> Result<(), Error> { + unsafe { + self.write(s.as_bytes()); + } + Ok(()) + } +}