From 73321deace9293bb4fc00461a4abf6c2ceface82 Mon Sep 17 00:00:00 2001
From: Eddy Ashton <edashton@microsoft.com>
Date: Thu, 14 Nov 2024 12:48:06 +0000
Subject: [PATCH] Verbose logging for cert renewals (#6645)

---
 src/kv/untyped_map.h    |  8 ++++++
 src/node/node_state.h   | 55 +++++++++++++++++++++++++++++++++++++++++
 src/node/rpc/frontend.h |  8 ++++--
 3 files changed, 69 insertions(+), 2 deletions(-)

diff --git a/src/kv/untyped_map.h b/src/kv/untyped_map.h
index ccfab022f5c7..767c5da2f782 100644
--- a/src/kv/untyped_map.h
+++ b/src/kv/untyped_map.h
@@ -730,6 +730,10 @@ namespace ccf::kv::untyped
       {
         for (auto& [version, writes] : commit_deltas)
         {
+          LOG_TRACE_FMT(
+            "Executing global hook on table {} at version {}",
+            get_name(),
+            version);
           global_hook(version, writes);
         }
       }
@@ -834,6 +838,10 @@ namespace ccf::kv::untyped
     {
       if (hook && !writes.empty())
       {
+        LOG_TRACE_FMT(
+          "Executing local hook on table {} at version {}",
+          get_name(),
+          version);
         return hook(version, writes);
       }
       return nullptr;
diff --git a/src/node/node_state.h b/src/node/node_state.h
index 129c2b7d6941..20323ac29712 100644
--- a/src/node/node_state.h
+++ b/src/node/node_state.h
@@ -2222,22 +2222,42 @@ namespace ccf
             ccf::kv::Version hook_version,
             const NodeEndorsedCertificates::Write& w)
             -> ccf::kv::ConsensusHookPtr {
+            LOG_INFO_FMT(
+              "[local] node_endorsed_certificates local hook at version {}, "
+              "with {} writes",
+              hook_version,
+              w.size());
             for (auto const& [node_id, endorsed_certificate] : w)
             {
               if (node_id != self)
               {
+                LOG_INFO_FMT(
+                  "[local] Ignoring endorsed certificate for other node {}",
+                  node_id);
                 continue;
               }
 
               if (!endorsed_certificate.has_value())
               {
+                LOG_FAIL_FMT(
+                  "[local] Endorsed cert for self ({}) has been deleted", self);
                 throw std::logic_error(fmt::format(
                   "Could not find endorsed node certificate for {}", self));
               }
 
               std::lock_guard<pal::Mutex> guard(lock);
 
+              if (endorsed_node_cert.has_value())
+              {
+                LOG_INFO_FMT(
+                  "[local] Previous endorsed node cert was:\n{}",
+                  endorsed_node_cert->str());
+              }
+
               endorsed_node_cert = endorsed_certificate.value();
+              LOG_INFO_FMT(
+                "[local] Under lock, setting endorsed node cert to:\n{}",
+                endorsed_node_cert->str());
               history->set_endorsed_certificate(endorsed_node_cert.value());
               n2n_channels->set_endorsed_node_cert(endorsed_node_cert.value());
             }
@@ -2251,21 +2271,33 @@ namespace ccf
           [this](
             ccf::kv::Version hook_version,
             const NodeEndorsedCertificates::Write& w) {
+            LOG_INFO_FMT(
+              "[global] node_endorsed_certificates global hook at version {}, "
+              "with {} writes",
+              hook_version,
+              w.size());
             for (auto const& [node_id, endorsed_certificate] : w)
             {
               if (node_id != self)
               {
+                LOG_INFO_FMT(
+                  "[global] Ignoring endorsed certificate for other node {}",
+                  node_id);
                 continue;
               }
 
               if (!endorsed_certificate.has_value())
               {
+                LOG_FAIL_FMT(
+                  "[global] Endorsed cert for self ({}) has been deleted",
+                  self);
                 throw std::logic_error(fmt::format(
                   "Could not find endorsed node certificate for {}", self));
               }
 
               std::lock_guard<pal::Mutex> guard(lock);
 
+              LOG_INFO_FMT("[global] Accepting network connections");
               accept_network_tls_connections();
 
               if (is_member_frontend_open_unsafe())
@@ -2279,15 +2311,31 @@ namespace ccf
                 auto [valid_from, valid_to] =
                   ccf::crypto::make_verifier(endorsed_node_cert.value())
                     ->validity_period();
+                LOG_INFO_FMT(
+                  "[global] Member frontend is open, so refreshing self-signed "
+                  "node cert");
+                LOG_INFO_FMT(
+                  "[global] Previously:\n{}", self_signed_node_cert.str());
                 self_signed_node_cert = create_self_signed_cert(
                   node_sign_kp,
                   config.node_certificate.subject_name,
                   subject_alt_names,
                   valid_from,
                   valid_to);
+                LOG_INFO_FMT("[global] Now:\n{}", self_signed_node_cert.str());
+
+                LOG_INFO_FMT("[global] Accepting node connections");
                 accept_node_tls_connections();
               }
+              else
+              {
+                LOG_INFO_FMT("[global] Member frontend is NOT open");
+                LOG_INFO_FMT(
+                  "[global] Self-signed node cert remains:\n{}",
+                  self_signed_node_cert.str());
+              }
 
+              LOG_INFO_FMT("[global] Opening members frontend");
               open_frontend(ActorsType::members);
             }
           }));
@@ -2316,6 +2364,13 @@ namespace ccf
               return;
             }
 
+            LOG_INFO_FMT(
+              "Executing global hook for service table at {}, to service "
+              "status {}. Cert is:\n{}",
+              hook_version,
+              w->status,
+              w->cert.str());
+
             network.identity->set_certificate(w->cert);
             if (w->status == ServiceStatus::OPEN)
             {
diff --git a/src/node/rpc/frontend.h b/src/node/rpc/frontend.h
index be375c8c7fe2..c7a5c06e2973 100644
--- a/src/node/rpc/frontend.h
+++ b/src/node/rpc/frontend.h
@@ -938,8 +938,12 @@ namespace ccf
     void open() override
     {
       std::lock_guard<ccf::pal::Mutex> mguard(open_lock);
-      is_open_ = true;
-      endpoints.init_handlers();
+      if (!is_open_)
+      {
+        LOG_INFO_FMT("Opening frontend");
+        is_open_ = true;
+        endpoints.init_handlers();
+      }
     }
 
     bool is_open() override