grassrootseconomics/openethereum
5
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Fix lock and rename tracing (#4403)

Browse Source 
* tracing, timeouts

* remove env_logger
This commit is contained in:
keorn 2017-02-02 19:11:43 +01:00 committed by Gav Wood
parent 015425d447
commit 76c39e3e66
5 changed files with 46 additions and 45 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
ethcore/res/tendermint.json
View File

@ -9,7 +9,11 @@
"0x82a978b3f5962a5b0957d9ee9eef472ee55b42f1", "0x82a978b3f5962a5b0957d9ee9eef472ee55b42f1",
"0x7d577a597b2742b498cb5cf0c26cdcd726d39e6e" "0x7d577a597b2742b498cb5cf0c26cdcd726d39e6e"
] ]
} },
"timeoutPropose": 10000,
"timeoutPrevote": 10000,
"timeoutPrecommit": 10000,
"timeoutCommit": 10000
} }
} }
}, },

18
ethcore/src/engines/authority_round.rs
View File

@ -159,7 +159,7 @@ impl IoHandler<()> for TransitionHandler {
fn initialize(&self, io: &IoContext<()>) { fn initialize(&self, io: &IoContext<()>) {
if let Some(engine) = self.engine.upgrade() { if let Some(engine) = self.engine.upgrade() {
io.register_timer_once(ENGINE_TIMEOUT_TOKEN, engine.remaining_step_duration().as_millis()) io.register_timer_once(ENGINE_TIMEOUT_TOKEN, engine.remaining_step_duration().as_millis())
.unwrap_or_else(|e| warn!(target: "poa", "Failed to start consensus step timer: {}.", e)) .unwrap_or_else(|e| warn!(target: "engine", "Failed to start consensus step timer: {}.", e))
} }
} }
@ -168,7 +168,7 @@ impl IoHandler<()> for TransitionHandler {
if let Some(engine) = self.engine.upgrade() { if let Some(engine) = self.engine.upgrade() {
engine.step(); engine.step();
io.register_timer_once(ENGINE_TIMEOUT_TOKEN, engine.remaining_step_duration().as_millis()) io.register_timer_once(ENGINE_TIMEOUT_TOKEN, engine.remaining_step_duration().as_millis())
.unwrap_or_else(|e| warn!(target: "poa", "Failed to restart consensus step timer: {}.", e)) .unwrap_or_else(|e| warn!(target: "engine", "Failed to restart consensus step timer: {}.", e))
} }
} }
} }
@ -234,14 +234,14 @@ impl Engine for AuthorityRound {
let step = self.step.load(AtomicOrdering::SeqCst); let step = self.step.load(AtomicOrdering::SeqCst);
if self.is_step_proposer(step, header.author()) { if self.is_step_proposer(step, header.author()) {
if let Ok(signature) = self.signer.sign(header.bare_hash()) { if let Ok(signature) = self.signer.sign(header.bare_hash()) {
trace!(target: "poa", "generate_seal: Issuing a block for step {}.", step); trace!(target: "engine", "generate_seal: Issuing a block for step {}.", step);
self.proposed.store(true, AtomicOrdering::SeqCst); self.proposed.store(true, AtomicOrdering::SeqCst);
return Seal::Regular(vec![encode(&step).to_vec(), encode(&(&H520::from(signature) as &[u8])).to_vec()]); return Seal::Regular(vec![encode(&step).to_vec(), encode(&(&H520::from(signature) as &[u8])).to_vec()]);
} else { } else {
warn!(target: "poa", "generate_seal: FAIL: Accounts secret key unavailable."); warn!(target: "engine", "generate_seal: FAIL: Accounts secret key unavailable.");
} }
} else { } else {
trace!(target: "poa", "generate_seal: Not a proposer for step {}.", step); trace!(target: "engine", "generate_seal: Not a proposer for step {}.", step);
} }
Seal::None Seal::None
} }
@ -260,7 +260,7 @@ impl Engine for AuthorityRound {
/// Check the number of seal fields. /// Check the number of seal fields.
fn verify_block_basic(&self, header: &Header, _block: Option<&[u8]>) -> Result<(), Error> { fn verify_block_basic(&self, header: &Header, _block: Option<&[u8]>) -> Result<(), Error> {
if header.seal().len() != self.seal_fields() { if header.seal().len() != self.seal_fields() {
trace!(target: "poa", "verify_block_basic: wrong number of seal fields"); trace!(target: "engine", "verify_block_basic: wrong number of seal fields");
Err(From::from(BlockError::InvalidSealArity( Err(From::from(BlockError::InvalidSealArity(
Mismatch { expected: self.seal_fields(), found: header.seal().len() } Mismatch { expected: self.seal_fields(), found: header.seal().len() }
))) )))
@ -279,11 +279,11 @@ impl Engine for AuthorityRound {
if verify_address(&correct_proposer, &proposer_signature, &header.bare_hash())? { if verify_address(&correct_proposer, &proposer_signature, &header.bare_hash())? {
Ok(()) Ok(())
} else { } else {
trace!(target: "poa", "verify_block_unordered: bad proposer for step: {}", header_step); trace!(target: "engine", "verify_block_unordered: bad proposer for step: {}", header_step);
Err(EngineError::NotProposer(Mismatch { expected: correct_proposer, found: header.author().clone() }))? Err(EngineError::NotProposer(Mismatch { expected: correct_proposer, found: header.author().clone() }))?
} }
} else { } else {
trace!(target: "poa", "verify_block_unordered: block from the future"); trace!(target: "engine", "verify_block_unordered: block from the future");
self.validators.report_benign(header.author()); self.validators.report_benign(header.author());
Err(BlockError::InvalidSeal)? Err(BlockError::InvalidSeal)?
} }
@ -297,7 +297,7 @@ impl Engine for AuthorityRound {
let step = header_step(header)?; let step = header_step(header)?;
// Check if parent is from a previous step. // Check if parent is from a previous step.
if step == header_step(parent)? { if step == header_step(parent)? {
trace!(target: "poa", "Multiple blocks proposed for step {}.", step); trace!(target: "engine", "Multiple blocks proposed for step {}.", step);
self.validators.report_malicious(header.author()); self.validators.report_malicious(header.author());
Err(EngineError::DoubleVote(header.author().clone()))?; Err(EngineError::DoubleVote(header.author().clone()))?;
} }

59
ethcore/src/engines/tendermint/mod.rs
View File

@ -159,13 +159,13 @@ impl Tendermint {
let message = ConsensusMessage::new(signature, h, r, *s, block_hash); let message = ConsensusMessage::new(signature, h, r, *s, block_hash);
let validator = self.signer.address(); let validator = self.signer.address();
self.votes.vote(message.clone(), &validator); self.votes.vote(message.clone(), &validator);
debug!(target: "poa", "Generated {:?} as {}.", message, validator); debug!(target: "engine", "Generated {:?} as {}.", message, validator);
self.handle_valid_message(&message); self.handle_valid_message(&message);
Some(message_rlp) Some(message_rlp)
}, },
Err(e) => { Err(e) => {
trace!(target: "poa", "Could not sign the message {}", e); trace!(target: "engine", "Could not sign the message {}", e);
None None
}, },
} }
@ -186,7 +186,7 @@ impl Tendermint {
fn to_next_height(&self, height: Height) { fn to_next_height(&self, height: Height) {
let new_height = height + 1; let new_height = height + 1;
debug!(target: "poa", "Received a Commit, transitioning to height {}.", new_height); debug!(target: "engine", "Received a Commit, transitioning to height {}.", new_height);
self.last_lock.store(0, AtomicOrdering::SeqCst); self.last_lock.store(0, AtomicOrdering::SeqCst);
self.height.store(new_height, AtomicOrdering::SeqCst); self.height.store(new_height, AtomicOrdering::SeqCst);
self.view.store(0, AtomicOrdering::SeqCst); self.view.store(0, AtomicOrdering::SeqCst);
@ -196,7 +196,7 @@ impl Tendermint {
/// Use via step_service to transition steps. /// Use via step_service to transition steps.
fn to_step(&self, step: Step) { fn to_step(&self, step: Step) {
if let Err(io_err) = self.step_service.send_message(step) { if let Err(io_err) = self.step_service.send_message(step) {
warn!(target: "poa", "Could not proceed to step {}.", io_err) warn!(target: "engine", "Could not proceed to step {}.", io_err)
} }
*self.step.write() = step; *self.step.write() = step;
match step { match step {
@ -212,10 +212,10 @@ impl Tendermint {
self.generate_and_broadcast_message(block_hash); self.generate_and_broadcast_message(block_hash);
}, },
Step::Precommit => { Step::Precommit => {
trace!(target: "poa", "to_step: Precommit."); trace!(target: "engine", "to_step: Precommit.");
let block_hash = match *self.lock_change.read() { let block_hash = match *self.lock_change.read() {
Some(ref m) if self.is_view(m) && m.block_hash.is_some() => { Some(ref m) if self.is_view(m) && m.block_hash.is_some() => {
trace!(target: "poa", "Setting last lock: {}", m.vote_step.view); trace!(target: "engine", "Setting last lock: {}", m.vote_step.view);
self.last_lock.store(m.vote_step.view, AtomicOrdering::SeqCst); self.last_lock.store(m.vote_step.view, AtomicOrdering::SeqCst);
m.block_hash m.block_hash
}, },
@ -224,7 +224,7 @@ impl Tendermint {
self.generate_and_broadcast_message(block_hash); self.generate_and_broadcast_message(block_hash);
}, },
Step::Commit => { Step::Commit => {
trace!(target: "poa", "to_step: Commit."); trace!(target: "engine", "to_step: Commit.");
// Commit the block using a complete signature set. // Commit the block using a complete signature set.
let view = self.view.load(AtomicOrdering::SeqCst); let view = self.view.load(AtomicOrdering::SeqCst);
let height = self.height.load(AtomicOrdering::SeqCst); let height = self.height.load(AtomicOrdering::SeqCst);
@ -234,7 +234,7 @@ impl Tendermint {
let proposal_step = VoteStep::new(height, view, Step::Propose); let proposal_step = VoteStep::new(height, view, Step::Propose);
let precommit_step = VoteStep::new(proposal_step.height, proposal_step.view, Step::Precommit); let precommit_step = VoteStep::new(proposal_step.height, proposal_step.view, Step::Precommit);
if let Some(seal) = self.votes.seal_signatures(proposal_step, precommit_step, &block_hash) { if let Some(seal) = self.votes.seal_signatures(proposal_step, precommit_step, &block_hash) {
trace!(target: "poa", "Collected seal: {:?}", seal); trace!(target: "engine", "Collected seal: {:?}", seal);
let seal = vec![ let seal = vec![
::rlp::encode(&view).to_vec(), ::rlp::encode(&view).to_vec(),
::rlp::encode(&seal.proposal).to_vec(), ::rlp::encode(&seal.proposal).to_vec(),
@ -243,7 +243,7 @@ impl Tendermint {
self.submit_seal(block_hash, seal); self.submit_seal(block_hash, seal);
self.to_next_height(height); self.to_next_height(height);
} else { } else {
warn!(target: "poa", "Not enough votes found!"); warn!(target: "engine", "Not enough votes found!");
} }
} }
} }
@ -262,7 +262,7 @@ impl Tendermint {
/// Find the designated for the given view. /// Find the designated for the given view.
fn view_proposer(&self, height: Height, view: View) -> Address { fn view_proposer(&self, height: Height, view: View) -> Address {
let proposer_nonce = height + view; let proposer_nonce = height + view;
trace!(target: "poa", "Proposer nonce: {}", proposer_nonce); trace!(target: "engine", "Proposer nonce: {}", proposer_nonce);
self.validators.get(proposer_nonce) self.validators.get(proposer_nonce)
} }
@ -291,7 +291,7 @@ impl Tendermint {
} }
fn increment_view(&self, n: View) { fn increment_view(&self, n: View) {
trace!(target: "poa", "increment_view: New view."); trace!(target: "engine", "increment_view: New view.");
self.view.fetch_add(n, AtomicOrdering::SeqCst); self.view.fetch_add(n, AtomicOrdering::SeqCst);
} }
@ -331,7 +331,7 @@ impl Tendermint {
&& message.block_hash.is_some() && message.block_hash.is_some()
&& self.has_enough_aligned_votes(message); && self.has_enough_aligned_votes(message);
if lock_change { if lock_change {
trace!(target: "poa", "handle_valid_message: Lock change."); trace!(target: "engine", "handle_valid_message: Lock change.");
*self.lock_change.write() = Some(message.clone()); *self.lock_change.write() = Some(message.clone());
} }
// Check if it can affect the step transition. // Check if it can affect the step transition.
@ -349,7 +349,7 @@ impl Tendermint {
self.increment_view(vote_step.view - self.view.load(AtomicOrdering::SeqCst)); self.increment_view(vote_step.view - self.view.load(AtomicOrdering::SeqCst));
Some(Step::Precommit) Some(Step::Precommit)
}, },
// Avoid counting twice. // Avoid counting votes twice.
Step::Prevote if lock_change => Some(Step::Precommit), Step::Prevote if lock_change => Some(Step::Precommit),
Step::Prevote if self.has_enough_aligned_votes(message) => Some(Step::Precommit), Step::Prevote if self.has_enough_aligned_votes(message) => Some(Step::Precommit),
Step::Prevote if self.has_enough_future_step_votes(&vote_step) => { Step::Prevote if self.has_enough_future_step_votes(&vote_step) => {
@ -360,7 +360,7 @@ impl Tendermint {
}; };
if let Some(step) = next_step { if let Some(step) = next_step {
trace!(target: "poa", "Transition to {:?} triggered.", step); trace!(target: "engine", "Transition to {:?} triggered.", step);
self.to_step(step); self.to_step(step);
} }
} }
@ -429,7 +429,7 @@ impl Engine for Tendermint {
let vote_info = message_info_rlp(&VoteStep::new(height, view, Step::Propose), bh.clone()); let vote_info = message_info_rlp(&VoteStep::new(height, view, Step::Propose), bh.clone());
if let Ok(signature) = self.signer.sign(vote_info.sha3()).map(Into::into) { if let Ok(signature) = self.signer.sign(vote_info.sha3()).map(Into::into) {
// Insert Propose vote. // Insert Propose vote.
debug!(target: "poa", "Submitting proposal {} at height {} view {}.", header.bare_hash(), height, view); debug!(target: "engine", "Submitting proposal {} at height {} view {}.", header.bare_hash(), height, view);
self.votes.vote(ConsensusMessage::new(signature, height, view, Step::Propose, bh), author); self.votes.vote(ConsensusMessage::new(signature, height, view, Step::Propose, bh), author);
// Remember proposal for later seal submission. // Remember proposal for later seal submission.
*self.proposal.write() = bh; *self.proposal.write() = bh;
@ -439,7 +439,7 @@ impl Engine for Tendermint {
::rlp::EMPTY_LIST_RLP.to_vec() ::rlp::EMPTY_LIST_RLP.to_vec()
]) ])
} else { } else {
warn!(target: "poa", "generate_seal: FAIL: accounts secret key unavailable"); warn!(target: "engine", "generate_seal: FAIL: accounts secret key unavailable");
Seal::None Seal::None
} }
} }
@ -457,7 +457,7 @@ impl Engine for Tendermint {
self.validators.report_malicious(&sender); self.validators.report_malicious(&sender);
Err(EngineError::DoubleVote(sender))? Err(EngineError::DoubleVote(sender))?
} }
trace!(target: "poa", "Handling a valid {:?} from {}.", message, sender); trace!(target: "engine", "Handling a valid {:?} from {}.", message, sender);
self.handle_valid_message(&message); self.handle_valid_message(&message);
} }
Ok(()) Ok(())
@ -519,7 +519,7 @@ impl Engine for Tendermint {
if origins.insert(address) { if origins.insert(address) {
signature_count += 1; signature_count += 1;
} else { } else {
warn!(target: "poa", "verify_block_unordered: Duplicate signature from {} on the seal.", address); warn!(target: "engine", "verify_block_unordered: Duplicate signature from {} on the seal.", address);
Err(BlockError::InvalidSeal)?; Err(BlockError::InvalidSeal)?;
} }
} }
@ -577,12 +577,12 @@ impl Engine for Tendermint {
let proposal = ConsensusMessage::new_proposal(header).expect("block went through full verification; this Engine verifies new_proposal creation; qed"); let proposal = ConsensusMessage::new_proposal(header).expect("block went through full verification; this Engine verifies new_proposal creation; qed");
if signatures_len != 1 { if signatures_len != 1 {
// New Commit received, skip to next height. // New Commit received, skip to next height.
trace!(target: "poa", "Received a commit: {:?}.", proposal.vote_step); trace!(target: "engine", "Received a commit: {:?}.", proposal.vote_step);
self.to_next_height(proposal.vote_step.height); self.to_next_height(proposal.vote_step.height);
return false; return false;
} }
let proposer = proposal.verify().expect("block went through full verification; this Engine tries verify; qed"); let proposer = proposal.verify().expect("block went through full verification; this Engine tries verify; qed");
debug!(target: "poa", "Received a new proposal {:?} from {}.", proposal.vote_step, proposer); debug!(target: "engine", "Received a new proposal {:?} from {}.", proposal.vote_step, proposer);
if self.is_view(&proposal) { if self.is_view(&proposal) {
*self.proposal.write() = proposal.block_hash.clone(); *self.proposal.write() = proposal.block_hash.clone();
} }
@ -594,7 +594,7 @@ impl Engine for Tendermint {
fn step(&self) { fn step(&self) {
let next_step = match *self.step.read() { let next_step = match *self.step.read() {
Step::Propose => { Step::Propose => {
trace!(target: "poa", "Propose timeout."); trace!(target: "engine", "Propose timeout.");
if self.proposal.read().is_none() { if self.proposal.read().is_none() {
// Report the proposer if no proposal was received. // Report the proposer if no proposal was received.
let current_proposer = self.view_proposer(self.height.load(AtomicOrdering::SeqCst), self.view.load(AtomicOrdering::SeqCst)); let current_proposer = self.view_proposer(self.height.load(AtomicOrdering::SeqCst), self.view.load(AtomicOrdering::SeqCst));
@ -603,26 +603,26 @@ impl Engine for Tendermint {
Step::Prevote Step::Prevote
}, },
Step::Prevote if self.has_enough_any_votes() => { Step::Prevote if self.has_enough_any_votes() => {
trace!(target: "poa", "Prevote timeout."); trace!(target: "engine", "Prevote timeout.");
Step::Precommit Step::Precommit
}, },
Step::Prevote => { Step::Prevote => {
trace!(target: "poa", "Prevote timeout without enough votes."); trace!(target: "engine", "Prevote timeout without enough votes.");
self.broadcast_old_messages(); self.broadcast_old_messages();
Step::Prevote Step::Prevote
}, },
Step::Precommit if self.has_enough_any_votes() => { Step::Precommit if self.has_enough_any_votes() => {
trace!(target: "poa", "Precommit timeout."); trace!(target: "engine", "Precommit timeout.");
self.increment_view(1); self.increment_view(1);
Step::Propose Step::Propose
}, },
Step::Precommit => { Step::Precommit => {
trace!(target: "poa", "Precommit timeout without enough votes."); trace!(target: "engine", "Precommit timeout without enough votes.");
self.broadcast_old_messages(); self.broadcast_old_messages();
Step::Precommit Step::Precommit
}, },
Step::Commit => { Step::Commit => {
trace!(target: "poa", "Commit timeout."); trace!(target: "engine", "Commit timeout.");
Step::Propose Step::Propose
}, },
}; };
@ -838,7 +838,6 @@ mod tests {
let (b, seal) = propose_default(&spec, proposer); let (b, seal) = propose_default(&spec, proposer);
assert!(b.lock().try_seal(spec.engine.as_ref(), seal).is_ok()); assert!(b.lock().try_seal(spec.engine.as_ref(), seal).is_ok());
spec.engine.stop();
} }
#[test] #[test]
@ -850,7 +849,6 @@ mod tests {
let (b, seal) = propose_default(&spec, proposer); let (b, seal) = propose_default(&spec, proposer);
let sealed = b.lock().seal(spec.engine.as_ref(), seal).unwrap(); let sealed = b.lock().seal(spec.engine.as_ref(), seal).unwrap();
assert!(spec.engine.is_proposal(sealed.header())); assert!(spec.engine.is_proposal(sealed.header()));
spec.engine.stop();
} }
#[test] #[test]
@ -858,7 +856,7 @@ mod tests {
let (spec, tap) = setup(); let (spec, tap) = setup();
let engine = spec.engine.clone(); let engine = spec.engine.clone();
let v0 = insert_and_register(&tap, engine.as_ref(), "0"); let v0 = insert_and_unlock(&tap, "0");
let v1 = insert_and_register(&tap, engine.as_ref(), "1"); let v1 = insert_and_register(&tap, engine.as_ref(), "1");
let h = 1; let h = 1;
@ -883,7 +881,6 @@ mod tests {
assert!(notify.messages.read().contains(&prevote_current)); assert!(notify.messages.read().contains(&prevote_current));
assert!(notify.messages.read().contains(&precommit_current)); assert!(notify.messages.read().contains(&precommit_current));
assert!(notify.messages.read().contains(&prevote_future)); assert!(notify.messages.read().contains(&prevote_future));
engine.stop();
} }
#[test] #[test]
@ -933,7 +930,5 @@ mod tests {
// Last precommit. // Last precommit.
vote(engine, |mh| tap.sign(v0, None, mh).map(H520::from), h, r, Step::Precommit, proposal); vote(engine, |mh| tap.sign(v0, None, mh).map(H520::from), h, r, Step::Precommit, proposal);
assert_eq!(client.chain_info().best_block_number, 1); assert_eq!(client.chain_info().best_block_number, 1);
engine.stop();
} }
} }

4
ethcore/src/engines/transition.rs
View File

@ -56,7 +56,9 @@ fn set_timeout<S: Sync + Send + Clone>(io: &IoContext<S>, timeout: Duration) {
impl <S> IoHandler<S> for TransitionHandler<S> where S: Sync + Send + Clone + 'static { impl <S> IoHandler<S> for TransitionHandler<S> where S: Sync + Send + Clone + 'static {
fn initialize(&self, io: &IoContext<S>) { fn initialize(&self, io: &IoContext<S>) {
set_timeout(io, self.timeouts.initial()); let initial = self.timeouts.initial();
trace!(target: "engine", "Setting the initial timeout to {}.", initial);
set_timeout(io, initial);
} }
/// Call step after timeout. /// Call step after timeout.

4
ethcore/src/engines/vote_collector.rs
View File

@ -118,13 +118,13 @@ impl <M: Message + Default + Encodable + Debug> VoteCollector<M> {
.get(&message.round()) .get(&message.round())
.map_or(false, |c| { .map_or(false, |c| {
let is_known = c.messages.contains(message); let is_known = c.messages.contains(message);
if is_known { trace!(target: "poa", "Known message: {:?}.", message); } if is_known { trace!(target: "engine", "Known message: {:?}.", message); }
is_known is_known
}) })
|| { || {
let guard = self.votes.read(); let guard = self.votes.read();
let is_old = guard.keys().next().map_or(true, |oldest| message.round() <= oldest); let is_old = guard.keys().next().map_or(true, |oldest| message.round() <= oldest);
if is_old { trace!(target: "poa", "Old message {:?}.", message); } if is_old { trace!(target: "engine", "Old message {:?}.", message); }
is_old is_old
} }
} }