From f9b5eb3a1513d2c6ee6e68af85096b0ec59972e8 Mon Sep 17 00:00:00 2001
From: teor <teor@riseup.net>
Date: Fri, 26 May 2023 04:28:25 +1000
Subject: [PATCH] fix(log): Limit RPC failure log length, add details to RPC
 failure logs (#6754)

* Limit the RPC failure log length

* Add more specific logs for some RPC tests

* Make sure the block hash is always available for logging
---
 zebra-rpc/src/constants.rs                     |  3 +++
 .../src/methods/get_block_template_rpcs.rs     |  6 +++---
 zebra-rpc/src/server/rpc_call_compatibility.rs | 18 +++++++++++++++---
 .../get_block_template_rpcs/submit_block.rs    |  5 ++++-
 4 files changed, 25 insertions(+), 7 deletions(-)

diff --git a/zebra-rpc/src/constants.rs b/zebra-rpc/src/constants.rs
index 9d549767b..58b119ad2 100644
--- a/zebra-rpc/src/constants.rs
+++ b/zebra-rpc/src/constants.rs
@@ -16,3 +16,6 @@ pub const INVALID_PARAMETERS_ERROR_CODE: ErrorCode = ErrorCode::ServerError(-1);
 /// `lightwalletd` expects error code `-8` when a block is not found:
 /// <https://github.com/adityapk00/lightwalletd/blob/c1bab818a683e4de69cd952317000f9bb2932274/common/common.go#L251-L254>
 pub const MISSING_BLOCK_ERROR_CODE: ErrorCode = ErrorCode::ServerError(-8);
+
+/// When logging parameter data, only log this much data.
+pub const MAX_PARAMS_LOG_LENGTH: usize = 100;
diff --git a/zebra-rpc/src/methods/get_block_template_rpcs.rs b/zebra-rpc/src/methods/get_block_template_rpcs.rs
index f7ea4e3f9..f9c5e3f01 100644
--- a/zebra-rpc/src/methods/get_block_template_rpcs.rs
+++ b/zebra-rpc/src/methods/get_block_template_rpcs.rs
@@ -737,7 +737,7 @@ where
             let block: Block = match block_bytes.zcash_deserialize_into() {
                 Ok(block_bytes) => block_bytes,
                 Err(error) => {
-                    tracing::info!(?error, "submit block failed");
+                    tracing::info!(?error, "submit block failed: block bytes could not be deserialized into a structurally valid block");
 
                     return Ok(submit_block::ErrorResponse::Rejected.into());
                 }
@@ -747,6 +747,7 @@ where
                 .coinbase_height()
                 .map(|height| height.0.to_string())
                 .unwrap_or_else(|| "invalid coinbase height".to_string());
+            let block_hash = block.hash();
 
             let chain_verifier_response = chain_verifier
                 .ready()
@@ -778,8 +779,7 @@ where
                         .downcast::<VerifyChainError>()
                         .map(|boxed_chain_error| *boxed_chain_error);
 
-                    // TODO: add block hash to error?
-                    tracing::info!(?error, ?block_height, "submit block failed");
+                    tracing::info!(?error, ?block_hash, ?block_height, "submit block failed verification");
 
                     error
                 }
diff --git a/zebra-rpc/src/server/rpc_call_compatibility.rs b/zebra-rpc/src/server/rpc_call_compatibility.rs
index e6f44c1eb..c3974ac3c 100644
--- a/zebra-rpc/src/server/rpc_call_compatibility.rs
+++ b/zebra-rpc/src/server/rpc_call_compatibility.rs
@@ -12,7 +12,7 @@ use jsonrpc_core::{
     BoxFuture, ErrorCode, Metadata, MethodCall, Notification,
 };
 
-use crate::constants::INVALID_PARAMETERS_ERROR_CODE;
+use crate::constants::{INVALID_PARAMETERS_ERROR_CODE, MAX_PARAMS_LOG_LENGTH};
 
 /// JSON-RPC [`Middleware`] with compatibility workarounds.
 ///
@@ -75,10 +75,22 @@ impl FixRpcResponseMiddleware {
     fn call_description(call: &Call) -> String {
         match call {
             Call::MethodCall(MethodCall { method, params, .. }) => {
-                format!(r#"method = {method:?}, params = {params:?}"#)
+                let mut params = format!("{params:?}");
+                if params.len() >= MAX_PARAMS_LOG_LENGTH {
+                    params.truncate(MAX_PARAMS_LOG_LENGTH);
+                    params.push_str("...");
+                }
+
+                format!(r#"method = {method:?}, params = {params}"#)
             }
             Call::Notification(Notification { method, params, .. }) => {
-                format!(r#"notification = {method:?}, params = {params:?}"#)
+                let mut params = format!("{params:?}");
+                if params.len() >= MAX_PARAMS_LOG_LENGTH {
+                    params.truncate(MAX_PARAMS_LOG_LENGTH);
+                    params.push_str("...");
+                }
+
+                format!(r#"notification = {method:?}, params = {params}"#)
             }
             Call::Invalid { .. } => "invalid request".to_owned(),
         }
diff --git a/zebrad/tests/common/get_block_template_rpcs/submit_block.rs b/zebrad/tests/common/get_block_template_rpcs/submit_block.rs
index 571ffa14f..de034460c 100644
--- a/zebrad/tests/common/get_block_template_rpcs/submit_block.rs
+++ b/zebrad/tests/common/get_block_template_rpcs/submit_block.rs
@@ -75,7 +75,10 @@ pub(crate) async fn run() -> Result<()> {
         let res_text = res.text().await?;
 
         // Test rpc endpoint response
-        assert!(res_text.contains(r#""result":null"#));
+        assert!(
+            res_text.contains(r#""result":null"#),
+            "unexpected response from submitblock RPC, should be null, was: {res_text}"
+        );
     }
 
     zebrad.kill(false)?;