Log improvements for v1.5

CHANGELOG.md

@@ -16,6 +16,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ### Changed
 
 - Redacted the contents of `CARTESI_EXPERIMENTAL_SUNODO_VALIDATOR_REDIS_ENDPOINT`.
+- server-manager tainted session errors logged on inspect-server.
+- Improved dispatcher logs.
 
 ## [1.5.0] 2024-07-22
 

offchain/dispatcher/src/dispatcher.rs

@@ -6,7 +6,7 @@ use eth_state_fold_types::{Block, BlockStreamItem};
 use rollups_events::DAppMetadata;
 use std::sync::Arc;
 use tokio_stream::StreamExt;
-use tracing::{error, instrument, trace, warn};
+use tracing::{error, info, instrument, trace, warn};
 use types::foldables::{InputBox, InputBoxInitialState};
 
 use crate::{
@@ -92,12 +92,8 @@ pub async fn start(
         match block_subscription.next().await {
             Some(Ok(BlockStreamItem::NewBlock(b))) => {
                 // Normal operation, react on newest block.
-                trace!(
-                    "Received block number {} and hash {:?}, parent: {:?}",
-                    b.number,
-                    b.hash,
-                    b.parent_hash
-                );
+                info!("Received block number {}", b.number);
+                trace!("Block hash {:?}, parent: {:?}", b.hash, b.parent_hash);
                 process_block(
                     &b,
                     &state_server,

offchain/dispatcher/src/drivers/context.rs

@@ -134,7 +134,9 @@ impl Context {
                 (Some(_), None) => true, // Consider input_epoch greater than None
                 (None, _) => false,      // None is never greater than any value
             },
-            "Assertion failed: last_input_epoch should be greater than last_finished_epoch"
+            "cannot finish epoch: last_input_epoch ({:?}) is not greater than last_finished_epoch ({:?})",
+            self.last_input_epoch,
+            self.last_finished_epoch
         );
 
         broker.finish_epoch(self.inputs_sent).await?;

offchain/dispatcher/src/drivers/machine.rs

@@ -53,7 +53,7 @@ impl MachineDriver {
         broker: &impl BrokerSend,
     ) -> Result<(), BrokerFacadeError> {
         tracing::trace!(
-            "Last input sent to machine manager `{}`, current input `{}`",
+            "Last input sent to advance-runner: `{}`; current input: `{}`",
             context.inputs_sent(),
             dapp_input_box.inputs.len()
         );

offchain/inspect-server/src/inspect.rs

@@ -1,15 +1,19 @@
 // (c) Cartesi and individual authors (see AUTHORS)
 // SPDX-License-Identifier: Apache-2.0 (see LICENSE)
 
-use tokio::sync::{mpsc, oneshot};
-use tonic::Request;
+use tokio::sync::{
+    mpsc,
+    oneshot::{self},
+};
+use tonic::{transport::Channel, Code, Request, Response, Status};
 use uuid::Uuid;
 
 use crate::config::InspectServerConfig;
 use crate::error::InspectError;
 
 use grpc_interfaces::cartesi_server_manager::{
-    server_manager_client::ServerManagerClient, InspectStateRequest,
+    server_manager_client::ServerManagerClient, GetSessionStatusRequest,
+    GetSessionStatusResponse, InspectStateRequest,
 };
 pub use grpc_interfaces::cartesi_server_manager::{
     CompletionStatus, InspectStateResponse, Report,
@@ -99,17 +103,72 @@ async fn handle_inspect(
                 grpc_request
                     .metadata_mut()
                     .insert("request-id", request_id.parse().unwrap());
-                let grpc_response = client.inspect_state(grpc_request).await;
+                let inspect_response = client.inspect_state(grpc_request).await;
 
-                tracing::debug!("got grpc response from inspect_state response={:?} request_id={}", grpc_response, request_id);
+                tracing::debug!("got grpc response from inspect_state response={:?} request_id={}",
+                                inspect_response, request_id);
 
-                let response = grpc_response
-                    .map(|result| result.into_inner())
-                    .map_err(|e| InspectError::InspectFailed {
-                        message: e.message().to_string(),
-                    });
+                let response = if inspect_response.is_ok() {
+                    Ok(inspect_response.unwrap().into_inner())
+                } else {
+                    // The server-manager does not inform the session tainted reason.
+                    // Trying to get it from the session's status.
+                    let message = handle_inspect_error(
+                        inspect_response.unwrap_err(),
+                        session_id.clone(),
+                        &mut client,
+                    )
+                    .await;
+                    Err(InspectError::InspectFailed { message })
+                };
                 respond(request.response_tx, response);
             }
         }
     }
 }
+
+async fn get_session_status(
+    session_id: String,
+    client: &mut ServerManagerClient<Channel>,
+) -> Result<Response<GetSessionStatusResponse>, Status> {
+    let session_id = session_id.clone();
+    let mut status_request =
+        Request::new(GetSessionStatusRequest { session_id });
+    let request_id = Uuid::new_v4().to_string();
+    status_request
+        .metadata_mut()
+        .insert("request-id", request_id.parse().unwrap());
+    client.get_session_status(status_request).await
+}
+
+async fn handle_inspect_error(
+    status: Status,
+    session_id: String,
+    client: &mut ServerManagerClient<Channel>,
+) -> String {
+    let mut message = status.message().to_string();
+
+    // If the session was previously tainted, the server-manager replies if with code DataLoss.
+    // Trying to recover the reason for the session tainted from the session's status.
+    // If not available, we return the original status error message.
+    if status.code() == Code::DataLoss {
+        let status_response = get_session_status(session_id, client).await;
+        if status_response.is_err() {
+            let err = status_response.unwrap_err().message().to_string();
+            tracing::error!("get-session-status error: {:?}", err);
+        } else {
+            let status_response = status_response.unwrap();
+            let status_response = status_response.get_ref();
+            let taint_status = status_response.taint_status.clone();
+            if let Some(taint_status) = taint_status {
+                message = format!(
+                    "Server manager session was tainted: {} ({})",
+                    taint_status.error_code, taint_status.error_message
+                );
+                tracing::error!(message);
+            }
+        }
+    }
+
+    message
+}