Log block ID prefix in more contexts; remove dup logging (closes #314)

Cargo.toml

@@ -17,6 +17,7 @@ members = [".", "tendermint-rs"]
 circle-ci = { repository = "tendermint/kms" }
 
 [dependencies]
+abscissa_core = "0.2"
 atomicwrites = "0.2"
 byteorder = "1.2"
 bytes = "0.4"
@@ -47,17 +48,14 @@ wait-timeout = "0.2"
 yubihsm = { version = "0.26", features = ["setup", "usb"], optional = true }
 zeroize = "0.9"
 
-[dependencies.abscissa_core]
-version = "0.2"
-
 [dependencies.tendermint]
 version = "0.10.0-rc0"
 path = "tendermint-rs"
 features = ["amino-types", "config", "secret-connection"]
 
 [dev-dependencies]
 tempfile = "3"
-rand = "0.6"
+rand = "0.7"
 
 [dev-dependencies.abscissa_core]
 version = "0.2"

src/chain/state.rs

@@ -60,6 +60,11 @@ impl State {
         }
     }
 
+    /// Borrow the current consensus state
+    pub fn consensus_state(&self) -> &consensus::State {
+        &self.consensus_state
+    }
+
     /// Check and update the chain's height, round, and step
     pub fn update_consensus_state(
         &mut self,
@@ -165,15 +170,6 @@ impl State {
 
         Ok(())
     }
-
-    /// Determine if a requested signing operation duplicates a previous one,
-    /// i.e. if the height/round/step and block ID are identical.
-    ///
-    /// This is used to signal to the user that a duplicate signing event
-    /// has occurred.
-    pub fn is_dup(&self, consensus_state: &consensus::State) -> bool {
-        &self.consensus_state == consensus_state
-    }
 }
 
 #[cfg(test)]

src/session.rs

@@ -176,33 +176,21 @@ where
         let registry = chain::REGISTRY.get();
         let chain = registry.get_chain(&self.chain_id).unwrap();
 
-        // The current double-signing logic allows for resigning the exact
-        // same block as the one it signed immediately prior, i.e. if the
-        // requested block ID is identical, and the height/round/step are
-        // identical, (re)computing the signature is allowed.
-        //
-        // Since Ed25519 is a deterministic signature algorithm, this has no
-        // deleterious effects, and provides fault tolerance in the event
-        // the KMS hands a signed block off to a validator that drops it
-        // on the floor (e.g. hardware failure)
-        //
-        // When this happens, this flag is set to notify the user that it
-        // signed a duplicate block.
-        let mut is_dup = false;
-
         if let Some(request_state) = &request.consensus_state() {
-            // TODO(tarcieri): better handle `PoisonError`?
             let mut chain_state = chain.state.lock().unwrap();
-            is_dup = chain_state.is_dup(request_state);
 
             if let Err(e) = chain_state.update_consensus_state(request_state.clone()) {
                 // Report double signing error back to the validator
                 if e.kind() == StateErrorKind::DoubleSign {
                     let height = request.height().unwrap();
 
                     warn!(
-                        "[{}:{}] attempt to double sign at height/round/step: {}",
-                        &self.chain_id, &self.peer_addr, request_state
+                        "[{}:{}] attempt to double sign at h/r/s: {} ({} != {})",
+                        &self.chain_id,
+                        &self.peer_addr,
+                        request_state,
+                        chain_state.consensus_state().block_id_prefix(),
+                        request_state.block_id_prefix()
                     );
 
                     let remote_err = RemoteError::double_sign(height);
@@ -233,7 +221,7 @@ where
         let started_at = Instant::now();
         let signature = chain.keyring.sign_ed25519(None, &to_sign)?;
 
-        self.log_signing_request(&request, started_at, is_dup);
+        self.log_signing_request(&request, started_at);
         request.set_signature(&signature);
 
         Ok(request.build_response(None))
@@ -256,44 +244,25 @@ where
     }
 
     /// Write an INFO logline about a signing request
-    fn log_signing_request<T: TendermintRequest + Debug>(
-        &self,
-        request: &T,
-        started_at: Instant,
-        is_dup: bool,
-    ) {
-        let (consensus_state, block_id) = match &request.consensus_state() {
-            Some(state) => {
-                let block_id_string = match &state.block_id {
-                    Some(id) => {
-                        let mut res = id.to_string();
-                        res.truncate(8);
-                        res
-                    }
-                    None => "none".to_owned(),
-                };
-
-                (state.to_string(), block_id_string)
-            }
-            None => ("none".to_owned(), "none".to_owned()),
-        };
+    fn log_signing_request<T: TendermintRequest + Debug>(&self, request: &T, started_at: Instant) {
+        let (consensus_state, block_id) = request
+            .consensus_state()
+            .map(|state| (state.to_string(), state.block_id_prefix()))
+            .unwrap_or_else(|| ("(none)".to_owned(), "(none)".to_owned()));
 
         let msg_type = request
             .msg_type()
             .map(|t| format!("{:?}", t))
             .unwrap_or_else(|| "Unknown".to_owned());
 
-        let dup_msg = if is_dup { " [dup]" } else { "" };
-
         info!(
-            "[{}@{}] signed {}:{} h/r/s:{} ({} ms){}",
+            "[{}@{}] signed {}:{} at h/r/s {} ({} ms)",
             &self.chain_id,
             &self.peer_addr,
             msg_type,
             block_id,
             consensus_state,
             started_at.elapsed().as_millis(),
-            dup_msg
         );
     }
 }

tendermint-rs/src/block/id.rs

@@ -10,6 +10,9 @@ use std::{
     str::{self, FromStr},
 };
 
+/// Length of a block ID prefix displayed for debugging purposes
+pub const PREFIX_LENGTH: usize = 10;
+
 /// Block identifiers which contain two distinct Merkle roots of the block,
 /// as well as the number of parts in the block.
 ///
@@ -41,6 +44,13 @@ impl Id {
     pub fn new(hash: Hash, parts: Option<parts::Header>) -> Self {
         Self { hash, parts }
     }
+
+    /// Get a shortened 12-character prefix of a block ID (ala git)
+    pub fn prefix(&self) -> String {
+        let mut result = self.to_string();
+        result.truncate(PREFIX_LENGTH);
+        result
+    }
 }
 
 // TODO: match gaia serialization? e.g `D2F5991B98D708FD2C25AA2BEBED9358F24177DE:1:C37A55FB95E9`

tendermint-rs/src/consensus/state.rs

@@ -32,6 +32,16 @@ pub struct State {
     pub block_id: Option<block::Id>,
 }
 
+impl State {
+    /// Get short prefix of the block ID for debugging purposes (ala git)
+    pub fn block_id_prefix(&self) -> String {
+        self.block_id
+            .as_ref()
+            .map(block::Id::prefix)
+            .unwrap_or_else(|| "(none)".to_owned())
+    }
+}
+
 impl fmt::Display for State {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
         write!(f, "{}/{}/{}", self.height, self.round, self.step)