rasant 1.1.0

use core::panic;
use ntime::Timestamp;
use std::error::Error;
use std::sync::{Arc, Mutex};

use crate::attributes;
use crate::attributes::Value;
use crate::constant::{ATTRIBUTE_KEY_ERROR, ATTRIBUTE_KEY_TRACE_FILENAME, ATTRIBUTE_KEY_TRACE_LINE, ATTRIBUTE_KEY_TRACE_LOGGER_ID, MAX_LOGGER_DEPTH};
use crate::filter;
use crate::format;
use crate::level::Level;
use crate::queue;
use crate::sink;
use crate::sink::{LogDepth, LogUpdate, PartialLogUpdate};
use crate::types::{AsyncSinkSender, FilterRef, SinkRef};

static GLOBAL_LOGGER_NEXT_UUID: Mutex<u32> = Mutex::new(0);

/// Base logger structure for Rasant.
pub struct Logger {
	id: u32,
	enabled: bool,
	depth: LogDepth,
	level: Level,
	async_sink_sender: Option<AsyncSinkSender>,
	attributes: attributes::Map,
	sinks: Vec<SinkRef>,
	filters: Vec<FilterRef>,
	common_partial_update: PartialLogUpdate,
	common_attributes: attributes::Map,
}

impl<'i> Logger {
	fn next_uuid() -> u32 {
		let mut next_id = GLOBAL_LOGGER_NEXT_UUID.lock().unwrap();
		let id = *next_id;
		*next_id += 1;

		id
	}

	/// Creates a brand new [`Logger`] instance, with a default level of [`Level::Warning`]
	/// and no associated sinks.
	pub fn new() -> Self {
		Self {
			id: Self::next_uuid(),
			enabled: true,
			depth: 0,
			level: Level::Warning,
			async_sink_sender: None,
			attributes: attributes::Map::new(),
			sinks: Vec::new(),
			filters: Vec::new(),
			common_partial_update: PartialLogUpdate::blank(),
			common_attributes: attributes::Map::new(),
		}
	}

	/// Returns whether this [`Logger`] is enabled or not. Disabled loggers will not write to
	/// any [`sink`], regardless of [`Level`].
	pub fn is_enabled(&self) -> bool {
		self.enabled
	}

	/// Enables this [`Logger`].
	pub fn enable(&mut self) {
		self.enabled = true;
	}

	/// Disables this [`Logger`].
	pub fn disable(&mut self) {
		self.enabled = false;
	}

	/// Returns `true` if this is a root [`Logger`] instance - i.e. it has no parents.
	pub fn is_root(&self) -> bool {
		return self.depth == 0;
	}

	fn has_sinks(&self) -> bool {
		!self.sinks.is_empty()
	}

	/// Returns the log [`Level`] for this [`Logger`] instance.
	pub fn level(&self) -> &Level {
		return &self.level;
	}

	/// Sets log [`Level`] for this [`Logger`] instance. Log updates below the
	/// given [`Level`] are ignored.
	pub fn set_level(&mut self, level: Level) -> &mut Self {
		if self.has_sinks() {
			self.trace_with("log level updated", [("name", Value::from(&level)), ("old_level", Value::from(&self.level))]);
		}
		self.level = level;

		self
	}

	/// Makes this [`Logger`] write all [`Level`]s, by setting the log level to minimum ([`Level::Trace`]).
	pub fn set_all_levels(&mut self) -> &mut Self {
		self.set_level(Level::Trace);

		self
	}

	/// Evaluates whether this [`Logger`] is in async mode or not.
	pub fn is_async(&self) -> bool {
		self.async_sink_sender.is_some()
	}

	/// Enables/disables async mode for this [`Logger`].
	///
	/// When async mode is enabled, log updates return immediately but are queued to
	/// write to the [`sink`]s associated to the [`Logger`] by a separate worker thread.
	/// Log updates for a given [`Logger`] are guaranteed to write in order.
	pub fn set_async(&mut self, async_writes: bool) -> &mut Self {
		if async_writes == self.is_async() {
			// nothing to do
			return self;
		}

		match async_writes {
			true => {
				queue::inc_refcount();
				self.async_sink_sender = Some(queue::get_sender());
			}
			false => {
				// order here is important! decrementing the async refcount before closing the
				// sender channel will deadlock active AsyncSinkHandler instances.
				self.async_sink_sender = None;
				queue::dec_refcount();
			}
		};

		if self.has_sinks() {
			self.trace_with(
				if async_writes { "enabled async log updates" } else { "disabled async log updates" },
				[("total_async_loggers", Value::from(queue::refcount()))],
			);
		}

		self
	}

	/// Adds a new logging [`sink`] to the [`Logger`] instance.
	///
	/// At least one [`sink`] is required for logging operations to succeed.
	pub fn add_sink<T: sink::Sink + Send + 'static>(&mut self, sink: T) -> &mut Self {
		// log*() locks sinks, so collect details we want to log about it beforehand
		let name: String = sink.name().into();

		self.sinks.push(Arc::new(Mutex::new(Box::new(sink))));

		self.trace_with(
			"added new log sink",
			[("name", Value::from(name)), ("total", Value::from(self.sinks.len() as u64)), ("async", Value::from(self.is_async()))],
		);

		self
	}

	/// Adds a new logging [`filter`] to the [`Logger`] instance.
	///
	/// Note that [`filter`]s are evaluated at logging time, and will introduce
	/// latency regardless of whether the [`Logger`] is async or not.
	pub fn add_filter<T: filter::Filter + Send + 'static>(&mut self, filter: T) -> &mut Self {
		let name: String = filter.name().into();
		self.filters.push(Arc::new(Mutex::new(Box::new(filter))));

		if self.has_sinks() {
			self.trace_with("added new log filter", [("name", Value::from(name)), ("total", Value::from(self.filters.len() as u64))]);
		}

		self
	}

	/// Sets an attribute value for a [`Logger`].
	///
	/// Attributes are key-value pairs of {attribute_name, [`Value`]}, and are attached
	/// to all log operations performed by the [`Logger`]. If the attribute already exists,
	/// it is overwritten.
	///
	/// The provided value must implement [`Into`] for [`Value`].
	pub fn set<T: Into<Value<'i>>>(&mut self, key: &'i str, v: T) -> &mut Self
	where
		Value<'i>: From<T>,
	{
		self.attributes.insert(key, Value::from(v));
		self
	}

	fn log_expanded<const X: usize, const Y: usize>(
		&mut self,
		level: Level,
		msg: &'i str,
		attrs_1: [(&'i str, Value); X],
		attrs_2: [(&'i str, Value); Y],
		loc: Option<&'static panic::Location<'static>>,
	) -> &mut Self {
		if !self.enabled {
			return self;
		}
		if !self.has_sinks() {
			panic!("tried to log without sinks configured for logger {id}", id = self.id);
		}
		// bail out early on negative log requests
		if !self.level.covers(&level) {
			return self;
		}

		let attrs = match attrs_1.is_empty() && attrs_2.is_empty() {
			true => &mut self.attributes,
			false => {
				// straight up copying and extending ephemeral attributes is the most efficient
				// way to deal with potential collisions. trust me, i've tried everything else.
				self.common_attributes.copy_from(&self.attributes);
				attrs_1.iter().for_each(|(k, v)| self.common_attributes.insert_ref_ephemeral(k, &v));
				attrs_2.iter().for_each(|(k, v)| self.common_attributes.insert_ref_ephemeral(k, &v));

				&mut self.common_attributes
			}
		};

		// add trace-specific attributes, if necessary.
		if level == Level::Trace {
			attrs.insert_ephemeral(ATTRIBUTE_KEY_TRACE_LOGGER_ID, Value::from(self.id));
			if let Some(loc) = loc {
				attrs.insert_ephemeral(ATTRIBUTE_KEY_TRACE_FILENAME, Value::from(loc.file()));
				attrs.insert_ephemeral(ATTRIBUTE_KEY_TRACE_LINE, Value::from(loc.line()));
			}
		}

		self.common_partial_update.when.copy_from(&Timestamp::now());
		self.common_partial_update.level = level;
		self.common_partial_update.depth = self.depth;
		self.common_partial_update.set_msg(msg);
		let update = LogUpdate::from((&self.common_partial_update, attrs as &attributes::Map));

		// apply filters, if any
		if self.filters.iter().any(|f| f.lock().unwrap().skip(&update)) {
			return self;
		}

		// if we're about to panic, parse the message before attempting to
		// deliver the log update - and losing ownership.
		let panic_msg: Option<String> = if level == Level::Panic { Some(format::as_panic_string(&update)) } else { None };

		for asink in self.sinks.iter() {
			let res = match self.async_sink_sender {
				Some(ref tx) => {
					queue::log(&tx, &asink, &update);
					Ok(())
				}
				None => asink.lock().unwrap().log(&update),
			};
			if let Err(e) = res {
				panic!("failed to log update {update:?} on sink {name} for logger {id}: {e}", name = asink.lock().unwrap().name(), id = self.id);
			}
		}

		if panic_msg.is_some() {
			// oh no :( log as best we can, then bail out
			self.flush();
			panic!("{}", panic_msg.unwrap());
		}

		self
	}

	/// Logs a message with a given level, and no additional attributes.
	#[inline]
	#[track_caller]
	pub fn log(&mut self, level: Level, msg: &'i str) -> &mut Self {
		self.log_expanded(level, msg, [], [], Some(panic::Location::caller()))
	}

	/// Logs a message with a given level and additional attribute [`Value`]s.
	#[inline]
	#[track_caller]
	pub fn log_with<const L: usize>(&mut self, level: Level, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(level, msg, attrs, [], Some(panic::Location::caller()))
	}

	/// Logs a [`Level::Trace`] message, with no user-provided attributes, and the caller's filename and line number annotated as attributes.
	#[inline]
	#[track_caller]
	pub fn trace(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Trace, msg, [], [], Some(panic::Location::caller()))
	}

	/// Logs a [`Level::Trace`] message, with additional attribute [`Value`]s. Caller's filename and line are also annotated as attributes.
	#[inline]
	#[track_caller]
	pub fn trace_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Trace, msg, attrs, [], Some(panic::Location::caller()))
	}

	/// Logs a [`Level::Debug`] message, with no additional attributes.
	#[inline]
	pub fn debug(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Debug, msg, [], [], None)
	}

	/// Logs a [`Level::Debug`] message, with additional attribute [`Value`]s.
	#[inline]
	pub fn debug_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Debug, msg, attrs, [], None)
	}

	/// Logs a [`Level::Info`] message, with no additional attributes.
	#[inline]
	pub fn info(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Info, msg, [], [], None)
	}

	/// Logs a [`Level::Info`] message, with additional attribute [`Value`]s.
	#[inline]
	pub fn info_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_with(Level::Info, msg, attrs)
	}

	/// Logs a [`Level::Warning`] message, with no additional attributes.
	#[inline]
	pub fn warn(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Warning, msg, [], [], None)
	}

	/// Logs a [`Level::Warning`] message, with additional attribute [`Value`]s.
	#[inline]
	pub fn warn_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Warning, msg, attrs, [], None)
	}

	/// Logs a [`Level::Error`] message, with no additional attributes.
	#[inline]
	pub fn err(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Error, msg, [], [], None)
	}

	/// Logs a [`Level::Error`] message, with additional attribute [`Value`]s.
	#[inline]
	pub fn err_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Error, msg, attrs, [], None)
	}

	/// Logs a [`Level::Error`] message for a given [`Error`], with no additional attributes.
	#[inline]
	pub fn error<T: Error>(&mut self, error: T, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Error, msg, [], [(ATTRIBUTE_KEY_ERROR, Value::from(error.to_string()))], None)
	}

	/// Logs a [`Level::Error`] message for a given [`Error`], with additional attribute [`Value`]s.
	#[inline]
	pub fn error_with<T: Error, const L: usize>(&mut self, error: T, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Error, msg, attrs, [(ATTRIBUTE_KEY_ERROR, Value::from(error.to_string()))], None)
	}

	/// Logs a [`Level::Fatal`] message, with no additional attributes.
	#[inline]
	pub fn fatal(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Fatal, msg, [], [], None)
	}

	/// Logs a [`Level::Fatal`] message, with additional attribute [`Value`]s.
	#[inline]
	pub fn fatal_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Fatal, msg, attrs, [], None)
	}

	/// Logs a [`Level::Panic`] message, with no additional attributes, and panics the current process.
	#[inline]
	pub fn panic(&mut self, msg: &'i str) -> &mut Self {
		self.log_expanded(Level::Panic, msg, [], [], None)
	}

	/// Logs a [`Level::Panic`] message, with additional attribute [`Value`]s, and panics the current process.
	#[inline]
	pub fn panic_with<const L: usize>(&mut self, msg: &'i str, attrs: [(&'i str, Value); L]) -> &mut Self {
		self.log_expanded(Level::Panic, msg, attrs, [], None)
	}

	/// Flushes all pending writes on [`sink`]s for this [`Logger`].
	///
	/// If async mode is enabled, flushing is deferred via the same queue used to write
	/// log messages. The method will not lock, and return immediately, but actual flushes
	/// will materialize later.
	pub fn flush(&mut self) -> &Self {
		for asink in self.sinks.iter() {
			// TODO: fix logging.
			//let name = asink.lock().unwrap().as_mut().name();
			let res = match self.async_sink_sender {
				Some(ref tx) => {
					queue::flush(&tx, &asink);
					Ok(())
				}
				None => asink.lock().unwrap().flush(),
			};
			if let Err(e) = res {
				panic!("failed to flush sink {name} for logger {id}: {e}", name = asink.lock().unwrap().name(), id = self.id);
			}
		}

		self
	}
}

impl Clone for Logger {
	fn clone(&self) -> Self {
		if self.depth >= MAX_LOGGER_DEPTH {
			panic!("cannot clone logger {id} with maximum log depth of {max_depth}", max_depth = MAX_LOGGER_DEPTH, id = self.id);
		}

		let mut clone = Self {
			id: Self::next_uuid(),
			enabled: self.enabled,
			depth: self.depth + 1,
			level: self.level,
			// async state is modified via set_async()
			async_sink_sender: None,
			attributes: self.attributes.clone(),
			sinks: self.sinks.clone(),
			filters: self.filters.clone(),
			common_partial_update: PartialLogUpdate::blank(),
			common_attributes: attributes::Map::new(),
		};
		clone.set_async(self.is_async());

		clone
	}
}

impl Drop for Logger {
	fn drop(&mut self) {
		self.flush();

		/*
		// If we're dropping a root logger, make sure any async writes left are processed.
		if self.depth == 0 {
			queue::flush_queue();
		}
		*/

		self.set_async(false);
	}
}

/* ----------------------- Tests ----------------------- */

#[cfg(test)]
mod basic {
	use crate::constant::MAX_LOGGER_DEPTH;

	use super::*;

	#[test]
	#[should_panic]
	fn panic_no_sinks() {
		let mut log = Logger::new();
		log.set_level(Level::Info).info("this should explode");
	}

	#[test]
	#[should_panic]
	fn panic_log_panics() {
		let mut log = Logger::new();
		log.add_sink(sink::stdout::default()).set_level(Level::Info);

		log.info("this should log fine");
		log.panic("and this should explode");
	}

	#[test]
	fn set_async_before_sinks() {
		let mut log = Logger::new();
		log.set_async(true).add_sink(sink::stdout::default());
		log.info("this should log fine");
	}

	#[test]
	#[should_panic]
	fn max_depth_exceeded() {
		let mut log = Logger::new();
		for _ in 0..MAX_LOGGER_DEPTH + 1 {
			log = log.clone();
		}
	}
}

#[cfg(test)]
mod log_disabling {
	use super::*;

	#[test]
	fn basic() {
		let mem_sink = sink::memory::Memory::new(sink::memory::MemoryConfig {
			mock_time: true,
			formatter_cfg: format::FormatterConfig {
				time_format: ntime::Format::UtcMillisDateTime,
				delimiter: vec![b'\n'],
				..format::FormatterConfig::default()
			},
			..sink::memory::MemoryConfig::default()
		});
		let mem_sink_output = mem_sink.output();

		let mut log = Logger::new();
		log.add_sink(mem_sink).set_level(Level::Info);

		let got: String;
		{
			log.disable();
			assert!(!log.is_enabled());
			log.info("these should not");
			log.warn("log anything");
			log.enable();
			assert!(log.is_enabled());
			log.info("but these");
			log.warn("should");

			got = mem_sink_output.as_string();
		}

		let want = "2026-03-04 15:10:15.000 [INF] but these\n\
		            2026-03-04 15:10:16.234 [WRN] should";
		assert_eq!(got, want);
	}

	#[test]
	fn disabled_without_sink() {
		let mut log = Logger::new();
		log.disable();

		log.info("disabled loggers without sinks should not panic");
	}
}

#[cfg(test)]
mod attribute_handling {
	use super::*;
	use crate::attributes::Scalar;

	#[test]
	fn set_casting() {
		let mut log = Logger::new();
		log.set("scalar", 12345);
		log.set("value_scalar", "hello!");
		log.set("casted_value_scalar", Value::from("hello!"));
		log.set("value_list", &[Scalar::from(12345 as u32), Scalar::from("hello!")]);
		log.set("value_map", (&[Scalar::from("key_a"), Scalar::from("key_b")], &[Scalar::from(12345 as u32), Scalar::from("hello!")]));
	}
}

#[cfg(test)]
mod formatting {
	use crate::FormatterConfig;
	use crate::console;

	use super::*;
	use ntime;
	use std::io::{Error, ErrorKind};

	#[test]
	fn color_formatted_output() {
		struct TestCase<'t> {
			name: &'t str,
			out_format: format::OutputFormat,
			time_format: ntime::Format,
			colorterm: bool,
			want: &'t str,
		}

		let test_cases = [
			TestCase {
				name: "compact default",
				out_format: format::OutputFormat::Compact,
				time_format: ntime::Format::UtcMillisDateTime,
				colorterm: false,
				want: "2026-03-04 15:10:15.000 [INF] root test info\n\
				       2026-03-04 15:10:16.234 [WRN] root test warn\n\
					   2026-03-04 15:10:17.468 [INF] first test info number=1\n\
					   2026-03-04 15:10:18.702 [WRN] first test warn number=1\n\
					   2026-03-04 15:10:19.936 [DBG] first test debug number=1\n\
					   2026-03-04 15:10:21.170 [ERR] something failed error=\"oh no\" number=1",
			},
			TestCase {
				name: "compact color, ANSI console",
				out_format: format::OutputFormat::ColorCompact,
				time_format: ntime::Format::UtcMillisDateTime,
				colorterm: true,
				want: "\u{1b}[37m2026-03-04 15:10:15.000 \u{1b}[32mINF \u{1b}[97mroot test info\u{1b}[0m\n\
				       \u{1b}[37m2026-03-04 15:10:16.234 \u{1b}[33mWRN \u{1b}[97mroot test warn\u{1b}[0m\n\
				       \u{1b}[37m2026-03-04 15:10:17.468 \u{1b}[32mINF \u{1b}[97mfirst test info \u{1b}[96mnumber=\u{1b}[37m1\u{1b}[0m\n\
				       \u{1b}[37m2026-03-04 15:10:18.702 \u{1b}[33mWRN \u{1b}[97mfirst test warn \u{1b}[96mnumber=\u{1b}[37m1\u{1b}[0m\n\
				       \u{1b}[37m2026-03-04 15:10:19.936 \u{1b}[94mDBG \u{1b}[37mfirst test debug \u{1b}[96mnumber=\u{1b}[37m1\u{1b}[0m\n\
				       \u{1b}[37m2026-03-04 15:10:21.170 \u{1b}[31mERR \u{1b}[97msomething failed \u{1b}[36merror=\u{1b}[91m\"oh no\" \u{1b}[96mnumber=\u{1b}[37m1\u{1b}[0m",
			},
			TestCase {
				name: "compact color, non-ANSI console",
				out_format: format::OutputFormat::ColorCompact,
				time_format: ntime::Format::UtcMillisDateTime,
				colorterm: false,
				want: "2026-03-04 15:10:15.000 INF root test info\n\
				       2026-03-04 15:10:16.234 WRN root test warn\n\
					   2026-03-04 15:10:17.468 INF first test info number=1\n\
					   2026-03-04 15:10:18.702 WRN first test warn number=1\n\
					   2026-03-04 15:10:19.936 DBG first test debug number=1\n\
					   2026-03-04 15:10:21.170 ERR something failed error=\"oh no\" number=1",
			},
			TestCase {
				name: "full color, ANSI console",
				out_format: format::OutputFormat::ColorFull,
				time_format: ntime::Format::UtcMillisDateTime,
				colorterm: true,
				want: "\u{1b}[37m2026-03-04 15:10:15.000 \u{1b}[32mINFO    \u{1b}[97mroot test info\u{1b}[0m
\u{1b}[37m2026-03-04 15:10:16.234 \u{1b}[33mWARNING \u{1b}[97mroot test warn\u{1b}[0m
\u{1b}[37m2026-03-04 15:10:17.468 \u{1b}[32mINFO    \u{1b}[96mnumber=\u{1b}[37m1
                                \u{1b}[97mfirst test info\u{1b}[0m
\u{1b}[37m2026-03-04 15:10:18.702 \u{1b}[33mWARNING \u{1b}[96mnumber=\u{1b}[37m1
                                \u{1b}[97mfirst test warn\u{1b}[0m
\u{1b}[37m2026-03-04 15:10:19.936 \u{1b}[94mDEBUG   \u{1b}[96mnumber=\u{1b}[37m1
                                \u{1b}[37mfirst test debug\u{1b}[0m
\u{1b}[37m2026-03-04 15:10:21.170 \u{1b}[31mERROR   \u{1b}[96mnumber=\u{1b}[37m1
                                \u{1b}[36merror=\u{1b}[91m\"oh no\"
                                \u{1b}[97msomething failed\u{1b}[0m",
			},
			TestCase {
				name: "full color, non-ANSI console",
				out_format: format::OutputFormat::ColorFull,
				time_format: ntime::Format::UtcMillisDateTime,
				colorterm: false,
				want: "2026-03-04 15:10:15.000 INFO    root test info
2026-03-04 15:10:16.234 WARNING root test warn
2026-03-04 15:10:17.468 INFO    number=1
                                first test info
2026-03-04 15:10:18.702 WARNING number=1
                                first test warn
2026-03-04 15:10:19.936 DEBUG   number=1
                                first test debug
2026-03-04 15:10:21.170 ERROR   number=1
                                error=\"oh no\"
                                something failed",
			},
		];

		for tc in test_cases {
			let got: String;

			{
				let mem_sink = sink::memory::Memory::new(sink::memory::MemoryConfig {
					mock_time: true,
					formatter_cfg: format::FormatterConfig {
						format: tc.out_format,
						time_format: tc.time_format,
						delimiter: vec![b'\n'],
						..FormatterConfig::default()
					},
					..sink::memory::MemoryConfig::default()
				});
				let mem_sink_output = mem_sink.output();
				console::colorterm_force(tc.colorterm);

				let mut log = Logger::new();
				log.add_sink(mem_sink).set_level(Level::Info);

				log.info("root test info").warn("root test warn").debug("root test debug");

				let mut nlog = log.clone();
				nlog.set_level(Level::Debug).set("number", 1);
				nlog.info("first test info")
					.warn("first test warn")
					.debug("first test debug")
					.trace("trace log to be ignored")
					.error(Error::new(ErrorKind::NotFound, "oh no"), "something failed");

				got = mem_sink_output.as_string();
				console::colorterm_unforce();
			}

			assert_eq!(got, tc.want, "{}", tc.name);
		}
	}
}