Retain Jepsen lifecycle evidence across permanent retirement

test/jepsen/src/group/jepsen/docker.clj

@@ -1,6 +1,7 @@
 (ns group.jepsen.docker
-  (:require [clojure.java.shell :as shell]
-            [clojure.string :as str]))
+  (:require [clojure.string :as str])
+  (:import (java.io File)
+           (java.util.concurrent TimeUnit)))
 
 (def containers
   {"n1" "group-jepsen-n1"
@@ -16,6 +17,8 @@
 (def replica-chain "GROUP_JEPSEN_REPLICA")
 (def replica-port 10000)
 
+(def ^:dynamic *command-timeout-ms* 30000)
+
 (defn container [node]
   (or (get containers (name node))
       (throw (ex-info "unknown Jepsen node" {:node node}))))
@@ -26,11 +29,30 @@
 
 (defn shell!
   [& args]
-  (let [{:keys [exit out err]} (apply shell/sh args)]
-    (when-not (zero? exit)
-      (throw (ex-info "command failed"
-                      {:command args, :exit exit, :out out, :err err})))
-    (str/trim out)))
+  (let [output (File/createTempFile "group-jepsen-command-" ".log")
+        errors (File/createTempFile "group-jepsen-command-" ".err")]
+    (try
+      (let [process (-> (ProcessBuilder. ^java.util.List (vec args))
+                        (.redirectError errors)
+                        (.redirectOutput output)
+                        .start)]
+        (try
+          (when-not (.waitFor process *command-timeout-ms* TimeUnit/MILLISECONDS)
+            (throw (ex-info "command timed out"
+                            {:command args :timeout-ms *command-timeout-ms*})))
+          (let [out (slurp output)
+                exit (.exitValue process)]
+            (when-not (zero? exit)
+              (throw (ex-info "command failed"
+                              {:command args :exit exit :out out :err (slurp errors)})))
+            (str/trim out))
+          (finally
+            (when (.isAlive process)
+              (.destroyForcibly process)
+              (.waitFor process 1000 TimeUnit/MILLISECONDS)))))
+      (finally
+        (.delete output)
+        (.delete errors)))))
 
 (defn docker!
   [& args]
@@ -64,9 +86,35 @@
 
 (defn reset-oracle! [node]
   (exec-sh! node
-            (str "rm -f /tmp/group-jepsen-unexpected-deaths "
-                 "/tmp/group-jepsen-persistent-events "
-                 "/tmp/group-jepsen-cursor-marker-corruption")))
+            (str "rm -f /tmp/group-jepsen-persistent-events "
+                 "/tmp/group-jepsen-cursor-marker-corruption && "
+                 ": > /tmp/group-jepsen-unexpected-deaths")))
+
+(defn parse-unexpected-deaths [contents]
+  (mapv (fn [line]
+          (let [[token reason :as fields] (str/split line #"\t" 2)]
+            (when (or (not= 2 (count fields)) (str/blank? token) (str/blank? reason))
+              (throw (ex-info "malformed lifecycle evidence" {:line line})))
+            {:token token :reason reason}))
+        (remove str/blank? (str/split-lines contents))))
+
+(defn retired-evidence!
+  "Reads the stopped container's durable oracle, without depending on its VM or socket.
+  Missing, truncated, unreadable, or oversized evidence is a qualification failure."
+  [node]
+  (let [file (File/createTempFile "group-jepsen-retired-" ".log")]
+    (try
+      (binding [*command-timeout-ms* 10000]
+        (docker! "cp"
+                 (str (container node) ":/tmp/group-jepsen-unexpected-deaths")
+                 (.getAbsolutePath file)))
+      (when (> (.length file) (* 8 1024 1024))
+        (throw (ex-info "lifecycle evidence exceeds collection bound" {:node node})))
+      (let [contents (slurp file)]
+        (when (and (seq contents) (not (str/ends-with? contents "\n")))
+          (throw (ex-info "truncated lifecycle evidence" {:node node})))
+        {:node (name node) :unexpected-deaths (parse-unexpected-deaths contents)})
+      (finally (.delete file)))))
 
 (defn ensure-firewall-chain! [node chain]
   (exec-sh!

test/jepsen/src/group/jepsen/model.clj

@@ -168,7 +168,16 @@
                                   (not= 0 (:snapshot-staging-count internal)))
                           [node internal]))))
               relevant-snapshots)
-        unexpected-deaths (->> relevant-snapshots vals (mapcat :unexpected-deaths) set)
+        completions (remove history/invoke? history)
+        retirement-evidence (keep #(get-in % [:value :lifecycle-evidence]) completions)
+        retired-nodes (set/difference (set (map name (:nodes test))) required-nodes)
+        collected-nodes (set (map :node retirement-evidence))
+        evidence-errors (vec (keep #(get-in % [:value :evidence-error]) completions))
+        missing-retirement-evidence (set/difference retired-nodes collected-nodes)
+        unexpected-deaths
+        (->> (concat (map :value (successful-snapshots history)) retirement-evidence)
+             (mapcat :unexpected-deaths)
+             set)
         live-tokens (set (keys (:owners expected)))
         actual-tokens (->> views
                            vals
@@ -198,6 +207,8 @@
                     (empty? (:conflicts expected))
                     (empty? mismatches)
                     (empty? unexpected-deaths)
+                    (empty? evidence-errors)
+                    (empty? missing-retirement-evidence)
                     (empty? orphaned)
                     (empty? missing-live)
                     (not latency-violation?))]
@@ -219,6 +230,8 @@
      :live-registry-conflicts (:conflicts expected)
      :mismatched-views mismatches
      :unexpected-owner-deaths unexpected-deaths
+     :lifecycle-evidence-errors evidence-errors
+     :missing-retirement-evidence missing-retirement-evidence
      :orphaned-owner-tokens orphaned
      :missing-live-owner-tokens missing-live
      :expected expected-view}))

test/jepsen/src/group/jepsen/nemesis.clj

@@ -139,10 +139,19 @@
 
   (invoke! [_this test op]
     (let [node (or (get-in op [:value :node]) (first (:nodes test)))]
-      (when (and (nil? @retired) (docker/running? node))
-        (db/kill! db test node)
+      (when (nil? @retired)
+        (when (docker/running? node)
+          (db/kill! db test node))
         (reset! retired node))
-      (assoc op :type :info, :value {:retired @retired})))
+      ;; Capture after the stop, including when an earlier nemesis already stopped
+      ;; the VM. Do not let loss of the client socket erase historical evidence.
+      (let [evidence (try
+                       {:lifecycle-evidence (docker/retired-evidence! @retired)}
+                       (catch Exception exception
+                         {:evidence-error {:node (name @retired)
+                                           :message (.getMessage exception)
+                                           :data (ex-data exception)}}))]
+        (assoc op :type :info, :value (merge {:retired @retired} evidence)))))
 
   (teardown! [_this test]
     (when-let [node @retired]

test/jepsen/test/group/jepsen/model_test.clj

@@ -90,10 +90,32 @@
 (deftest accepts-a-permanently-retired-node-and-requires-its-absence
   (let [survivors ["n2" "n3"]
         permanent-test (assoc test-map :terminal-nodes survivors)
-        history [(snapshot-op 1 "n2" survivors [] (empty-registry) (empty-pg))
+        history [{:index 0 :process :nemesis :type :info :f :retire-node
+                  :value {:retired "n1" :lifecycle-evidence {:node "n1" :unexpected-deaths []}}}
+                 (snapshot-op 1 "n2" survivors [] (empty-registry) (empty-pg))
                  (snapshot-op 2 "n3" survivors [] (empty-registry) (empty-pg))]]
     (is (:valid? (model/analyze permanent-test history)))))
 
+(deftest retirement-cannot-discard-earlier-invalid-lifecycle-evidence
+  (let [survivors ["n2" "n3"]
+        test (assoc test-map :terminal-nodes survivors)
+        retirement {:index 2 :process :nemesis :type :info :f :retire-node
+                    :value {:retired "n1"
+                            :lifecycle-evidence {:node "n1" :unexpected-deaths []}}}
+        terminal [(snapshot-op 3 "n2" survivors [] (empty-registry) (empty-pg))
+                  (snapshot-op 4 "n3" survivors [] (empty-registry) (empty-pg))]
+        prior (with-unexpected-death
+                (snapshot-op 1 "n1" [] (empty-registry) (empty-pg)) "lost-owner")]
+    (is (false? (:valid? (model/analyze test (concat [prior retirement] terminal)))))
+    (is (false? (:valid? (model/analyze test terminal))))
+    (is (false? (:valid? (model/analyze test
+                          (cons (assoc-in retirement [:value :lifecycle-evidence :unexpected-deaths]
+                                          [{:token "lost-owner" :reason ":boom"}])
+                                terminal)))))
+    (is (false? (:valid? (model/analyze test
+                          (cons (assoc-in retirement [:value :evidence-error] {:message "timeout"})
+                                terminal)))))))
+
 (deftest rejects-zombies-missing-live-owners-and-divergence
   (let [live (owner "live" [(registration nil 0 1)] [])
         stale-registry (assoc-in (empty-registry) ["root" 0] "dead")

test/jepsen/test/group/jepsen/retired_evidence_test.clj

@@ -0,0 +1,62 @@
+(ns group.jepsen.retired-evidence-test
+  (:require [clojure.test :refer :all]
+            [group.jepsen.docker :as docker]
+            [group.jepsen.nemesis :as group-nemesis]
+            [jepsen.db :as db]
+            [jepsen.nemesis :as nemesis]))
+
+(deftest collector-reads-stopped-container-through-command-boundary
+  (let [calls (atom [])]
+    (with-redefs [docker/docker!
+                  (fn [& args]
+                    (swap! calls conj args)
+                    (is (= 10000 docker/*command-timeout-ms*))
+                    (spit (last args) "n1/boot/owner/1\t:boom\n"))]
+      (is (= {:node "n1" :unexpected-deaths [{:token "n1/boot/owner/1" :reason ":boom"}]}
+             (docker/retired-evidence! "n1")))
+      (is (= ["cp" "group-jepsen-n1:/tmp/group-jepsen-unexpected-deaths"]
+             (vec (take 2 (first @calls))))))))
+
+(deftest collector-distinguishes-empty-evidence-from-loss
+  (doseq [contents ["" "bad\n" "token\t:boom"]]
+    (with-redefs [docker/docker! (fn [& args] (spit (last args) contents))]
+      (if (= "" contents)
+        (is (= [] (:unexpected-deaths (docker/retired-evidence! "n1"))))
+        (is (thrown? Exception (docker/retired-evidence! "n1"))))))
+  (with-redefs [docker/docker! (fn [& _] (throw (ex-info "missing file" {:exit 1})))]
+    (is (thrown? Exception (docker/retired-evidence! "n1")))))
+
+(deftest workload-reset-initializes-empty-evidence-before-mutations
+  (with-redefs [docker/exec-sh!
+                (fn [node script]
+                  (is (= "n1" node))
+                  (is (re-find #": > /tmp/group-jepsen-unexpected-deaths" script)))]
+    (docker/reset-oracle! "n1")))
+
+(deftest retirement-captures-after-stop-even-if-node-was-already-unavailable
+  (doseq [running? [true false]]
+    (let [calls (atom [])
+          database (reify db/Process
+                     (start! [_ _ _])
+                     (kill! [_ _ node] (swap! calls conj [:kill node])))
+          n (group-nemesis/->RetirementNemesis database (atom nil))]
+      (with-redefs [docker/running? (constantly running?)
+                    docker/retired-evidence! (fn [node]
+                                               (swap! calls conj [:collect node])
+                                               {:node node :unexpected-deaths []})]
+        (is (= {:node "n1" :unexpected-deaths []}
+               (get-in (nemesis/invoke! n {:nodes ["n1"]} {:f :retire})
+                       [:value :lifecycle-evidence])))
+        (is (= (if running? [[:kill "n1"] [:collect "n1"]] [[:collect "n1"]])
+               @calls))))))
+
+(deftest retirement-preserves-collector-failure-in-history
+  (with-redefs [docker/running? (constantly false)
+                docker/retired-evidence! (fn [_] (throw (ex-info "timeout" {})))]
+    (let [n (group-nemesis/->RetirementNemesis nil (atom nil))
+          op (nemesis/invoke! n {:nodes ["n1"]} {:f :retire})]
+      (is (= "timeout" (get-in op [:value :evidence-error :message]))))))
+
+(deftest command-timeout-is-bounded
+  (binding [docker/*command-timeout-ms* 20]
+    (is (thrown-with-msg? Exception #"timed out" (docker/shell! "sleep" "10")))))