diff --git a/test/jepsen/src/group/jepsen/docker.clj b/test/jepsen/src/group/jepsen/docker.clj index da9cc6f..d0fc147 100644 --- a/test/jepsen/src/group/jepsen/docker.clj +++ b/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! diff --git a/test/jepsen/src/group/jepsen/model.clj b/test/jepsen/src/group/jepsen/model.clj index bc772aa..711a7cf 100644 --- a/test/jepsen/src/group/jepsen/model.clj +++ b/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})) diff --git a/test/jepsen/src/group/jepsen/nemesis.clj b/test/jepsen/src/group/jepsen/nemesis.clj index e11c40f..c0c3a2a 100644 --- a/test/jepsen/src/group/jepsen/nemesis.clj +++ b/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] diff --git a/test/jepsen/test/group/jepsen/model_test.clj b/test/jepsen/test/group/jepsen/model_test.clj index 81e5263..81af566 100644 --- a/test/jepsen/test/group/jepsen/model_test.clj +++ b/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") diff --git a/test/jepsen/test/group/jepsen/retired_evidence_test.clj b/test/jepsen/test/group/jepsen/retired_evidence_test.clj new file mode 100644 index 0000000..3491e73 --- /dev/null +++ b/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")))))