search

scylladb / scylladb

NoSQL data store using the seastar framework, compatible with Apache Cassandra
http://scylladb.com
GNU Affero General Public License v3.0
13.58k stars 1.29k forks source link

Missing key in cassandra-harry verification while doing rolling restart of the cluster #10598

Closed fruch closed 12 months ago

fruch commented 2 years ago

Installation details

Kernel Version: 5.13.0-1021-aws Scylla version (or git commit hash): 5.0~rc3-20220406.f92622e0d with build-id 2b79c4744216b294fdbd2f277940044c899156ea Cluster size: 6 nodes (i3.large)

Scylla Nodes used in this run:

OS / Image: ami-0e4ae5e4a139c50f3 (aws: eu-north-1)

Test: longevity-harry-2h-test Test id: 5ad966f5-8ded-437d-9224-7601b95777f1 Test name: scylla-staging/fruch/longevity-harry-2h-test Test config file(s):

Issue description

During RollingRestartCluster, cassandra-harry fail in it's verification find only 19 key out of 134 expected ones. It's doing the query six times, and in all of them get the same results

This is the query, a prepare statment that runs with ConsistencyLevel.QUORUM:

SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? ORDER BY ck0000 DESC, ck0001 DESC;

Form cassandra-harry log, Partition state is the expected result, Observed state is the result from the query (notice that the expected is in reverse order then the observed)

java.lang.RuntimeException: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Expected results to have the same number of results, but expected result iterator has more results.

Partition state:
...
133 lines like the following
...
RowState{cd=9101507508570737439, vds=[216457386, -9223372036854775808, 2148363779, -9223372036854775808], lts=[2379820, -9223372036854775808, 2379820, -9223372036854775808], clustering=[1092247935856, 2.1378701E-38], values=[216457386, null, -2146603517, null]}

Observed state:
resultSetRow(2952445832411809646L, 9101507508570737439L, staticValues(13953956969167411L,185L,31129L,215L,148L), slts(2379990L,2379990L,2379990L,2379990L,2379990L), values(216457386L,-9223372036854775808L,2148363779L,-9223372036854775808L), lts(2379820L,-9223372036854775808L,2379820L,-9223372036854775808L), clustering=[1092247935856, 2.1378701E-38], values=[216457386, null, -2146603517, null], statics=[9.77609217999303E-308, -71, 31129, -41, -108])
...
18 lines like that

With nemesis running this is happens 3/4 time it run

On steady state, with nemesis cassandra-harry finish with success, on 5.0.rc3

On master we are facing a coredump without nemesis, so we can't compare (#10553)

Logs:

Jenkins job URL

fruch commented 2 years ago

More times it happened:

Installation details

Kernel Version: 5.13.0-1021-aws Scylla version (or git commit hash): 5.0~rc3-20220406.f92622e0d with build-id 2b79c4744216b294fdbd2f277940044c899156ea Cluster size: 6 nodes (i3.large) OS / Image: ami-0e4ae5e4a139c50f3 (aws: eu-north-1)

Test: longevity-harry-2h-test Test id: a4bdcc57-c0d5-4e25-8ab7-56a32f1d6a40

Logs:

Jenkins job URL

slivne commented 2 years ago

Can we try and run this on 4.6 - to see if this is a regression

slivne commented 2 years ago

@fruch ^^

slivne commented 2 years ago

@eliransin try to find someone that can help look at this

fruch commented 2 years ago

@slivne @eliransin

Happens also on 4.6.3, so it's no regression:

Kernel Version: 5.11.0-1022-aws Scylla version (or git commit hash): 4.6.3-20220414.8bf149fdd with build-id 8d16d8972498cc769071ff25309b009eb77bf77a Cluster size: 6 nodes (i3.large)

OS / Image: ami-010abbe835b052d37 (aws: eu-north-1)

Test: longevity-harry-2h-test Test id: fc555304-c2e8-4e9d-8c0c-9d0e8f37260d Test name: scylla-staging/fruch/longevity-harry-2h-test Test config file(s):

Logs:

Jenkins job URL

soyacz commented 2 years ago

The same happened during destroy_data_then_repair disruption. More test details:

Installation details

Kernel Version: 5.13.0-1025-aws Scylla version (or git commit hash): 5.0~rc6-20220523.338edcc02 with build-id 60217f35371db2b1283e0c5bc67a7f5604768d41 Cluster size: 6 nodes (i3.large)

Scylla Nodes used in this run:

OS / Image: ami-07b5745a1e6de34ce (aws: eu-west-1)

Test: longevity-harry-2h-test Test id: 73b768fb-6b82-4e6e-ba97-408f305b5b1b Test name: scylla-5.0/longevity/longevity-harry-2h-test Test config file(s):

Logs:

Jenkins job URL

roydahan commented 2 years ago

@eliransin will someone look at it? I'm setting the high lable since otherwise no one will ever fix it. And if no one is going to fix it, we can just stop running the test.

eliransin commented 2 years ago

@roydahan does it happen all the time. Can I have a reproducer job so I can debug? Did we or can we run it against Cassandra to eliminate a bug it cassandra-harry? if the same failure occure in cassandra, this would mean one of the two:

  1. Bug in cassandra-harry
  2. Bug in cassandra HL design which we replicated (at least to some extent) - I think this is unlikely.
fruch commented 2 years ago

@roydahan does it happen all the time. Can I have a reproducer job so I can debug?

you can use https://jenkins.scylladb.com/view/master/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/, it a 2.5h run.

Did we or can we run it against Cassandra to eliminate a bug it cassandra-harry?

we don't have SCT setup to run Cassandra with our nemesis

if the same failure occure in cassandra, this would mean one of the two:

  1. Bug in cassandra-harry
  2. Bug in cassandra HL design which we replicated (at least to some extent) - I think this is unlikely.

Again, just to add, in steadily state, without restarting nodes, cassandra-harry verification is working correctly. So we can only look at the querying the tool is doing, and see that it's doing inserts, and then scans of the last 100 item it's inserted, and compares that to what's it has in memory (very similar to Gemini, but without an oracle)

eliransin commented 2 years ago

Where is the cassandra-harry log (on which tar file?)

fruch commented 2 years ago

Where is the cassandra-harry log (on which tar file?)

in the loader-set

DoronArazii commented 2 years ago

@eliransin are we planning to fix this for 5.1?

eliransin commented 2 years ago

I am not sure we will have the bandwidth for it for 5.1

DoronArazii commented 2 years ago

Pushing to 5.2 as we don't have the bandwidth to deal with it now. Per @fruch it is not a regression

/Cc @roydahan @slivne

DoronArazii commented 1 year ago

Pushed as a waterfall from version to version. Dropping this case to the large backlog (5.x) until we will have a commitment for that.

/Cc @eliransin @mykaul

dorlaor commented 1 year ago

The problem is important enough we'll analyze and solve it. Just pushing it to more versions is useless. First QA need to analyze this, it's not enough to report a bug, there is a chance the test isn't good enough - let's see that the test accounts write acknowledgements an there are no timeouts in the write/read. Should be done by the code analysis (I think that c-s ignores errors/timeouts and doesn't retry) and looking at the logs

fruch commented 1 year ago

The problem is important enough we'll analyze and solve it. Just pushing it to more versions is useless. First QA need to analyze this, it's not enough to report a bug, there is a chance the test isn't good enough - let's see that the test accounts write acknowledgements an there are no timeouts in the write/read. Should be done by the code analysis (I think that c-s ignores errors/timeouts and doesn't retry) and looking at the logs

This isn't cassandra-stress, it didn't see any code path that should be ignoring errors or timeouts, it has a crude retry of 10 times. One could have a look at the monitor data to see if there were write/read errors (I don't recall we've seen such)

I don't know which more analysis we can do in this case, exactly the reason why we open such an issue, to continue the discussion.

If the answer is it's not important enough and no one has time to help, 🤷‍♂️

dorlaor commented 1 year ago

If all possible errors are logged and there is nothing in the log, you need to pass it to R&D. If it's not the case, keep on digging and modify the test.

This is important enough to invest in

On Tue, Jan 24, 2023 at 9:20 PM Israel Fruchter @.***> wrote:

The problem is important enough we'll analyze and solve it. Just pushing it to more versions is useless. First QA need to analyze this, it's not enough to report a bug, there is a chance the test isn't good enough - let's see that the test accounts write acknowledgements an there are no timeouts in the write/read. Should be done by the code analysis (I think that c-s ignores errors/timeouts and doesn't retry) and looking at the logs

This isn't cassandra-stress, it didn't see any code path that should be ignoring errors or timeouts, it has a crude retry of 10 times. One could have a look at the monitor data to see if there were write/read errors (I don't recall we've seen such)

I don't know which more analysis we can do in this case, exactly the reason why we open such an issue, to continue the discussion.

If the answer is it's not important enough and no one has time to help, 🤷‍♂️

— Reply to this email directly, view it on GitHub https://github.com/scylladb/scylladb/issues/10598#issuecomment-1402468274, or unsubscribe https://github.com/notifications/unsubscribe-auth/AANHURP5M5QVUZ6AANB7YULWUATQTANCNFSM5WHJ5KZA . You are receiving this because you commented.Message ID: @.***>

enaydanov commented 1 year ago

Got it again in 2023.1.0-rc2

Installation details

Kernel Version: 5.15.0-1031-aws Scylla version (or git commit hash): 2023.1.0~rc2-20230302.726f8a090337 with build-id efcc950cda22875aa488c5295c6cc68f35d9cc6f

Cluster size: 6 nodes (i3.large)

Scylla Nodes used in this run:

OS / Image: ami-0336a5a646b08dc25 (aws: eu-west-1)

Test: longevity-harry-2h-test Test id: 10a155f9-f3c2-4e45-b516-51ee8d98edcf Test name: enterprise-2023.1/longevity/longevity-harry-2h-test Test config file(s):

Logs and commands ``` ... < t:2023-03-02 22:39:35,728 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > ERROR 22:39:35 Execution failed! < t:2023-03-02 22:39:35,728 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > java.lang.RuntimeException: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset: < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Expected: RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Actual: resultSetRow(-312204954194982442L, -4445887274093701454L, values(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), lts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L)) < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 < ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=2074792767L,"ZHHyABdiABdiABdiABdiABdibOQJErRC227232222242401992261652502182002497211145237223559401352342038446114203381021391391252171414312651087315986123227165834815329259826233731861469021314541363289272523981051121621131311371853621510715214820512420114948214871116129132230106830205204391066717093125492586244239143715915222728838836459205983381217106163932091621627653761242282012207716315228178249118241565493811444278161878517901091801459817020624598137231238316616013322198261541211079682862291851742061872261201964372250671392019011321165762554941783219121124203164443370331425020174","ZHHyABdiABdiABdiABdiABdiMmxIrHJa402504117874401112617217816717211821521525285209239212617575732187137741427390751791901037723724363991001045895774223176572152421981310118513419173861312092990255145112061707015310723207163251221151871032211631502101752119474111151342465718895627715318851821061561471871031862361072464023119129151102091789228161103186108160421971891666917258842161114197227255443613021018610016613112316444111513124915549214412124217235702392301949834242093918469924134153189214281238076",300589051948L} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Partition state: < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Static row: RowState{cd=static, vds=[-9223372036854775808, 250, -9223372036854775808, 228, 241], lts=[-9223372036854775808, 2809992, -9223372036854775808, 2809982, 2809992], clustering=static, values=[null, -6, null, -28, -15]} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-9190871138611796997, vds=[-9223372036854775808, -9223372036854775808, 1220311521, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809942, -9223372036854775808], clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null]} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-8182246842348799055, vds=[169275034, -9223372036854775808, 2726525259, -9223372036854775808], lts=[2809942, -9223372036854775808, 2809942, -9223372036854775808], clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null]} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-7573753742675275085, vds=[-9223372036854775808, -9223372036854775808, 539423093, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809992, -9223372036854775808], clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null]} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6761072511231364841, vds=[3653646284, 19556, 2583407908, 14303535], lts=[2809922, 2809922, 2809922, 2809922], clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38]} < t:2023-03-02 22:39:35,729 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6755184332854527549, vds=[1514729027, 22507, 1375948190, 4674618], lts=[2809942, 2809942, 2809942, 2809942], clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6579675572465669320, vds=[3346598222, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809982, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6348878881990124215, vds=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2592895], lts=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2809982], clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6090827227009693323, vds=[-9223372036854775808, 18853, 1939790280, 9673696], lts=[-9223372036854775808, 2809952, 2809952, 2809952], clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5460187383243502911, vds=[1730736368, -9223372036854775808, -9223372036854775808, 15717141], lts=[2809912, -9223372036854775808, -9223372036854775808, 2809912], clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5360066345574909300, vds=[1711535784, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809962, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Observed state: < t:2023-03-02 22:39:35,730 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4445887274093701454L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L), clustering=[284760282204, 5.059094E-39], values=[null, null, null, 1.532721E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4659417242173934802L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1278521867L,-9223372036854775808L,3886783250L,10198772L), lts(2809992L,-9223372036854775808L,2809992L,2809992L), clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5360066345574909300L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1711535784L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809962L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5460187383243502911L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1730736368L,-9223372036854775808L,-9223372036854775808L,15717141L), lts(2809912L,-9223372036854775808L,-9223372036854775808L,2809912L), clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6090827227009693323L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,18853L,1939790280L,9673696L), lts(-9223372036854775808L,2809952L,2809952L,2809952L), clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6348878881990124215L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2592895L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809982L), clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6579675572465669320L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3346598222L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809982L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6755184332854527549L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1514729027L,22507L,1375948190L,4674618L), lts(2809942L,2809942L,2809942L,2809942L), clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6761072511231364841L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3653646284L,19556L,2583407908L,14303535L), lts(2809922L,2809922L,2809922L,2809922L), clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -7573753742675275085L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,539423093L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809992L,-9223372036854775808L), clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,731 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -8182246842348799055L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(169275034L,-9223372036854775808L,2726525259L,-9223372036854775808L), lts(2809942L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -9190871138611796997L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,1220311521L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelValidator.visit(ParallelValidator.java:102) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.runner.Runner$SequentialRunner.run(Runner.java:319) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.runner.Runner$SequentialRunner.lambda$start$3(Runner.java:305) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.runner.Runner.lambda$reportThrowable$1(Runner.java:154) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.lang.Thread.run(Thread.java:829) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Caused by: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset: < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Expected: RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Actual: resultSetRow(-312204954194982442L, -4445887274093701454L, values(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), lts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L)) < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 < ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=2074792767L,"ZHHyABdiABdiABdiABdiABdibOQJErRC227232222242401992261652502182002497211145237223559401352342038446114203381021391391252171414312651087315986123227165834815329259826233731861469021314541363289272523981051121621131311371853621510715214820512420114948214871116129132230106830205204391066717093125492586244239143715915222728838836459205983381217106163932091621627653761242282012207716315228178249118241565493811444278161878517901091801459817020624598137231238316616013322198261541211079682862291851742061872261201964372250671392019011321165762554941783219121124203164443370331425020174","ZHHyABdiABdiABdiABdiABdiMmxIrHJa402504117874401112617217816717211821521525285209239212617575732187137741427390751791901037723724363991001045895774223176572152421981310118513419173861312092990255145112061707015310723207163251221151871032211631502101752119474111151342465718895627715318851821061561471871031862361072464023119129151102091789228161103186108160421971891666917258842161114197227255443613021018610016613112316444111513124915549214412124217235702392301949834242093918469924134153189214281238076",300589051948L} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Partition state: < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Static row: RowState{cd=static, vds=[-9223372036854775808, 250, -9223372036854775808, 228, 241], lts=[-9223372036854775808, 2809992, -9223372036854775808, 2809982, 2809992], clustering=static, values=[null, -6, null, -28, -15]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-9190871138611796997, vds=[-9223372036854775808, -9223372036854775808, 1220311521, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809942, -9223372036854775808], clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-8182246842348799055, vds=[169275034, -9223372036854775808, 2726525259, -9223372036854775808], lts=[2809942, -9223372036854775808, 2809942, -9223372036854775808], clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-7573753742675275085, vds=[-9223372036854775808, -9223372036854775808, 539423093, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809992, -9223372036854775808], clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6761072511231364841, vds=[3653646284, 19556, 2583407908, 14303535], lts=[2809922, 2809922, 2809922, 2809922], clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6755184332854527549, vds=[1514729027, 22507, 1375948190, 4674618], lts=[2809942, 2809942, 2809942, 2809942], clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6579675572465669320, vds=[3346598222, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809982, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6348878881990124215, vds=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2592895], lts=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2809982], clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6090827227009693323, vds=[-9223372036854775808, 18853, 1939790280, 9673696], lts=[-9223372036854775808, 2809952, 2809952, 2809952], clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5460187383243502911, vds=[1730736368, -9223372036854775808, -9223372036854775808, 15717141], lts=[2809912, -9223372036854775808, -9223372036854775808, 2809912], clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5360066345574909300, vds=[1711535784, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809962, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,732 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Observed state: < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4445887274093701454L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L), clustering=[284760282204, 5.059094E-39], values=[null, null, null, 1.532721E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4659417242173934802L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1278521867L,-9223372036854775808L,3886783250L,10198772L), lts(2809992L,-9223372036854775808L,2809992L,2809992L), clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5360066345574909300L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1711535784L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809962L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5460187383243502911L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1730736368L,-9223372036854775808L,-9223372036854775808L,15717141L), lts(2809912L,-9223372036854775808L,-9223372036854775808L,2809912L), clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6090827227009693323L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,18853L,1939790280L,9673696L), lts(-9223372036854775808L,2809952L,2809952L,2809952L), clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6348878881990124215L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2592895L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809982L), clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6579675572465669320L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3346598222L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809982L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6755184332854527549L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1514729027L,22507L,1375948190L,4674618L), lts(2809942L,2809942L,2809942L,2809942L), clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6761072511231364841L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3653646284L,19556L,2583407908L,14303535L), lts(2809922L,2809922L,2809922L,2809922L), clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -7573753742675275085L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,539423093L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809992L,-9223372036854775808L), clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -8182246842348799055L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(169275034L,-9223372036854775808L,2726525259L,-9223372036854775808L), lts(2809942L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -9190871138611796997L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,1220311521L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,733 f:db_log_reader.py l:113 c:sdcm.db_log_reader p:DEBUG > 2023-03-02T22:39:35+00:00 longevity-harry-2h-2023-1-db-node-10a155f9-1 !INFO | scylla-jmx[14837]: Connecting to http://127.0.0.1:10000 < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelValidator.visit(ParallelValidator.java:98) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > ... 9 common frames omitted < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Caused by: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset: < t:2023-03-02 22:39:35,733 f:db_log_reader.py l:113 c:sdcm.db_log_reader p:DEBUG > 2023-03-02T22:39:35+00:00 longevity-harry-2h-2023-1-db-node-10a155f9-1 !INFO | scylla-jmx[14837]: Starting the JMX server < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Expected: RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Actual: resultSetRow(-312204954194982442L, -4445887274093701454L, values(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), lts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L)) < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 < ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=2074792767L,"ZHHyABdiABdiABdiABdiABdibOQJErRC227232222242401992261652502182002497211145237223559401352342038446114203381021391391252171414312651087315986123227165834815329259826233731861469021314541363289272523981051121621131311371853621510715214820512420114948214871116129132230106830205204391066717093125492586244239143715915222728838836459205983381217106163932091621627653761242282012207716315228178249118241565493811444278161878517901091801459817020624598137231238316616013322198261541211079682862291851742061872261201964372250671392019011321165762554941783219121124203164443370331425020174","ZHHyABdiABdiABdiABdiABdiMmxIrHJa402504117874401112617217816717211821521525285209239212617575732187137741427390751791901037723724363991001045895774223176572152421981310118513419173861312092990255145112061707015310723207163251221151871032211631502101752119474111151342465718895627715318851821061561471871031862361072464023119129151102091789228161103186108160421971891666917258842161114197227255443613021018610016613112316444111513124915549214412124217235702392301949834242093918469924134153189214281238076",300589051948L} < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Partition state: < t:2023-03-02 22:39:35,733 f:events_processes.py l:147 c:sdcm.sct_events.events_processes p:DEBUG > Get process `MainDevice' from EventsProcessesRegistry[lod_dir=/home/ubuntu/sct-results/20230302-203720-413967,id=0x7f2b5b58ca90,default=True] < t:2023-03-02 22:39:35,733 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Static row: RowState{cd=static, vds=[-9223372036854775808, 250, -9223372036854775808, 228, 241], lts=[-9223372036854775808, 2809992, -9223372036854775808, 2809982, 2809992], clustering=static, values=[null, -6, null, -28, -15]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-9190871138611796997, vds=[-9223372036854775808, -9223372036854775808, 1220311521, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809942, -9223372036854775808], clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-8182246842348799055, vds=[169275034, -9223372036854775808, 2726525259, -9223372036854775808], lts=[2809942, -9223372036854775808, 2809942, -9223372036854775808], clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-7573753742675275085, vds=[-9223372036854775808, -9223372036854775808, 539423093, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809992, -9223372036854775808], clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6761072511231364841, vds=[3653646284, 19556, 2583407908, 14303535], lts=[2809922, 2809922, 2809922, 2809922], clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6755184332854527549, vds=[1514729027, 22507, 1375948190, 4674618], lts=[2809942, 2809942, 2809942, 2809942], clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6579675572465669320, vds=[3346598222, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809982, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6348878881990124215, vds=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2592895], lts=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2809982], clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6090827227009693323, vds=[-9223372036854775808, 18853, 1939790280, 9673696], lts=[-9223372036854775808, 2809952, 2809952, 2809952], clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5460187383243502911, vds=[1730736368, -9223372036854775808, -9223372036854775808, 15717141], lts=[2809912, -9223372036854775808, -9223372036854775808, 2809912], clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5360066345574909300, vds=[1711535784, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809962, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,734 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Observed state: < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4445887274093701454L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L), clustering=[284760282204, 5.059094E-39], values=[null, null, null, 1.532721E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4659417242173934802L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1278521867L,-9223372036854775808L,3886783250L,10198772L), lts(2809992L,-9223372036854775808L,2809992L,2809992L), clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5360066345574909300L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1711535784L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809962L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5460187383243502911L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1730736368L,-9223372036854775808L,-9223372036854775808L,15717141L), lts(2809912L,-9223372036854775808L,-9223372036854775808L,2809912L), clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6090827227009693323L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,18853L,1939790280L,9673696L), lts(-9223372036854775808L,2809952L,2809952L,2809952L), clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6348878881990124215L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2592895L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809982L), clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6579675572465669320L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3346598222L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809982L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6755184332854527549L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1514729027L,22507L,1375948190L,4674618L), lts(2809942L,2809942L,2809942L,2809942L), clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6761072511231364841L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3653646284L,19556L,2583407908L,14303535L), lts(2809922L,2809922L,2809922L,2809922L), clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -7573753742675275085L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,539423093L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809992L,-9223372036854775808L), clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -8182246842348799055L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(169275034L,-9223372036854775808L,2726525259L,-9223372036854775808L), lts(2809942L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -9190871138611796997L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,1220311521L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.model.QuiescentChecker.validate(QuiescentChecker.java:124) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.model.QuiescentChecker.validate(QuiescentChecker.java:62) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelRecentValidator.doOne(ParallelRecentValidator.java:88) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelRecentValidator.doOne(ParallelRecentValidator.java:44) < t:2023-03-02 22:39:35,735 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelValidator.lambda$startThreads$0(ParallelValidator.java:65) < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) < t:2023-03-02 22:39:35,735 f:file_logger.py l:101 c:sdcm.sct_events.file_logger p:INFO > 2023-03-02 22:39:35.733: (JMXServiceEvent Severity.NORMAL) period_type=begin event_id=78e9d47b-92bf-4b31-aa3c-93addb1a14e8 node=longevity-harry-2h-2023-1-db-node-10a155f9-1 < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > ... 3 common frames omitted < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > ERROR [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,727 HarryRunner.java:81 - Execution failed! < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > java.lang.RuntimeException: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset: < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Expected: RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Actual: resultSetRow(-312204954194982442L, -4445887274093701454L, values(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), lts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L)) < t:2023-03-02 22:39:35,736 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 < ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=2074792767L,"ZHHyABdiABdiABdiABdiABdibOQJErRC227232222242401992261652502182002497211145237223559401352342038446114203381021391391252171414312651087315986123227165834815329259826233731861469021314541363289272523981051121621131311371853621510715214820512420114948214871116129132230106830205204391066717093125492586244239143715915222728838836459205983381217106163932091621627653761242282012207716315228178249118241565493811444278161878517901091801459817020624598137231238316616013322198261541211079682862291851742061872261201964372250671392019011321165762554941783219121124203164443370331425020174","ZHHyABdiABdiABdiABdiABdiMmxIrHJa402504117874401112617217816717211821521525285209239212617575732187137741427390751791901037723724363991001045895774223176572152421981310118513419173861312092990255145112061707015310723207163251221151871032211631502101752119474111151342465718895627715318851821061561471871031862361072464023119129151102091789228161103186108160421971891666917258842161114197227255443613021018610016613112316444111513124915549214412124217235702392301949834242093918469924134153189214281238076",300589051948L} < t:2023-03-02 22:39:35,737 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Partition state: < t:2023-03-02 22:39:35,738 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Static row: RowState{cd=static, vds=[-9223372036854775808, 250, -9223372036854775808, 228, 241], lts=[-9223372036854775808, 2809992, -9223372036854775808, 2809982, 2809992], clustering=static, values=[null, -6, null, -28, -15]} < t:2023-03-02 22:39:35,738 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-9190871138611796997, vds=[-9223372036854775808, -9223372036854775808, 1220311521, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809942, -9223372036854775808], clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null]} < t:2023-03-02 22:39:35,738 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-8182246842348799055, vds=[169275034, -9223372036854775808, 2726525259, -9223372036854775808], lts=[2809942, -9223372036854775808, 2809942, -9223372036854775808], clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null]} < t:2023-03-02 22:39:35,738 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-7573753742675275085, vds=[-9223372036854775808, -9223372036854775808, 539423093, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809992, -9223372036854775808], clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null]} < t:2023-03-02 22:39:35,738 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6761072511231364841, vds=[3653646284, 19556, 2583407908, 14303535], lts=[2809922, 2809922, 2809922, 2809922], clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6755184332854527549, vds=[1514729027, 22507, 1375948190, 4674618], lts=[2809942, 2809942, 2809942, 2809942], clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6579675572465669320, vds=[3346598222, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809982, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6348878881990124215, vds=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2592895], lts=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2809982], clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6090827227009693323, vds=[-9223372036854775808, 18853, 1939790280, 9673696], lts=[-9223372036854775808, 2809952, 2809952, 2809952], clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5460187383243502911, vds=[1730736368, -9223372036854775808, -9223372036854775808, 15717141], lts=[2809912, -9223372036854775808, -9223372036854775808, 2809912], clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5360066345574909300, vds=[1711535784, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809962, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Observed state: < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4445887274093701454L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L), clustering=[284760282204, 5.059094E-39], values=[null, null, null, 1.532721E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4659417242173934802L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1278521867L,-9223372036854775808L,3886783250L,10198772L), lts(2809992L,-9223372036854775808L,2809992L,2809992L), clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5360066345574909300L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1711535784L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809962L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5460187383243502911L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1730736368L,-9223372036854775808L,-9223372036854775808L,15717141L), lts(2809912L,-9223372036854775808L,-9223372036854775808L,2809912L), clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6090827227009693323L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,18853L,1939790280L,9673696L), lts(-9223372036854775808L,2809952L,2809952L,2809952L), clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6348878881990124215L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2592895L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809982L), clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6579675572465669320L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3346598222L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809982L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6755184332854527549L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1514729027L,22507L,1375948190L,4674618L), lts(2809942L,2809942L,2809942L,2809942L), clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6761072511231364841L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3653646284L,19556L,2583407908L,14303535L), lts(2809922L,2809922L,2809922L,2809922L), clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -7573753742675275085L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,539423093L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809992L,-9223372036854775808L), clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -8182246842348799055L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(169275034L,-9223372036854775808L,2726525259L,-9223372036854775808L), lts(2809942L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -9190871138611796997L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,1220311521L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelValidator.visit(ParallelValidator.java:102) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.runner.Runner$SequentialRunner.run(Runner.java:319) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.runner.Runner$SequentialRunner.lambda$start$3(Runner.java:305) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.runner.Runner.lambda$reportThrowable$1(Runner.java:154) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) < t:2023-03-02 22:39:35,739 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.lang.Thread.run(Thread.java:829) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Caused by: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset: < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Expected: RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Actual: resultSetRow(-312204954194982442L, -4445887274093701454L, values(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), lts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L)) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 < ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=2074792767L,"ZHHyABdiABdiABdiABdiABdibOQJErRC227232222242401992261652502182002497211145237223559401352342038446114203381021391391252171414312651087315986123227165834815329259826233731861469021314541363289272523981051121621131311371853621510715214820512420114948214871116129132230106830205204391066717093125492586244239143715915222728838836459205983381217106163932091621627653761242282012207716315228178249118241565493811444278161878517901091801459817020624598137231238316616013322198261541211079682862291851742061872261201964372250671392019011321165762554941783219121124203164443370331425020174","ZHHyABdiABdiABdiABdiABdiMmxIrHJa402504117874401112617217816717211821521525285209239212617575732187137741427390751791901037723724363991001045895774223176572152421981310118513419173861312092990255145112061707015310723207163251221151871032211631502101752119474111151342465718895627715318851821061561471871031862361072464023119129151102091789228161103186108160421971891666917258842161114197227255443613021018610016613112316444111513124915549214412124217235702392301949834242093918469924134153189214281238076",300589051948L} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Partition state: < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Static row: RowState{cd=static, vds=[-9223372036854775808, 250, -9223372036854775808, 228, 241], lts=[-9223372036854775808, 2809992, -9223372036854775808, 2809982, 2809992], clustering=static, values=[null, -6, null, -28, -15]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-9190871138611796997, vds=[-9223372036854775808, -9223372036854775808, 1220311521, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809942, -9223372036854775808], clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-8182246842348799055, vds=[169275034, -9223372036854775808, 2726525259, -9223372036854775808], lts=[2809942, -9223372036854775808, 2809942, -9223372036854775808], clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-7573753742675275085, vds=[-9223372036854775808, -9223372036854775808, 539423093, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809992, -9223372036854775808], clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6761072511231364841, vds=[3653646284, 19556, 2583407908, 14303535], lts=[2809922, 2809922, 2809922, 2809922], clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6755184332854527549, vds=[1514729027, 22507, 1375948190, 4674618], lts=[2809942, 2809942, 2809942, 2809942], clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6579675572465669320, vds=[3346598222, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809982, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6348878881990124215, vds=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2592895], lts=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2809982], clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6090827227009693323, vds=[-9223372036854775808, 18853, 1939790280, 9673696], lts=[-9223372036854775808, 2809952, 2809952, 2809952], clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5460187383243502911, vds=[1730736368, -9223372036854775808, -9223372036854775808, 15717141], lts=[2809912, -9223372036854775808, -9223372036854775808, 2809912], clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5360066345574909300, vds=[1711535784, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809962, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Observed state: < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4445887274093701454L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L), clustering=[284760282204, 5.059094E-39], values=[null, null, null, 1.532721E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4659417242173934802L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1278521867L,-9223372036854775808L,3886783250L,10198772L), lts(2809992L,-9223372036854775808L,2809992L,2809992L), clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5360066345574909300L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1711535784L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809962L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5460187383243502911L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1730736368L,-9223372036854775808L,-9223372036854775808L,15717141L), lts(2809912L,-9223372036854775808L,-9223372036854775808L,2809912L), clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6090827227009693323L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,18853L,1939790280L,9673696L), lts(-9223372036854775808L,2809952L,2809952L,2809952L), clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6348878881990124215L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2592895L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809982L), clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6579675572465669320L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3346598222L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809982L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6755184332854527549L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1514729027L,22507L,1375948190L,4674618L), lts(2809942L,2809942L,2809942L,2809942L), clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6761072511231364841L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3653646284L,19556L,2583407908L,14303535L), lts(2809922L,2809922L,2809922L,2809922L), clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -7573753742675275085L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,539423093L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809992L,-9223372036854775808L), clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -8182246842348799055L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(169275034L,-9223372036854775808L,2726525259L,-9223372036854775808L), lts(2809942L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -9190871138611796997L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,1220311521L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999) < t:2023-03-02 22:39:35,740 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelValidator.visit(ParallelValidator.java:98) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > ... 9 common frames omitted < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Caused by: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset: < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Expected: RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Actual: resultSetRow(-312204954194982442L, -4445887274093701454L, values(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), lts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L)) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 < ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=2074792767L,"ZHHyABdiABdiABdiABdiABdibOQJErRC227232222242401992261652502182002497211145237223559401352342038446114203381021391391252171414312651087315986123227165834815329259826233731861469021314541363289272523981051121621131311371853621510715214820512420114948214871116129132230106830205204391066717093125492586244239143715915222728838836459205983381217106163932091621627653761242282012207716315228178249118241565493811444278161878517901091801459817020624598137231238316616013322198261541211079682862291851742061872261201964372250671392019011321165762554941783219121124203164443370331425020174","ZHHyABdiABdiABdiABdiABdiMmxIrHJa402504117874401112617217816717211821521525285209239212617575732187137741427390751791901037723724363991001045895774223176572152421981310118513419173861312092990255145112061707015310723207163251221151871032211631502101752119474111151342465718895627715318851821061561471871031862361072464023119129151102091789228161103186108160421971891666917258842161114197227255443613021018610016613112316444111513124915549214412124217235702392301949834242093918469924134153189214281238076",300589051948L} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Partition state: < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Static row: RowState{cd=static, vds=[-9223372036854775808, 250, -9223372036854775808, 228, 241], lts=[-9223372036854775808, 2809992, -9223372036854775808, 2809982, 2809992], clustering=static, values=[null, -6, null, -28, -15]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-9190871138611796997, vds=[-9223372036854775808, -9223372036854775808, 1220311521, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809942, -9223372036854775808], clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-8182246842348799055, vds=[169275034, -9223372036854775808, 2726525259, -9223372036854775808], lts=[2809942, -9223372036854775808, 2809942, -9223372036854775808], clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-7573753742675275085, vds=[-9223372036854775808, -9223372036854775808, 539423093, -9223372036854775808], lts=[-9223372036854775808, -9223372036854775808, 2809992, -9223372036854775808], clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6761072511231364841, vds=[3653646284, 19556, 2583407908, 14303535], lts=[2809922, 2809922, 2809922, 2809922], clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6755184332854527549, vds=[1514729027, 22507, 1375948190, 4674618], lts=[2809942, 2809942, 2809942, 2809942], clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6579675572465669320, vds=[3346598222, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809982, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6348878881990124215, vds=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2592895], lts=[-9223372036854775808, -9223372036854775808, -9223372036854775808, 2809982], clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-6090827227009693323, vds=[-9223372036854775808, 18853, 1939790280, 9673696], lts=[-9223372036854775808, 2809952, 2809952, 2809952], clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5460187383243502911, vds=[1730736368, -9223372036854775808, -9223372036854775808, 15717141], lts=[2809912, -9223372036854775808, -9223372036854775808, 2809912], clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-5360066345574909300, vds=[1711535784, -9223372036854775808, -9223372036854775808, -9223372036854775808], lts=[2809962, -9223372036854775808, -9223372036854775808, -9223372036854775808], clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > RowState{cd=-4659417242173934802, vds=[1278521867, -9223372036854775808, 3886783250, 10198772], lts=[2809992, -9223372036854775808, 2809992, 2809992], clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38]} < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > Observed state: < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4445887274093701454L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,10937863L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809892L), clustering=[284760282204, 5.059094E-39], values=[null, null, null, 1.532721E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -4659417242173934802L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1278521867L,-9223372036854775808L,3886783250L,10198772L), lts(2809992L,-9223372036854775808L,2809992L,2809992L), clustering=[272032904307, 2.0979812E-38], values=[1278521867, null, -408184046, 1.4291524E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5360066345574909300L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1711535784L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809962L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[230270963387, 1.1316769E-38], values=[1711535784, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -5460187383243502911L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1730736368L,-9223372036854775808L,-9223372036854775808L,15717141L), lts(2809912L,-9223372036854775808L,-9223372036854775808L,2809912L), clustering=[224303284502, 1.648833E-38], values=[1730736368, null, null, 2.2024406E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6090827227009693323L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,18853L,1939790280L,9673696L), lts(-9223372036854775808L,2809952L,2809952L,2809952L), clustering=[186714220633, 1.9036299E-38], values=[null, 18853, 1939790280, 1.3555735E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6348878881990124215L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2592895L), lts(-9223372036854775808L,-9223372036854775808L,-9223372036854775808L,2809982L), clustering=[171333143404, 2.3497434E-38], values=[null, null, null, 3.63342E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6579675572465669320L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3346598222L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2809982L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), clustering=[157576588653, 2.0425943E-38], values=[-948369074, null, null, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6755184332854527549L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(1514729027L,22507L,1375948190L,4674618L), lts(2809942L,2809942L,2809942L,2809942L), clustering=[147115451335, 2.1670939E-38], values=[1514729027, 22507, 1375948190, 6.550535E-39], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -6761072511231364841L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(3653646284L,19556L,2583407908L,14303535L), lts(2809922L,2809922L,2809922L,2809922L), clustering=[146764488555, 9.315954E-39], values=[-641321012, 19556, -1711559388, 2.0043522E-38], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -7573753742675275085L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,539423093L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809992L,-9223372036854775808L), clustering=[98324912439, 1.3047348E-38], values=[null, null, 539423093, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -8182246842348799055L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(169275034L,-9223372036854775808L,2726525259L,-9223372036854775808L), lts(2809942L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[62055897385, 5.60042E-39], values=[169275034, null, -1568442037, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > resultSetRow(-312204954194982442L, -9190871138611796997L, staticValues(-9223372036854775808L,250L,-9223372036854775808L,228L,241L), slts(-9223372036854775808L,2809992L,-9223372036854775808L,2809982L,2809992L), values(-9223372036854775808L,-9223372036854775808L,1220311521L,-9223372036854775808L), lts(-9223372036854775808L,-9223372036854775808L,2809942L,-9223372036854775808L), clustering=[1937204494, 1.5372394E-38], values=[null, null, 1220311521, null], statics=[null, -6, null, -28, -15]) < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > < t:2023-03-02 22:39:35,741 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.model.QuiescentChecker.validate(QuiescentChecker.java:124) < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.model.QuiescentChecker.validate(QuiescentChecker.java:62) < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelRecentValidator.doOne(ParallelRecentValidator.java:88) < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelRecentValidator.doOne(ParallelRecentValidator.java:44) < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at harry.visitors.ParallelValidator.lambda$startThreads$0(ParallelValidator.java:65) < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700) < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > ... 3 common frames omitted < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,728 HarryRunner.java:93 - Shutting down executor.. < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,733 HarryRunner.java:99 - Shutting down runner.. < t:2023-03-02 22:39:35,742 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,737 Runner.java:329 - Shutting down... < t:2023-03-02 22:39:35,817 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,816 Runner.java:98 - Tearing down setup... < t:2023-03-02 22:39:35,817 f:base.py l:228 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,816 HarryRunner.java:107 - Exiting... < t:2023-03-02 22:39:36,319 f:base.py l:146 c:RemoteLibSSH2CmdRunner p:ERROR > Error executing command: "sudo docker exec 3843d585e9e16a266b0cc22c788d49e038f21b03b58bd0a4c73be6d6f46cf897 /bin/sh -c 'STRESS_TEST_MARKER=L7I74PC1ISKRY3ELFCQ2; cassandra-harry -run-time 2 -run-time-unit HOURS -node 10.4.0.74'"; Exit status: 1 < t:2023-03-02 22:39:36,319 f:base.py l:148 c:RemoteLibSSH2CmdRunner p:DEBUG > STDOUT: :35,737 Runner.java:329 - Shutting down... < t:2023-03-02 22:39:36,319 f:base.py l:148 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,816 Runner.java:98 - Tearing down setup... < t:2023-03-02 22:39:36,319 f:base.py l:148 c:RemoteLibSSH2CmdRunner p:DEBUG > INFO [main] instance_id_IS_UNDEFINED 2023-03-02 22:39:35,816 HarryRunner.java:107 - Exiting... ... ``` - Restore Monitor Stack command: `$ hydra investigate show-monitor 10a155f9-f3c2-4e45-b516-51ee8d98edcf` - Restore monitor on AWS instance using [Jenkins job](https://jenkins.scylladb.com/view/QA/job/QA-tools/job/hydra-show-monitor/parambuild/?test_id=10a155f9-f3c2-4e45-b516-51ee8d98edcf) - Show all stored logs command: `$ hydra investigate show-logs 10a155f9-f3c2-4e45-b516-51ee8d98edcf` ## Logs: - **db-cluster-10a155f9.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/db-cluster-10a155f9.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/db-cluster-10a155f9.tar.gz) - **sct-runner-10a155f9.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/sct-runner-10a155f9.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/sct-runner-10a155f9.tar.gz) - **monitor-set-10a155f9.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/monitor-set-10a155f9.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/monitor-set-10a155f9.tar.gz) - **loader-set-10a155f9.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/loader-set-10a155f9.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/loader-set-10a155f9.tar.gz) - **parallel-timelines-report-10a155f9.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/parallel-timelines-report-10a155f9.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/10a155f9-f3c2-4e45-b516-51ee8d98edcf/20230302_230236/parallel-timelines-report-10a155f9.tar.gz) [Jenkins job URL](https://jenkins.scylladb.com/job/enterprise-2023.1/job/longevity/job/longevity-harry-2h-test/2/)
fgelcer commented 1 year ago

@DoronArazii

DoronArazii commented 1 year ago

@ptrsmrn did we had any fixes around this in the last 6 months?

ptrsmrn commented 1 year ago

@cvybhu is looking into it

cvybhu commented 1 year ago

Reading the cassandra harry logs, specifically cassandra-harry-l0-df244f51-e953-4039-8b6f-d08eabfc4243.log from the loader set, I see that just before the validation error there was an error saying that an INSERT statement has failed:

ERROR 12:36:52 Caught message while trying to execute CompiledStatement{cql='BEGIN UNLOGGED BATCH
INSERT INTO harry.table0 (pk0000,pk0001,pk0002,ck0000,ck0001,regular0000,regular0001) VALUES (?, ?, ?, ?, ?, ?, ?) USING TIMESTAMP 1652791011659406; UPDATE harry.table0 USING TIMESTAMP 1652791011659406 SET regular0001 = ?, regular0002 = ? WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 = ? AND ck0001 = ?;
APPLY BATCH;', bindings=2450526259L,"ZHHyABdiABdiABdiABdiABdibMpLLWYc246338536017219215786200249516516921755301071520113020085215215133154139102441651501722212916516878952652107670141217518237232138187448255471668243130146116331434722023121319016822719423910121153122207461854648122552532184423923024113411364233331986924958207911001111961088354138251159261119688181249669118342164192352792541321511311811321615620924251722271118814155922622710920022886118231891034244135126130207161239521312221819318015162235141108572412619882371622101887411013448248182572525220388","ZHHyABdiABdiABdiABdiABdijpiHlFPu18810071292471623018914611020917537255129295411201312172422501021331684211625292220223167178108254902252285854386",865384412096L,(float)2.0980271E-38,-1417954105,(short)-14460,(short)19283,965534980,2450526259L,"ZHHyABdiABdiABdiABdiABdibMpLLWYc246338536017219215786200249516516921755301071520113020085215215133154139102441651501722212916516878952652107670141217518237232138187448255471668243130146116331434722023121319016822719423910121153122207461854648122552532184423923024113411364233331986924958207911001111961088354138251159261119688181249669118342164192352792541321511311811321615620924251722271118814155922622710920022886118231891034244135126130207161239521312221819318015162235141108572412619882371622101887411013448248182572525220388","ZHHyABdiABdiABdiABdiABdijpiHlFPu18810071292471623018914611020917537255129295411201312172422501021331684211625292220223167178108254902252285854386",289220137400L,(float)1.5767209E-38}
com.datastax.driver.core.exceptions.TransportException: [/10.0.3.136:9042] Connection has been closed
    at com.datastax.driver.core.Connection$ConnectionCloseFuture.force(Connection.java:1397)
    at com.datastax.driver.core.Connection$ConnectionCloseFuture.force(Connection.java:1378)
    at com.datastax.driver.core.Connection.defunct(Connection.java:570)
    at com.datastax.driver.core.Connection$ChannelCloseListener.operationComplete(Connection.java:1328)
    at com.datastax.driver.core.Connection$ChannelCloseListener.operationComplete(Connection.java:1318)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:512)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:505)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:484)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:425)
    at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
    at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:84)
    at io.netty.channel.AbstractChannel$CloseFuture.setClosed(AbstractChannel.java:1093)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.doClose0(AbstractChannel.java:710)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:686)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:557)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.closeOnRead(AbstractNioByteChannel.java:71)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:162)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:646)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:546)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:500)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:460)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
ERROR [pool-3-thread-2] instance_id_IS_UNDEFINED 2022-05-17 12:36:52,344 MutatingVisitor.java:164 - Caught message while trying to execute CompiledStatement{cql='BEGIN UNLOGGED BATCH
INSERT INTO harry.table0 (pk0000,pk0001,pk0002,ck0000,ck0001,regular0000,regular0001) VALUES (?, ?, ?, ?, ?, ?, ?) USING TIMESTAMP 1652791011659406; UPDATE harry.table0 USING TIMESTAMP 1652791011659406 SET regular0001 = ?, regular0002 = ? WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 = ? AND ck0001 = ?;
APPLY BATCH;', bindings=2450526259L,"ZHHyABdiABdiABdiABdiABdibMpLLWYc246338536017219215786200249516516921755301071520113020085215215133154139102441651501722212916516878952652107670141217518237232138187448255471668243130146116331434722023121319016822719423910121153122207461854648122552532184423923024113411364233331986924958207911001111961088354138251159261119688181249669118342164192352792541321511311811321615620924251722271118814155922622710920022886118231891034244135126130207161239521312221819318015162235141108572412619882371622101887411013448248182572525220388","ZHHyABdiABdiABdiABdiABdijpiHlFPu18810071292471623018914611020917537255129295411201312172422501021331684211625292220223167178108254902252285854386",865384412096L,(float)2.0980271E-38,-1417954105,(short)-14460,(short)19283,965534980,2450526259L,"ZHHyABdiABdiABdiABdiABdibMpLLWYc246338536017219215786200249516516921755301071520113020085215215133154139102441651501722212916516878952652107670141217518237232138187448255471668243130146116331434722023121319016822719423910121153122207461854648122552532184423923024113411364233331986924958207911001111961088354138251159261119688181249669118342164192352792541321511311811321615620924251722271118814155922622710920022886118231891034244135126130207161239521312221819318015162235141108572412619882371622101887411013448248182572525220388","ZHHyABdiABdiABdiABdiABdijpiHlFPu18810071292471623018914611020917537255129295411201312172422501021331684211625292220223167178108254902252285854386",289220137400L,(float)1.5767209E-38}
com.datastax.driver.core.exceptions.TransportException: [/10.0.3.136:9042] Connection has been closed
    at com.datastax.driver.core.Connection$ConnectionCloseFuture.force(Connection.java:1397)
    at com.datastax.driver.core.Connection$ConnectionCloseFuture.force(Connection.java:1378)
    at com.datastax.driver.core.Connection.defunct(Connection.java:570)
    at com.datastax.driver.core.Connection$ChannelCloseListener.operationComplete(Connection.java:1328)
    at com.datastax.driver.core.Connection$ChannelCloseListener.operationComplete(Connection.java:1318)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:512)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:505)
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:484)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:425)
    at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
    at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:84)
    at io.netty.channel.AbstractChannel$CloseFuture.setClosed(AbstractChannel.java:1093)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.doClose0(AbstractChannel.java:710)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:686)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:557)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.closeOnRead(AbstractNioByteChannel.java:71)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:162)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:646)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:546)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:500)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:460)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)

A moment later there's the validation error:

ERROR 12:37:59 Dumping results into the file:failure.dump
ERROR [pool-4-thread-1] instance_id_IS_UNDEFINED 2022-05-17 12:37:59,796 Runner.java:497 - Dumping results into the file:failure.dump
ERROR 12:37:59 Execution failed!
java.lang.RuntimeException: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Found a row in the model that is not present in the resultset:
Expected: RowState{cd=-2680195869748707583, vds=[-9223372036854775808, -9223372036854775808, 3295175451, 16481971], lts=[-9223372036854775808, -9223372036854775808, 2450810, 2450810], clustering=[390003691143, 3.741939E-39], values=[null, null, -999791845, 2.309616E-38]}
Actual: resultSetRow(-4848934879607217747L, -2681267964583869968L, values(64895744886884297L,191L,40452L,236L,223L), lts(2450990L,2450980L,2450990L,2450990L,2450990L), values(4217329462L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L), lts(2450960L,-9223372036854775808L,-9223372036854775808L,-9223372036854775808L))
Query: CompiledStatement{cql='SELECT pk0000, pk0001, pk0002, ck0000, ck0001, static0000, static0001, static0002, static0003, static0004, regular0000, regular0001, regular0002, regular0003, writetime(static0000), writetime(static0001), writetime(static0002), writetime(static0003), writetime(static0004), writetime(regular0000), writetime(regular0001), writetime(regular0002), writetime(regular0003) FROM harry.table0 WHERE pk0000 = ? AND pk0001 = ? AND pk0002 = ? AND ck0000 <= ? ORDER BY ck0000 DESC, ck0001 DESC;', bindings=1018503018L,"ZHHyABdiABdiABdiABdiABdixSFhALUT131226229842317120712319025208204148451361407410623224313022030891841822481141252399720661253252313515918524797108172171301914840","ZHHyABdiABdiABdiABdiABdifnZdiaVk103382413760411412106713510217112919880114149917513323115357119998916316360104240131139205892235117330841991652825411564452497751881811785110459131256514141592280160230129126188131123112851591494119236226018715199538947122289328114149320312725519612945541115716118075143105108181881081138118216281584021210614121127117118024521681294892159139451221318946382572382212031622032491059829171116187561294422671177713924912017784243197411258518793226145151232191892264711311025525011121071011961011212251104248178751402482241711697416221117684180292991046121445150153150151208161143122244208169387223817445251147131371372614253261137980243204116902031165089202125121475821421933247242160146945070221761613015441282122026712916814120193171258831184227254822522242321311312462245120452411579841081291671821121499201661821971872375111387205467943541931971126745891711777467345418214338128771661238916158194782001920663921392174158146121866824110211325220524421164103176157231104226145890146199992722199818621019913492129107162554132213758120193",818566072796L}
Partition state:
Static row: RowSta

At the first glance it looks like a bug in Cassandra Harry. A node goes down due to rolling restart, and because of that inserting a row fails with ConnectionClosed exception. The row doesn't get inserted, and because of this the validation fails.

The driver should retry all idempotent queries that failed due to IO errors, at least that's what the rust driver does.

cvybhu commented 1 year ago

Okay, it looks like the MutatingVisitor retries each query 10 times: https://github.com/apache/cassandra-harry/blob/5570c254df4fd6495c864f4021970ae005a62ce5/harry-core/src/harry/visitors/MutatingVisitor.java

After ten tries it would write "Can not execute statement %s after %d retries", but there is no such message in the logs, which means that all the queries succeeded.

So the initial idea about harry bug was most likely wrong.

cvybhu commented 1 year ago

So the row is successfully written, but it isn't visible during read.

One more idea - is scylla configured with durable_writes = true?

If the database responds before the data is actually written to persistent storage, we could end up losing data. Imagine a scenario like this: 1) A is down, B and C are up 2) Harry writes a row with CL=QUORUM, it reaches B and C 3) A comes back up, doesn't know about the row 4) B goes down before the change is persisted, it forgets about the row 5) B goes back up 7) Harry reads with CL=QUORUM, it reaches A and B, both of them don't know about the row 8) The read doesn't return the row

I heard that there are multiple modes for the commitlog, maybe the default mode doesn't persist the changes?

fruch commented 1 year ago

Well the disconnect backtraces are normal, and we see them in c-s when nodes go down.

cvybhu commented 1 year ago

Looking at the scylla.yaml, there's commitlog_sync: periodic and commitlog_sync_period_in_ms: 10000. AFAIU this means that we save the commitlog to disk every 10 seconds.

But what happens if the node is restarted before the 10 seconds pass. Does it flush the commitlog one last time? If not, then we could lose some data.

api_address: 127.0.0.1
api_doc_dir: /opt/scylladb/api/api-doc/
api_ui_dir: /opt/scylladb/swagger-ui/dist/
batch_size_fail_threshold_in_kb: 1024
batch_size_warn_threshold_in_kb: 128
broadcast_rpc_address: 10.0.3.210
cluster_name: longevity-harry-2h-test-har-db-cluster-5ad966f5
commitlog_segment_size_in_mb: 32
commitlog_sync: periodic
commitlog_sync_period_in_ms: 10000
endpoint_snitch: org.apache.cassandra.locator.Ec2Snitch
experimental: true
listen_address: 10.0.3.210
num_tokens: 256
partitioner: org.apache.cassandra.dht.Murmur3Partitioner
prometheus_address: 0.0.0.0
rpc_address: 10.0.3.210
seed_provider:
- class_name: org.apache.cassandra.locator.SimpleSeedProvider
  parameters:
  - seeds: 10.0.3.210
fruch commented 1 year ago

Looking at the scylla.yaml, there's commitlog_sync: periodic and commitlog_sync_period_in_ms: 10000. AFAIU this means that we save the commitlog to disk every 10 seconds.

But what happens if the node is restarted before the 10 seconds pass. Does it flush the commitlog one last time? If not, then we could lose some data.

api_address: 127.0.0.1
api_doc_dir: /opt/scylladb/api/api-doc/
api_ui_dir: /opt/scylladb/swagger-ui/dist/
batch_size_fail_threshold_in_kb: 1024
batch_size_warn_threshold_in_kb: 128
broadcast_rpc_address: 10.0.3.210
cluster_name: longevity-harry-2h-test-har-db-cluster-5ad966f5
commitlog_segment_size_in_mb: 32
commitlog_sync: periodic
commitlog_sync_period_in_ms: 10000
endpoint_snitch: org.apache.cassandra.locator.Ec2Snitch
experimental: true
listen_address: 10.0.3.210
num_tokens: 256
partitioner: org.apache.cassandra.dht.Murmur3Partitioner
prometheus_address: 0.0.0.0
rpc_address: 10.0.3.210
seed_provider:
- class_name: org.apache.cassandra.locator.SimpleSeedProvider
  parameters:
  - seeds: 10.0.3.210

Loose data from one node is quite normal We are not reading the data here with ONE

cvybhu commented 1 year ago

Loose data from one node is quite normal We are not reading the data here with ONE

The problem is that we might lose data on two nodes. One node is down so it doesn't know about the change, and the other could forget the change during the restart

cvybhu commented 1 year ago

Hmm I ran this test 5 times (3, 4, 5, 6, 7) and it didn't fail.

Maybe the issue has been fixed in the meantime?

fruch commented 1 year ago

Hmm I ran this test 5 times (3, 4, 5, 6, 7) and it didn't fail.

Maybe the issue has been fixed in the meantime?

It's more of the fact the specific nemesis in question wasn't run, SCT "randomly" (based on a seed) picks the order of nemesis being used.

So we can change the test to run only the rolling restary nemesis

Or we can supply a specific nemesis seed that would have that nemesis for the current SCT master. (Unfortunately it's still a moving target)

fruch commented 1 year ago

@cvybhu

I'm running it with a seed that would run the rolling restart nemesis

https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/8/

and lets it if it still happening, also last report of it was on 2023.1 rc, so if it clears on master, and wouldn't on 2023.1, we still need to figure it out

fruch commented 1 year ago

Damn, it didn't exactly run the sequence I wanted to recreate, but it did fail similarly but on disrupt_disable_binary_gossip_execute_major_compaction this nemesis is fairly new, but it does something very simple on one node only disablebinary and disablegossip, and then compaction

introduced in: https://github.com/scylladb/scylla-cluster-tests/pull/6478

anyhow again, disabling one node shouldn't break a test tool that works in cl=QUORUM.

Installation details

Kernel Version: 5.15.0-1044-aws Scylla version (or git commit hash): 5.4.0~dev-20230910.0656810c2877 with build-id 2156440484bcf26ee80adb62c33ea5d7f689a57c

Cluster size: 6 nodes (i4i.large)

Scylla Nodes used in this run:

OS / Image: ami-023effc126ea4f201 (aws: undefined_region)

Test: longevity-harry-2h-test Test id: 0f07e6be-f5ad-412f-9788-39cc5857868b Test name: scylla-master/reproducers/longevity-harry-2h-test Test config file(s):

Logs and commands - Restore Monitor Stack command: `$ hydra investigate show-monitor 0f07e6be-f5ad-412f-9788-39cc5857868b` - Restore monitor on AWS instance using [Jenkins job](https://jenkins.scylladb.com/view/QA/job/QA-tools/job/hydra-show-monitor/parambuild/?test_id=0f07e6be-f5ad-412f-9788-39cc5857868b) - Show all stored logs command: `$ hydra investigate show-logs 0f07e6be-f5ad-412f-9788-39cc5857868b` ## Logs: - **db-cluster-0f07e6be.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/db-cluster-0f07e6be.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/db-cluster-0f07e6be.tar.gz) - **sct-runner-events-0f07e6be.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/sct-runner-events-0f07e6be.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/sct-runner-events-0f07e6be.tar.gz) - **sct-0f07e6be.log.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/sct-0f07e6be.log.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/sct-0f07e6be.log.tar.gz) - **loader-set-0f07e6be.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/loader-set-0f07e6be.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/loader-set-0f07e6be.tar.gz) - **monitor-set-0f07e6be.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/monitor-set-0f07e6be.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/monitor-set-0f07e6be.tar.gz) - **parallel-timelines-report-0f07e6be.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/parallel-timelines-report-0f07e6be.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/0f07e6be-f5ad-412f-9788-39cc5857868b/20230912_120804/parallel-timelines-report-0f07e6be.tar.gz) [Jenkins job URL](https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/8/) [Argus](https://argus.scylladb.com/test/2a9ce2cc-b264-45e9-8740-3a43d3177d74/runs?additionalRuns[]=0f07e6be-f5ad-412f-9788-39cc5857868b)
cvybhu commented 1 year ago

Thank you, so it does reproduce on the newest master.

I think it would be good to run another run with a slightly modified scylla.yaml. I would like to replace:

commitlog_sync: periodic
commitlog_sync_period_in_ms: 10000

With:

commitlog_sync: batch
commitlog_sync_batch_window_in_ms: 2

This should make all of the writes durable, so there would be no excuse for losing data when a node stops. If this doesn't fail, then that would confirm the theory that commitlog isn't flushed when the node stops.

@fruch could you start another run with a modified scylla.yaml? I can try to do it, but I have no idea how SCTs work, there's no scylla.yaml argument in the Jenkins job. I would need some pointers.

fruch commented 1 year ago

@cvybhu see how to apply it in SCT configuration of the test: https://github.com/fruch/scylla-cluster-tests/commit/8eb2a892d631498e79ec8c3a938efa2fbfc2efdc

I've run it again in https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/10/

cvybhu commented 1 year ago

Ah that's a nice option, thanks!

cvybhu commented 1 year ago

@cvybhu see how to apply it in SCT configuration of the test: fruch/scylla-cluster-tests@8eb2a89

I've run it again in https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/10/

Damn it still failed, even with commitlog_sync: batch.

Here are the logs: https://cloudius-jenkins-test.s3.amazonaws.com/2c6ef546-2c2a-42d5-ad35-e6430deb0bb3/20230913_145818/loader-set-2c6ef546.tar.gz

This means that either my theory was wrong, and it's not a commitlog problem at all, or that the problem also occurs with the batch setting. It'll require further investigation.

cvybhu commented 1 year ago

Another idea: maybe rolling restart needs to perform nodetool drain?

It looks like the docs say that you should run it before restarting, but the nemesis doesn't do it. There's even an existing issue about it: https://github.com/scylladb/scylla-cluster-tests/issues/5167

fruch commented 1 year ago

Another idea: maybe rolling restart needs to perform nodetool drain?

It looks like the docs say that you should run it before restarting, but the nemesis doesn't do it. There's even an existing issue about it: https://github.com/scylladb/scylla-cluster-tests/issues/5167

We could try, but there are quite lots of other cases, i.e. nemesis that we won't be gracefully shutting down scylla, like start/stop a single node, of killing a node with -9 signal.

I wonder what makes this tool validation more problematic in this case, then c-s, s-b or gemini.

Gemini works with other scylladb as oracle, and this one has a in-memory oracle, I wonder why its expectations are different.

fruch commented 1 year ago

@cvybhu running it with drain (even that I doubt it's related) https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/11/

fruch commented 1 year ago

@cvybhu running it with drain (even that I doubt it's related) https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/11/

@cvybhu yep, still failing, adding drain didn't changed the situation :

Installation details

Kernel Version: 5.15.0-1045-aws Scylla version (or git commit hash): 5.4.0~dev-20230921.a56a4b6226e6 with build-id 616f734e7c7fb5e3ee8898792b3c415d2574a132

Cluster size: 6 nodes (i4i.large)

Scylla Nodes used in this run:

OS / Image: ami-00f051bf1c684c01a (aws: undefined_region)

Test: longevity-harry-2h-test Test id: 4fe8bf36-0412-4080-b0a9-e4f88ef6b3af Test name: scylla-master/reproducers/longevity-harry-2h-test Test config file(s):

Logs and commands - Restore Monitor Stack command: `$ hydra investigate show-monitor 4fe8bf36-0412-4080-b0a9-e4f88ef6b3af` - Restore monitor on AWS instance using [Jenkins job](https://jenkins.scylladb.com/view/QA/job/QA-tools/job/hydra-show-monitor/parambuild/?test_id=4fe8bf36-0412-4080-b0a9-e4f88ef6b3af) - Show all stored logs command: `$ hydra investigate show-logs 4fe8bf36-0412-4080-b0a9-e4f88ef6b3af` ## Logs: - **db-cluster-4fe8bf36.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/db-cluster-4fe8bf36.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/db-cluster-4fe8bf36.tar.gz) - **sct-runner-events-4fe8bf36.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/sct-runner-events-4fe8bf36.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/sct-runner-events-4fe8bf36.tar.gz) - **sct-4fe8bf36.log.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/sct-4fe8bf36.log.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/sct-4fe8bf36.log.tar.gz) - **loader-set-4fe8bf36.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/loader-set-4fe8bf36.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/loader-set-4fe8bf36.tar.gz) - **monitor-set-4fe8bf36.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/monitor-set-4fe8bf36.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/monitor-set-4fe8bf36.tar.gz) - **parallel-timelines-report-4fe8bf36.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/parallel-timelines-report-4fe8bf36.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/4fe8bf36-0412-4080-b0a9-e4f88ef6b3af/20230921_090317/parallel-timelines-report-4fe8bf36.tar.gz) [Jenkins job URL](https://jenkins.scylladb.com/job/scylla-master/job/reproducers/job/longevity-harry-2h-test/11/) [Argus](https://argus.scylladb.com/test/2a9ce2cc-b264-45e9-8740-3a43d3177d74/runs?additionalRuns[]=4fe8bf36-0412-4080-b0a9-e4f88ef6b3af)
cvybhu commented 1 year ago

I tried to make a reproducer using dtest, but it didn't find any missing rows.

The code is here: https://gist.github.com/cvybhu/2b5e04f6f964a1ee2c2cbc6b1097ebef

It does a lot of rolling restarts while inserting rows and verifying that they exist in the table.

For some reason the test dies after about ~45mins every time I run it. No idea what's wrong, some timeout or something (?) -> log.txt. That doesn't really matter, what matters is that it doesn't find any missing rows in the first 45 mins.

I wasn't able to reproduce the issue using a simple reproducer, so I will dive deeper into Cassandra Harry and try to reproduce it locally using Harry and ccm.

fruch commented 1 year ago

I tried to make a reproducer using dtest, but it didn't find any missing rows.

The code is here: https://gist.github.com/cvybhu/2b5e04f6f964a1ee2c2cbc6b1097ebef

It does a lot of rolling restarts while inserting rows and verifying that they exist in the table.

For some reason the test dies after about ~45mins every time I run it. No idea what's wrong, some timeout or something (?) -> log.txt. That doesn't really matter, what matters is that it doesn't find any missing rows in the first 45 mins.

I wasn't able to reproduce the issue using a simple reproducer, so I will dive deeper into Cassandra Harry and try to reproduce it locally using Harry and ccm.

Trying it locally is a good idea

I would try using the same docker image

2700 secs is the default dtest timeout, it can be enlarged with a decorator on the test.

Anyhow I would recommend opening a PR and we'll try helping to it

cvybhu commented 1 year ago

I got cassandra-harry to run locally and I can confirm that it does reproduce locally. I made a script which starts a 6 node cluster and constantly runs rolling restarts while cassandra-harry does its thing. The error happens almost immediately after starting. It doesn't reproduce when I disable the rolling restarts. That's great news, I have something local that I can work with now :)

Here's the script:

import ccmlib
from ccmlib.scylla_cluster import ScyllaCluster
import time

cluster = ScyllaCluster(
    "/home/jancio/.ccm",
    "roller",
    cassandra_version="release:2023.1.1",
    force_wait_for_cluster_start=True,
    manager=None,
    skip_manager_server=None)

print("Starting the cluster...")
cluster.populate(6).start()
print("Cluster started!")

print("Sleeping 60 seconds to let the cluster settle...")
time.sleep(60)
print("Sleep done")

def rolling_restart():
    print("Starting a rolling restart!")
    for node in cluster.nodelist():
        print(f"Restarting node {node.address()}")
        node.stop(wait_other_notice=True)
        node.start(wait_other_notice=True, wait_for_binary_proto=True)

        # Sleep a bit, otherwise it doesn't work
        time.sleep(30)

    print("Rolling restart done")

while True:
    rolling_restart()
    time.sleep(30)
cvybhu commented 1 year ago

2700 secs is the default dtest timeout, it can be enlarged with a decorator on the test. Anyhow I would recommend opening a PR and we'll try helping to it

I only made this test to try and reproduce this bug, I didn't really mean for it to become an official test. Anyhow I have another reproducer now, so I'm gonna focus on that.

fruch commented 1 year ago

2700 secs is the default dtest timeout, it can be enlarged with a decorator on the test. Anyhow I would recommend opening a PR and we'll try helping to it

I only made this test to try and reproduce this bug, I didn't really mean for it to become an official test. Anyhow I have another reproducer now, so I'm gonna focus on that.

If it proven to be a scylla core issue, having a formal test would recommended. but local reproducer is a good start (I'll help to adapt it when and if needed)

cvybhu commented 1 year ago

I also ran the test using Cassandra, and it didn't fail. I was hoping that this is something with cassandra-harry, but this data points towards it really being Scylla's fault. I'll keep investigating.

cvybhu commented 1 year ago

Okay maybe it's something with Harry after all.

I reduced the test to make it smaller by changing external.yaml to:

schema_provider:
  fixed:
    keyspace: harry
    table: test_table
    partition_keys:
      pk1: smallint
    clustering_keys:
      ck1: smallint
    regular_columns:
      r1: smallint
    static_keys:
...
runner:
  sequential:
    run_time: 2
    run_time_unit: "HOURS"

    visitors:
      - logging:
          row_visitor:
            mutating: {}
      - parallel_validate_recent_partitions:
          partition_count: 1
          queries_per_partition: 1
          concurrency: 1
          model:
            quiescent_checker: {}

And now it fails immediately after starting up, on both Scylla and Cassandra, even without a rolling restart.

In operations.log it's clear that it inserts these rows:

LTS: 0. Pd 28953. Cd 34363. M 0. OpId: 0 Statement CompiledStatement{cql='UPDATE harry.test_table USING TIMESTAMP 1696363940366000 SET r1 = ? WHERE pk1 = ? AND ck1 = ?;', bindings=(short)-23979,(short)-3815,(short)1595}
LTS: 0. Pd 28953. Cd 16514. M 0. OpId: 1 Statement CompiledStatement{cql='UPDATE harry.test_table USING TIMESTAMP 1696363940366000 SET r1 = ? WHERE pk1 = ? AND ck1 = ?;', bindings=(short)-8744,(short)-3815,(short)-16254}
LTS: 0. Pd 28953. Cd 54945. M 1. OpId: 2 Statement CompiledStatement{cql='INSERT INTO harry.test_table (pk1,ck1) VALUES (?, ?) USING TIMESTAMP 1696363940366000;', bindings=(short)-3815,(short)22177}
LTS: 0. Pd 28953. Cd 51946. M 1. OpId: 3 Statement CompiledStatement{cql='UPDATE harry.test_table USING TIMESTAMP 1696363940366000 SET r1 = ? WHERE pk1 = ? AND ck1 = ?;', bindings=(short)-23292,(short)-3815,(short)19178}
LTS: 0. Pd 28953. Finished
LTS: 1. Pd 43920. Cd 39188. M 0. OpId: 0 Statement CompiledStatement{cql='INSERT INTO harry.test_table (pk1,ck1,r1) VALUES (?, ?, ?) USING TIMESTAMP 1696363940366001;', bindings=(short)11152,(short)6420,(short)23445}
LTS: 1. Pd 43920. Cd 65320. M 0. OpId: 1 Statement CompiledStatement{cql='INSERT INTO harry.test_table (pk1,ck1,r1) VALUES (?, ?, ?) USING TIMESTAMP 1696363940366001;', bindings=(short)11152,(short)32552,(short)7293}
LTS: 1. Pd 43920. Cd 60286. M 1. OpId: 2 Statement CompiledStatement{cql='INSERT INTO harry.test_table (pk1,ck1) VALUES (?, ?) USING TIMESTAMP 1696363940366001;', bindings=(short)11152,(short)27518}
LTS: 1. Pd 43920. Cd 41517. M 1. OpId: 3 Statement CompiledStatement{cql='INSERT INTO harry.test_table (pk1,ck1) VALUES (?, ?) USING TIMESTAMP 1696363940366001;', bindings=(short)11152,(short)8749}
LTS: 1. Pd 43920. Finished

But Harry complains that the partition with pk1 = 1152 should be empty, which is obviously wrong.

ERROR [main] instance_id_IS_UNDEFINED 2023-10-03 22:12:20,475 HarryRunner.java:54 - Failed due to exception: java.util.concurrent.ExecutionException: harry.model.Model$ValidationException: Expected results to have the same number of results, but actual result iterator has more results.
Expected: []
Actual:   [resultSetRow(43920L, 65320, values(7293L), lts(1L)), resultSetRow(43920L, 60286, values(-9223372036854775808L), lts(-9223372036854775808L)), resultSetRow(43920L, 41517, values(-9223372036854775808L), lts(-9223372036854775808L)), resultSetRow(43920L, 39188, values(23445L), lts(1L))]
Query: CompiledStatement{cql='SELECT pk1, ck1, r1, writetime(r1) FROM harry.test_table WHERE pk1 = ? ORDER BY ck1 DESC;', bindings=(short)11152}
Partition state:

Observed state:
resultSetRow(43920L, 65320, values(7293L), lts(1L))
resultSetRow(43920L, 60286, values(-9223372036854775808L), lts(-9223372036854775808L))
resultSetRow(43920L, 41517, values(-9223372036854775808L), lts(-9223372036854775808L))
resultSetRow(43920L, 39188, values(23445L), lts(1L))

Here's the full log (enrichened with some custom debug prints): small-fail-log.txt

It looks like some kind of race condition in Harry - it doesn't expect the rows that it has just inserted a moment ago. I'm digging into the code, trying to figure out what's going on there.

cvybhu commented 1 year ago

I reduced the test to make it smaller by changing external.yaml to:

It turns out that Harry doesn't correctly handle types smaller than 8 bytes.

Harry uses a clever random number generator which is able to work both ways. Given an index i it generates random 64 bit value v on that index. But it can also do the opposite - given a value v it's able to determine the i from which this value was generated.

Sadly there's a bug - when the partition key column is less than 64 bits Harry "adjusts entropy" by discarding all bytes above the column's size. So, if a column is of type smallint it would only leave the lower 16 bits of the value, the rest gets zeroed out. Later when Harry tries to figure out what i corresponds to this value it doesn't work because the value lost 48 bits. As a result it tries to calculate the wrong things and the test fails.

It's good to know, I'll probably go and open an issue in Cassandra's JIRA, but this doesn't answer the question why the original test failed. Conveniently all column types in the default configuration have > 64 bits, so they aren't affected by this bug ;)

fruch commented 1 year ago

Also doesn't answer how Cassandra was working o.k. as you reported vs. scylla