Improved logging (#138)

* Improved logging

* Removed some unwraps

substrate/Cargo.lock

@@ -1223,7 +1223,9 @@ dependencies = [
 name = "polkadot-cli"
 version = "0.1.0"
 dependencies = [
+ "ansi_term 0.10.2 (registry+https://github.com/rust-lang/crates.io-index)",
  "app_dirs 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "atty 0.2.6 (registry+https://github.com/rust-lang/crates.io-index)",
  "clap 2.31.2 (registry+https://github.com/rust-lang/crates.io-index)",
  "ctrlc 1.1.1 (git+https://github.com/paritytech/rust-ctrlc.git)",
  "ed25519 0.1.0",
@@ -1231,11 +1233,13 @@ dependencies = [
  "error-chain 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)",
  "futures 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)",
  "hex-literal 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "lazy_static 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)",
  "log 0.3.9 (registry+https://github.com/rust-lang/crates.io-index)",
  "polkadot-executor 0.1.0",
  "polkadot-primitives 0.1.0",
  "polkadot-runtime 0.1.0",
  "polkadot-service 0.1.0",
+ "regex 0.2.5 (registry+https://github.com/rust-lang/crates.io-index)",
  "substrate-client 0.1.0",
  "substrate-codec 0.1.0",
  "substrate-executor 0.1.0",
@@ -1244,6 +1248,7 @@ dependencies = [
  "substrate-rpc-servers 0.1.0",
  "substrate-runtime-support 0.1.0",
  "substrate-state-machine 0.1.0",
+ "time 0.1.39 (registry+https://github.com/rust-lang/crates.io-index)",
  "tokio-core 0.1.12 (registry+https://github.com/rust-lang/crates.io-index)",
  "triehash 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)",
 ]

substrate/polkadot/cli/Cargo.toml

@@ -9,6 +9,11 @@ clap = { version = "2.27", features = ["yaml"] }
 env_logger = "0.4"
 error-chain = "0.11"
 log = "0.3"
+atty = "0.2"
+regex = "0.2"
+time = "0.1"
+ansi_term = "0.10"
+lazy_static = "1.0"
 hex-literal = "0.1"
 triehash = "0.1"
 ed25519 = { path = "../../substrate/ed25519" }

substrate/polkadot/cli/src/informant.rs

@@ -45,7 +45,7 @@ pub fn start(service: &Service, handle: reactor::Handle) {
 				(SyncState::Downloading, None) => "Syncing".into(),
 				(SyncState::Downloading, Some(n)) => format!("Syncing, target=#{}", n),
 			};
-			println!("{} ({} peers), best: #{} ({})", status, sync_status.num_peers, best_block.number, hash)
+			info!(target: "polkadot", "{} ({} peers), best: #{} ({})", status, sync_status.num_peers, best_block.number, hash)
 		} else {
 			warn!("Error getting best block information");
 		}
@@ -62,5 +62,3 @@ pub fn start(service: &Service, handle: reactor::Handle) {
 	handle.spawn(display_block_import);
 }
 
-
-

substrate/polkadot/cli/src/lib.rs

@@ -20,6 +20,10 @@
 
 extern crate app_dirs;
 extern crate env_logger;
+extern crate atty;
+extern crate ansi_term;
+extern crate regex;
+extern crate time;
 extern crate futures;
 extern crate tokio_core;
 extern crate ctrlc;
@@ -37,6 +41,8 @@ extern crate polkadot_executor;
 extern crate polkadot_runtime;
 extern crate polkadot_service as service;
 
+#[macro_use]
+extern crate lazy_static;
 #[macro_use]
 extern crate clap;
 #[macro_use]
@@ -183,7 +189,7 @@ fn start_server<T, F>(mut address: SocketAddr, start: F) -> Result<T, io::Error>
 }
 
 fn parse_address(default: &str, port_param: &str, matches: &clap::ArgMatches) -> Result<SocketAddr, String> {
-	let mut address: SocketAddr = default.parse().unwrap();
+	let mut address: SocketAddr = default.parse().ok().ok_or(format!("Invalid address specified for --{}.", port_param))?;
 	if let Some(port) = matches.value_of(port_param) {
 		let port: u16 = port.parse().ok().ok_or(format!("Invalid port for --{} specified.", port_param))?;
 		address.set_port(port);
@@ -219,6 +225,8 @@ fn default_base_path() -> PathBuf {
 }
 
 fn init_logger(pattern: &str) {
+	use ansi_term::Colour;
+
 	let mut builder = env_logger::LogBuilder::new();
 	// Disable info logging by default for some modules:
 	builder.filter(Some("ws"), log::LogLevelFilter::Warn);
@@ -231,7 +239,37 @@ fn init_logger(pattern: &str) {
 	}
 
 	builder.parse(pattern);
+	let isatty = atty::is(atty::Stream::Stderr);
+	let enable_color = isatty;
 
+	let format = move |record: &log::LogRecord| {
+		let timestamp = time::strftime("%Y-%m-%d %H:%M:%S", &time::now()).expect("Error formatting log timestamp");
+
+		let mut output = if log::max_log_level() <= log::LogLevelFilter::Info {
+			format!("{} {}", Colour::Black.bold().paint(timestamp), record.args())
+		} else {
+			let name = ::std::thread::current().name().map_or_else(Default::default, |x| format!("{}", Colour::Blue.bold().paint(x)));
+			format!("{} {} {} {}  {}", Colour::Black.bold().paint(timestamp), name, record.level(), record.target(), record.args())
+		};
+
+		if !enable_color {
+			output = kill_color(output.as_ref());
+		}
+
+		if !isatty && record.level() <= log::LogLevel::Info && atty::is(atty::Stream::Stdout) {
+			// duplicate INFO/WARN output to console
+			println!("{}", output);
+		}
+		output
+	};
+	builder.format(format);
 
 	builder.init().expect("Logger initialized only once.");
 }
+
+fn kill_color(s: &str) -> String {
+	lazy_static! {
+		static ref RE: regex::Regex = regex::Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex");
+	}
+	RE.replace_all(s, "").to_string()
+}