Multi-mode logging. (#1643)

* Multi-mode logging.

Better for miners (they get immediate notification of new block).
Better for general use (less superfluous information shown).

* Remove comment.

[ci:skip]

* Minor string change

[ci:skip]

* Minor message tweak.

* Minor tweaks and indentation fix.

ethcore/src/client/client.rs

@@ -22,21 +22,18 @@ use std::sync::{Arc, Weak};
 use std::path::{Path, PathBuf};
 use std::fmt;
 use std::sync::atomic::{AtomicUsize, AtomicBool, Ordering as AtomicOrdering};
-use std::time::Instant;
+use std::time::{Instant, Duration};
+use time::precise_time_ns;
 
 // util
+use util::{journaldb, rlp, Bytes, Stream, View, PerfTimer, Itertools, Mutex, RwLock, Colour};
+use util::journaldb::JournalDB;
+use util::rlp::{RlpStream, Rlp, UntrustedRlp};
 use util::numbers::*;
 use util::panics::*;
 use util::io::*;
-use util::rlp;
 use util::sha3::*;
-use util::Bytes;
-use util::rlp::{RlpStream, Rlp, UntrustedRlp};
-use util::journaldb;
-use util::journaldb::JournalDB;
 use util::kvdb::*;
-use util::{Stream, View, PerfTimer, Itertools};
-use util::{Mutex, RwLock};
 
 // other
 use views::BlockView;
@@ -145,6 +142,8 @@ pub struct Client {
 	notify: RwLock<Option<Weak<ChainNotify>>>,
 	queue_transactions: AtomicUsize,
 	previous_enode: Mutex<Option<String>>,
+	skipped: AtomicUsize,
+	last_import: Mutex<Instant>,
 	last_hashes: RwLock<VecDeque<H256>>,
 }
 
@@ -233,6 +232,8 @@ impl Client {
 			notify: RwLock::new(None),
 			queue_transactions: AtomicUsize::new(0),
 			previous_enode: Mutex::new(None),
+			skipped: AtomicUsize::new(0),
+			last_import: Mutex::new(Instant::now()),
 			last_hashes: RwLock::new(VecDeque::new()),
 		};
 		Ok(Arc::new(client))
@@ -367,16 +368,21 @@ impl Client {
 
 			for block in blocks {
 				let header = &block.header;
+				let start = precise_time_ns();
 
 				if invalid_blocks.contains(&header.parent_hash) {
 					invalid_blocks.insert(header.hash());
 					continue;
 				}
+				let tx_count = block.transactions.len();
+				let size = block.bytes.len();
+
 				let closed_block = self.check_and_close_block(&block);
 				if let Err(_) = closed_block {
 					invalid_blocks.insert(header.hash());
 					continue;
 				}
+
 				let closed_block = closed_block.unwrap();
 				imported_blocks.push(header.hash());
 
@@ -384,7 +390,30 @@ impl Client {
 				import_results.push(route);
 
 				self.report.write().accrue_block(&block);
-				trace!(target: "client", "Imported #{} ({})", header.number(), header.hash());
+
+				let duration_ns = precise_time_ns() - start;
+
+				let mut last_import = self.last_import.lock();
+				if Instant::now() > *last_import + Duration::from_secs(1) {
+					let queue_info = self.queue_info();
+					let importing = queue_info.unverified_queue_size + queue_info.verified_queue_size > 3;
+					if !importing { 
+						let skipped = self.skipped.load(AtomicOrdering::Relaxed);
+						info!(target: "import", "Imported {} {} ({} txs, {} Mgas, {} ms, {} KiB){}",
+							Colour::White.bold().paint(format!("#{}", header.number())),
+							Colour::White.bold().paint(format!("{}", header.hash())),
+							Colour::Yellow.bold().paint(format!("{}", tx_count)),
+							Colour::Yellow.bold().paint(format!("{:.2}", header.gas_used.low_u64() as f32 / 1000000f32)),
+							Colour::Purple.bold().paint(format!("{:.2}", duration_ns as f32 / 1000000f32)),
+							Colour::Blue.bold().paint(format!("{:.2}", size as f32 / 1024f32)),
+							if skipped > 0 { format!(" + another {} block(s)", Colour::Red.bold().paint(format!("{}", skipped))) } else { String::new() } 
+						);
+						*last_import = Instant::now();
+					}
+					self.skipped.store(0, AtomicOrdering::Relaxed);
+				} else {
+					self.skipped.fetch_add(1, AtomicOrdering::Relaxed); 
+				}
 			}
 
 			let imported = imported_blocks.len();

parity/informant.rs

@@ -15,7 +15,7 @@
 // along with Parity.  If not, see <http://www.gnu.org/licenses/>.
 
 extern crate ansi_term;
-use self::ansi_term::Colour::{White, Yellow, Green, Cyan, Blue, Purple};
+use self::ansi_term::Colour::{White, Yellow, Green, Cyan, Blue};
 use self::ansi_term::Style;
 
 use std::time::{Instant, Duration};
@@ -83,12 +83,17 @@ impl Informant {
 			return;
 		}
 
-		*self.last_tick.write() = Instant::now();
-
 		let chain_info = client.chain_info();
 		let queue_info = client.queue_info();
 		let cache_info = client.blockchain_cache_info();
 
+		let importing = queue_info.unverified_queue_size + queue_info.verified_queue_size > 3;
+		if !importing && elapsed < Duration::from_secs(30) {
+			return;
+		}
+
+		*self.last_tick.write() = Instant::now();
+
 		let mut write_report = self.report.write();
 		let report = client.report();
 
@@ -97,42 +102,46 @@ impl Informant {
 			false => t,
 		};
 
-		if let (_, _, &Some(ref last_report)) = (
+		info!("{}   {}   {}",
-			self.chain_info.read().deref(),
+			match importing {
-			self.cache_info.read().deref(),
+				true => format!("{} {}   {}   {}+{} Qed", 
-			write_report.deref()
-		) {
-			println!("{} {}   {} blk/s {} tx/s {} Mgas/s   {}{}+{} Qed   {} db {} chain {} queue{}",
 					paint(White.bold(), format!("{:>8}", format!("#{}", chain_info.best_block_number))),
 					paint(White.bold(), format!("{}", chain_info.best_block_hash)),
-
+					{
+						let last_report = match write_report.deref() { &Some(ref last_report) => last_report.clone(), _ => ClientReport::default() };
+						format!("{} blk/s {} tx/s {} Mgas/s",  
 							paint(Yellow.bold(), format!("{:4}", ((report.blocks_imported - last_report.blocks_imported) * 1000) as u64 / elapsed.as_milliseconds())),
 							paint(Yellow.bold(), format!("{:4}", ((report.transactions_applied - last_report.transactions_applied) * 1000) as u64 / elapsed.as_milliseconds())),
-				paint(Yellow.bold(), format!("{:3}", ((report.gas_processed - last_report.gas_processed) / From::from(elapsed.as_milliseconds() * 1000)).low_u64())),
+							paint(Yellow.bold(), format!("{:3}", ((report.gas_processed - last_report.gas_processed) / From::from(elapsed.as_milliseconds() * 1000)).low_u64()))
-
-				match maybe_status {
-					Some((ref sync_info, ref net_config)) => {
-						format!("{}/{}/{} peers   {} ",
-							paint(Green.bold(), format!("{:2}", sync_info.num_active_peers)),
-							paint(Green.bold(), format!("{:2}", sync_info.num_peers)),
-							paint(Green.bold(), format!("{:2}", net_config.ideal_peers)),
-							paint(Cyan.bold(), format!("{:>8}", format!("#{}", sync_info.last_imported_block_number.unwrap_or(chain_info.best_block_number)))),
 						)
-					}
-					None => String::new()
 					},
-
+					paint(Green.bold(), format!("{:5}", queue_info.unverified_queue_size)),
-				paint(Blue.bold(), format!("{:5}", queue_info.unverified_queue_size)),
+					paint(Green.bold(), format!("{:5}", queue_info.verified_queue_size))
-				paint(Blue.bold(), format!("{:5}", queue_info.verified_queue_size)),
+				),
-
+				false => String::new(),
-				paint(Purple.bold(), format!("{:>8}", Informant::format_bytes(report.state_db_mem))),
+			},
-				paint(Purple.bold(), format!("{:>8}", Informant::format_bytes(cache_info.total()))),
+			match maybe_status {
-				paint(Purple.bold(), format!("{:>8}", Informant::format_bytes(queue_info.mem_used))),
+				Some((ref sync_info, ref net_config)) => format!("{}{}/{}/{} peers",
-				if let Some((ref sync_info, _)) = maybe_status {
+					match importing {
-					format!(" {} sync", paint(Purple.bold(), format!("{:>8}", Informant::format_bytes(sync_info.mem_used))))
+						true => format!("{}   ", paint(Green.bold(), format!("{:>8}", format!("#{}", sync_info.last_imported_block_number.unwrap_or(chain_info.best_block_number))))),
-				} else { String::new() },
+						false => String::new(),
-			);
+					},
+					paint(Cyan.bold(), format!("{:2}", sync_info.num_active_peers)),
+					paint(Cyan.bold(), format!("{:2}", sync_info.num_peers)),
+					paint(Cyan.bold(), format!("{:2}", net_config.ideal_peers))
+				),
+				None => String::new(),
+			},
+			format!("{} db {} chain {} queue{}", 
+				paint(Blue.bold(), format!("{:>8}", Informant::format_bytes(report.state_db_mem))),
+				paint(Blue.bold(), format!("{:>8}", Informant::format_bytes(cache_info.total()))),
+				paint(Blue.bold(), format!("{:>8}", Informant::format_bytes(queue_info.mem_used))),
+				match maybe_status {
+					Some((ref sync_info, _)) => format!(" {} sync", paint(Blue.bold(), format!("{:>8}", Informant::format_bytes(sync_info.mem_used)))), 
+					_ => String::new(),
 				}
+			)
+		);
 
 		*self.chain_info.write().deref_mut() = Some(chain_info);
 		*self.cache_info.write().deref_mut() = Some(cache_info);

parity/main.rs

@@ -83,7 +83,7 @@ use std::thread::sleep;
 use std::time::Duration;
 use rustc_serialize::hex::FromHex;
 use ctrlc::CtrlC;
-use util::{H256, ToPretty, PayloadInfo, Bytes, Colour, version, journaldb};
+use util::{H256, ToPretty, PayloadInfo, Bytes, Colour, version, journaldb, RotatingLogger};
 use util::panics::{MayPanic, ForwardPanic, PanicHandler};
 use ethcore::client::{BlockID, BlockChainClient, ClientConfig, get_db_path, BlockImportError,
 	ChainNotify, Mode};
@@ -129,6 +129,13 @@ fn execute(conf: Configuration) {
 		daemonize(&conf);
 	}
 
+	// Setup panic handler
+	let panic_handler = PanicHandler::new_in_arc();
+	// Setup logging
+	let logger = setup_log::setup_log(&conf.args.flag_logging, conf.have_color(), &conf.args.flag_log_file);
+	// Raise fdlimit
+	unsafe { ::fdlimit::raise_fd_limit(); }
+
 	if conf.args.cmd_account {
 		execute_account_cli(conf);
 		return;
@@ -140,16 +147,16 @@ fn execute(conf: Configuration) {
 	}
 
 	if conf.args.cmd_export {
-		execute_export(conf);
+		execute_export(conf, panic_handler);
 		return;
 	}
 
 	if conf.args.cmd_import {
-		execute_import(conf);
+		execute_import(conf, panic_handler);
 		return;
 	}
 
-	execute_client(conf, spec, client_config);
+	execute_client(conf, spec, client_config, panic_handler, logger);
 }
 
 #[cfg(not(windows))]
@@ -169,7 +176,7 @@ fn daemonize(_conf: &Configuration) {
 fn execute_upgrades(conf: &Configuration, spec: &Spec, client_config: &ClientConfig) {
 	match ::upgrade::upgrade(Some(&conf.path())) {
 		Ok(upgrades_applied) if upgrades_applied > 0 => {
-			println!("Executed {} upgrade scripts - ok", upgrades_applied);
+			debug!("Executed {} upgrade scripts - ok", upgrades_applied);
 		},
 		Err(e) => {
 			die!("Error upgrading parity data: {:?}", e);
@@ -184,15 +191,7 @@ fn execute_upgrades(conf: &Configuration, spec: &Spec, client_config: &ClientCon
 	}
 }
 
-fn execute_client(conf: Configuration, spec: Spec, client_config: ClientConfig) {
+fn execute_client(conf: Configuration, spec: Spec, client_config: ClientConfig, panic_handler: Arc<PanicHandler>, logger: Arc<RotatingLogger>) {
-	// Setup panic handler
-	let panic_handler = PanicHandler::new_in_arc();
-
-	// Setup logging
-	let logger = setup_log::setup_log(&conf.args.flag_logging, conf.have_color(), &conf.args.flag_log_file);
-	// Raise fdlimit
-	unsafe { ::fdlimit::raise_fd_limit(); }
-
 	info!("Starting {}", Colour::White.bold().paint(format!("{}", version())));
 	info!("Using state DB journalling strategy {}", Colour::White.bold().paint(match client_config.pruning {
 		journaldb::Algorithm::Archive => "archive",
@@ -337,15 +336,7 @@ enum DataFormat {
 	Binary,
 }
 
-fn execute_export(conf: Configuration) {
+fn execute_export(conf: Configuration, panic_handler: Arc<PanicHandler>) {
-	// Setup panic handler
-	let panic_handler = PanicHandler::new_in_arc();
-
-	// Setup logging
-	let _logger = setup_log::setup_log(&conf.args.flag_logging, conf.have_color(), &conf.args.flag_log_file);
-	// Raise fdlimit
-	unsafe { ::fdlimit::raise_fd_limit(); }
-
 	let spec = conf.spec();
 	let client_config = conf.client_config(&spec);
 
@@ -398,15 +389,7 @@ fn execute_export(conf: Configuration) {
 	}
 }
 
-fn execute_import(conf: Configuration) {
+fn execute_import(conf: Configuration, panic_handler: Arc<PanicHandler>) {
-	// Setup panic handler
-	let panic_handler = PanicHandler::new_in_arc();
-
-	// Setup logging
-	let _logger = setup_log::setup_log(&conf.args.flag_logging, conf.have_color(), &conf.args.flag_log_file);
-	// Raise fdlimit
-	unsafe { ::fdlimit::raise_fd_limit(); }
-
 	let spec = conf.spec();
 	let client_config = conf.client_config(&spec);
 
@@ -441,11 +424,11 @@ fn execute_import(conf: Configuration) {
 			first_read = instream.read(&mut(first_bytes[..])).unwrap_or_else(|_| die!("Error reading from the file/stream."));
 			match first_bytes[0] {
 				0xf9 => {
-					println!("Autodetected binary data format.");
+					info!("Autodetected binary data format.");
 					DataFormat::Binary
 				}
 				_ => {
-					println!("Autodetected hex data format.");
+					info!("Autodetected hex data format.");
 					DataFormat::Hex
 				}
 			}
@@ -496,9 +479,10 @@ fn execute_signer(conf: Configuration) {
 	}
 
 	let path = conf.directories().signer;
-	new_token(path).unwrap_or_else(|e| {
+	let code = new_token(path).unwrap_or_else(|e| {
 		die!("Error generating token: {:?}", e)
 	});
+	println!("This key code will authorise your System Signer UI: {}", if conf.args.flag_no_color { code } else { format!("{}", Colour::White.bold().paint(code)) });
 }
 
 fn execute_account_cli(conf: Configuration) {

parity/signer.rs

@@ -54,13 +54,13 @@ fn codes_path(path: String) -> PathBuf {
 	p
 }
 
-pub fn new_token(path: String) -> io::Result<()> {
+pub fn new_token(path: String) -> io::Result<String> {
 	let path = codes_path(path);
 	let mut codes = try!(signer::AuthCodes::from_file(&path));
 	let code = try!(codes.generate_new());
 	try!(codes.to_file(&path));
-	info!("This key code will authorise your System Signer UI: {}", Colour::White.bold().paint(code));
+	trace!("New key code created: {}", Colour::White.bold().paint(&code[..]));
-	Ok(())
+	Ok(code)
 }
 
 fn do_start(conf: Configuration, deps: Dependencies) -> SignerServer {

parity/upgrade.rs

@@ -64,7 +64,6 @@ impl UpgradeKey {
 
 // dummy upgrade (remove when the first one is in)
 fn dummy_upgrade() -> Result<(), Error> {
-	println!("Adding ver.lock");
 	Ok(())
 }