Log all signature events at INFO level

...and improve logging at the debug level in general.

Previously the KMS logged no information about what it signed at the
default loglevel (INFO). To get that information, you had to log at the
DEBUG level.

This adds short loglines at the INFO level. They contain the chain ID,
signed message type (proposal, prevote, precommit), and block height.

Additionally, at the debug level it now prints debug messages containing
the complete incoming request and response.

src/rpc.rs

@@ -20,6 +20,7 @@ use tendermint::amino_types::*;
 pub const MAX_MSG_LEN: usize = 1024;
 
 /// Requests to the KMS
+#[derive(Debug)]
 pub enum Request {
     /// Sign the given message
     SignProposal(SignProposalRequest),
@@ -31,6 +32,7 @@ pub enum Request {
 }
 
 /// Responses from the KMS
+#[derive(Debug)]
 pub enum Response {
     /// Signature response
     SignedVote(SignedVoteResponse),

src/session.rs

@@ -33,7 +33,7 @@ pub struct Session<Connection> {
     /// Chain ID for this session
     chain_id: chain::Id,
 
-    // Do not sign blocks greates than this height
+    /// Do not sign blocks greater than this height
     max_height: Option<tendermint::block::Height>,
 
     /// TCP connection to a validator node
@@ -129,15 +129,20 @@ where
             info!("terminate signal received");
             return Ok(false);
         }
-        debug!("started handling request ... ");
-        let response = match Request::read(&mut self.connection)? {
+
+        let request = Request::read(&mut self.connection)?;
+        debug!("received request: {:?}", &request);
+
+        let response = match request {
             Request::SignProposal(req) => self.sign(req)?,
             Request::SignVote(req) => self.sign(req)?,
             // non-signable requests:
             Request::ReplyPing(ref req) => self.reply_ping(req),
             Request::ShowPublicKey(ref req) => self.get_public_key(req)?,
         };
 
+        debug!("sending response: {:?}", &response);
+
         let mut buf = vec![];
 
         match response {
@@ -148,7 +153,7 @@ where
         }
 
         self.connection.write_all(&buf)?;
-        debug!("... success handling request");
+
         Ok(true)
     }
 
@@ -185,8 +190,9 @@ where
         // from keyring here:
         let sig = chain.keyring.sign_ed25519(None, &to_sign)?;
 
+        self.log_signing_request(&request);
         request.set_signature(&sig);
-        debug!("successfully signed request:\n {:?}", request);
+
         Ok(request.build_response())
     }
 
@@ -205,4 +211,22 @@ where
             *chain.keyring.default_pubkey()?,
         )))
     }
+
+    /// Write an INFO logline about a signing request
+    fn log_signing_request<T: TendermintRequest + Debug>(&self, request: &T) {
+        let height = request
+            .height()
+            .map(|h| h.to_string())
+            .unwrap_or_else(|| "none".to_owned());
+
+        let msg_type = request
+            .msg_type()
+            .map(|t| format!("{:?}", t))
+            .unwrap_or_else(|| "Unknown".to_owned());
+
+        info!(
+            "[{}] signed {:?} at height: {}",
+            self.chain_id, msg_type, height
+        );
+    }
 }

tendermint-rs/src/amino_types/proposal.rs

@@ -159,6 +159,10 @@ impl SignableMsg for SignProposalRequest {
     fn height(&self) -> Option<i64> {
         self.proposal.as_ref().map(|proposal| proposal.height)
     }
+
+    fn msg_type(&self) -> Option<SignedMsgType> {
+        Some(SignedMsgType::Proposal)
+    }
 }
 
 impl ConsensusMessage for Proposal {

tendermint-rs/src/amino_types/signature.rs

@@ -18,6 +18,7 @@ pub trait SignableMsg {
     fn validate(&self) -> Result<(), ValidationError>;
     fn consensus_state(&self) -> Option<consensus::State>;
     fn height(&self) -> Option<i64>;
+    fn msg_type(&self) -> Option<SignedMsgType>;
 }
 
 /// Signed message types. This follows:

tendermint-rs/src/amino_types/vote.rs

@@ -38,9 +38,14 @@ pub struct Vote {
 }
 
 impl Vote {
-    fn is_valid_vote_type(&self) -> bool {
-        self.vote_type == SignedMsgType::PreVote.to_u32()
-            || self.vote_type == SignedMsgType::PreCommit.to_u32()
+    fn msg_type(&self) -> Option<SignedMsgType> {
+        if self.vote_type == SignedMsgType::PreVote.to_u32() {
+            Some(SignedMsgType::PreVote)
+        } else if self.vote_type == SignedMsgType::PreCommit.to_u32() {
+            Some(SignedMsgType::PreCommit)
+        } else {
+            None
+        }
     }
 }
 
@@ -179,11 +184,14 @@ impl SignableMsg for SignVoteRequest {
     fn height(&self) -> Option<i64> {
         self.vote.as_ref().map(|vote| vote.height)
     }
+    fn msg_type(&self) -> Option<SignedMsgType> {
+        self.vote.as_ref().and_then(|vote| vote.msg_type())
+    }
 }
 
 impl ConsensusMessage for Vote {
     fn validate_basic(&self) -> Result<(), ValidationError> {
-        if !self.is_valid_vote_type() {
+        if self.msg_type().is_none() {
             return Err(InvalidMessageType.into());
         }
         if self.height < 0 {