search

yugabyte / yugabyte-db

YugabyteDB - the cloud native distributed SQL database for mission-critical applications.
https://www.yugabyte.com
Other
8.96k stars 1.07k forks source link

[Jepsen] Running tests in batch (i.e. test-all) fails from some point onward #1599

Closed frozenspider closed 5 years ago

frozenspider commented 5 years ago

Here's what happens when I try to run the whole suite like this

lein run test-all -o debian --url ... --concurrency 20 --only-workloads-expected-to-pass

After some time, all subsequent test begin to fail - and error point to the fact that tests' setup code isn't run properly

YSQL:

Test  17 / 128
INFO [2019-06-21 11:45:50,739] jepsen test runner - jepsen.core Running test:
 {:trace-cql false,
 :replication-factor 3,
 :final-recovery-time 30,
 :api :ysql,
 :concurrency 20,
 :db
 #object[yugabyte.auto$community_edition$reify__3294 0x1bbf7e81 "yugabyte.auto$community_edition$reify__3294@1bbf7e81"],
 :name "yb 1.1.10.0 set nemesis kill-tserver",
 :start-time
 #object[org.joda.time.DateTime 0x63064672 "2019-06-21T11:45:50.000Z"],
 :net
 #object[jepsen.net$reify__5190 0x3ba6707e "jepsen.net$reify__5190@3ba6707e"],
 :client
 {:conn-wrapper nil,
  :inner-client {},
  :setup? #<Atom@1cd853ee: true>,
  :teardown? #<Atom@57330423: true>},
 :barrier
 #object[java.util.concurrent.CyclicBarrier 0x2a68932b "java.util.concurrent.CyclicBarrier@2a68932b"],
 :ssh
 {:username "root",
  :password "root",
  :strict-host-key-checking false,
  :private-key-path nil},
 :nemesis-long-recovery false,
 :checker
 #object[jepsen.checker$compose$reify__4748 0x4fe0aa21 "jepsen.checker$compose$reify__4748@4fe0aa21"],
 :nemesis
 #object[jepsen.nemesis$compose$reify__5318 0x7a7b6556 "jepsen.nemesis$compose$reify__5318@7a7b6556"],
 :active-histories #<Atom@75f2a654: #{}>,
 :nodes ["n1" "n2" "n3" "n4" "n5"],
 :test-count 1,
 :url
 "http://10.150.0.10:8000/yugabyte-ce-1.2.11.0-358049cfba55b2cc91d3b9c059907925f83a3d32-release-centos-x86_64.tar.gz",
 :generator
 (gen/timelimit 60 (gen/concat [(gen/on #{:nemesis} (gen/delayfn #object[clojure.core$partial$fn__5824 0x7e168d90 "clojure.core$partial$fn__5824@7e168d90"] (gen/mix [(gen/seqone ((gen/mix [{:type :info, :f :kill-tserver, :value nil}]) {:type :info, :f :start-tserver, :value nil} (gen/mix [{:type :info, :f :kill-tserver, :value nil}]) {:type :info, :f :start-tserver, :value nil} (gen/mix [{:type :info, :f :kill-tserver, :value nil}]) {:type :info, :f :start-tserver, :value nil} (gen/mix [{:type :info, :f :kill-tserver, :value nil}]) {:type :info, :f :start-tserver, :value nil}))]))) (gen/on #object[clojure.core$complement$fn__5654 0xcf0e8b4 "clojure.core$complement$fn__5654@cf0e8b4"] (gen/delayfn #object[clojure.core$partial$fn__5824 0x6a53cddc "clojure.core$partial$fn__5824@6a53cddc"] (gen/reserve [[0 10 (gen/seqone ({:type :invoke, :f :add, :value 0} {:type :invoke, :f :add, :value 1} {:type :invoke, :f :add, :value 2} {:type :invoke, :f :add, :value 3} {:type :invoke, :f :add, :value 4} {:type :invoke, :f :add, :value 5} {:type :invoke, :f :add, :value 6} {:type :invoke, :f :add, :value 7}))]] {:type :invoke, :f :read, :value nil})))])),
 :os
 #object[jepsen.os.debian.Debian 0x64864875 "jepsen.os.debian.Debian@64864875"],
 :time-limit 60,
 :yugabyte-ssh false,
 :version "1.1.10.0",
 :workload :ysql/set,
 :only-workloads-expected-to-pass true,
 :experimental-tuning-flags false}

INFO [2019-06-21 11:45:51,129] jepsen node n1 - jepsen.os.debian n1 setting up debian
INFO [2019-06-21 11:45:51,129] jepsen node n2 - jepsen.os.debian n2 setting up debian
INFO [2019-06-21 11:45:51,130] jepsen node n3 - jepsen.os.debian n3 setting up debian
INFO [2019-06-21 11:45:51,131] jepsen node n5 - jepsen.os.debian n5 setting up debian
INFO [2019-06-21 11:45:51,131] jepsen node n4 - jepsen.os.debian n4 setting up debian
INFO [2019-06-21 11:45:51,739] jepsen node n4 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 11:45:51,739] jepsen node n2 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 11:45:51,739] jepsen node n5 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 11:45:51,740] jepsen node n1 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 11:45:51,740] jepsen node n3 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 11:45:53,790] jepsen test runner - jepsen.db Tearing down DB
INFO [2019-06-21 11:45:53,791] jepsen node n1 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 11:45:53,791] jepsen node n2 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 11:45:53,791] jepsen node n3 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 11:45:53,791] jepsen node n4 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 11:45:53,792] jepsen node n5 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 11:45:53,994] jepsen node n1 - jepsen.control.util Stopping /home/yugabyte/bin/yb-master
INFO [2019-06-21 11:45:53,995] jepsen node n2 - jepsen.control.util Stopping /home/yugabyte/bin/yb-master
INFO [2019-06-21 11:45:53,995] jepsen node n3 - jepsen.control.util Stopping /home/yugabyte/bin/yb-master
INFO [2019-06-21 11:45:54,300] jepsen test runner - jepsen.db Setting up DB
INFO [2019-06-21 11:45:54,403] jepsen node n1 - yugabyte.auto Starting master and tserver for ysql API
INFO [2019-06-21 11:45:54,403] jepsen node n2 - yugabyte.auto Starting master and tserver for ysql API
INFO [2019-06-21 11:45:54,403] jepsen node n3 - yugabyte.auto Starting master and tserver for ysql API
INFO [2019-06-21 11:45:54,403] jepsen node n5 - yugabyte.auto Starting master and tserver for ysql API
INFO [2019-06-21 11:45:54,403] jepsen node n4 - yugabyte.auto Starting master and tserver for ysql API
INFO [2019-06-21 11:45:54,504] jepsen node n5 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 11:45:54,504] jepsen node n4 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 11:45:54,505] jepsen node n1 - jepsen.control.util starting yb-master
INFO [2019-06-21 11:45:54,505] jepsen node n2 - jepsen.control.util starting yb-master
INFO [2019-06-21 11:45:54,505] jepsen node n3 - jepsen.control.util starting yb-master
INFO [2019-06-21 11:45:55,009] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:55,109] jepsen node n4 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:55,110] jepsen node n3 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 11:45:55,110] jepsen node n1 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 11:45:55,210] jepsen node n2 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 11:45:55,514] jepsen node n1 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:55,515] jepsen node n3 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:55,615] jepsen node n2 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:56,211] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:56,311] jepsen node n4 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:56,716] jepsen node n1 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:56,717] jepsen node n3 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:56,817] jepsen node n2 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:57,413] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:57,513] jepsen node n4 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:57,918] jepsen node n1 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:57,918] jepsen node n3 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:58,018] jepsen node n2 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:58,515] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:58,714] jepsen node n4 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:59,120] jepsen node n3 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:59,120] jepsen node n1 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:59,220] jepsen node n2 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:59,717] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:45:59,916] jepsen node n4 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:46:00,322] jepsen node n1 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:46:00,322] jepsen node n3 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:46:00,422] jepsen node n2 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:46:00,919] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 11:46:02,120] jepsen test runner - jepsen.db Setting up primary n1
INFO [2019-06-21 11:46:02,121] jepsen test runner - jepsen.core Relative time begins now
INFO [2019-06-21 11:46:02,123] jepsen nemesis - jepsen.core Setting up nemesis
INFO [2019-06-21 11:46:02,123] jepsen worker 0 - jepsen.core Setting up worker 0
INFO [2019-06-21 11:46:02,123] jepsen worker 1 - jepsen.core Setting up worker 1
INFO [2019-06-21 11:46:02,123] jepsen worker 2 - jepsen.core Setting up worker 2
INFO [2019-06-21 11:46:02,123] jepsen worker 3 - jepsen.core Setting up worker 3
INFO [2019-06-21 11:46:02,123] jepsen worker 4 - jepsen.core Setting up worker 4
INFO [2019-06-21 11:46:02,124] jepsen worker 5 - jepsen.core Setting up worker 5
INFO [2019-06-21 11:46:02,124] jepsen worker 6 - jepsen.core Setting up worker 6
INFO [2019-06-21 11:46:02,127] jepsen worker 7 - jepsen.core Setting up worker 7
INFO [2019-06-21 11:46:02,129] jepsen worker 8 - jepsen.core Setting up worker 8
INFO [2019-06-21 11:46:02,129] jepsen worker 9 - jepsen.core Setting up worker 9
INFO [2019-06-21 11:46:02,129] jepsen worker 11 - jepsen.core Setting up worker 11
INFO [2019-06-21 11:46:02,130] jepsen worker 12 - jepsen.core Setting up worker 12
INFO [2019-06-21 11:46:02,130] jepsen worker 13 - jepsen.core Setting up worker 13
INFO [2019-06-21 11:46:02,131] jepsen worker 10 - jepsen.core Setting up worker 10
INFO [2019-06-21 11:46:02,132] jepsen worker 14 - jepsen.core Setting up worker 14
INFO [2019-06-21 11:46:02,133] jepsen worker 15 - jepsen.core Setting up worker 15
INFO [2019-06-21 11:46:02,133] jepsen worker 18 - jepsen.core Setting up worker 18
INFO [2019-06-21 11:46:02,133] jepsen worker 17 - jepsen.core Setting up worker 17
INFO [2019-06-21 11:46:02,134] jepsen worker 19 - jepsen.core Setting up worker 19
INFO [2019-06-21 11:46:02,135] jepsen worker 16 - jepsen.core Setting up worker 16
INFO [2019-06-21 11:46:11,935] jepsen nemesis - jepsen.core Running nemesis
INFO [2019-06-21 11:46:11,935] jepsen worker 0 - jepsen.core Running worker 0
INFO [2019-06-21 11:46:11,936] jepsen worker 2 - jepsen.core Running worker 2
INFO [2019-06-21 11:46:11,936] jepsen worker 1 - jepsen.core Running worker 1
INFO [2019-06-21 11:46:11,936] jepsen worker 3 - jepsen.core Running worker 3
INFO [2019-06-21 11:46:11,936] jepsen worker 4 - jepsen.core Running worker 4
INFO [2019-06-21 11:46:11,936] jepsen worker 5 - jepsen.core Running worker 5
INFO [2019-06-21 11:46:11,936] jepsen worker 6 - jepsen.core Running worker 6
INFO [2019-06-21 11:46:11,936] jepsen worker 7 - jepsen.core Running worker 7
INFO [2019-06-21 11:46:11,936] jepsen worker 8 - jepsen.core Running worker 8
INFO [2019-06-21 11:46:11,936] jepsen worker 9 - jepsen.core Running worker 9
INFO [2019-06-21 11:46:11,936] jepsen worker 10 - jepsen.core Running worker 10
INFO [2019-06-21 11:46:11,936] jepsen worker 11 - jepsen.core Running worker 11
INFO [2019-06-21 11:46:11,936] jepsen worker 12 - jepsen.core Running worker 12
INFO [2019-06-21 11:46:11,936] jepsen worker 13 - jepsen.core Running worker 13
INFO [2019-06-21 11:46:11,936] jepsen worker 15 - jepsen.core Running worker 15
INFO [2019-06-21 11:46:11,936] jepsen worker 14 - jepsen.core Running worker 14
INFO [2019-06-21 11:46:11,937] jepsen worker 16 - jepsen.core Running worker 16
INFO [2019-06-21 11:46:11,937] jepsen worker 17 - jepsen.core Running worker 17
INFO [2019-06-21 11:46:11,937] jepsen worker 18 - jepsen.core Running worker 18
INFO [2019-06-21 11:46:11,937] jepsen worker 19 - jepsen.core Running worker 19
INFO [2019-06-21 11:46:11,945] jepsen worker 14 - jepsen.util 14    :invoke :read   nil
WARN [2019-06-21 11:46:11,954] jepsen worker 14 - yugabyte.ysql.set Encountered error with conn "n5"; reopening
INFO [2019-06-21 11:46:11,956] jepsen worker 17 - jepsen.util 17    :invoke :read   nil
WARN [2019-06-21 11:46:11,964] jepsen worker 17 - yugabyte.ysql.set Encountered error with conn "n3"; reopening
INFO [2019-06-21 11:46:11,967] jepsen worker 5 - jepsen.util 5  :invoke :add    0
INFO [2019-06-21 11:46:11,977] jepsen worker 6 - jepsen.util 6  :invoke :add    1
INFO [2019-06-21 11:46:11,977] jepsen worker 16 - jepsen.util 16    :invoke :read   nil
WARN [2019-06-21 11:46:11,982] jepsen worker 5 - yugabyte.ysql.set Encountered error with conn "n1"; reopening
INFO [2019-06-21 11:46:11,983] jepsen worker 4 - jepsen.util 4  :invoke :add    2
WARN [2019-06-21 11:46:11,986] jepsen worker 16 - yugabyte.ysql.set Encountered error with conn "n2"; reopening
INFO [2019-06-21 11:46:11,987] jepsen worker 19 - jepsen.util 19    :invoke :read   nil
INFO [2019-06-21 11:46:11,991] jepsen worker 11 - jepsen.util 11    :invoke :read   nil
INFO [2019-06-21 11:46:11,995] jepsen worker 9 - jepsen.util 9  :invoke :add    3
WARN [2019-06-21 11:46:11,999] jepsen worker 19 - yugabyte.ysql.set Encountered error with conn "n5"; reopening
WARN [2019-06-21 11:46:11,999] jepsen worker 4 - yugabyte.ysql.set Encountered error with conn "n5"; reopening
WARN [2019-06-21 11:46:11,999] jepsen worker 6 - yugabyte.ysql.set Encountered error with conn "n2"; reopening
WARN [2019-06-21 11:46:12,006] jepsen worker 11 - yugabyte.ysql.set Encountered error with conn "n2"; reopening
INFO [2019-06-21 11:46:12,016] jepsen worker 1 - jepsen.util 1  :invoke :add    5
INFO [2019-06-21 11:46:12,016] jepsen worker 8 - jepsen.util 8  :invoke :add    4
INFO [2019-06-21 11:46:12,017] jepsen worker 7 - jepsen.util 7  :invoke :add    6
WARN [2019-06-21 11:46:12,032] jepsen worker 9 - yugabyte.ysql.set Encountered error with conn "n5"; reopening
WARN [2019-06-21 11:46:12,033] jepsen worker 7 - yugabyte.ysql.set Encountered error with conn "n3"; reopening
WARN [2019-06-21 11:46:12,041] jepsen worker 8 - yugabyte.ysql.set Encountered error with conn "n4"; reopening
INFO [2019-06-21 11:46:12,049] jepsen worker 14 - jepsen.util 14    :info   :read   nil [:psql-exception "ERROR: relation \"elements\" does not exist\n  Position: 17"]
WARN [2019-06-21 11:46:12,051] jepsen worker 1 - yugabyte.ysql.set Encountered error with conn "n2"; reopening
INFO [2019-06-21 11:46:12,054] jepsen worker 2 - jepsen.util 2  :invoke :add    7
INFO [2019-06-21 11:46:12,067] jepsen worker 17 - jepsen.util 17    :info   :read   nil [:psql-exception "ERROR: relation \"elements\" does not exist\n  Position: 17"]
...

YCQL:

Test  52 / 128
INFO [2019-06-21 12:27:12,580] jepsen test runner - jepsen.core Running test:
 {:trace-cql false,
 :replication-factor 3,
 :final-recovery-time 30,
 :api :ycql,
 :concurrency 20,
 :db
 #object[yugabyte.auto$community_edition$reify__3294 0x7ff70cf1 "yugabyte.auto$community_edition$reify__3294@7ff70cf1"],
 :name "yb 1.1.10.0 set-index nemesis pause-tserver",
 :start-time
 #object[org.joda.time.DateTime 0x4c8d9359 "2019-06-21T12:27:12.000Z"],
 :net
 #object[jepsen.net$reify__5190 0x3ba6707e "jepsen.net$reify__5190@3ba6707e"],
 :client {:conn nil, :keyspace-created #<Promise@15f3f9cf: true>},
 :barrier
 #object[java.util.concurrent.CyclicBarrier 0x32400c30 "java.util.concurrent.CyclicBarrier@32400c30"],
 :ssh
 {:username "root",
  :password "root",
  :strict-host-key-checking false,
  :private-key-path nil},
 :nemesis-long-recovery false,
 :checker
 #object[jepsen.checker$compose$reify__4748 0x10dea33e "jepsen.checker$compose$reify__4748@10dea33e"],
 :nemesis
 #object[jepsen.nemesis$compose$reify__5318 0x3f5f7e1d "jepsen.nemesis$compose$reify__5318@3f5f7e1d"],
 :active-histories #<Atom@6650679f: #{}>,
 :nodes ["n1" "n2" "n3" "n4" "n5"],
 :test-count 1,
 :url
 "http://10.150.0.10:8000/yugabyte-ce-1.2.11.0-358049cfba55b2cc91d3b9c059907925f83a3d32-release-centos-x86_64.tar.gz",
 :generator
 (gen/timelimit 60 (gen/concat [(gen/on #{:nemesis} (gen/delayfn #object[clojure.core$partial$fn__5824 0x61782dbd "clojure.core$partial$fn__5824@61782dbd"] (gen/mix [(gen/seqone ((gen/mix [{:type :info, :f :pause-tserver, :value nil}]) {:type :info, :f :resume-tserver, :value nil} (gen/mix [{:type :info, :f :pause-tserver, :value nil}]) {:type :info, :f :resume-tserver, :value nil} (gen/mix [{:type :info, :f :pause-tserver, :value nil}]) {:type :info, :f :resume-tserver, :value nil} (gen/mix [{:type :info, :f :pause-tserver, :value nil}]) {:type :info, :f :resume-tserver, :value nil}))]))) (gen/on #object[clojure.core$complement$fn__5654 0x20731f82 "clojure.core$complement$fn__5654@20731f82"] (gen/delayfn #object[clojure.core$partial$fn__5824 0x1306f49a "clojure.core$partial$fn__5824@1306f49a"] (gen/reserve [[0 10 (gen/seqone ({:type :invoke, :f :add, :value 0} {:type :invoke, :f :add, :value 1} {:type :invoke, :f :add, :value 2} {:type :invoke, :f :add, :value 3} {:type :invoke, :f :add, :value 4} {:type :invoke, :f :add, :value 5} {:type :invoke, :f :add, :value 6} {:type :invoke, :f :add, :value 7}))]] {:type :invoke, :f :read, :value nil})))])),
 :os
 #object[jepsen.os.debian.Debian 0x64864875 "jepsen.os.debian.Debian@64864875"],
 :time-limit 60,
 :yugabyte-ssh false,
 :version "1.1.10.0",
 :workload :ycql/set-index,
 :only-workloads-expected-to-pass true,
 :experimental-tuning-flags false}

INFO [2019-06-21 12:27:12,966] jepsen node n1 - jepsen.os.debian n1 setting up debian
INFO [2019-06-21 12:27:12,966] jepsen node n2 - jepsen.os.debian n2 setting up debian
INFO [2019-06-21 12:27:12,966] jepsen node n3 - jepsen.os.debian n3 setting up debian
INFO [2019-06-21 12:27:12,969] jepsen node n4 - jepsen.os.debian n4 setting up debian
INFO [2019-06-21 12:27:12,971] jepsen node n5 - jepsen.os.debian n5 setting up debian
ERROR [2019-06-21 12:27:12,985] cluster546-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
... (and a lot more of these)
INFO [2019-06-21 12:27:13,594] jepsen node n4 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 12:27:13,595] jepsen node n3 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 12:27:13,595] jepsen node n5 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 12:27:13,595] jepsen node n2 - jepsen.os.debian Installing #{libzip4}
INFO [2019-06-21 12:27:13,595] jepsen node n1 - jepsen.os.debian Installing #{libzip4}
ERROR [2019-06-21 12:27:13,988] cluster546-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
... (and a lot more of these)
WARN [2019-06-21 12:27:15,521] jepsen node n5 - jepsen.control Encountered error with conn [:control "n5"]; reopening
WARN [2019-06-21 12:27:15,544] jepsen node n3 - jepsen.control Encountered error with conn [:control "n3"]; reopening
INFO [2019-06-21 12:27:15,721] jepsen test runner - jepsen.db Tearing down DB
INFO [2019-06-21 12:27:15,722] jepsen node n1 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 12:27:15,722] jepsen node n2 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 12:27:15,722] jepsen node n3 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 12:27:15,722] jepsen node n5 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
INFO [2019-06-21 12:27:15,722] jepsen node n4 - jepsen.control.util Stopping /home/yugabyte/bin/yb-tserver
WARN [2019-06-21 12:27:15,782] jepsen node n4 - jepsen.control Encountered error with conn [:control "n4"]; reopening
INFO [2019-06-21 12:27:15,925] jepsen node n1 - jepsen.control.util Stopping /home/yugabyte/bin/yb-master
INFO [2019-06-21 12:27:15,925] jepsen node n2 - jepsen.control.util Stopping /home/yugabyte/bin/yb-master
INFO [2019-06-21 12:27:15,925] jepsen node n3 - jepsen.control.util Stopping /home/yugabyte/bin/yb-master
ERROR [2019-06-21 12:27:15,989] cluster546-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
... (and a lot more of these)
INFO [2019-06-21 12:27:17,698] jepsen test runner - jepsen.db Setting up DB
INFO [2019-06-21 12:27:17,801] jepsen node n1 - yugabyte.auto Starting master and tserver for ycql API
INFO [2019-06-21 12:27:17,801] jepsen node n5 - yugabyte.auto Starting master and tserver for ycql API
INFO [2019-06-21 12:27:17,801] jepsen node n3 - yugabyte.auto Starting master and tserver for ycql API
INFO [2019-06-21 12:27:17,801] jepsen node n4 - yugabyte.auto Starting master and tserver for ycql API
INFO [2019-06-21 12:27:17,801] jepsen node n2 - yugabyte.auto Starting master and tserver for ycql API
INFO [2019-06-21 12:27:17,902] jepsen node n4 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 12:27:17,902] jepsen node n2 - jepsen.control.util starting yb-master
INFO [2019-06-21 12:27:17,902] jepsen node n1 - jepsen.control.util starting yb-master
INFO [2019-06-21 12:27:17,902] jepsen node n5 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 12:27:17,903] jepsen node n3 - jepsen.control.util starting yb-master
ERROR [2019-06-21 12:27:17,990] cluster546-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
... (and a lot more of these)
INFO [2019-06-21 12:27:18,408] jepsen node n5 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 12:27:18,410] jepsen node n4 - yugabyte.auto Waiting for tservers to come online
INFO [2019-06-21 12:27:18,507] jepsen node n2 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 12:27:18,509] jepsen node n1 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 12:27:18,511] jepsen node n3 - jepsen.control.util starting yb-tserver
INFO [2019-06-21 12:27:18,910] jepsen node n2 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:18,912] jepsen node n1 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:18,914] jepsen node n3 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:18,930] jepsen node n1 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.11:9042 added
INFO [2019-06-21 12:27:18,930] jepsen node n1 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.12:9042 added
INFO [2019-06-21 12:27:18,930] jepsen node n1 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.13:9042 added
INFO [2019-06-21 12:27:18,932] jepsen node n2 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.11:9042 added
INFO [2019-06-21 12:27:18,933] jepsen node n2 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.12:9042 added
INFO [2019-06-21 12:27:18,933] jepsen node n2 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.13:9042 added
INFO [2019-06-21 12:27:18,937] jepsen node n3 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.11:9042 added
INFO [2019-06-21 12:27:18,937] jepsen node n3 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.12:9042 added
INFO [2019-06-21 12:27:18,937] jepsen node n3 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.13:9042 added
ERROR [2019-06-21 12:27:18,990] cluster498-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
... (and a lot more of these)
INFO [2019-06-21 12:27:19,016] cluster521-reconnection-0 - com.datastax.driver.core.Cluster Cassandra host /192.168.122.14:9042 removed
INFO [2019-06-21 12:27:19,018] cluster521-reconnection-0 - com.datastax.driver.core.Cluster Cassandra host /192.168.122.15:9042 removed
INFO [2019-06-21 12:27:19,019] cluster466-reconnection-1 - com.datastax.driver.core.Cluster Cassandra host /192.168.122.14:9042 removed
ERROR [2019-06-21 12:27:19,020] cluster392-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
INFO [2019-06-21 12:27:19,021] cluster466-reconnection-1 - com.datastax.driver.core.Cluster Cassandra host /192.168.122.15:9042 removed
ERROR [2019-06-21 12:27:19,027] cluster447-reconnection-0 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
ERROR [2019-06-21 12:27:19,029] cluster469-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
INFO [2019-06-21 12:27:19,610] jepsen node n5 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:19,611] jepsen node n4 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:19,625] jepsen node n5 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.11:9042 added
...
INFO [2019-06-21 12:27:19,676] jepsen node n2 - yugabyte.ycql.client Cluster ready
INFO [2019-06-21 12:27:19,685] jepsen node n4 - yugabyte.ycql.client Cluster ready
INFO [2019-06-21 12:27:19,694] jepsen node n5 - yugabyte.ycql.client Cluster ready
INFO [2019-06-21 12:27:19,703] jepsen node n3 - yugabyte.ycql.client Cluster ready
INFO [2019-06-21 12:27:19,712] jepsen node n1 - yugabyte.ycql.client Cluster ready
ERROR [2019-06-21 12:27:19,992] cluster658-reconnection-0 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
ERROR [2019-06-21 12:27:19,992] cluster370-reconnection-1 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
...
INFO [2019-06-21 12:27:21,915] jepsen test runner - jepsen.db Setting up primary n1
INFO [2019-06-21 12:27:21,916] jepsen test runner - jepsen.core Relative time begins now
INFO [2019-06-21 12:27:21,918] jepsen nemesis - jepsen.core Setting up nemesis
INFO [2019-06-21 12:27:21,918] jepsen worker 0 - jepsen.core Setting up worker 0
INFO [2019-06-21 12:27:21,918] jepsen worker 0 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:21,918] jepsen worker 1 - jepsen.core Setting up worker 1
INFO [2019-06-21 12:27:21,918] jepsen worker 2 - jepsen.core Setting up worker 2
INFO [2019-06-21 12:27:21,918] jepsen worker 3 - jepsen.core Setting up worker 3
INFO [2019-06-21 12:27:21,918] jepsen worker 1 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:21,918] jepsen worker 6 - jepsen.core Setting up worker 6
INFO [2019-06-21 12:27:21,918] jepsen worker 5 - jepsen.core Setting up worker 5
INFO [2019-06-21 12:27:21,918] jepsen worker 4 - jepsen.core Setting up worker 4
INFO [2019-06-21 12:27:21,918] jepsen worker 7 - jepsen.core Setting up worker 7
INFO [2019-06-21 12:27:21,918] jepsen worker 9 - jepsen.core Setting up worker 9
INFO [2019-06-21 12:27:21,918] jepsen worker 10 - jepsen.core Setting up worker 10
INFO [2019-06-21 12:27:21,918] jepsen worker 8 - jepsen.core Setting up worker 8
INFO [2019-06-21 12:27:21,919] jepsen worker 11 - jepsen.core Setting up worker 11
INFO [2019-06-21 12:27:21,919] jepsen worker 12 - jepsen.core Setting up worker 12
INFO [2019-06-21 12:27:21,919] jepsen worker 13 - jepsen.core Setting up worker 13
INFO [2019-06-21 12:27:21,919] jepsen worker 14 - jepsen.core Setting up worker 14
INFO [2019-06-21 12:27:21,919] jepsen worker 15 - jepsen.core Setting up worker 15
INFO [2019-06-21 12:27:21,919] jepsen worker 16 - jepsen.core Setting up worker 16
INFO [2019-06-21 12:27:21,919] jepsen worker 3 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:21,919] jepsen worker 2 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
INFO [2019-06-21 12:27:21,919] jepsen worker 17 - jepsen.core Setting up worker 17
INFO [2019-06-21 12:27:21,919] jepsen worker 18 - jepsen.core Setting up worker 18
INFO [2019-06-21 12:27:21,919] jepsen worker 19 - jepsen.core Setting up worker 19
INFO [2019-06-21 12:27:21,919] jepsen worker 6 - com.datastax.driver.core.ClockFactory Using native clock to generate timestamps.
...
INFO [2019-06-21 12:27:21,944] jepsen worker 2 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.11:9042 added
...
WARN [2019-06-21 12:27:21,965] jepsen node n2 - jepsen.control Encountered error with conn [:control "n2"]; reopening
...
INFO [2019-06-21 12:27:21,966] jepsen worker 12 - com.datastax.driver.core.Cluster New Cassandra host /192.168.122.11:9042 added
...
ERROR [2019-06-21 12:27:21,980] cluster699-reconnection-0 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
WARN [2019-06-21 12:27:21,986] cluster699-nio-worker-0 - com.datastax.driver.core.Session Error creating pool to /192.168.122.15:9042
com.datastax.driver.core.exceptions.ConnectionException: [/192.168.122.15:9042] Pool was closed during initialization
    at com.datastax.driver.core.HostConnectionPool$2.onSuccess(HostConnectionPool.java:148) [cassandra-driver-core-3.2.0-yb-19.jar:na]
    at com.datastax.driver.core.HostConnectionPool$2.onSuccess(HostConnectionPool.java:134) [cassandra-driver-core-3.2.0-yb-19.jar:na]
    at com.google.common.util.concurrent.Futures$6.run(Futures.java:1773) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:613) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.CollectionFuture$CollectionFutureRunningState.handleAllCompleted(CollectionFuture.java:76) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AggregateFuture$RunningState.processCompleted(AggregateFuture.java:255) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AggregateFuture$RunningState.decrementCountAndMaybeComplete(AggregateFuture.java:242) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AggregateFuture$RunningState.access$300(AggregateFuture.java:91) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AggregateFuture$RunningState$1.run(AggregateFuture.java:146) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.completeWithFuture(AbstractFuture.java:730) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.setFuture(AbstractFuture.java:666) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AsyncCatchingFuture.doFallback(Futures.java:826) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AsyncCatchingFuture.doFallback(Futures.java:813) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AbstractCatchingFuture.run(Futures.java:789) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.completeWithFuture(AbstractFuture.java:730) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.setFuture(AbstractFuture.java:666) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AsyncCatchingFuture.doFallback(Futures.java:826) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AsyncCatchingFuture.doFallback(Futures.java:813) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AbstractCatchingFuture.run(Futures.java:789) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.Futures$AbstractChainingFuture.run(Futures.java:1405) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:456) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:817) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:753) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:634) [guava-19.0.jar:na]
    at com.google.common.util.concurrent.SettableFuture.setException(SettableFuture.java:53) [guava-19.0.jar:na]
    at com.datastax.driver.core.Connection$1.operationComplete(Connection.java:179) [cassandra-driver-core-3.2.0-yb-19.jar:na]
    at com.datastax.driver.core.Connection$1.operationComplete(Connection.java:162) [cassandra-driver-core-3.2.0-yb-19.jar:na]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:122) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.connect(AbstractNioChannel.java:241) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.connect(DefaultChannelPipeline.java:1226) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeConnect(AbstractChannelHandlerContext.java:540) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:525) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.ChannelOutboundHandlerAdapter.connect(ChannelOutboundHandlerAdapter.java:47) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeConnect(AbstractChannelHandlerContext.java:540) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:525) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.ChannelOutboundHandlerAdapter.connect(ChannelOutboundHandlerAdapter.java:47) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeConnect(AbstractChannelHandlerContext.java:540) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:525) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.ChannelDuplexHandler.connect(ChannelDuplexHandler.java:50) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeConnect(AbstractChannelHandlerContext.java:540) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:525) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:507) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.DefaultChannelPipeline.connect(DefaultChannelPipeline.java:970) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.AbstractChannel.connect(AbstractChannel.java:215) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.bootstrap.Bootstrap$2.run(Bootstrap.java:166) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:399) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:446) [netty-transport-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144) [netty-common-4.0.44.Final.jar:4.0.44.Final]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
INFO [2019-06-21 12:27:22,001] jepsen worker 10 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,001] jepsen worker 6 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,001] jepsen worker 3 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,002] jepsen worker 19 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,003] jepsen worker 17 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,004] jepsen worker 9 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,004] jepsen worker 4 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,005] jepsen worker 16 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,005] jepsen worker 15 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,006] jepsen worker 13 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,006] jepsen worker 7 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,006] jepsen worker 8 - yugabyte.ycql.client Timed out, retrying
INFO [2019-06-21 12:27:22,009] jepsen worker 18 - yugabyte.ycql.client Timed out, retrying
ERROR [2019-06-21 12:27:22,980] cluster699-reconnection-0 - com.datastax.driver.core.ControlConnection [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
INFO [2019-06-21 12:27:32,067] jepsen nemesis - jepsen.core Tearing down nemesis
INFO [2019-06-21 12:27:32,067] jepsen worker 0 - jepsen.core Tearing down worker 0
INFO [2019-06-21 12:27:32,068] jepsen worker 3 - jepsen.core Tearing down worker 3
INFO [2019-06-21 12:27:32,068] jepsen worker 2 - jepsen.core Tearing down worker 2
INFO [2019-06-21 12:27:32,068] jepsen worker 1 - jepsen.core Tearing down worker 1
INFO [2019-06-21 12:27:32,069] jepsen worker 5 - jepsen.core Tearing down worker 5
INFO [2019-06-21 12:27:32,069] jepsen worker 4 - jepsen.core Tearing down worker 4
INFO [2019-06-21 12:27:32,069] jepsen worker 13 - jepsen.core Tearing down worker 13
INFO [2019-06-21 12:27:32,069] jepsen worker 6 - jepsen.core Tearing down worker 6
INFO [2019-06-21 12:27:32,069] jepsen worker 7 - jepsen.core Tearing down worker 7
INFO [2019-06-21 12:27:32,069] jepsen worker 10 - jepsen.core Tearing down worker 10
INFO [2019-06-21 12:27:32,069] jepsen worker 9 - jepsen.core Tearing down worker 9
INFO [2019-06-21 12:27:32,069] jepsen worker 14 - jepsen.core Tearing down worker 14
INFO [2019-06-21 12:27:32,069] jepsen worker 16 - jepsen.core Tearing down worker 16
INFO [2019-06-21 12:27:32,069] jepsen worker 15 - jepsen.core Tearing down worker 15
INFO [2019-06-21 12:27:32,069] jepsen worker 18 - jepsen.core Tearing down worker 18
INFO [2019-06-21 12:27:32,069] jepsen worker 17 - jepsen.core Tearing down worker 17
INFO [2019-06-21 12:27:32,069] jepsen worker 8 - jepsen.core Tearing down worker 8
INFO [2019-06-21 12:27:32,069] jepsen worker 11 - jepsen.core Tearing down worker 11
INFO [2019-06-21 12:27:32,069] jepsen worker 12 - jepsen.core Tearing down worker 12
INFO [2019-06-21 12:27:32,069] jepsen worker 19 - jepsen.core Tearing down worker 19
INFO [2019-06-21 12:27:32,070] jepsen test runner - jepsen.core Snarfing log files
frozenspider commented 5 years ago

Note this part for YSQL

 :name "yb 1.1.10.0 set nemesis kill-tserver",
 ...
 :client
 {:conn-wrapper nil,
  :inner-client {},
  :setup? #<Atom@1cd853ee: true>,
  :teardown? #<Atom@57330423: true>},

These setup? and teardown? atomics represent a state of stateful clients, which are initialized to failse upon construction. Clients aren't supposed to be reused, but it appears that they were.

frozenspider commented 5 years ago

The problem was caused by the fact that clients were lazily evaluated once and then reused upon subsequent test - but the clients were stateful so they weren't intended to. Fixed by making client constructor to be re-evaluated every time.