[Debug] Debug pending snapshot

.threading_canary

@@ -1 +1 @@
-This looks like a "job" for Threading Canary!!!
+This looks like a "job" for Threading Canary!!!

getting_started/setup_vm/ccf-dev.yml

@@ -46,3 +46,6 @@
     - import_role:
         name: perf-tool
         tasks_from: install.yml
+    - import_role:
+        name: lldb
+        tasks_from: install.yml

getting_started/setup_vm/roles/lldb/tasks/install.yml

@@ -0,0 +1,8 @@
+- name: Include vars
+  include_vars: common.yml
+
+- name: Install debs
+  apt:
+    name: "lldb"
+    update_cache: yes
+  become: yes

getting_started/setup_vm/roles/lldb/vars/common.yml

@@ -0,0 +1 @@
+workspace: "/tmp/"

src/node/node_state.h

@@ -2512,7 +2512,7 @@ namespace ccf
             kv::Version version, const Signatures::Write& w) {
             assert(w.has_value());
             auto sig = w.value();
-            s->record_signature(version, sig.sig, sig.node, sig.cert);
+            s->record_signature(version, sig.sig, sig.node, sig.cert); // called after bisiness logic is excecuted
             return kv::ConsensusHookPtr(nullptr);
           }));
 

src/node/snapshotter.h

@@ -15,6 +15,7 @@
 
 #include <deque>
 #include <optional>
+#include<unistd.h> 
 
 namespace ccf
 {
@@ -167,6 +168,7 @@ namespace ccf
         static_cast<consensus::Index>(snapshot_version);
       consensus::Index snapshot_evidence_idx =
         static_cast<consensus::Index>(evidence_version);
+      LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: snapshot_ snapshot_idx: {}, snapshot_evidence_idx {}", snapshot_idx, snapshot_evidence_idx);
       pending_snapshots.emplace_back(
         snapshot_idx,
         snapshot_evidence_idx,
@@ -194,8 +196,21 @@ namespace ccf
 
       for (auto it = pending_snapshots.begin(); it != pending_snapshots.end();)
       {
+        LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: update_indices idx: {}, it->evidence_idx: {}", idx, it->evidence_idx);
         if (idx > it->evidence_idx)
         {
+          if (!it->sig.has_value()) {
+            LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: : A_LOG: sig doesn't have value");
+          }
+          if (!it->tree.has_value()) {
+            LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: : tree doesn't have value");
+          }
+          if (!it->node_id.has_value()) {
+            LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: : node_id doesn't have value");
+          }
+          if (!it->node_cert.has_value()) {
+            LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: : node_cert doesn't have value");
+          }
           auto serialised_receipt = build_and_serialise_receipt(
             it->sig.value(),
             it->tree.value(),
@@ -311,9 +326,11 @@ namespace ccf
       const crypto::Pem& node_cert)
     {
       std::lock_guard<ccf::pal::Mutex> guard(lock);
+      LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: record_signature idx: {}", idx);
 
       for (auto& pending_snapshot : pending_snapshots)
       {
+        LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: pending_snapshot.evidence_idx: {}", pending_snapshot.evidence_idx);
         if (
           pending_snapshot.evidence_idx < idx &&
           !pending_snapshot.sig.has_value())
@@ -343,6 +360,7 @@ namespace ccf
 
     void schedule_snapshot(consensus::Index idx)
     {
+      LOG_TRACE_FMT("PENDING_SNAPSHOTS_DEBUG: schedule_snapshot idx: {}", idx);
       auto msg = std::make_unique<threading::Tmsg<SnapshotMsg>>(&snapshot_cb);
       msg->data.self = shared_from_this();
       msg->data.snapshot = store->snapshot(idx);

tests/infra/network.py

@@ -310,6 +310,10 @@ def _add_node(
             try:
                 node.wait_for_node_to_join(timeout=JOIN_TIMEOUT)
             except TimeoutError:
+                try:
+                    node.show_stack_trace()
+                except Exception as e:
+                    LOG.info(f"Failed to get stack trace: {e}")
                 LOG.error(f"New node {node.local_node_id} failed to join the network")
                 raise
 
@@ -764,6 +768,10 @@ def join_node(
             )
         except TimeoutError as e:
             LOG.error(f"New pending node {node.node_id} failed to join the network")
+            try:
+                node.show_stack_trace()
+            except Exception as exception:
+                LOG.info(f"Failed to get stack trace: {exception}")
             if stop_on_error:
                 assert node.remote.check_done()
             errors, _ = node.stop()
@@ -801,6 +809,10 @@ def trust_node(
                 # has caught up and observed commit on the service open transaction.
                 node.wait_for_node_to_join(timeout=args.ledger_recovery_timeout)
         except (ValueError, TimeoutError):
+            try:
+                node.show_stack_trace()
+            except Exception as e:
+                LOG.info(f"Failed to get stack trace: {e}")
             LOG.error(f"New trusted node {node.node_id} failed to join the network")
             node.stop()
             raise
@@ -841,6 +853,10 @@ def retire_node(self, remote_node, node_to_retire, timeout=10):
                     pass
                 time.sleep(0.1)
             else:
+                try:
+                    remote_node.show_stack_trace()
+                except Exception as e:
+                    LOG.info(f"Failed to get stack trace: {e}")
                 raise TimeoutError(f"Timed out waiting for node to become removed: {r}")
 
         self.nodes.remove(node_to_retire)

tests/infra/node.py

@@ -452,6 +452,12 @@ def stop(self, *args, **kwargs):
             return self.remote.stop(*args, **kwargs)
         return [], []
 
+    def show_stack_trace(self):
+        # pylint: disable=no-member
+        if self.remote and self.remote.show_stack_trace:
+            # pylint: disable=no-member
+            self.remote.show_stack_trace()
+
     def is_stopped(self):
         return self.network_state == NodeNetworkState.stopped
 

tests/infra/remote.py

@@ -517,14 +517,62 @@ def get_logs(
             ignore_error_patterns=ignore_error_patterns,
         )
 
+    def print_stack_trace(self):
+        if shutil.which("lldb") != "":
+            # To avoid errors on decoding lldb output as utf-8.
+            # We shoud find a way to force lldb to use utf-8.
+            errors = "ignore"
+            lldb_timeout = 20
+            try:
+                command = [
+                    "lldb",
+                    "--one-line",
+                    f"process attach --pid {self.proc.pid}",
+                    "--one-line",
+                    "thread backtrace all",
+                    "--one-line",
+                    "quit",
+                ]
+                if os.geteuid() != 0:
+                    # Add sudo if not root
+                    command.insert(0, "sudo")
+                completed_lldb_process = subprocess.run(
+                    command,
+                    stdout=subprocess.PIPE,
+                    stderr=subprocess.STDOUT,
+                    universal_newlines=True,
+                    errors=errors,
+                    text=True,
+                    timeout=lldb_timeout,
+                    check=True,
+                )
+                LOG.info(f"stack trace: {completed_lldb_process.stdout}")
+            except subprocess.TimeoutExpired:
+                LOG.info(
+                    "Failed to get stack trace. lldb did not finish within {lldb_timeout} seconds."
+                )
+            except Exception as e:
+                LOG.info(f"Failed to get stack trace: {e}")
+        else:
+            LOG.info("Couldn't find lldb installed")
+
     def stop(self, ignore_error_patterns=None):
         """
         Disconnect the client, and therefore shut down the command as well.
         """
         LOG.info("[{}] closing".format(self.hostname))
         if self.proc:
             self.proc.terminate()
-            self.proc.wait(10)
+            timeout = 10
+            try:
+                self.proc.wait(timeout)
+            except subprocess.TimeoutExpired:
+                LOG.exception(
+                    f"Process didn't finish within {timeout} seconds. Tyring to get stack trace..."
+                )
+                self.print_stack_trace()
+                raise
+
             exit_code = self.proc.returncode
             if exit_code is not None and exit_code < 0:
                 signal_str = signal.strsignal(-exit_code)

tests/tests.sh

@@ -17,6 +17,17 @@ pip install -q -U -r ../tests/requirements.txt
 pip install -q -U -r ../tests/perf-system/requirements.txt
 echo "Python environment successfully setup"
 
+# We can delete it when
+# lldb is included in the CI images
+if ! command -v lldb; then
+    SUDO=""
+    if [ "$EUID" != 0 ]; then
+        SUDO="sudo"
+    fi
+    $SUDO apt update
+    $SUDO apt install -y lldb
+fi
+
 # Export where the VENV has been set, so tests running
 # a sandbox.sh can inherit it rather create a new one
 VENV_DIR=$(realpath env)