#![doc = include_str!("../README.md")]
#![deny(warnings)]
#![deny(rust_2018_idioms)]
#![deny(clippy::all)]
#![deny(clippy::pedantic)]
#![deny(clippy::perf)]
#![deny(clippy::nursery)]
#![deny(clippy::cargo)]
pub use loggy_macros::scope;
use chrono::Utc;
use lazy_static::lazy_static;
use log::{logger, set_logger, set_max_level, Level, LevelFilter, Log, Metadata, Record};
use parking_lot::Mutex;
use std::cell::Cell;
use std::fmt::Write;
use std::io::{stderr, Write as IoWrite};
use std::marker::PhantomData;
use std::panic::{catch_unwind, set_hook, take_hook, AssertUnwindSafe};
use std::sync::atomic::AtomicBool;
use std::thread::panicking;
use unindent::unindent;
pub const VERSION: &str = "0.5.3";
#[macro_export]
macro_rules! log {
( $level:expr , $format:literal $( ; $( $tail:tt )* )? ) => {
{
if $level == log::Level::Error || log::log_enabled!($level) {
#[allow(unused_mut)]
let mut string = format!($format);
$(
let mut indent = " ".to_owned();
log!( @collect string , indent , $( $tail )* );
)?
log::log!( $level , "{}" , string );
}
}
};
( $level:expr , $format:literal $( , $value:expr )* $( ; $( $tail:tt )* )? ) => {
{
if $level == log::Level::Error || log::log_enabled!($level) {
#[allow(unused_mut)]
let mut string = format!($format $( , $value )* );
$(
let mut indent = " ".to_owned();
log!( @collect string , indent , $( $tail )* );
)?
log::log!( $level , "{}" , string );
}
}
};
( @collect $string:ident , $indent:ident , $name:ident $( , )? ) => {
$string.push_str(format!("\n{}{}: {}", $indent, stringify!($name), $name).as_str());
};
( @collect $string:ident , $indent:ident , $name:ident , $( $tail:tt )* ) => {
log!( @collect $string , $indent , $name );
log!( @collect $string , $indent , $( $tail )* );
};
( @collect $string:ident, $indent:ident , $name:ident => $value:expr $( , )? ) => {
$string.push_str(format!("\n{}{}: {}", $indent, stringify!($name), $value).as_str());
};
( @collect $string:ident, $indent:ident , $name:ident => $value:expr , $( $tail:tt )* ) => {
log!( @collect $string , $indent , $name => $value );
log!( @collect $string , $indent , $( $tail )* );
};
( @collect $string:ident , $indent:ident, $name:ident { $( $nest:tt )* } $( , )? ) => {
$string.push_str(format!("\n{}{}:", $indent, stringify!($name)).as_str());
$indent.push_str(" ");
log!( @collect $string , $indent , $( $nest )* );
$indent.pop();
$indent.pop();
};
( @collect $string:ident , $indent:ident, $name:ident { $( $nest:tt )* } , $( $tail:tt )* ) => {
log!( @collect $string , $indent , $name { $( $nest )* } );
log!( @collect $string , $indent , $( $tail )* );
};
}
#[macro_export]
macro_rules! error { ( $( $arg:tt )* ) => {
loggy::log!( log::Level::Error , $( $arg )* );
} }
#[macro_export]
macro_rules! panic {
( $( $arg:tt )* ) => {
{
loggy::force_panic();
loggy::error!( $( $arg )* );
std::unreachable!();
}
}
}
#[macro_export]
macro_rules! warn { ( $( $arg:tt )* ) => { loggy::log!( log::Level::Warn , $( $arg )* )
} }
#[macro_export]
macro_rules! note {
( $is_error:expr, $( $arg:tt )* ) => {
if $is_error {
loggy::error!( $( $arg )* );
} else {
loggy::warn!( $( $arg )* );
}
};
}
#[macro_export]
macro_rules! info { ( $( $arg:tt )* ) => { loggy::log!( log::Level::Info , $( $arg )* ) } }
#[macro_export]
macro_rules! debug { ( $( $arg:tt )* ) => { loggy::log!( log::Level::Debug , $( $arg )* ) } }
#[macro_export]
macro_rules! todox { ( $( $arg:tt )* ) => { loggy::debug!( $( $arg )* ) } }
#[macro_export]
macro_rules! trace { ( $( $arg:tt )* ) => { loggy::log!( log::Level::Trace , $( $arg )* ) } }
#[macro_export]
macro_rules! is_an_error {
($default:expr) => {
static IS_AN_ERROR: std::sync::atomic::AtomicBool =
std::sync::atomic::AtomicBool::new($default);
pub fn set_is_an_error(is_error: bool) -> bool {
IS_AN_ERROR.swap(is_error, std::sync::atomic::Ordering::Relaxed)
}
pub fn is_an_error() -> bool {
IS_AN_ERROR.load(std::sync::atomic::Ordering::Relaxed)
}
};
}
#[derive(Clone, Copy)]
struct NamedScope {
name: &'static str,
index: Option<isize>,
errors: usize,
}
thread_local! { static NAMED_SCOPE: Cell<Option<NamedScope>> = Cell::new(None);
}
#[must_use] pub fn scope_errors() -> usize {
NAMED_SCOPE.with(|named_scope| {
named_scope
.get() .map_or(0, |named_scope| named_scope.errors)
})
}
pub struct Scope<'a> {
previous: Option<NamedScope>,
name_lifetime: PhantomData<&'a str>,
}
impl<'a> Scope<'a> {
#[must_use] pub fn new(name: &'a str) -> Self {
let name_ptr: *const str = name;
let static_name_ref: &'static str = unsafe { &*name_ptr };
let next: NamedScope = NamedScope {
name: static_name_ref,
index: None,
errors: 0,
};
let previous = NAMED_SCOPE.with(|named_scope| named_scope.replace(Some(next)));
Scope {
previous,
name_lifetime: PhantomData,
}
}
#[must_use]
pub fn new_indexed(name: &'a str, index: isize) -> Self {
let name_ptr: *const str = name;
let static_name_ref: &'static str = unsafe { &*name_ptr };
let next: NamedScope = NamedScope {
name: static_name_ref,
index: Some(index),
errors: 0,
};
let previous = NAMED_SCOPE.with(|named_scope| named_scope.replace(Some(next)));
Scope {
previous,
name_lifetime: PhantomData,
}
}
pub fn with<T, Code: FnOnce() -> T>(name: &'a str, code: Code) -> T {
let _scope = Scope::new(name);
code()
}
pub fn with_indexed<T, Code: FnOnce() -> T>(name: &'a str, index: isize, code: Code) -> T {
let _scope = Scope::new_indexed(name, index);
code()
}
}
impl<'a> Drop for Scope<'a> {
fn drop(&mut self) {
let current = NAMED_SCOPE
.with(|named_scope| named_scope.replace(self.previous))
.unwrap();
if current.errors > 0 && !panicking() {
current.index.map_or_else(
|| {
std::panic!(
"{}: [ERROR] {}: failed with {} error(s)", Loggy::global().prefix,
current.name, current.errors );
},
|index| {
std::panic!(
"{}: [ERROR] {}@{}: failed with {} error(s)",
Loggy::global().prefix,
current.name,
index,
current.errors
);
},
);
}
}
}
pub struct Loggy {
pub prefix: &'static str,
pub show_time: bool,
pub show_thread: bool,
}
static TOTAL_THREADS: std::sync::atomic::AtomicUsize = std::sync::atomic::AtomicUsize::new(0);
thread_local!(
static THREAD_ID: Cell<Option<usize>> = Cell::new(None);
static FORCE_PANIC: Cell<bool> = Cell::new(false);
);
impl Log for Loggy {
fn enabled(&self, metadata: &Metadata<'_>) -> bool {
metadata.level() == Level::Error
|| metadata.level() == Level::Debug
|| metadata.level() <= log::max_level()
}
fn log(&self, record: &Record<'_>) {
if self.enabled(record.metadata()) {
emit_message(record.level(), self.format_message(record).as_ref());
}
}
fn flush(&self) {
stderr().flush().unwrap();
}
}
impl Loggy {
fn global() -> &'static Self {
let logger_ptr: *const dyn Log = logger();
#[allow(clippy::cast_ptr_alignment)]
#[allow(clippy::ptr_as_ptr)]
unsafe {
&*(logger_ptr as *const Self)
}
}
fn format_message(&self, record: &Record<'_>) -> String {
let now = if self.show_time {
format!("{}", Utc::now().format("%F %T%.3f")) } else {
String::new()
};
let mut message = String::with_capacity(128);
writeln!(&mut message, "{}", record.args()).unwrap();
let mut buffer = String::with_capacity(128 + message.len());
let mut level = record.level().to_string();
for (index, line) in message.lines().enumerate() {
if index > 0 {
level = level.to_lowercase();
}
self.append_prefix(&mut buffer, now.as_ref(), level.as_ref(), record);
writeln!(&mut buffer, " {}", line).unwrap();
}
buffer
}
fn append_prefix(&self, mut message: &mut String, now: &str, level: &str, record: &Record<'_>) {
message.push_str(self.prefix);
if self.show_thread {
THREAD_ID.with(|thread_id_cell| {
if thread_id_cell.get().is_none() {
let total_threads =
TOTAL_THREADS.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
thread_id_cell.set(Some(total_threads));
}
let current_thread_id = thread_id_cell.get().unwrap();
write!(&mut message, "[{}]", current_thread_id).unwrap();
});
}
message.push(':');
if self.show_time {
message.push(' '); message.push_str(now); }
write!(&mut message, " [{}]", level).unwrap();
if record.level() == Level::Debug {
write!(
&mut message,
" {}:{}:",
record.file().unwrap(), record.line().unwrap() )
.unwrap();
}
let (scope, index) = NAMED_SCOPE.with(|named_scope| {
named_scope
.get() .map_or((record.module_path().unwrap(), None), |scope| {
(scope.name, scope.index)
})
});
if !scope.is_empty() {
if let Some(index) = index {
write!(&mut message, " {}@{}:", scope, index).unwrap();
} else {
write!(&mut message, " {}:", scope).unwrap();
}
}
}
}
lazy_static! { static ref LOG_BUFFER: Mutex<Cell<Option<String>>> = Mutex::new(Cell::new(None));
static ref MIRROR_TO_STDERR: bool = std::env::var("LOGGY_MIRROR_TO_STDERR")
.map(|var| !var.is_empty())
.unwrap_or(false);
}
static DID_SET_LOGGER: AtomicBool = AtomicBool::new(false);
#[doc(hidden)] pub fn force_panic() {
FORCE_PANIC.with(|force_panic| {
force_panic.set(true);
});
}
fn emit_message(level: Level, message: &str) {
if level == Level::Debug {
eprint!("{}", message); return; }
if level == Level::Error {
if FORCE_PANIC.with(|force_panic| force_panic.replace(false)) {
std::panic!("{}", message);
} else {
NAMED_SCOPE.with(|maybe_named_scope| {
if let Some(ref mut named_scope) = maybe_named_scope.get() {
named_scope.errors += 1;
maybe_named_scope.set(Some(*named_scope));
} else {
std::panic!(
"{}: error! called outside a named scope", Loggy::global().prefix,
);
}
});
}
}
let mut log_buffer = LOG_BUFFER.lock();
log_buffer.get_mut().as_mut().map_or_else(
|| eprint!("{}", message),
|buffer| {
if *MIRROR_TO_STDERR {
eprint!("{}", message); }
buffer.push_str(message);
},
);
}
struct Capture {}
impl Capture {
fn new() -> Self {
if !DID_SET_LOGGER.swap(true, std::sync::atomic::Ordering::Relaxed) {
set_logger(&Loggy {
prefix: "test", show_time: false, show_thread: false, })
.unwrap();
set_max_level(LevelFilter::Trace);
}
LOG_BUFFER.lock().set(Some(String::new()));
TOTAL_THREADS.store(0, std::sync::atomic::Ordering::Relaxed);
THREAD_ID.with(|thread_id_cell| thread_id_cell.set(None));
Self {}
}
}
impl Drop for Capture {
fn drop(&mut self) {
LOG_BUFFER.lock().set(None);
}
}
lazy_static! { static ref SINGLE_TEST: Mutex<()> = Mutex::new(());
}
pub fn assert_logs<Code: FnOnce() -> Result, Result>(expected_log: &str, code: Code) -> Result {
let _single_test = SINGLE_TEST.lock();
do_assert_logs_panics(Some(expected_log), None, code).unwrap()
}
pub fn assert_panics<Code: FnOnce() -> Result, Result>(expected_panic: &str, code: Code) {
let _single_test = SINGLE_TEST.lock();
do_assert_logs_panics(None, Some(expected_panic), code);
}
pub fn assert_logs_panics<Code: FnOnce() -> Result, Result>(
expected_log: &str,
expected_panic: &str,
code: Code,
) {
let _single_test = SINGLE_TEST.lock();
do_assert_logs_panics(Some(expected_log), Some(expected_panic), code);
}
pub fn assert_errors<Code: FnOnce() -> Result, Result>(
scope: &str,
expected_log: &str,
code: Code,
) {
let expected_errors = expected_log.matches("[ERROR]").count();
assert!(expected_errors > 0, "expected log contains no errors");
assert_logs_panics(
expected_log, format!(
"test: [ERROR] {}: failed with {} error(s)", scope, expected_errors )
.as_str(), || Scope::with(scope, code),
);
}
fn do_assert_logs_panics<Code: FnOnce() -> Result, Result>(
expected_log: Option<&str>,
expected_panic: Option<&str>,
code: Code,
) -> Option<Result> {
let _capture = Capture::new();
if let Some(expected_panic) = expected_panic {
let prev_hook = take_hook();
set_hook(Box::new(|_| {}));
let result = catch_unwind(AssertUnwindSafe(code));
set_hook(prev_hook);
do_assert_logs(expected_log);
match result {
Ok(_) => std::panic!("test did not panic"),
Err(error) => {
#[allow(clippy::option_if_let_else)]
let actual_panic = if let Some(actual_panic) = error.downcast_ref::<String>() {
actual_panic.as_str()
} else if let Some(actual_panic) = error.downcast_ref::<&'static str>() {
actual_panic
} else {
"unknown panic"
};
let expected_panic = fix_expected(expected_panic);
if actual_panic != expected_panic {
print!(
"ACTUAL PANIC:\n>>>\n{}<<<\nIS DIFFERENT FROM EXPECTED PANIC:\n>>>\n{}<<<\n",
actual_panic, expected_panic
);
assert_eq!("ACTUAL PANIC", "EXPECTED PANIC");
} }
}
None
} else {
let result = code();
do_assert_logs(expected_log);
Some(result)
}
}
fn do_assert_logs(expected_log: Option<&str>) {
if let Some(expected_log) = expected_log {
let actual_log = LOG_BUFFER.lock().take().unwrap();
let expected_log = fix_expected(expected_log);
if actual_log != expected_log {
print!(
"ACTUAL LOG:\n>>>\n{}<<<\nIS DIFFERENT FROM EXPECTED LOG:\n>>>\n{}<<<\n",
actual_log, expected_log
);
assert_eq!("ACTUAL LOG", "EXPECTED LOG");
} }
}
pub fn assert_writes<Code: FnOnce(&mut dyn IoWrite)>(expected_string: &str, code: Code) {
let mut actual_bytes: Vec<u8> = vec![];
code(&mut actual_bytes);
let actual_string = String::from_utf8(actual_bytes).ok().unwrap();
let expected_string = fix_expected(expected_string);
if actual_string != expected_string {
print!(
"ACTUAL WRITTEN:\n>>>\n{}<<<\nIS DIFFERENT FROM EXPECTED WRITTEN:\n>>>\n{}<<<\n",
actual_string, expected_string
);
assert_eq!("ACTUAL WRITTEN", "EXPECTED WRITTEN");
}
}
fn fix_expected(expected: &str) -> String {
let needs_trailing_newline = expected.ends_with('\n') || expected.ends_with(' ');
let expected = unindent(expected);
let expected = expected.strip_prefix('\n').unwrap_or(&expected);
match (expected.ends_with('\n'), needs_trailing_newline) {
(true, false) => expected.strip_suffix('\n').unwrap().to_owned(), (false, true) => format!("{}\n", expected),
_ => expected.to_owned(),
}
}