// Copyright 2017 Oren Ben-Kiki. See the COPYRIGHT
// file at the top-level directory of this distribution and at
// http://rust-lang.org/COPYRIGHT.
//
// Licensed under the MIT license
// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
// option. This file may not be copied, modified, or distributed
// except according to those terms.

//! An opinionated library for developing and testing rust applications that use logging.

extern crate log;
extern crate time;

#[macro_use]
extern crate lazy_static;

use log::{Log, LogLevel, LogMetadata, LogRecord, SetLoggerError};
use std::cell::RefCell;
use std::fmt::Write;
use std::sync::{Mutex, Once, ONCE_INIT};

/// Generate a debug log message.
///
/// This is identical to invoking `debug!(...)`. Renaming it `todox!` ensures
/// all uses will be reported by `cargo todox`, to ensure their removal once
/// their usefulness is past.
///
/// `LogLevel::Debug` messages are given special treatment by `loggy`. They are
/// always emitted in tests generated by the `test_loggy!` macro. They are
/// always directed to the standard error stream, and not captured in the log
/// buffer, even in such tests.
#[macro_export]
macro_rules! todox {
    (target: $target:expr, $($arg:tt)*) => (
        debug!(target: $target, $($arg)*);
    );
    ($($arg:tt)*) => (
        debug!($($arg)*);
    )
}

/// Generate either an error or a warning, depending on some configuration
/// parameter.
///
/// Invoking `note!(is_error, ...)` is identical to invoking `error!` if
/// `is_error` is `true`, or `warn!` if `is_error` is `false`. This allows
/// easily handling conditions whose handling depends on command line
/// arguments or other considerations.
#[macro_export]
macro_rules! note {
    ($is_error:expr, target: $target:expr, $($arg:tt)*) => (
        log!(target: $target,
             if $is_error { log::LogLevel::Error } else { log::LogLevel::Warn },
             $($arg)*);
    );
    ($is_error:expr, $($arg:tt)*) => (
        log!(if $is_error { log::LogLevel::Error } else { log::LogLevel::Warn },
             $($arg)*);
    )
}

/// Control the behavior of the `loggy` logger.
pub struct Loggy {
    /// A prefix appended to each message.
    ///
    /// This typically contains the name of the program.
    pub prefix: &'static str,

    /// Whether to include the date and time in the log message.
    pub show_time: bool,

    /// The threshold level of messages to actually emit.
    ///
    /// When running tests, `LogLevel::Debug` messages are always emitted,
    /// regardless of this setting, to facilitate debugging failing tests.
    pub log_level: LogLevel,
}

impl Log for Loggy {
    fn enabled(&self, metadata: &LogMetadata) -> bool {
        metadata.level() == LogLevel::Debug || metadata.level() <= self.log_level
    }

    fn log(&self, record: &LogRecord) {
        count_errors(record.level());
        if self.enabled(record.metadata()) {
            emit_message(record.level(), self.format_message(record).as_ref());
        }
    }
}

lazy_static!(static ref TOTAL_THREADS: Mutex<RefCell<usize>> = Mutex::new(RefCell::new(0)););

thread_local!(static THREAD_ID: RefCell<Option<usize>> = RefCell::new(None););

impl Loggy {
    fn format_message(&self, record: &LogRecord) -> String {
        let mut message = String::with_capacity(256);
        message.push_str(self.prefix);

        THREAD_ID.with(|thread_id_cell| {
            let mut current_thread_option = thread_id_cell.borrow_mut();
            if current_thread_option.is_none() {
                let lock_total_threads = TOTAL_THREADS.lock().unwrap();
                let mut total_threads = lock_total_threads.borrow_mut();
                *current_thread_option = Some(*total_threads);
                *total_threads += 1;
            }
            let current_thread_id = current_thread_option.unwrap();
            if current_thread_id > 0 {
                write!(&mut message, "[{}]", current_thread_id).unwrap();
            }
        });

        message.push(':');

        if self.show_time {
            message.push(' ');
            message.push_str(
                time::strftime("%Y-%m-%d %H:%M:%S", &time::now())
                    .unwrap()
                    .as_ref(),
            );
        }

        write!(&mut message, " [{}]", record.level().to_string()).unwrap();

        if record.level() == LogLevel::Debug {
            write!(
                &mut message,
                " {}:{}:",
                record.location().file(),
                record.location().line()
            ).unwrap();
        } else {
            write!(&mut message, " {}:", record.location().module_path()).unwrap();
        }

        write!(&mut message, " {}\n", record.args()).unwrap();

        message
    }
}

lazy_static!(static ref TOTAL_ERRORS: Mutex<RefCell<usize>> = Mutex::new(RefCell::new(0)););

thread_local!(static THREAD_ERRORS: RefCell<usize> = RefCell::new(0););

fn count_errors(level: LogLevel) {
    if level == LogLevel::Error {
        let lock_errors = TOTAL_ERRORS.lock().unwrap();
        *lock_errors.borrow_mut() += 1;
        THREAD_ERRORS.with(|thread_errors_cell| {
            *thread_errors_cell.borrow_mut() += 1;
        });
    }
}

enum LogSink {
    Stderr,
    Buffer,
}

lazy_static!(static ref LOG_BUFFER: Mutex<RefCell<Option<String>>> =
    Mutex::new(RefCell::new(None)););

fn set_log_sink(log_sink: LogSink) {
    let lock_log_buffer = LOG_BUFFER.lock().unwrap();
    match log_sink {
        LogSink::Stderr => {
            *lock_log_buffer.borrow_mut() = None;
        }
        LogSink::Buffer => {
            *lock_log_buffer.borrow_mut() = Some(String::new());
        }
    };
}

/// Assert that the collected log messages are as expected.
///
/// This clears the log buffer following the comparison.
///
/// This is meant to be used in tests using the `test_loggy!` macro. Tests using
/// this macro expect the log buffer being clear at the end of the test, either
/// by using this function or `clear_log`.
pub fn assert_log(expected: &str) {
    let lock_log_buffer = LOG_BUFFER.lock().unwrap();
    let mut log_buffer = lock_log_buffer.borrow_mut();
    match *log_buffer {
        None => {
            panic!("asserting log when logging to stderr");
        }
        Some(ref mut actual) => {
            if actual != expected {
                print!(
                    "ACTUAL LOG:\n{}\nIS DIFFERENT FROM EXPECTED LOG:\n{}\n",
                    actual,
                    expected
                );
                assert_eq!("ACTUAL LOG", "EXPECTED LOG");
            }
            actual.clear();
        }
    }
}

/// Clear the log buffer following the comparison.
///
/// This is meant to be used in tests using the `test_loggy!` macro. Tests using
/// this macro expect the log buffer being clear at the end of the test, either
/// by using this function or `assert_log`.
pub fn clear_log() {
    let lock_log_buffer = LOG_BUFFER.lock().unwrap();
    let mut log_buffer = lock_log_buffer.borrow_mut();
    match *log_buffer {
        None => {
            panic!("clearing log when logging to stderr");
        }
        Some(ref mut actual) => {
            actual.clear();
        }
    }
}

lazy_static!(static ref MIRROR_TO_STDERR: bool =
    std::env::var("LOGGY_MIRROR_TO_STDERR").map(|var| var != "").unwrap_or(false););

fn emit_message(log_level: LogLevel, message: &str) {
    if log_level == LogLevel::Debug {
        eprint!("{}", message);
        return;
    }
    let lock_log_buffer = LOG_BUFFER.lock().unwrap();
    let mut log_buffer = lock_log_buffer.borrow_mut();
    match *log_buffer {
        None => {
            eprint!("{}", message);
        }
        Some(ref mut buffer) => {
            if *MIRROR_TO_STDERR {
                eprint!("{}", message);
            }
            buffer.push_str(message.as_ref());
        }
    }
}

/// Initialize the global logger with `loggy`.
///
/// This is done automatically (once) for tests using the `test_loggy!` macro.
pub fn init(loggy: Loggy) -> Result<(), SetLoggerError> {
    log::set_logger(|max_log_level| {
        max_log_level.set(
            if cfg!(debug_assertions) {
                LogLevel::Debug
            } else {
                loggy.log_level
            }.to_log_level_filter(),
        );
        return Box::new(loggy);
    })
}

static LOGGER_INIT: Once = ONCE_INIT;

/// Create a test case using `loggy`.
///
/// `test_loggy!(name, { ... });` creates a test case which captures all log
/// messages (except for `LogLevel::Debug` messages). It is expected to use
/// either `assert_log` or `clear_log` to clear the buffered log before the test
/// ends. It is possible to provide additional attributes in addition to
/// `#[test]` by specifying them before the name, as in
/// `test_loggy!(#[cfg(debug_assertions)], name, { ... });`
///
/// Since `loggy` collects messages from all threads, `test_loggy!` tests must
/// be run with `RUST_TEST_THREADS=1`, otherwise "bad things will happen".
/// However, such tests may freely spawn multiple new threads.
///
/// If the environment variable `LOGGY_MIRROR_TO_STDERR` is set to any non empty
/// value, then all log messages will be mirrored to the standard error stream,
/// in addition to being captured. This places the `LogLevel::Debug` messages
/// in the context of the other log messages, to help in debugging.
#[macro_export]
macro_rules! test_loggy {
    ($(#[$attr:meta])*, $name:ident, $test:block) => {
        #[test]
        $( #[$attr] )*
        fn $name() {
            loggy::before_test(false);
            $test
            loggy::after_test();
        }
    };
    ($name:ident, $test:block) => {
        #[test]
        fn $name() {
            loggy::before_test();
            $test
            loggy::after_test();
        }
    };
}

#[doc(hidden)]
pub fn before_test() {
    LOGGER_INIT.call_once(|| {
        init(Loggy {
            prefix: "test",
            show_time: false,
            log_level: LogLevel::Info,
        }).unwrap()
    });

    let lock_total_threads = TOTAL_THREADS.lock().unwrap();
    *lock_total_threads.borrow_mut() = 0;

    let lock_errors = TOTAL_ERRORS.lock().unwrap();
    *lock_errors.borrow_mut() = 0;

    THREAD_ID.with(|thread_id_cell| { *thread_id_cell.borrow_mut() = None; });

    THREAD_ERRORS.with(|thread_errors_cell| {
        *thread_errors_cell.borrow_mut() = 0;
    });

    set_log_sink(LogSink::Buffer);
}

#[doc(hidden)]
pub fn after_test() {
    assert_log("");
    set_log_sink(LogSink::Stderr);
}

/// Track the number of errors in the scope of the lifetime of the instance of
/// this class.
pub struct ErrorsScope {
    errors: usize,
}

impl ErrorsScope {
    /// Create a new errors tracking scope.
    ///
    /// Initially, the scope is considered to have had no errors, regardless of
    /// any previous calls to `error!`.
    pub fn new() -> ErrorsScope {
        THREAD_ERRORS.with(|thread_errors_cell| {
            ErrorsScope { errors: *thread_errors_cell.borrow() }
        })
    }

    /// Return the number of calls to `error!` in the current thread since this
    /// instance was created.
    ///
    /// This includes calls to `note!` if the value given to `is_error` is
    /// `true`.
    pub fn errors(&self) -> usize {
        THREAD_ERRORS.with(|thread_errors_cell| {
            *thread_errors_cell.borrow() - self.errors
        })
    }

    /// Return whether any calles to `error!` were made in the current thread
    /// since this instance was created.
    ///
    /// This includes calls to `note!` if the value given to `is_error` is
    /// `true`.
    pub fn had_errors(&self) -> bool {
        self.errors() > 0
    }
}

/// Return the total number of calls to `error!` in the whole program.
///
/// This is reset for each test using the `test_loggy!` macro.
pub fn errors() -> usize {
    let lock_errors = TOTAL_ERRORS.lock().unwrap();
    let errors = *lock_errors.borrow();
    errors
}

/// Return whether there were any calls to `error!` in the whole program.
///
/// This is reset for each test using the `test_loggy!` macro.
pub fn had_errors() -> bool {
    errors() > 0
}