//! # logsley
//! This is an opinionated Rust logging library.
//!
//! ## Features
//! - Configure the logger with one function call
//! - Thread scoped variables
//! - Task scoped variables, with the `async` feature enabled
//! - See logging output from tests
//! - Works with libraries that use
//!   [`log`](https://crates.io/crates/log),
//!   [`slog`](https://crates.io/crates/slog),
//!   [`slog-scope`](https://crates.io/crates/slog-scope),
//!   and [`slog-scope-futures`](https://crates.io/crates/slog-scope-futures).
//! - Logs JSON by default.
//!   Set `DEV_LOG_FORMAT=full` env var to get pretty output in your terminal.
//! - Adjust logging verbosity of modules with simple string parameter,
//!   and override it with the `RUST_LOG env var.`
//!   Example: `RUST_LOG=some::spammy::module=warn,my::buggy::module=trace`.
//!   See [`slog-envlogger`](https://docs.rs/slog-envlogger/2.2.0/slog_envlogger/) for details.
//! - Approved by Sir Robin of Logsley:<br/>
//!   ![Cary Elwes as Robin Hood in the film Robin Hood Men in Tights (1993)](robinhood.jpg)
//!
//!
//! ## Limitations
//! - Uses macros
//!
//! ## Examples
//! ```rust
//! // You should do logging like this.
//!
//! # fn f() {
//! let _global_logger_guard =
//!   logsley::configure("info").unwrap();
//! logsley::thread_scope("main", || {
//!   // Log named values:
//!   logsley::error!("err {}", 1; "x" => 2);
//!   // {"time_ns":1604899904064111000,
//!   // "time":"2020-11-08T21:31:44.064-08:00",
//!   // "module":"opinion",
//!   // "level":"ERROR",
//!   // "message":"err 1",
//!   // "thread":"main",
//!   // "x":2}
//!   logsley::warn!("warn {}", 1; "x" => 2);
//!   logsley::info!("info {}", 1; "x" => 2);
//!   logsley::debug!("debug {}", 1; "x" => 2);
//!   logsley::trace!("trace {}", 1; "x" => 2);
//!
//!   // Log simple messages:
//!   log::info!("log {}", 1);
//!   // {"time_ns":1604899904065070000,
//!   // "time":"2020-11-08T21:31:44.065-08:00",
//!   // "module":"opinion",
//!   // "level":"INFO",
//!   // "message":"log 1",
//!   // "thread":"main"}
//!
//!   std::thread::spawn(|| {
//!     logsley::thread_scope("thread1", || {
//!       logsley::info!("in thread {}", 1; "x" => 2);
//!   })})
//!   .join()
//!   .unwrap();
//!   // {"time_ns":1604899904065111000,
//!   // "time":"2020-11-08T21:31:44.065-08:00",
//!   // "module":"opinion",
//!   // "level":"INFO",
//!   // "message":"in thread 1",
//!   // "thread":"thread1",
//!   // "x":2}
//!
//!   async_std::task::block_on(
//!     logsley::task_scope("task1", async move {
//!       logsley::info!(
//!         "logsley in task {}", 1; "x" => 2);
//!   }));
//!   // {"time_ns":1604899904065241000,
//!   // "time":"2020-11-08T21:31:44.065-08:00",
//!   // "module":"opinion",
//!   // "level":"INFO",
//!   // "message":"logsley in task 1",
//!   // "task":"task1",
//!   // "thread":"main",
//!   // "x":2}
//!  
//!   panic!("uhoh");
//!   // {"time_ns":1604899904955593000,
//!   // "time":"2020-11-08T21:31:44.955-08:00",
//!   // "module":"log_panics",
//!   // "level":"ERROR",
//!   // "message":"thread 'main' panicked at 'uhoh': examples/opinion.rs:30\n
//!   //   0: backtrace::backtrace::libunwind::trace\n
//!   //             at /.../backtrace-0.3.54/src/backtrace/libunwind.rs:90:5\n
//!   //      backtrace::backtrace::trace_unsynchronized\n
//!   //             at /.../backtrace-0.3.54/src/backtrace/mod.rs:66:5\n
//!   //   1: backtrace::backtrace::trace\n
//!   //             at /.../backtrace-0.3.54/src/backtrace/mod.rs:53:14\n
//!   //   2: backtrace::capture::Backtrace::create\n
//!   //             at /.../backtrace-0.3.54/src/capture.rs:176:9\n
//!   //   3: backtrace::capture::Backtrace::new\n
//!   //             at /.../backtrace-0.3.54/src/capture.rs:140:22\n
//!   //   4: log_panics::init::{{closure}}\n
//!   //             at /.../log-panics-2.0.0/src/lib.rs:52:25\n
//!   //   5: std::panicking::rust_panic_with_hook\n
//!   //             at /.../library/std/src/panicking.rs:581:17\n
//!   //   6: std::panicking::begin_panic::{{closure}}\n
//!   //             at /.../library/std/src/panicking.rs:506:9\n
//!   //   7: std::sys_common::backtrace::__rust_end_short_backtrace\n
//!   //             at /.../library/std/src/sys_common/backtrace.rs:153:18\n
//!   //   8: std::panicking::begin_panic\n
//!   //             at /.../library/std/src/panicking.rs:505:12\n
//!   //   9: opinion::main::{{closure}}\n
//!   //             at examples/opinion.rs:30:9\n
//!   //  10: slog_scope::scope\n
//!   //             at /.../slog-scope-4.3.0/lib.rs:248:5\n
//!   //  11: logsley::thread_scope\n
//!   //             at src/lib.rs:179:5\n
//!   //  12: opinion::main\n
//!   //             at examples/opinion.rs:5:5\n
//!   //  13: core::ops::function::FnOnce::call_once\n
//!   //             at /.../library/core/src/ops/function.rs:227:5\n
//!   //  14: std::sys_common::backtrace::__rust_begin_short_backtrace\n
//!   //             at /.../library/std/src/sys_common/backtrace.rs:137:18\n
//!   //  15: std::rt::lang_start::{{closure}}\n
//!   //             at /.../library/std/src/rt.rs:66:18\n
//!   //  16: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once\n
//!   //             at /.../library/core/src/ops/function.rs:259:13\n
//!   //      std::panicking::try::do_call\n
//!   //             at /.../library/std/src/panicking.rs:381:40\n
//!   //      std::panicking::try\n
//!   //             at /.../library/std/src/panicking.rs:345:19\n
//!   //      std::panic::catch_unwind\n
//!   //             at /.../library/std/src/panic.rs:382:14\n
//!   //      std::rt::lang_start_internal\n
//!   //             at /.../library/std/src/rt.rs:51:25\n
//!   //  17: std::rt::lang_start\n
//!   //             at /.../library/std/src/rt.rs:65:5\n
//!   //  18: _main\n",
//!   // "thread":"main"}
//!   });
//! }
//! ```
//! For a runnable example, see [examples/opinion.rs](examples/opinion.rs).
//!
//! Set the default log level to `info`.
//! The program will emit log messages with level `info` and higher.
//! ```rust
//! let _global_logger_guard = logsley::configure("info");
//! log::error!("emitted");
//! log::warn!("emitted");
//! log::info!("emitted");
//! log::debug!("not emitted");
//! log::trace!("not emitted");
//! ```
//!
//! Set the default log level to `info` and set the level for `chatty::module1` to `warn`.
//! ```rust
//! let _global_logger_guard =
//!     logsley::configure("info,chatty::module1=warn");
//! ```
//!
//! Use the environment variable to override default log level.
//! `module1` still gets its special log level.
//! ```rust
//! std::env::set_var("RUST_LOG", "debug");
//! let _global_logger_guard =
//!     logsley::configure("info,module1=warn");
//! ```
//!
//! Use the environment variable to set `module1` to `debug`.
//! ```rust
//! std::env::set_var("RUST_LOG", "module1=debug");
//! let _global_logger_guard =
//!     logsley::configure("info");
//! ```
//!
//! ## Documentation
//! https://docs.rs/logsley
//!
//! ## Alternatives
//! - [log](https://crates.io/crates/log)
//! - [log-panics](https://crates.io/crates/log-panics)
//! - [slog](https://crates.io/crates/slog)
//! - [slog-async](https://crates.io/crates/slog-async)
//! - [slog-envlogger](https://crates.io/crates/slog-envlogger)
//! - [slog-json](https://crates.io/crates/slog-json)
//! - [slog-scope](https://crates.io/crates/slog-scope)
//! - [slog-scope-futures](https://crates.io/crates/slog-scope-futures)
//! - [slog-stdlog](https://crates.io/crates/slog-stdlog)
//! - [slog-term](https://crates.io/crates/slog-term)
//!
//! ## Release Process
//! 1. Edit `Cargo.toml` and bump version number.
//! 1. Run `./release.sh`
//!
//! ## Changelog
//! - v0.1.8 - Add `async` feature
//! - v0.1.7 - Bugfix.
//! - v0.1.6 - Add missing `slog` reexport.
//! - v0.1.5 - Rename `OutputFormat::JSON` to `Json` to satisfy nightly clippy.
//! - v0.1.4 - Update docs.
//! - v0.1.3 - Fix missing slog_scope::logger error
//! - v0.1.2 - Fix panic in configure_for_test
//! - v0.1.1 - Make example code fit in crates.io's 60-column code views.
//! - v0.1.0 - First published version
//!
//! ## TODO
//! - DONE - Try to make this crate comply with the [Rust API Guidelines](https://rust-lang.github.io/api-guidelines/).
//! - DONE - Include Readme.md info in the crate's docs.
//! - DONE - Make the repo public
//! - DONE - Set up continuous integration tests and banner.
//!   - https://gitlab.com/mattdark/firebase-example/blob/master/.gitlab-ci.yml
//!   - https://medium.com/astraol/optimizing-ci-cd-pipeline-for-rust-projects-gitlab-docker-98df64ae3bc4
//!   - https://hub.docker.com/_/rust
//! - DONE - Add some documentation tests
//!   - https://doc.rust-lang.org/rustdoc/documentation-tests.html
//!   - https://doc.rust-lang.org/stable/rust-by-example/testing/doc_testing.html
//! - DONE - Publish to creates.io
//! - DONE - Read through https://crate-ci.github.io/index.html
//! - DONE - Add and update a changelog
//!   - Update it manually
//!   - https://crate-ci.github.io/release/changelog.html
//! - Get a code review from an experienced rustacean
//! - Add features: threads, futures, term
#![forbid(unsafe_code)]

#[doc(hidden)]
pub mod reexports {
    pub mod slog {
        pub use slog::{debug, error, info, trace, warn};
    }
    pub mod slog_scope {
        pub use slog_scope::logger;
    }
}

#[derive(Clone, Debug, PartialEq)]
pub enum OutputFormat {
    Json,
    Compact,
    Full,
    Plain,
}

/// Configure `log` and `slog` to emit JSON to stdout.
///
/// Applies global and per-module filtering rules from `filters` and overrides them with
/// rules from the `RUST_LOG` environment variable.
/// The `filters` syntax is quite expressive.
/// See the [slog_envlogger docs](https://docs.rs/slog-envlogger/2.2.0/slog_envlogger/)
///
/// You can set the `DEV_LOG_FORMAT` environment variable to one of:
/// - `"json"` or `""` to log in JSON format.
/// - `"compact"` to print scope variables on their own line and indent log messages emitted inside
///   the scope.
/// - `"full"` to print scope variables on every line, with color.
/// - `"plain"` to print without color.
///
/// Release binaries always log JSON.  Only debug binaries check the `DEV_LOG_FORMAT` env var.
///
/// Examples:
/// - Set the default log level to `info`.
///   The program will emit log messages with level `info` and higher.
///   ```
///   # fn f() {
///   let _global_logger_guard = logsley::configure("info");
///   logsley::info!("a message"; "some_data" => 123, "other_data" => "val1");
///   slog::info!(slog_scope::logger(), "a message"; "some_data" => 123, "other_data" => "val1");
///   log::info!("a message; some_data={} other_data={}", 123, "val1");
///   log::debug!("some details");  // Not emitted
///   # }
///   ```
/// - Set the default log level to `info` and set the level for `chatty::module1` to `warn`.
///   ```
///   # fn f() {
///   let _global_logger_guard = logsley::configure("info,chatty::module1=warn");
///   # }
///   ```
/// - Use the environment variable to override default log level.
///   `module1` still gets its special log level.
///   ```
///   # fn f() {
///   std::env::set_var("RUST_LOG", "debug");
///   let _global_logger_guard = logsley::configure("info,module1=warn");
///   # }
///   ```
/// - Use the environment variable to set `module1` to `debug`.
///   ```
///   # fn f() {
///   std::env::set_var("RUST_LOG", "module1=debug");
///   let _global_logger_guard = logsley::configure("info");
///   # }
///   ```
///
/// Example output:
/// ```json
/// {"time_ns":1585851354242507000, "time":"2020-04-02T18:15:54.242521000Z", \
/// "module":"mod1","level":"ERROR","message":"msg1", "thread":"main","x":2}
/// ```
pub fn configure(
    filters: &str,
) -> Result<slog_scope::GlobalLoggerGuard, Box<dyn std::error::Error>> {
    let format = OutputFormat::Json;
    #[cfg(debug_assertions)] // Include the following statement in debug binaries, not release.
    let format = match std::env::var("DEV_LOG_FORMAT").unwrap_or_default().as_ref() {
        "" | "json" => format,
        "compact" => OutputFormat::Compact,
        "full" => OutputFormat::Full,
        "plain" => OutputFormat::Plain,
        s => panic!("Invalid DEV_LOG_FORMAT env var value {:?}", s),
    };
    configure_inner(filters, format)
}

#[derive(Debug, PartialEq, Clone)]
pub struct ChangingConfigNotAllowed {}
impl std::fmt::Display for ChangingConfigNotAllowed {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> Result<(), std::fmt::Error> {
        write!(f, "ChangingConfigNotAllowed")
    }
}
impl std::error::Error for ChangingConfigNotAllowed {}

/// Configures `log` and `slog` to emit to stdout with "plain" format.
/// Can be called multiple times from different threads.
/// Each call leaks a `GlobalLoggerGuard` which contains only a `bool`.
pub fn configure_for_test(
    filters: &str,
    format: OutputFormat,
) -> Result<(), ChangingConfigNotAllowed> {
    let mut hasher = std::collections::hash_map::DefaultHasher::new();
    std::hash::Hasher::write(&mut hasher, filters.as_bytes());
    let filters_hash = std::hash::Hasher::finish(&hasher);

    static TEST_CONFIG: once_cell::sync::Lazy<
        std::sync::Mutex<Option<(u64, OutputFormat, slog_scope::GlobalLoggerGuard)>>,
    > = once_cell::sync::Lazy::new(|| std::sync::Mutex::new(None));
    let mut test_config_lock = TEST_CONFIG.lock().unwrap();
    match test_config_lock.as_ref() {
        None => {
            // log::set_max_level(log::LevelFilter::Trace);
            let guard = configure_inner(filters, OutputFormat::Plain).unwrap();
            *test_config_lock = Some((filters_hash, format, guard));
            Ok(())
        }
        Some(tuple) if tuple.0 == filters_hash && tuple.1 == format => Ok(()),
        _ => Err(ChangingConfigNotAllowed {}),
    }
}

fn configure_inner(
    filters: &str,
    output_format: OutputFormat,
) -> Result<slog_scope::GlobalLoggerGuard, Box<dyn std::error::Error>> {
    let _time_fn =
        |_: &slog::Record| chrono::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Nanos, true);
    let _time_ns_fn = |_: &slog::Record| {
        std::time::SystemTime::now()
            .duration_since(std::time::SystemTime::UNIX_EPOCH)
            // Use default Duration (0 seconds) if system time is before epoch.
            .unwrap_or_default()
            // Nanoseconds overflow u64 in the year 2554.
            .as_nanos() as u64
    };
    let _module_fn = |record: &slog::Record| record.module();
    let _level_fn = |record: &slog::Record| match record.level() {
        slog::Level::Critical => "ERROR",
        slog::Level::Error => "ERROR",
        slog::Level::Warning => "WARN",
        slog::Level::Info => "INFO",
        slog::Level::Debug => "DEBUG",
        slog::Level::Trace => "TRACE",
    };
    let _message_fn = |record: &slog::Record| record.msg().to_string();
    let _time_fn = |_record: &slog::Record| {
        chrono::Local::now().to_rfc3339_opts(chrono::SecondsFormat::Millis, true)
    };
    let _write_timestamp_fn = |w: &mut dyn std::io::Write| {
        w.write(
            chrono::Local::now()
                .to_rfc3339_opts(chrono::SecondsFormat::Millis, true)
                .as_bytes(),
        )
        .map(|_| ())
    };
    let drain: Box<dyn slog::Drain<Ok = (), Err = std::io::Error> + Send> = match output_format {
        OutputFormat::Json => {
            Box::new(
                slog_json::Json::new(std::io::stdout())
                    .add_key_value(slog::o!(
                        // Fields are in reverse order.
                        "message" => slog::FnValue(_message_fn),
                        "level" => slog::FnValue(_level_fn),
                        "module" => slog::FnValue(_module_fn),
                        "time" => slog::FnValue(_time_fn),
                        "time_ns" => slog::FnValue(_time_ns_fn),
                        // TODONT(mleonhard) Don't include 'process' or 'host'.
                        // Supervisor and collector will add these values and
                        // will not trust any values already present.
                    ))
                    .build(),
            )
        }
        OutputFormat::Compact => Box::new(
            slog_term::CompactFormat::new(slog_term::TermDecorator::new().build())
                .use_custom_timestamp(_write_timestamp_fn)
                .build(),
        ),
        OutputFormat::Full => Box::new(
            slog_term::FullFormat::new(slog_term::TermDecorator::new().build())
                .use_custom_timestamp(_write_timestamp_fn)
                .build(),
        ),
        OutputFormat::Plain => Box::new(
            slog_term::FullFormat::new(slog_term::PlainDecorator::new(std::io::stdout()))
                .use_custom_timestamp(_write_timestamp_fn)
                .build(),
        ),
    };
    let drain = slog_envlogger::LogBuilder::new(drain)
        .parse(filters)
        // Add any level overrides from environment variable
        .parse(&match std::env::var("RUST_LOG") {
            Ok(x) => Ok(x),
            Err(std::env::VarError::NotPresent) => Ok(String::new()),
            Err(x) => Err(x),
        }?)
        .build();
    let drain = slog::Fuse(std::sync::Mutex::new(drain));
    let drain = slog::Fuse(
        slog_async::Async::new(drain)
            .chan_size(1024)
            .overflow_strategy(slog_async::OverflowStrategy::Block)
            .build(),
    );
    let logger = slog::Logger::root(drain, slog::o!());
    let _guard = slog_scope::set_global_logger(logger);
    slog_stdlog::init()?;
    log_panics::init();
    Ok(_guard)
}

pub fn thread_scope<SF, R>(name: &str, f: SF) -> R
where
    SF: FnOnce() -> R,
{
    let _name = name;
    let logger = slog_scope::logger().new(slog::o!("thread" => String::from(_name)));
    slog_scope::scope(&logger, f)
}

#[cfg(feature = "async")]
/// Enable the `async` feature to use this function.
pub fn task_scope<F>(name: &'static str, f: F) -> slog_scope_futures::SlogScope<slog::Logger, F>
where
    F: std::future::Future,
{
    let _name = name;
    slog_scope_futures::SlogScope::new(slog_scope::logger().new(slog::o!("task" => _name)), f)
}

#[macro_export]
macro_rules! error (
    ($($args:tt)+) => {
        logsley::reexports::slog::error!(logsley::reexports::slog_scope::logger(), $($args)+)
    };
);
#[macro_export]
macro_rules! warn (
    ($($args:tt)+) => {
        logsley::reexports::slog::warn!(logsley::reexports::slog_scope::logger(), $($args)+)
    };
);
#[macro_export]
macro_rules! info (
    ($($args:tt)+) => {
        logsley::reexports::slog::info!(logsley::reexports::slog_scope::logger(), $($args)+)
    };
);
#[macro_export]
macro_rules! debug (
    ($($args:tt)+) => {
        logsley::reexports::slog::debug!(logsley::reexports::slog_scope::logger(), $($args)+)
    };
);
#[macro_export]
macro_rules! trace (
    ($($args:tt)+) => {
        logsley::reexports::slog::trace!(logsley::reexports::slog_scope::logger(), $($args)+)
    };
);