refactor: use fil_logger instead of pretty_env_logger

The log output changes and now looks like the one [IPFS go-log] is
producing. You can also toggle the output to JSON with setting
the environment variable `GOLOG_LOG_FMT=json`.

Example for console outpute:

```console
$ RUST_LOG=debug cargo run --example stacked -- --size 16
    Finished dev [unoptimized + debuginfo] target(s) in 0.15s
     Running `/home/vmx/src/pl/filecoin/rust-fil-proofs/target/debug/examples/stacked --size 16`
2019-11-14T19:42:35.240 INFO stacked > hasher: pedersen
2019-11-14T19:42:35.240 INFO stacked > data size: 16 kB
2019-11-14T19:42:35.240 INFO stacked > m: 6
2019-11-14T19:42:35.240 INFO stacked > expansion_degree: 8
2019-11-14T19:42:35.240 INFO stacked > layer_challenges: LayerChallenges { layers: 10, max_count: 1 }
2019-11-14T19:42:35.240 INFO stacked > layers: 10
2019-11-14T19:42:35.240 INFO stacked > partitions: 1
2019-11-14T19:42:35.240 INFO stacked > circuit: false
2019-11-14T19:42:35.240 INFO stacked > groth: false
2019-11-14T19:42:35.240 INFO stacked > bench: false
2019-11-14T19:42:35.241 INFO stacked > running setup
2019-11-14T19:42:35.241 INFO stacked > setup complete
2019-11-14T19:42:35.241 INFO stacked > generating zeroed data
2019-11-14T19:42:35.241 INFO stacked > running replicate
2019-11-14T19:42:35.241 INFO storage_proofs::stacked::proof > building merkle tree for the original data
2019-11-14T19:42:35.241 INFO storage_proofs::stacked::proof > generate labels
2019-11-14T19:42:35.242 INFO storage_proofs::stacked::proof > hashing columns with 7 chunks
2019-11-14T19:42:35.243 INFO storage_proofs::stacked::proof > generating layer: 1
2019-11-14T19:42:35.636 INFO storage_proofs::stacked::proof > generating layer: 2
2019-11-14T19:42:36.041 INFO storage_proofs::stacked::proof > generating layer: 3
2019-11-14T19:42:36.443 INFO storage_proofs::stacked::proof > generating layer: 4
2019-11-14T19:42:36.843 INFO storage_proofs::stacked::proof > generating layer: 5
2019-11-14T19:42:37.243 INFO storage_proofs::stacked::proof > generating layer: 6
2019-11-14T19:42:37.648 INFO storage_proofs::stacked::proof > generating layer: 7
2019-11-14T19:42:38.060 INFO storage_proofs::stacked::proof > generating layer: 8
2019-11-14T19:42:38.460 INFO storage_proofs::stacked::proof > generating layer: 9
2019-11-14T19:42:38.859 INFO storage_proofs::stacked::proof > generating layer: 10
2019-11-14T19:43:36.429 INFO storage_proofs::stacked::proof > Labels generated
2019-11-14T19:43:36.429 INFO storage_proofs::stacked::proof > encoding data
2019-11-14T19:43:36.429 INFO storage_proofs::stacked::proof > building tree_c
2019-11-14T19:43:36.432 INFO storage_proofs::stacked::proof > building tree_r_last
2019-11-14T19:43:36.965 INFO storage_proofs::stacked::proof > tree_c done
2019-11-14T19:43:36.965 INFO storage_proofs::stacked::proof > tree_r_last done
2019-11-14T19:43:36.968 INFO stacked > replication_time: 61.727274001s
2019-11-14T19:43:36.968 INFO stacked > replication_time/byte: 3.767533ms
2019-11-14T19:43:36.968 INFO stacked > replication_time/GiB: 4045357.755400192s
2019-11-14T19:43:36.969 INFO stacked > generating 1 partition proofs
2019-11-14T19:43:36.974 INFO stacked > vanilla_proving_time: 4.922457ms
2019-11-14T19:43:36.974 INFO stacked > sampling verifying (samples: 5)
2019-11-14T19:43:40.364 INFO stacked > Verification complete
2019-11-14T19:43:40.364 INFO stacked > average_vanilla_verifying_time: 0.678136971 seconds
```

Example for JSON output:

```console
$ RUST_LOG=debug GOLOG_LOG_FMT=json cargo run --example stacked -- --size 16
    Finished dev [unoptimized + debuginfo] target(s) in 0.15s
     Running `/home/vmx/src/pl/filecoin/rust-fil-proofs/target/debug/examples/stacked --size 16`
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:483","msg":"hasher: pedersen"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:160","msg":"data size: 16 kB"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:161","msg":"m: 6"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:162","msg":"expansion_degree: 8"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:163","msg":"layer_challenges: LayerChallenges { layers: 10, max_count: 1 }"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:164","msg":"layers: 10"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:165","msg":"partitions: 1"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:166","msg":"circuit: false"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:167","msg":"groth: false"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:168","msg":"bench: false"}"
{"level":"info","ts":"2019-11-14T19:44:43.519+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:181","msg":"running setup"}"
{"level":"info","ts":"2019-11-14T19:44:43.520+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:184","msg":"setup complete"}"
{"level":"info","ts":"2019-11-14T19:44:43.520+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:115","msg":"generating zeroed data"}"
{"level":"info","ts":"2019-11-14T19:44:43.520+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:198","msg":"running replicate"}"
{"level":"info","ts":"2019-11-14T19:44:43.520+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:445","msg":"building merkle tree for the original data"}"
{"level":"info","ts":"2019-11-14T19:44:43.520+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:244","msg":"generate labels"}"
{"level":"info","ts":"2019-11-14T19:44:43.520+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:275","msg":"hashing columns with 7 chunks"}"
{"level":"info","ts":"2019-11-14T19:44:43.521+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 1"}"
{"level":"info","ts":"2019-11-14T19:44:43.921+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 2"}"
{"level":"info","ts":"2019-11-14T19:44:44.346+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 3"}"
{"level":"info","ts":"2019-11-14T19:44:44.755+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 4"}"
{"level":"info","ts":"2019-11-14T19:44:45.161+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 5"}"
{"level":"info","ts":"2019-11-14T19:44:45.568+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 6"}"
{"level":"info","ts":"2019-11-14T19:44:45.969+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 7"}"
{"level":"info","ts":"2019-11-14T19:44:46.375+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 8"}"
{"level":"info","ts":"2019-11-14T19:44:46.781+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 9"}"
{"level":"info","ts":"2019-11-14T19:44:47.189+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:311","msg":"generating layer: 10"}"
{"level":"info","ts":"2019-11-14T19:45:45.272+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:406","msg":"Labels generated"}"
{"level":"info","ts":"2019-11-14T19:45:45.273+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:460","msg":"encoding data"}"
{"level":"info","ts":"2019-11-14T19:45:45.273+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:482","msg":"building tree_c"}"
{"level":"info","ts":"2019-11-14T19:45:45.276+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:476","msg":"building tree_r_last"}"
{"level":"info","ts":"2019-11-14T19:45:45.786+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:495","msg":"tree_c done"}"
{"level":"info","ts":"2019-11-14T19:45:45.795+01:00","logger":"storage_proofs::stacked::proof","caller":"storage-proofs/src/stacked/proof.rs:497","msg":"tree_r_last done"}"
{"level":"info","ts":"2019-11-14T19:45:45.797+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:216","msg":"replication_time: 62.277651547s"}"
{"level":"info","ts":"2019-11-14T19:45:45.798+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:230","msg":"replication_time/byte: 3.801125ms"}"
{"level":"info","ts":"2019-11-14T19:45:45.798+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:231","msg":"replication_time/GiB: 4081426.890752s"}"
{"level":"info","ts":"2019-11-14T19:45:45.798+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:233","msg":"generating 1 partition proofs"}"
{"level":"info","ts":"2019-11-14T19:45:45.802+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:248","msg":"vanilla_proving_time: 3.957739ms"}"
{"level":"info","ts":"2019-11-14T19:45:45.802+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:253","msg":"sampling verifying (samples: 5)"}"
{"level":"info","ts":"2019-11-14T19:45:49.456+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:270","msg":"Verification complete"}"
{"level":"info","ts":"2019-11-14T19:45:49.456+01:00","logger":"stacked","caller":"filecoin-proofs/examples/stacked.rs:276","msg":"average_vanilla_verifying_time: 0.730860279 seconds"}"
```

[IPFS go-log]: https://github.com/ipfs/go-log

Author: vmx

README.md

@@ -100,13 +100,13 @@ For development purposes we have an (experimental) support for CPU and memory pr
 
 For better logging with backtraces on errors, developers should use `expects` rather than `expect` on `Result<T, E>` and `Option<T>`.
 
-The crate use [`log`](https://crates.io/crates/log) for logging, which by default does not log at all. In order to log output crates like [`pretty_env_logger`](https://crates.io/crates/pretty_env_logger) can be used.
+The crate use [`log`](https://crates.io/crates/log) for logging, which by default does not log at all. In order to log output crates like [`fil_logger`](https://crates.io/crates/fil_logger) can be used.
 
 For example
 
 ```rust
 fn main() {
-    pretty_env_logger::init();
+    fil_logger::init();
 }
 ```
 

fil-proofs-tooling/Cargo.toml

@@ -36,7 +36,7 @@ heim = "0.0.8"
 futures-preview = "0.3.0-alpha.17"
 raw-cpuid = "7.0.3"
 blake2s_simd = "0.5.6"
-pretty_env_logger = "0.3.1"
+fil_logger = "0.1"
 log = "0.4.8"
 uom = "0.25.0"
 merkletree = "0.13.0"

fil-proofs-tooling/src/bin/benchy/main.rs

@@ -8,7 +8,7 @@ mod hash_fns;
 mod stacked;
 
 fn main() {
-    pretty_env_logger::init_timed();
+    fil_logger::init();
 
     let stacked_cmd = SubCommand::with_name("stacked")
                 .about("Run stacked sealing")

filecoin-proofs/Cargo.toml

@@ -31,7 +31,7 @@ paired = "0.16.0"
 fil-sapling-crypto = "0.2.0"
 clap = "2"
 log = "0.4.7"
-pretty_env_logger = "0.3.0"
+fil_logger = "0.1"
 env_proxy = "0.3"
 os_type = "2.2.0"
 flate2 = { version = "1.0.9", features = ["rust_backend"]}
@@ -54,7 +54,6 @@ features = ["default-tls-vendored"]
 gperftools = "0.2"
 criterion = "0.3"
 rexpect = "0.3.0"
-pretty_env_logger = "0.3.1"
 pretty_assertions = "0.6.1"
 rand_xorshift = "0.2.0"
 failure = "0.1"

filecoin-proofs/examples/stacked.rs

@@ -415,7 +415,7 @@ fn do_the_work<H: 'static>(
 }
 
 fn main() {
-    pretty_env_logger::init_timed();
+    fil_logger::init();
 
     let matches = App::new(stringify!("DrgPoRep Vanilla Bench"))
         .version("1.0")

filecoin-proofs/src/api/mod.rs

@@ -276,6 +276,7 @@ mod tests {
 
     use std::collections::BTreeMap;
     use std::io::{Seek, SeekFrom, Write};
+    use std::sync::Once;
 
     use ff::Field;
     use paired::bls12_381::{Bls12, Fr};
@@ -290,6 +291,13 @@ mod tests {
     };
     use crate::types::{PoStConfig, SectorSize};
 
+    static INIT_LOGGER: Once = Once::new();
+    fn init_logger() {
+        INIT_LOGGER.call_once(|| {
+            fil_logger::init();
+        });
+    }
+
     #[test]
     fn test_verify_seal_fr32_validation() {
         let convertible_to_fr_bytes = [0; 32];
@@ -362,7 +370,7 @@ mod tests {
     #[test]
     #[ignore]
     fn test_verify_post_fr32_validation() {
-        pretty_env_logger::try_init().ok();
+        init_logger();
 
         let not_convertible_to_fr_bytes = [255; 32];
         let out = bytes_into_fr::<Bls12>(&not_convertible_to_fr_bytes);
@@ -408,7 +416,7 @@ mod tests {
     #[test]
     #[ignore]
     fn test_seal_lifecycle() -> Result<()> {
-        pretty_env_logger::try_init().ok();
+        init_logger();
 
         let rng = &mut XorShiftRng::from_seed(crate::TEST_SEED);
 

filecoin-proofs/src/bin/paramcache.rs

@@ -117,7 +117,7 @@ fn cache_post_params(post_config: PoStConfig) {
 
 // Run this from the command-line to pre-generate the groth parameters used by the API.
 pub fn main() {
-    pretty_env_logger::init_timed();
+    fil_logger::init();
 
     let matches = App::new("paramcache")
         .version("0.1")

filecoin-proofs/src/bin/paramfetch.rs

@@ -44,7 +44,7 @@ impl<R: Read> Read for FetchProgress<R> {
 }
 
 pub fn main() {
-    pretty_env_logger::init_timed();
+    fil_logger::init();
 
     let matches = App::new("paramfetch")
         .version("1.1")

filecoin-proofs/src/bin/parampublish.rs

@@ -23,7 +23,7 @@ const ERROR_IPFS_COMMAND: &str = "failed to run ipfs";
 const ERROR_IPFS_PUBLISH: &str = "failed to publish via ipfs";
 
 pub fn main() {
-    pretty_env_logger::init_timed();
+    fil_logger::init();
 
     let matches = App::new("parampublish")
         .version("1.0")

storage-proofs/Cargo.toml

@@ -44,7 +44,6 @@ paired = { version = "0.16.0", features = ["serde"] }
 fil-sapling-crypto = "0.2.0"
 serde_json = "1.0"
 log = "0.4.7"
-pretty_env_logger = "0.3.0"
 pretty_assertions = "0.6.1"
 crossbeam = "0.7.2"
 num_cpus = "1.10.1"