From 8e382a759346449dce5ea31298f83c19d35c3de5 Mon Sep 17 00:00:00 2001 From: Yeastplume Date: Thu, 12 Oct 2017 17:56:44 +0100 Subject: [PATCH] slog-rs logging (#171) * added global slog instance, changed all logging macro formats to include logger instance * adding configuration to logging, allowing for multiple log outputs * updates to test, changes to build docs * rustfmt * moving logging functions into util crate --- Cargo.toml | 4 +- api/Cargo.toml | 2 +- api/src/client.rs | 23 ++-- api/src/endpoints.rs | 6 +- api/src/lib.rs | 2 +- api/src/rest.rs | 65 ++++------ api/src/types.rs | 5 +- chain/Cargo.toml | 3 +- chain/src/chain.rs | 43 ++++--- chain/src/lib.rs | 3 +- chain/src/pipe.rs | 53 ++++---- chain/src/store.rs | 12 +- chain/src/sumtree.rs | 40 +++--- chain/src/types.rs | 7 +- config/Cargo.toml | 1 + config/src/config.rs | 2 + config/src/lib.rs | 1 + config/src/types.rs | 14 ++- doc/build.md | 22 ++-- grin.toml | 34 ++++- grin/Cargo.toml | 3 +- grin/src/adapters.rs | 94 ++++++++------ grin/src/lib.rs | 3 +- grin/src/miner.rs | 156 ++++++++++++----------- grin/src/seed.rs | 97 +++++++-------- grin/src/server.rs | 18 +-- grin/src/sync.rs | 12 +- grin/tests/framework.rs | 1 - grin/tests/simulnet.rs | 6 - p2p/Cargo.toml | 5 +- p2p/src/conn.rs | 114 +++++++---------- p2p/src/handshake.rs | 29 +++-- p2p/src/lib.rs | 2 +- p2p/src/msg.rs | 31 ++--- p2p/src/peer.rs | 86 ++++++------- p2p/src/protocol.rs | 41 +++--- p2p/src/rate_limit.rs | 10 +- p2p/src/server.rs | 46 ++++--- p2p/src/store.rs | 24 ++-- p2p/src/types.rs | 2 +- p2p/tests/peer_handshake.rs | 2 - pool/Cargo.toml | 2 +- pool/src/lib.rs | 1 - pow/Cargo.toml | 6 +- pow/src/cuckoo.rs | 242 +++++------------------------------- pow/src/lib.rs | 30 ++--- pow/src/plugin.rs | 17 ++- src/bin/grin.rs | 21 ++-- store/Cargo.toml | 4 +- store/src/lib.rs | 24 ++-- store/src/sumtree.rs | 62 ++++----- util/Cargo.toml | 12 +- util/src/lib.rs | 39 +++++- util/src/logger.rs | 87 +++++++++++++ util/src/types.rs | 62 +++++++++ wallet/Cargo.toml | 2 +- wallet/src/checker.rs | 18 +-- wallet/src/info.rs | 8 +- wallet/src/lib.rs | 2 +- wallet/src/receiver.rs | 125 +++++++++++-------- wallet/src/sender.rs | 20 ++- wallet/src/types.rs | 71 +++++------ 62 files changed, 973 insertions(+), 1006 deletions(-) create mode 100644 util/src/logger.rs create mode 100644 util/src/types.rs diff --git a/Cargo.toml b/Cargo.toml index b076c52a1..586605849 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,15 +15,15 @@ grin_grin = { path = "./grin" } grin_config = { path = "./config" } grin_core = { path = "./core" } grin_pow = { path = "./pow"} +grin_util = { path = "./util"} secp256k1zkp = { git = "https://github.com/mimblewimble/rust-secp256k1-zkp" } blake2-rfc = "~0.2.17" clap = "^2.23.3" daemonize = "^0.2.3" -env_logger="^0.3.5" -log = "^0.3" serde = "~1.0.8" serde_derive = "~1.0.8" serde_json = "~1.0.2" +slog = "^2.0.12" # TODO - once "patch" is available we should be able to clean up the workspace dependencies # [patch.crate-io] diff --git a/api/Cargo.toml b/api/Cargo.toml index 23434fe27..d8c2f401e 100644 --- a/api/Cargo.toml +++ b/api/Cargo.toml @@ -12,8 +12,8 @@ grin_store = { path = "../store" } grin_util = { path = "../util" } secp256k1zkp = { git = "https://github.com/mimblewimble/rust-secp256k1-zkp" } hyper = "~0.10.6" +slog = "^2.0.12" iron = "~0.5.1" -log = "~0.3" router = "~0.5.1" serde = "~1.0.8" serde_derive = "~1.0.8" diff --git a/api/src/client.rs b/api/src/client.rs index 0b7dcb790..80e8df75d 100644 --- a/api/src/client.rs +++ b/api/src/client.rs @@ -26,14 +26,12 @@ use rest::Error; /// returns a JSON object. Handles request building, JSON deserialization and /// response code checking. pub fn get<'a, T>(url: &'a str) -> Result -where - for<'de> T: Deserialize<'de>, + where for<'de> T: Deserialize<'de> { let client = hyper::Client::new(); let res = check_error(client.get(url).send())?; - serde_json::from_reader(res).map_err(|e| { - Error::Internal(format!("Server returned invalid JSON: {}", e)) - }) + serde_json::from_reader(res) + .map_err(|e| Error::Internal(format!("Server returned invalid JSON: {}", e))) } /// Helper function to easily issue a HTTP POST request with the provided JSON @@ -41,18 +39,15 @@ where /// building, JSON serialization and deserialization, and response code /// checking. pub fn post<'a, IN, OUT>(url: &'a str, input: &IN) -> Result -where - IN: Serialize, - for<'de> OUT: Deserialize<'de>, + where IN: Serialize, + for<'de> OUT: Deserialize<'de> { - let in_json = serde_json::to_string(input).map_err(|e| { - Error::Internal(format!("Could not serialize data to JSON: {}", e)) - })?; + let in_json = serde_json::to_string(input) + .map_err(|e| Error::Internal(format!("Could not serialize data to JSON: {}", e)))?; let client = hyper::Client::new(); let res = check_error(client.post(url).body(&mut in_json.as_bytes()).send())?; - serde_json::from_reader(res).map_err(|e| { - Error::Internal(format!("Server returned invalid JSON: {}", e)) - }) + serde_json::from_reader(res) + .map_err(|e| Error::Internal(format!("Server returned invalid JSON: {}", e))) } // convert hyper error and check for non success response codes diff --git a/api/src/endpoints.rs b/api/src/endpoints.rs index 4e2660bfc..6f63b6ef3 100644 --- a/api/src/endpoints.rs +++ b/api/src/endpoints.rs @@ -24,6 +24,7 @@ use rest::*; use types::*; use secp::pedersen::Commitment; use util; +use util::LOGGER; /// ApiEndpoint implementation for the blockchain. Exposes the current chain /// state as a simple JSON object. @@ -69,7 +70,7 @@ impl ApiEndpoint for OutputApi { } fn get(&self, id: String) -> ApiResult { - debug!("GET output {}", id); + debug!(LOGGER, "GET output {}", id); let c = util::from_hex(id.clone()).map_err(|_| { Error::Argument(format!("Not a valid commitment: {}", id)) })?; @@ -130,6 +131,7 @@ where identifier: "?.?.?.?".to_string(), }; info!( + LOGGER, "Pushing transaction with {} inputs and {} outputs to pool.", tx.inputs.len(), tx.outputs.len() @@ -172,7 +174,7 @@ pub fn start_rest_apis( apis.register_endpoint("/pool".to_string(), PoolApi { tx_pool: tx_pool }); apis.start(&addr[..]).unwrap_or_else(|e| { - error!("Failed to start API HTTP server: {}.", e); + error!(LOGGER, "Failed to start API HTTP server: {}.", e); }); }); } diff --git a/api/src/lib.rs b/api/src/lib.rs index 626e22887..5585995d0 100644 --- a/api/src/lib.rs +++ b/api/src/lib.rs @@ -21,7 +21,7 @@ extern crate secp256k1zkp as secp; extern crate hyper; #[macro_use] -extern crate log; +extern crate slog; extern crate iron; extern crate router; extern crate serde; diff --git a/api/src/rest.rs b/api/src/rest.rs index d88135816..6911a00fe 100644 --- a/api/src/rest.rs +++ b/api/src/rest.rs @@ -36,6 +36,7 @@ use serde::de::DeserializeOwned; use serde_json; use store; +use util::LOGGER; /// Errors that can be returned by an ApiEndpoint implementation. #[derive(Debug)] @@ -171,13 +172,13 @@ impl Handler for ApiWrapper Method::Get => { let res = self.0.get(extract_param(req, "id")?)?; let res_json = serde_json::to_string(&res) - .map_err(|e| IronError::new(e, status::InternalServerError))?; + .map_err(|e| IronError::new(e, status::InternalServerError))?; Ok(Response::with((status::Ok, res_json))) } Method::Put => { let id = extract_param(req, "id")?; let t: E::T = serde_json::from_reader(req.body.by_ref()) - .map_err(|e| IronError::new(e, status::BadRequest))?; + .map_err(|e| IronError::new(e, status::BadRequest))?; self.0.update(id, t)?; Ok(Response::with(status::NoContent)) } @@ -188,7 +189,7 @@ impl Handler for ApiWrapper } Method::Post => { let t: E::T = serde_json::from_reader(req.body.by_ref()) - .map_err(|e| IronError::new(e, status::BadRequest))?; + .map_err(|e| IronError::new(e, status::BadRequest))?; let id = self.0.create(t)?; Ok(Response::with((status::Created, id.to_string()))) } @@ -203,8 +204,7 @@ struct OpWrapper { } impl Handler for OpWrapper -where - E: ApiEndpoint, + where E: ApiEndpoint { fn handle(&self, req: &mut Request) -> IronResult { let t: E::OP_IN = serde_json::from_reader(req.body.by_ref()).map_err(|e| { @@ -219,7 +219,7 @@ where Ok(Response::with((status::Ok, res_json))) } Err(e) => { - error!("API operation: {:?}", e); + error!(LOGGER, "API operation: {:?}", e); Err(IronError::from(e)) } } @@ -227,9 +227,8 @@ where } fn extract_param(req: &mut Request, param: &'static str) -> IronResult -where - ID: ToString + FromStr, - ::Err: Debug + Send + error::Error + 'static, + where ID: ToString + FromStr, + ::Err: Debug + Send + error::Error + 'static { let id = req.extensions @@ -237,9 +236,8 @@ where .unwrap() .find(param) .unwrap_or(""); - id.parse::().map_err( - |e| IronError::new(e, status::BadRequest), - ) + id.parse::() + .map_err(|e| IronError::new(e, status::BadRequest)) } /// HTTP server allowing the registration of ApiEndpoint implementations. @@ -279,9 +277,8 @@ impl ApiServer { /// Register a new API endpoint, providing a relative URL for the new /// endpoint. pub fn register_endpoint(&mut self, subpath: String, endpoint: E) - where - E: ApiEndpoint, - <::ID as FromStr>::Err: Debug + Send + error::Error, + where E: ApiEndpoint, + <::ID as FromStr>::Err: Debug + Send + error::Error { assert_eq!(subpath.chars().nth(0).unwrap(), '/'); @@ -299,13 +296,9 @@ impl ApiServer { endpoint: endpoint.clone(), }; let full_path = format!("{}/{}", root.clone(), op_s.clone()); - self.router.route( - op.to_method(), - full_path.clone(), - wrapper, - route_name, - ); - info!("route: POST {}", full_path); + self.router + .route(op.to_method(), full_path.clone(), wrapper, route_name); + info!(LOGGER, "route: POST {}", full_path); } else { // regular REST operations @@ -317,21 +310,18 @@ impl ApiServer { _ => panic!("unreachable"), }; let wrapper = ApiWrapper(endpoint.clone()); - self.router.route( - op.to_method(), - full_path.clone(), - wrapper, - route_name, - ); - info!("route: {} {}", op.to_method(), full_path); + self.router + .route(op.to_method(), full_path.clone(), wrapper, route_name); + info!(LOGGER, "route: {} {}", op.to_method(), full_path); } } // support for the HTTP Options method by differentiating what's on the // root resource vs the id resource - let (root_opts, sub_opts) = endpoint.operations().iter().fold( - (vec![], vec![]), - |mut acc, op| { + let (root_opts, sub_opts) = endpoint + .operations() + .iter() + .fold((vec![], vec![]), |mut acc, op| { let m = op.to_method(); if m == Method::Post { acc.0.push(m); @@ -339,23 +329,18 @@ impl ApiServer { acc.1.push(m); } acc - }, - ); + }); self.router.options( root.clone(), move |_: &mut Request| { - Ok(Response::with( - (status::Ok, Header(headers::Allow(root_opts.clone()))), - )) + Ok(Response::with((status::Ok, Header(headers::Allow(root_opts.clone()))))) }, "option_".to_string() + route_postfix, ); self.router.options( root.clone() + "/:id", move |_: &mut Request| { - Ok(Response::with( - (status::Ok, Header(headers::Allow(sub_opts.clone()))), - )) + Ok(Response::with((status::Ok, Header(headers::Allow(sub_opts.clone()))))) }, "option_id_".to_string() + route_postfix, ); diff --git a/api/src/types.rs b/api/src/types.rs index 57c7605c8..41d682a31 100644 --- a/api/src/types.rs +++ b/api/src/types.rs @@ -58,10 +58,7 @@ impl Output { pub fn from_output(output: &core::Output, block_header: &core::BlockHeader) -> Output { let (output_type, lock_height) = match output.features { x if x.contains(core::transaction::COINBASE_OUTPUT) => { - ( - OutputType::Coinbase, - block_header.height + global::coinbase_maturity(), - ) + (OutputType::Coinbase, block_header.height + global::coinbase_maturity()) } _ => (OutputType::Transaction, 0), }; diff --git a/chain/Cargo.toml b/chain/Cargo.toml index 15b7910fa..59d1ace21 100644 --- a/chain/Cargo.toml +++ b/chain/Cargo.toml @@ -7,13 +7,14 @@ workspace = ".." [dependencies] bitflags = "^0.7.0" byteorder = "^0.5" -log = "^0.3" +slog = "^2.0.12" serde = "~1.0.8" serde_derive = "~1.0.8" time = "^0.1" grin_core = { path = "../core" } grin_keychain = { path = "../keychain" } +grin_util = { path = "../util" } grin_store = { path = "../store" } secp256k1zkp = { git = "https://github.com/mimblewimble/rust-secp256k1-zkp" } diff --git a/chain/src/chain.rs b/chain/src/chain.rs index 9dcefb78c..0c775a033 100644 --- a/chain/src/chain.rs +++ b/chain/src/chain.rs @@ -28,6 +28,7 @@ use pipe; use store; use sumtree; use types::*; +use util::LOGGER; use core::global::{MiningParameterMode, MINING_PARAMETER_MODE}; @@ -69,12 +70,11 @@ impl Chain { /// on the current chain head to make sure it exists and creates one based /// on /// the genesis block if necessary. - pub fn init( - db_root: String, - adapter: Arc, - gen_block: Option, - pow_verifier: fn(&BlockHeader, u32) -> bool, - ) -> Result { + pub fn init(db_root: String, + adapter: Arc, + gen_block: Option, + pow_verifier: fn(&BlockHeader, u32) -> bool) + -> Result { let chain_store = store::ChainKVStore::new(db_root.clone())?; // check if we have a head in store, otherwise the genesis block is it @@ -92,7 +92,7 @@ impl Chain { // saving a new tip based on genesis let tip = Tip::new(gen.hash()); chain_store.save_head(&tip)?; - info!("Saved genesis block with hash {}", gen.hash()); + info!(LOGGER, "Saved genesis block with hash {}", gen.hash()); tip } Err(e) => return Err(Error::StoreErr(e)), @@ -138,6 +138,7 @@ impl Chain { } Err(ref e) => { info!( + LOGGER, "Rejected block {} at {} : {:?}", b.hash(), b.header.height, @@ -151,11 +152,10 @@ impl Chain { /// Attempt to add a new header to the header chain. Only necessary during /// sync. - pub fn process_block_header( - &self, - bh: &BlockHeader, - opts: Options, - ) -> Result, Error> { + pub fn process_block_header(&self, + bh: &BlockHeader, + opts: Options) + -> Result, Error> { let head = self.store.get_header_head().map_err(&Error::StoreErr)?; let ctx = self.ctx_from_head(head, opts); @@ -213,9 +213,9 @@ impl Chain { let sumtrees = self.sumtrees.read().unwrap(); let is_unspent = sumtrees.is_unspent(output_ref)?; if is_unspent { - self.store.get_output_by_commit(output_ref).map_err( - &Error::StoreErr, - ) + self.store + .get_output_by_commit(output_ref) + .map_err(&Error::StoreErr) } else { Err(Error::OutputNotFound) } @@ -266,16 +266,15 @@ impl Chain { /// Gets the block header at the provided height pub fn get_header_by_height(&self, height: u64) -> Result { - self.store.get_header_by_height(height).map_err( - &Error::StoreErr, - ) + self.store + .get_header_by_height(height) + .map_err(&Error::StoreErr) } /// Gets the block header by the provided output commitment - pub fn get_block_header_by_output_commit( - &self, - commit: &Commitment, - ) -> Result { + pub fn get_block_header_by_output_commit(&self, + commit: &Commitment) + -> Result { self.store .get_block_header_by_output_commit(commit) .map_err(&Error::StoreErr) diff --git a/chain/src/lib.rs b/chain/src/lib.rs index 32101f0ce..4fbfa8b4f 100644 --- a/chain/src/lib.rs +++ b/chain/src/lib.rs @@ -24,13 +24,14 @@ extern crate bitflags; extern crate byteorder; #[macro_use] -extern crate log; +extern crate slog; extern crate serde; #[macro_use] extern crate serde_derive; extern crate time; extern crate grin_core as core; +extern crate grin_util as util; extern crate grin_store; extern crate secp256k1zkp as secp; diff --git a/chain/src/pipe.rs b/chain/src/pipe.rs index eec025d92..f04314e58 100644 --- a/chain/src/pipe.rs +++ b/chain/src/pipe.rs @@ -27,6 +27,7 @@ use types::*; use store; use sumtree; use core::global; +use util::LOGGER; /// Contextual information required to process a new block and either reject or /// accept it. @@ -53,6 +54,7 @@ pub fn process_block(b: &Block, mut ctx: BlockContext) -> Result, Er // spend resources reading the full block when its header is invalid info!( + LOGGER, "Starting validation pipeline for block {} at {} with {} inputs and {} outputs.", b.hash(), b.header.height, @@ -74,6 +76,7 @@ pub fn process_block(b: &Block, mut ctx: BlockContext) -> Result, Er validate_block(b, &mut ctx, &mut extension)?; debug!( + LOGGER, "Block at {} with hash {} is valid, going to save and append.", b.header.height, b.hash() @@ -92,6 +95,7 @@ pub fn process_block(b: &Block, mut ctx: BlockContext) -> Result, Er pub fn process_block_header(bh: &BlockHeader, mut ctx: BlockContext) -> Result, Error> { info!( + LOGGER, "Starting validation pipeline for block header {} at {}.", bh.hash(), bh.height @@ -135,6 +139,7 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E // check version, enforces scheduled hard fork if !consensus::valid_header_version(header.height, header.version) { error!( + LOGGER, "Invalid block header version received ({}), maybe update Grin?", header.version ); @@ -142,8 +147,7 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E } if header.timestamp > - time::now_utc() + time::Duration::seconds(12 * (consensus::BLOCK_TIME_SEC as i64)) - { + time::now_utc() + time::Duration::seconds(12 * (consensus::BLOCK_TIME_SEC as i64)) { // refuse blocks more than 12 blocks intervals in future (as in bitcoin) // TODO add warning in p2p code if local time is too different from peers return Err(Error::InvalidBlockTime); @@ -155,16 +159,16 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E } else { consensus::DEFAULT_SIZESHIFT }; - debug!("Validating block with cuckoo size {}", cycle_size); + debug!(LOGGER, "Validating block with cuckoo size {}", cycle_size); if !(ctx.pow_verifier)(header, cycle_size as u32) { return Err(Error::InvalidPow); } } // first I/O cost, better as late as possible - let prev = try!(ctx.store.get_block_header(&header.previous).map_err( - &Error::StoreErr, - )); + let prev = try!(ctx.store + .get_block_header(&header.previous) + .map_err(&Error::StoreErr)); if header.height != prev.height + 1 { return Err(Error::InvalidBlockHeight); @@ -183,9 +187,8 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E } let diff_iter = store::DifficultyIter::from(header.previous, ctx.store.clone()); - let difficulty = consensus::next_difficulty(diff_iter).map_err(|e| { - Error::Other(e.to_string()) - })?; + let difficulty = consensus::next_difficulty(diff_iter) + .map_err(|e| Error::Other(e.to_string()))?; if header.difficulty < difficulty { return Err(Error::DifficultyTooLow); } @@ -195,11 +198,10 @@ fn validate_header(header: &BlockHeader, ctx: &mut BlockContext) -> Result<(), E } /// Fully validate the block content. -fn validate_block( - b: &Block, - ctx: &mut BlockContext, - ext: &mut sumtree::Extension, -) -> Result<(), Error> { +fn validate_block(b: &Block, + ctx: &mut BlockContext, + ext: &mut sumtree::Extension) + -> Result<(), Error> { if b.header.height > ctx.head.height + 1 { return Err(Error::Orphan); } @@ -248,11 +250,7 @@ fn validate_block( if forked_block.header.height > 0 { let last_output = &forked_block.outputs[forked_block.outputs.len() - 1]; let last_kernel = &forked_block.kernels[forked_block.kernels.len() - 1]; - ext.rewind( - forked_block.header.height, - last_output, - last_kernel, - )?; + ext.rewind(forked_block.header.height, last_output, last_kernel)?; } // apply all forked blocks, including this new one @@ -265,8 +263,7 @@ fn validate_block( let (utxo_root, rproof_root, kernel_root) = ext.roots(); if utxo_root.hash != b.header.utxo_root || rproof_root.hash != b.header.range_proof_root || - kernel_root.hash != b.header.kernel_root - { + kernel_root.hash != b.header.kernel_root { return Err(Error::InvalidRoot); } @@ -276,10 +273,8 @@ fn validate_block( if let Ok(output) = ctx.store.get_output_by_commit(&input.commitment()) { if output.features.contains(transaction::COINBASE_OUTPUT) { if let Ok(output_header) = - ctx.store.get_block_header_by_output_commit( - &input.commitment(), - ) - { + ctx.store + .get_block_header_by_output_commit(&input.commitment()) { // TODO - make sure we are not off-by-1 here vs. the equivalent tansaction // validation rule @@ -333,7 +328,12 @@ fn update_head(b: &Block, ctx: &mut BlockContext) -> Result, Error> // TODO if we're switching branch, make sure to backtrack the sum trees ctx.head = tip.clone(); - info!("Updated head to {} at {}.", b.hash(), b.header.height); + info!( + LOGGER, + "Updated head to {} at {}.", + b.hash(), + b.header.height + ); Ok(Some(tip)) } else { Ok(None) @@ -352,6 +352,7 @@ fn update_header_head(bh: &BlockHeader, ctx: &mut BlockContext) -> Result