diff --git a/Cargo.lock b/Cargo.lock index bb58d5fd5ed4..ee7cffadab46 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1705,6 +1705,7 @@ name = "polkadot-api" version = "0.1.0" dependencies = [ "error-chain 0.12.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", diff --git a/api/Cargo.toml b/api/Cargo.toml index 019b2339acba..bf51a09ef2a6 100644 --- a/api/Cargo.toml +++ b/api/Cargo.toml @@ -16,6 +16,7 @@ substrate-client = { git = "https://github.com/paritytech/substrate" } substrate-primitives = { git = "https://github.com/paritytech/substrate" } substrate-executor = { git = "https://github.com/paritytech/substrate" } substrate-state-machine = { git = "https://github.com/paritytech/substrate" } +log = "0.3" [dev-dependencies] substrate-keyring = { git = "https://github.com/paritytech/substrate" } diff --git a/api/src/full.rs b/api/src/full.rs index 7ccffecd1d77..f6d557029125 100644 --- a/api/src/full.rs +++ b/api/src/full.rs @@ -97,18 +97,33 @@ impl> PolkadotApi for Client Result { use substrate_executor::error::ErrorKind as ExecErrorKind; - use codec::{Decode, Encode}; - use runtime::Block as RuntimeBlock; + use codec::Encode; + use state_machine::ExecutionManager; + use client::CallExecutor; + + let parent = at; + let res = self.state_at(&parent).map_err(Error::from).and_then(|state| { + let mut overlay = Default::default(); + let execution_manager = || ExecutionManager::Both(|wasm_result, native_result| { + warn!("Consensus error between wasm and native runtime execution at block {:?}", at); + warn!(" While executing block {:?}", (block.header.number, block.header.hash())); + warn!(" Native result {:?}", native_result); + warn!(" Wasm result {:?}", wasm_result); + wasm_result + }); + let (r, _) = self.executor().call_at_state( + &state, + &mut overlay, + "execute_block", + &block.encode(), + execution_manager() + )?; + + Ok(r) + }); - let encoded = block.encode(); - let runtime_block = match RuntimeBlock::decode(&mut &encoded[..]) { - Some(x) => x, - None => return Ok(false), - }; - - let res = with_runtime!(self, at, || ::runtime::Executive::execute_block(runtime_block)); match res { - Ok(()) => Ok(true), + Ok(_) => Ok(true), Err(err) => match err.kind() { &ErrorKind::Executor(ExecErrorKind::Runtime) => Ok(false), _ => Err(err) @@ -148,8 +163,10 @@ impl> PolkadotApi for Client Result> { use codec::{Encode, Decode}; + let runtime_version = self.runtime_version_at(at)?; + with_runtime!(self, at, || { - let extrinsics = ::runtime::inherent_extrinsics(inherent_data); + let extrinsics = ::runtime::inherent_extrinsics(inherent_data, runtime_version); extrinsics.into_iter() .map(|x| x.encode()) // get encoded representation .map(|x| Decode::decode(&mut &x[..])) // get byte-vec equivalent to extrinsic @@ -229,6 +246,7 @@ mod tests { assert_eq!(block.header.number, 1); assert!(block.header.extrinsics_root != Default::default()); + assert!(client.evaluate_block(&id, block).unwrap()); } #[test] @@ -251,6 +269,7 @@ mod tests { assert_eq!(block.header.number, 1); assert!(block.header.extrinsics_root != Default::default()); + assert!(client.evaluate_block(&id, block).unwrap()); } #[test] diff --git a/api/src/lib.rs b/api/src/lib.rs index 8c1e4b1de832..1265faf961fc 100644 --- a/api/src/lib.rs +++ b/api/src/lib.rs @@ -32,6 +32,9 @@ extern crate substrate_state_machine as state_machine; #[macro_use] extern crate error_chain; +#[macro_use] +extern crate log; + #[cfg(test)] extern crate substrate_keyring as keyring; diff --git a/consensus/src/offline_tracker.rs b/consensus/src/offline_tracker.rs index efb317ea5c91..eb6c2480c414 100644 --- a/consensus/src/offline_tracker.rs +++ b/consensus/src/offline_tracker.rs @@ -21,14 +21,18 @@ use polkadot_primitives::AccountId; use std::collections::HashMap; use std::time::{Instant, Duration}; -// time before we report a validator. -const REPORT_TIME: Duration = Duration::from_secs(60 * 5); - struct Observed { last_round_end: Instant, offline_since: Instant, } +#[derive(Eq, PartialEq)] +enum Activity { + Offline, + StillOffline(Duration), + Online, +} + impl Observed { fn new() -> Observed { let now = Instant::now(); @@ -38,31 +42,32 @@ impl Observed { } } - fn note_round_end(&mut self, was_online: bool) { - let now = Instant::now(); - + fn note_round_end(&mut self, now: Instant, was_online: Option) { self.last_round_end = now; - if was_online { + if let Some(false) = was_online { self.offline_since = now; } } - fn is_active(&self) -> bool { + /// Returns what we have observed about the online/offline state of the validator. + fn activity(&self) -> Activity { // can happen if clocks are not monotonic - if self.offline_since > self.last_round_end { return true } - self.last_round_end.duration_since(self.offline_since) < REPORT_TIME + if self.offline_since > self.last_round_end { return Activity::Online } + if self.offline_since == self.last_round_end { return Activity::Offline } + Activity::StillOffline(self.last_round_end.duration_since(self.offline_since)) } } /// Tracks offline validators and can issue a report for those offline. pub struct OfflineTracker { observed: HashMap, + block_instant: Instant, } impl OfflineTracker { /// Create a new tracker. pub fn new() -> Self { - OfflineTracker { observed: HashMap::new() } + OfflineTracker { observed: HashMap::new(), block_instant: Instant::now() } } /// Note new consensus is starting with the given set of validators. @@ -71,23 +76,33 @@ impl OfflineTracker { let set: HashSet<_> = validators.iter().cloned().collect(); self.observed.retain(|k, _| set.contains(k)); + + self.block_instant = Instant::now(); } /// Note that a round has ended. pub fn note_round_end(&mut self, validator: AccountId, was_online: bool) { - self.observed.entry(validator) - .or_insert_with(Observed::new) - .note_round_end(was_online); + self.observed.entry(validator).or_insert_with(Observed::new); + for (val, obs) in self.observed.iter_mut() { + obs.note_round_end( + self.block_instant, + if val == &validator { + Some(was_online) + } else { + None + } + ) + } } /// Generate a vector of indices for offline account IDs. pub fn reports(&self, validators: &[AccountId]) -> Vec { validators.iter() .enumerate() - .filter_map(|(i, v)| if self.is_online(v) { - None - } else { + .filter_map(|(i, v)| if self.is_known_offline_now(v) { Some(i as u32) + } else { + None }) .collect() } @@ -101,13 +116,15 @@ impl OfflineTracker { }; // we must think all validators reported externally are offline. - let thinks_online = self.is_online(v); - !thinks_online + self.is_known_offline_now(v) }) } - fn is_online(&self, v: &AccountId) -> bool { - self.observed.get(v).map(Observed::is_active).unwrap_or(true) + /// Rwturns true only if we have seen the validator miss the last round. For further + /// rounds where we can't say for sure that they're still offline, we give them the + /// benefit of the doubt. + fn is_known_offline_now(&self, v: &AccountId) -> bool { + self.observed.get(v).map(|o| o.activity() == Activity::Offline).unwrap_or(false) } } @@ -121,17 +138,30 @@ mod tests { let v = [0; 32].into(); let v2 = [1; 32].into(); let v3 = [2; 32].into(); + tracker.note_new_block(&[v, v2, v3]); tracker.note_round_end(v, true); tracker.note_round_end(v2, true); tracker.note_round_end(v3, true); + assert_eq!(tracker.reports(&[v, v2, v3]), vec![0u32; 0]); + + tracker.note_new_block(&[v, v2, v3]); + tracker.note_round_end(v, true); + tracker.note_round_end(v2, false); + tracker.note_round_end(v3, true); + assert_eq!(tracker.reports(&[v, v2, v3]), vec![1]); - let slash_time = REPORT_TIME + Duration::from_secs(5); - tracker.observed.get_mut(&v).unwrap().offline_since -= slash_time; - tracker.observed.get_mut(&v2).unwrap().offline_since -= slash_time; + tracker.note_new_block(&[v, v2, v3]); + tracker.note_round_end(v, false); + assert_eq!(tracker.reports(&[v, v2, v3]), vec![0]); - assert_eq!(tracker.reports(&[v, v2, v3]), vec![0, 1]); + tracker.note_new_block(&[v, v2, v3]); + tracker.note_round_end(v, false); + tracker.note_round_end(v2, true); + tracker.note_round_end(v3, false); + assert_eq!(tracker.reports(&[v, v2, v3]), vec![0, 2]); - tracker.note_new_block(&[v, v3]); + tracker.note_new_block(&[v, v2]); + tracker.note_round_end(v, false); assert_eq!(tracker.reports(&[v, v2, v3]), vec![0]); } } diff --git a/consensus/src/service.rs b/consensus/src/service.rs index b2880a575226..2db0e8ed707b 100644 --- a/consensus/src/service.rs +++ b/consensus/src/service.rs @@ -62,32 +62,26 @@ fn start_bft( const DELAY_UNTIL: Duration = Duration::from_millis(5000); let mut handle = LocalThreadHandle::current(); - let work = Delay::new(Instant::now() + DELAY_UNTIL) - .then(move |res| { - if let Err(e) = res { - warn!(target: "bft", "Failed to force delay of consensus: {:?}", e); - } + match bft_service.build_upon(&header) { + Ok(Some(bft_work)) => { + // do not poll work for some amount of time. + let work = Delay::new(Instant::now() + DELAY_UNTIL).then(move |res| { + if let Err(e) = res { + warn!(target: "bft", "Failed to force delay of consensus: {:?}", e); + } - match bft_service.build_upon(&header) { - Ok(maybe_bft_work) => { - if maybe_bft_work.is_some() { - debug!(target: "bft", "Starting agreement. After forced delay for {:?}", - DELAY_UNTIL); - } + debug!(target: "bft", "Starting agreement. After forced delay for {:?}", + DELAY_UNTIL); - maybe_bft_work - } - Err(e) => { - warn!(target: "bft", "BFT agreement error: {}", e); - None - } + bft_work + }); + if let Err(e) = handle.spawn_local(Box::new(work)) { + warn!(target: "bft", "Couldn't initialize BFT agreement: {:?}", e); } - }) - .map(|_| ()); - - if let Err(e) = handle.spawn_local(Box::new(work)) { - debug!(target: "bft", "Couldn't initialize BFT agreement: {:?}", e); - } + } + Ok(None) => trace!(target: "bft", "Could not start agreement on top of {}", header.hash()), + Err(e) => warn!(target: "bft", "BFT agreement error: {}", e), + } } // creates a task to prune redundant entries in availability store upon block finalization @@ -198,6 +192,7 @@ impl Service { client.import_notification_stream().for_each(move |notification| { if notification.is_new_best { + trace!(target: "bft", "Attempting to start new consensus round after import notification of {:?}", notification.hash); start_bft(notification.header, bft_service.clone()); } Ok(()) @@ -221,14 +216,12 @@ impl Service { let c = client.clone(); let s = bft_service.clone(); - interval.map_err(|e| debug!("Timer error: {:?}", e)).for_each(move |_| { + interval.map_err(|e| debug!(target: "bft", "Timer error: {:?}", e)).for_each(move |_| { if let Ok(best_block) = c.best_block_header() { let hash = best_block.hash(); - let last_agreement = s.last_agreement(); - let can_build_upon = last_agreement - .map_or(true, |x| !x.live || x.parent_hash != hash); - if hash == prev_best && can_build_upon { - debug!("Starting consensus round after a timeout"); + + if hash == prev_best { + debug!(target: "bft", "Starting consensus round after a timeout"); start_bft(best_block, s.clone()); } prev_best = hash; diff --git a/primitives/src/lib.rs b/primitives/src/lib.rs index bf3e2fd56536..ecff56529b8f 100644 --- a/primitives/src/lib.rs +++ b/primitives/src/lib.rs @@ -120,4 +120,4 @@ pub struct InherentData { pub parachain_heads: Vec<::parachain::CandidateReceipt>, /// Indices of offline validators. pub offline_indices: Vec, -} +} \ No newline at end of file diff --git a/runtime/src/lib.rs b/runtime/src/lib.rs index 203ac58c6b65..02590b2e0fda 100644 --- a/runtime/src/lib.rs +++ b/runtime/src/lib.rs @@ -250,7 +250,7 @@ pub mod api { apply_extrinsic => |extrinsic| super::Executive::apply_extrinsic(extrinsic), execute_block => |block| super::Executive::execute_block(block), finalise_block => |()| super::Executive::finalise_block(), - inherent_extrinsics => |inherent| super::inherent_extrinsics(inherent), + inherent_extrinsics => |(inherent, version)| super::inherent_extrinsics(inherent, version), validator_count => |()| super::Session::validator_count(), validators => |()| super::Session::validators() ); diff --git a/runtime/src/utils.rs b/runtime/src/utils.rs index acef06092539..c016d3690ddd 100644 --- a/runtime/src/utils.rs +++ b/runtime/src/utils.rs @@ -22,9 +22,10 @@ use runtime_primitives::traits::{Checkable, AuxLookup}; use timestamp::Call as TimestampCall; use parachains::Call as ParachainsCall; use session::Call as SessionCall; +use version::RuntimeVersion; /// Produces the list of inherent extrinsics. -pub fn inherent_extrinsics(data: ::primitives::InherentData) -> Vec { +pub fn inherent_extrinsics(data: ::primitives::InherentData, runtime_version: RuntimeVersion) -> Vec { let make_inherent = |function| UncheckedExtrinsic::new( Extrinsic { signed: Default::default(), @@ -39,7 +40,7 @@ pub fn inherent_extrinsics(data: ::primitives::InherentData) -> Vec