From 01c2c3bbb782a9a4d4b9e8e16ade22ff6ac37640 Mon Sep 17 00:00:00 2001
From: Henry de Valence <hdevalence@penumbralabs.xyz>
Date: Tue, 31 Oct 2023 12:31:49 -0700
Subject: [PATCH] summonerd: clean up tracing for coordinator

---
 tools/summonerd/src/coordinator.rs | 14 +++++++++-----
 tools/summonerd/src/main.rs        | 10 ++++++++--
 tools/summonerd/src/participant.rs |  3 ++-
 3 files changed, 19 insertions(+), 8 deletions(-)

diff --git a/tools/summonerd/src/coordinator.rs b/tools/summonerd/src/coordinator.rs
index 6b65ce2684..da915c5e81 100644
--- a/tools/summonerd/src/coordinator.rs
+++ b/tools/summonerd/src/coordinator.rs
@@ -19,9 +19,9 @@ impl Coordinator {
     pub async fn run<P: Phase + 'static>(mut self) -> Result<()> {
         loop {
             let participant_count = self.queue.len().await;
-            tracing::debug!(
+            tracing::info!(
                 participant_count = participant_count,
-                "top of coordinator loop"
+                "starting ceremony round"
             );
             // 1. Inform all participants of their position
             self.queue.inform_all().await?;
@@ -33,12 +33,16 @@ impl Coordinator {
                 }
                 tokio::time::sleep(Duration::from_secs(QUEUE_SLEEP_TIME_SECS)).await;
             };
+            tracing::info!(
+                address = ?contributor.address().display_short_form(),
+                "requesting contribution from participant"
+            );
             // 3. Get their contribution, or time out.
             self.contribute::<P>(contributor).await?;
         }
     }
 
-    #[tracing::instrument(skip_all, fields(address = ?contributor.address()))]
+    #[tracing::instrument(skip_all, fields(address = ?contributor.address().display_short_form()))]
     async fn contribute<P: Phase>(&mut self, contributor: Participant) -> Result<()> {
         let address = contributor.address();
         match tokio::time::timeout(
@@ -57,7 +61,6 @@ impl Coordinator {
         }
     }
 
-    #[tracing::instrument(skip_all)]
     async fn contribute_inner<P: Phase>(&mut self, mut contributor: Participant) -> Result<()> {
         let address = contributor.address();
         let parent = P::current_crs(&self.storage)
@@ -65,7 +68,7 @@ impl Coordinator {
             .expect("the phase should've been initialized by now");
         let maybe = contributor.contribute::<P>(&parent).await?;
         if let Some(unvalidated) = maybe {
-            tracing::debug!("validating contribution");
+            tracing::info!("validating contribution");
             let root = P::fetch_root(&self.storage).await?;
             let maybe_contribution = tokio::task::spawn_blocking(move || {
                 if let Some(contribution) = P::validate(&root, unvalidated) {
@@ -76,6 +79,7 @@ impl Coordinator {
                 None
             })
             .await?;
+            tracing::info!("saving contribution");
             if let Some(contribution) = maybe_contribution {
                 P::commit_contribution(&self.storage, address, contribution).await?;
                 contributor
diff --git a/tools/summonerd/src/main.rs b/tools/summonerd/src/main.rs
index 8e91026295..7d5cc0a141 100644
--- a/tools/summonerd/src/main.rs
+++ b/tools/summonerd/src/main.rs
@@ -32,6 +32,7 @@ use std::io::Read;
 use std::net::SocketAddr;
 use storage::Storage;
 use tonic::transport::Server;
+use tracing::Instrument;
 use tracing_subscriber::{prelude::*, EnvFilter};
 use url::Url;
 
@@ -175,9 +176,14 @@ impl Opt {
                         .await?;
                 let queue = ParticipantQueue::new();
                 let coordinator = Coordinator::new(storage.clone(), queue.clone());
+                let coordinator_span = tracing::error_span!("coordinator");
                 let coordinator_handle = match marker {
-                    PhaseMarker::P1 => tokio::spawn(coordinator.run::<Phase1>()),
-                    PhaseMarker::P2 => tokio::spawn(coordinator.run::<Phase2>()),
+                    PhaseMarker::P1 => {
+                        tokio::spawn(coordinator.run::<Phase1>().instrument(coordinator_span))
+                    }
+                    PhaseMarker::P2 => {
+                        tokio::spawn(coordinator.run::<Phase2>().instrument(coordinator_span))
+                    }
                 };
                 let service = CoordinatorService::new(knower, storage.clone(), queue, marker);
                 let grpc_server = Server::builder().add_service(
diff --git a/tools/summonerd/src/participant.rs b/tools/summonerd/src/participant.rs
index 436b4e378c..ec996608ee 100644
--- a/tools/summonerd/src/participant.rs
+++ b/tools/summonerd/src/participant.rs
@@ -70,11 +70,11 @@ impl Participant {
         })
     }
 
-    #[tracing::instrument(skip(self, parent))]
     pub async fn contribute<P: Phase>(
         &mut self,
         parent: &P::CRS,
     ) -> Result<Option<P::RawContribution>> {
+        tracing::info!("sending ContributeNow message to participant");
         self.tx
             .send(Ok(ParticipateResponse {
                 msg: Some(ResponseMsg::ContributeNow(ContributeNow {
@@ -89,6 +89,7 @@ impl Participant {
             msg: Some(RequestMsg::Contribution(contribution)),
         }) = msg
         {
+            tracing::info!("got Contribution message from participant, deserializing...");
             let deserialized =
                 tokio::task::spawn_blocking(move || P::deserialize_contribution(contribution))
                     .await??;