feat: metrics logger (nervosnetwork#43)

* add logger config

* add logger.metrics example

* Revert "add logger.metrics example"

This reverts commit 7c04ff3.

* add logger module instruction

* chore: add newline to the end of text file

* refactor: change serde to json crate to manipulate json

* chore: remove patch version in Cargo.toml depencencies

.gitignore

@@ -26,3 +26,4 @@ tests/e2e/node_modules/
 
 # rocksdb
 **/rocksdb/
+logs/

common/logger/Cargo.toml

@@ -7,5 +7,6 @@ edition = "2018"
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
 [dependencies]
-env_logger = "0.6"
 log = "0.4"
+log4rs = "0.8"
+json = "0.12"

common/logger/README.md

@@ -0,0 +1,67 @@
+# Logger Module Instruction
+
+## Logger Config
+
+The logger config in `config.toml` is listed below with default values.
+
+```toml
+[logger]
+filter = "info"
+log_to_console = true
+console_show_file_and_line = false
+log_path = "logs/"
+log_to_file = true
+metrics = true
+```
+
+`filter` is the root logger filter, must be one of `off`, `trace`, `debug`, `info`, `warn` and `error`.
+
+If `log_to_console` is `true`, logs like below will be logged to console.
+
+```
+[2019-12-02T10:02:45.779337+08:00 INFO overlord::state::process] Overlord: state receive commit event epoch ID 11220, round 0
+```
+
+If `console_show_file_and_line` is `true`, log file and line number will also be logged to console, pretty useful for debugging.
+
+```
+[2019-12-02T10:05:28.343228+08:00 INFO core_network::peer_manager core/network/src/peer_manager/mod.rs:1035] network: PeerId(QmYSZUy3G5Mf5GSTKfH7LXJeFJrVW59rX1qPPfapuH7AUw): connected peer_ip(s): []
+```
+
+If `log_to_file` is true, logs like below will be logged to `{log_path}/muta.log`.
+It is json format, good for machine understanding.
+
+```
+{"time":"2019-12-01T22:01:57.839042+08:00","message":"network: PeerId(QmYSZUy3G5Mf5GSTKfH7LXJeFJrVW59rX1qPPfapuH7AUw): connect addrs [\"/ip4/0.0.0.0/tcp/1888\"]","module_path":"core_network::peer_manager","file":"core/network/src/peer_manager/mod.rs","line":591,"level":"INFO","target":"core_network::peer_manager","thread":"tokio-runtime-worker-0","thread_id":123145432756224,"mdc":{}}
+```
+
+This crate uses `log4rs` to init the logger, but you don't need to add dependency for that. After invoking the `init` function in this crate, you can use `log` crate to log.
+
+## Metrics
+
+Metrics is an independent logger, it `metrics` is `true`, the metrics will be logged to `{log_path}/metrics.log`.
+
+```
+{"time":"2019-12-01T22:02:49.035084+08:00","message":"{\"epoch_id\":7943,\"name\":\"save_epoch\",\"ordered_tx_num\":0}","module_path":"common_logger","file":"common/logger/src/lib.rs","line":83,"level":"TRACE","target":"metrics","thread":"tokio-runtime-worker-3","thread_id":123145445486592,"mdc":{}}
+```
+
+If you want to use log metrics in a module, you need to add this crate as dependency and use the code below to add a metric. The `name` field is reserved, please avoid using this as a key in your metrics.
+
+```rust
+common_logger::metrics("save_epoch", common_logger::object! {
+    "epoch_id" => epoch.header.epoch_id,
+    "ordered_tx_num" => epoch.ordered_tx_hashes.len(),
+});
+```
+
+This signature of the function is showed below. The `JsonValue` is a `enum` from [`json crate`](https://docs.rs/json/0.12.0/json/enum.JsonValue.html).
+
+```rust
+pub fn metrics(name: &str, mut content: JsonValue)
+```
+
+## Yaml File
+
+The `log.yml` in this crate is the yaml style config of log4rs with default logger config.
+
+If you need more customized configurations, you can copy the file to some config path, edit the file, and replace the `init` function with `log4rs::init_file("/path/to/log.yml", Default::default()).unwrap();`.

common/logger/log.yml

@@ -0,0 +1,36 @@
+# This file is yaml style config, can make testing the logger more easily.
+# When you need to do some test, Add the code below to the `init` function.
+# log4rs::init_file("common/logger/log.yml", Default::default()).unwrap();
+# reference: <https://docs.rs/log4rs/0.8.3/log4rs/>
+appenders:
+  console:
+    kind: console
+    encoder:
+      # this pattern below contains file name and line, usefule for debugging
+      # pattern: "[{d} {h({l})} {t} {f}:{L}] {m}{n}"
+      pattern: "[{d} {h({l})} {t}] {m}{n}"
+
+  file:
+    kind: file
+    path: logs/muta.log
+    encoder:
+      kind: json
+
+  metrics:
+    kind: file
+    path: logs/metrics.log
+    encoder:
+      kind: json
+
+root:
+  level: info
+  appenders:
+  - console
+  - file
+
+loggers:
+  metrics:
+    level: trace
+    appenders:
+    - metrics
+    additive: false

common/logger/src/lib.rs

@@ -1,73 +1,88 @@
-use std::env;
+use std::path::PathBuf;
 
-pub enum Flag {
-    Main, // Used in main function
-    Test, // Used in test function
-}
+use json::JsonValue;
+use log::LevelFilter;
+use log4rs::append::console::ConsoleAppender;
+use log4rs::append::file::FileAppender;
+use log4rs::config::{Appender, Config, Logger, Root};
+use log4rs::encode::json::JsonEncoder;
+use log4rs::encode::pattern::PatternEncoder;
 
-/// Function init should used in main or test function.
-pub fn init(flag: Flag) {
-    match flag {
-        Flag::Main => {
-            env::var("RUST_LOG").unwrap_or_else(|_| {
-                env::set_var("RUST_LOG", "info");
-                "info".into()
-            });
-            env_logger::init();
-        }
-        Flag::Test => {
-            let _ = env_logger::builder().is_test(true).try_init();
-        }
-    }
-}
+pub use json::array;
+pub use json::object;
 
-#[cfg(test)]
-mod tests {
-    use super::{init, Flag};
-    use log::{debug, error, info, trace, warn};
+pub fn init(
+    filter: String,
+    log_to_console: bool,
+    console_show_file_and_line: bool,
+    log_to_file: bool,
+    metrics: bool,
+    log_path: PathBuf,
+) {
+    let console = ConsoleAppender::builder()
+        .encoder(Box::new(PatternEncoder::new(
+            if console_show_file_and_line {
+                "[{d} {h({l})} {t} {f}:{L}] {m}{n}"
+            } else {
+                "[{d} {h({l})} {t}] {m}{n}"
+            },
+        )))
+        .build();
 
-    #[test]
-    fn test_debug() {
-        init(Flag::Test);
-        debug!("Hello World!");
-        debug!("Hello {}", "World!");
-        debug!("Hell{} {}", "o", "World!");
-        debug!("Hell{} World", 0);
-    }
+    let file = FileAppender::builder()
+        .encoder(Box::new(JsonEncoder::new()))
+        .build(log_path.join("muta.log"))
+        .unwrap();
 
-    #[test]
-    fn test_error() {
-        init(Flag::Test);
-        error!("Hello World!");
-        error!("Hello {}", "World!");
-        error!("Hell{} {}", "o", "World!");
-        error!("Hell{} World", 0);
-    }
+    let metrics_appender = FileAppender::builder()
+        .encoder(Box::new(JsonEncoder::new()))
+        .build(log_path.join("metrics.log"))
+        .unwrap();
 
-    #[test]
-    fn test_info() {
-        init(Flag::Test);
-        info!("Hello World!");
-        info!("Hello {}", "World!");
-        info!("Hell{} {}", "o", "World!");
-        info!("Hell{} World", 0);
+    let mut root_builder = Root::builder();
+    if log_to_console {
+        root_builder = root_builder.appender("console");
     }
-
-    #[test]
-    fn test_warn() {
-        init(Flag::Test);
-        warn!("Hello World!");
-        warn!("Hello {}", "World!");
-        warn!("Hell{} {}", "o", "World!");
-        warn!("Hell{} World", 0);
+    if log_to_file {
+        root_builder = root_builder.appender("file");
     }
+    let level_filter = match filter.as_ref() {
+        "off" => LevelFilter::Off,
+        "error" => LevelFilter::Error,
+        "info" => LevelFilter::Info,
+        "warn" => LevelFilter::Warn,
+        "debug" => LevelFilter::Debug,
+        "trace" => LevelFilter::Trace,
+        f => {
+            println!("invalid logger.filter {}, use info", f);
+            LevelFilter::Info
+        }
+    };
+    let root = root_builder.build(level_filter);
 
-    #[test]
-    fn test_trace() {
-        init(Flag::Test);
-        trace!("Hello World!");
-        trace!("Hello {}", "World!");
-        trace!("Hell{} {}", "o", "World!");
-        trace!("Hell{} World", 0);
-    }
+    let metrics_logger = Logger::builder().additive(false).appender("metrics").build(
+        "metrics",
+        if metrics {
+            LevelFilter::Trace
+        } else {
+            LevelFilter::Off
+        },
+    );
+
+    let config = Config::builder()
+        .appender(Appender::builder().build("console", Box::new(console)))
+        .appender(Appender::builder().build("file", Box::new(file)))
+        .appender(Appender::builder().build("metrics", Box::new(metrics_appender)))
+        .logger(metrics_logger)
+        .build(root)
+        .unwrap();
+
+    log4rs::init_config(config).unwrap();
+}
+
+pub fn metrics(name: &str, mut content: JsonValue) {
+    log::trace!(target: "metrics", "{}", {
+        content["name"] = name.into();
+        content
+    });
 }

devtools/chain/config.toml

@@ -41,3 +41,11 @@ precommit_denominator = 30
 
 [executor]
 light = false
+
+[logger]
+filter = "info"
+log_to_console = true
+console_show_file_and_line = false
+log_path = "logs/"
+log_to_file = true
+metrics = true

src/config.rs

@@ -58,6 +58,29 @@ pub struct ConfigExecutor {
     pub light: bool,
 }
 
+#[derive(Debug, Deserialize)]
+pub struct ConfigLogger {
+    pub filter:                     String,
+    pub log_to_console:             bool,
+    pub console_show_file_and_line: bool,
+    pub log_to_file:                bool,
+    pub metrics:                    bool,
+    pub log_path:                   PathBuf,
+}
+
+impl Default for ConfigLogger {
+    fn default() -> Self {
+        Self {
+            filter:                     "info".into(),
+            log_to_console:             true,
+            console_show_file_and_line: false,
+            log_to_file:                true,
+            metrics:                    true,
+            log_path:                   "logs/".into(),
+        }
+    }
+}
+
 #[derive(Debug, Deserialize)]
 pub struct Config {
     // chain id
@@ -67,11 +90,13 @@ pub struct Config {
     // db config
     pub data_path: PathBuf,
 
-    pub graphql:   ConfigGraphQL,
-    pub network:   ConfigNetwork,
-    pub mempool:   ConfigMempool,
+    pub graphql: ConfigGraphQL,
+    pub network: ConfigNetwork,
+    pub mempool: ConfigMempool,
     pub consensus: ConfigConsensus,
-    pub executor:  ConfigExecutor,
+    pub executor: ConfigExecutor,
+    #[serde(default)]
+    pub logger: ConfigLogger,
 }
 
 impl Config {

src/main.rs

@@ -43,8 +43,6 @@ use crate::config::Config;
 
 #[runtime::main(runtime_tokio::Tokio)]
 async fn main() {
-    common_logger::init(common_logger::Flag::Main);
-
     let matches = clap::App::new("Muta")
         .version("v0.1.0")
         .author("Muta Dev <[email protected]>")
@@ -59,6 +57,14 @@ async fn main() {
         .get_matches();
     let args_config = matches.value_of("config").unwrap();
     let cfg: Config = common_config_parser::parse(args_config).unwrap();
+    common_logger::init(
+        cfg.logger.filter.clone(),
+        cfg.logger.log_to_console,
+        cfg.logger.console_show_file_and_line,
+        cfg.logger.log_to_file,
+        cfg.logger.metrics,
+        cfg.logger.log_path.clone(),
+    );
     log::info!("Go with config: {:?}", cfg);
 
     // init genesis