Spurious test failure: Data was not replicated to second node

Question

Spurious test failure: Data was not replicated to second node

wallrj opened this issue 6 years ago · 1 comments

https://jetstack-build-infra.appspot.com/build/jetstack-logs/pr-logs/pull/jetstack_navigator/336/navigator-e2e-v1-9/722/

W0427 14:56:41.930] + retry stdout_matches testvalue1 cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:41.930] + local TIMEOUT=60
W0427 14:56:41.930] + local SLEEP=10
W0427 14:56:41.930] + :
W0427 14:56:41.931] + case "${1}" in
W0427 14:56:41.931] + break
W0427 14:56:41.931] + local start_time
W0427 14:56:41.931] ++ date +%s
W0427 14:56:41.931] + start_time=1524841001
W0427 14:56:41.931] + local end_time
W0427 14:56:41.931] + end_time=1524841061
W0427 14:56:41.931] + stdout_matches testvalue1 cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:41.931] + local expected=testvalue1
W0427 14:56:41.932] + shift
W0427 14:56:41.932] + local actual
W0427 14:56:41.932] ++ cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:41.932] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:56:41.932] ++ shift
W0427 14:56:41.932] ++ in_cluster_command test-cassandra-1524840199-15915 cassandra:latest /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:41.932] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:56:41.932] ++ shift
W0427 14:56:41.932] ++ local image=cassandra:latest
W0427 14:56:41.932] ++ shift
W0427 14:56:41.932] ++ kubectl run in-cluster-cmd-17569 --namespace=test-cassandra-1524840199-15915 --image=cassandra:latest --restart=Never --rm --stdin=true --attach=true --quiet --limits=cpu=100m,memory=500Mi --requests=cpu=100m,memory=500Mi -- /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:46.894] Using CQL driver: <module 'cassandra' from '/usr/share/cassandra/lib/cassandra-driver-internal-only-3.11.0-bb96859b.zip/cassandra-driver-3.11.0-bb96859b/cassandra/__init__.py'>
W0427 14:56:46.894] Using connect timeout: 5 seconds
W0427 14:56:46.894] Using 'utf-8' encoding
W0427 14:56:46.894] Using ssl: False
W0427 14:56:49.360] + actual=
W0427 14:56:49.360] + grep --quiet testvalue1
W0427 14:56:49.361] + local exit_code=1
W0427 14:56:49.362] ++ date +%s
W0427 14:56:49.363] + local current_time=1524841009
W0427 14:56:49.363] + local remaining_time=52
W0427 14:56:49.363] + [[ 52 -le 0 ]]
W0427 14:56:49.363] + local sleep_time=10
W0427 14:56:49.363] + [[ 52 -lt 10 ]]
W0427 14:56:49.363] + sleep 10
W0427 14:56:59.364] + stdout_matches testvalue1 cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:59.364] + local expected=testvalue1
W0427 14:56:59.364] + shift
W0427 14:56:59.364] + local actual
W0427 14:56:59.364] ++ cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:59.364] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:56:59.364] ++ shift
W0427 14:56:59.365] ++ in_cluster_command test-cassandra-1524840199-15915 cassandra:latest /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:56:59.365] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:56:59.365] ++ shift
W0427 14:56:59.365] ++ local image=cassandra:latest
W0427 14:56:59.365] ++ shift
W0427 14:56:59.365] ++ kubectl run in-cluster-cmd-11392 --namespace=test-cassandra-1524840199-15915 --image=cassandra:latest --restart=Never --rm --stdin=true --attach=true --quiet --limits=cpu=100m,memory=500Mi --requests=cpu=100m,memory=500Mi -- /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:03.303] Using CQL driver: <module 'cassandra' from '/usr/share/cassandra/lib/cassandra-driver-internal-only-3.11.0-bb96859b.zip/cassandra-driver-3.11.0-bb96859b/cassandra/__init__.py'>
W0427 14:57:03.303] Using connect timeout: 5 seconds
W0427 14:57:03.303] Using 'utf-8' encoding
W0427 14:57:03.303] Using ssl: False
W0427 14:57:04.665] + actual=
W0427 14:57:04.665] + grep --quiet testvalue1
W0427 14:57:04.667] + local exit_code=1
W0427 14:57:04.667] ++ date +%s
W0427 14:57:04.668] + local current_time=1524841024
W0427 14:57:04.668] + local remaining_time=37
W0427 14:57:04.668] + [[ 37 -le 0 ]]
W0427 14:57:04.668] + local sleep_time=10
W0427 14:57:04.669] + [[ 37 -lt 10 ]]
W0427 14:57:04.669] + sleep 10
W0427 14:57:14.670] + stdout_matches testvalue1 cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:14.670] + local expected=testvalue1
W0427 14:57:14.670] + shift
W0427 14:57:14.670] + local actual
W0427 14:57:14.670] ++ cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:14.670] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:57:14.670] ++ shift
W0427 14:57:14.670] ++ in_cluster_command test-cassandra-1524840199-15915 cassandra:latest /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:14.670] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:57:14.670] ++ shift
W0427 14:57:14.671] ++ local image=cassandra:latest
W0427 14:57:14.671] ++ shift
W0427 14:57:14.671] ++ kubectl run in-cluster-cmd-17005 --namespace=test-cassandra-1524840199-15915 --image=cassandra:latest --restart=Never --rm --stdin=true --attach=true --quiet --limits=cpu=100m,memory=500Mi --requests=cpu=100m,memory=500Mi -- /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:18.692] Using CQL driver: <module 'cassandra' from '/usr/share/cassandra/lib/cassandra-driver-internal-only-3.11.0-bb96859b.zip/cassandra-driver-3.11.0-bb96859b/cassandra/__init__.py'>
W0427 14:57:18.692] Using connect timeout: 5 seconds
W0427 14:57:18.692] Using 'utf-8' encoding
W0427 14:57:18.692] Using ssl: False
W0427 14:57:19.844] + actual=
W0427 14:57:19.844] + grep --quiet testvalue1
W0427 14:57:19.846] + local exit_code=1
W0427 14:57:19.846] ++ date +%s
W0427 14:57:19.847] + local current_time=1524841039
W0427 14:57:19.847] + local remaining_time=22
W0427 14:57:19.847] + [[ 22 -le 0 ]]
W0427 14:57:19.847] + local sleep_time=10
W0427 14:57:19.847] + [[ 22 -lt 10 ]]
W0427 14:57:19.847] + sleep 10
W0427 14:57:29.848] + stdout_matches testvalue1 cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:29.848] + local expected=testvalue1
W0427 14:57:29.849] + shift
W0427 14:57:29.849] + local actual
W0427 14:57:29.849] ++ cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:29.849] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:57:29.849] ++ shift
W0427 14:57:29.849] ++ in_cluster_command test-cassandra-1524840199-15915 cassandra:latest /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:29.849] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:57:29.849] ++ shift
W0427 14:57:29.849] ++ local image=cassandra:latest
W0427 14:57:29.849] ++ shift
W0427 14:57:29.850] ++ kubectl run in-cluster-cmd-19612 --namespace=test-cassandra-1524840199-15915 --image=cassandra:latest --restart=Never --rm --stdin=true --attach=true --quiet --limits=cpu=100m,memory=500Mi --requests=cpu=100m,memory=500Mi -- /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:34.100] Using CQL driver: <module 'cassandra' from '/usr/share/cassandra/lib/cassandra-driver-internal-only-3.11.0-bb96859b.zip/cassandra-driver-3.11.0-bb96859b/cassandra/__init__.py'>
W0427 14:57:34.100] Using connect timeout: 5 seconds
W0427 14:57:34.100] Using 'utf-8' encoding
W0427 14:57:34.100] Using ssl: False
W0427 14:57:35.430] + actual=
W0427 14:57:35.430] + grep --quiet testvalue1
W0427 14:57:35.431] + local exit_code=1
W0427 14:57:35.432] ++ date +%s
W0427 14:57:35.433] + local current_time=1524841055
W0427 14:57:35.433] + local remaining_time=6
W0427 14:57:35.433] + [[ 6 -le 0 ]]
W0427 14:57:35.433] + local sleep_time=10
W0427 14:57:35.433] + [[ 6 -lt 10 ]]
W0427 14:57:35.433] + sleep_time=6
W0427 14:57:35.433] + sleep 6
W0427 14:57:41.434] + stdout_matches testvalue1 cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:41.434] + local expected=testvalue1
W0427 14:57:41.434] + shift
W0427 14:57:41.434] + local actual
W0427 14:57:41.434] ++ cql_connect test-cassandra-1524840199-15915 cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:41.435] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:57:41.435] ++ shift
W0427 14:57:41.435] ++ in_cluster_command test-cassandra-1524840199-15915 cassandra:latest /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:41.435] ++ local namespace=test-cassandra-1524840199-15915
W0427 14:57:41.435] ++ shift
W0427 14:57:41.435] ++ local image=cassandra:latest
W0427 14:57:41.435] ++ shift
W0427 14:57:41.435] ++ kubectl run in-cluster-cmd-2294 --namespace=test-cassandra-1524840199-15915 --image=cassandra:latest --restart=Never --rm --stdin=true --attach=true --quiet --limits=cpu=100m,memory=500Mi --requests=cpu=100m,memory=500Mi -- /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 14:57:45.592] Using CQL driver: <module 'cassandra' from '/usr/share/cassandra/lib/cassandra-driver-internal-only-3.11.0-bb96859b.zip/cassandra-driver-3.11.0-bb96859b/cassandra/__init__.py'>
W0427 14:57:45.593] Using connect timeout: 5 seconds
W0427 14:57:45.593] Using 'utf-8' encoding
W0427 14:57:45.593] Using ssl: False
W0427 14:57:46.725] + actual=
W0427 14:57:46.726] + grep --quiet testvalue1
W0427 14:57:46.727] + local exit_code=1
W0427 14:57:46.728] ++ date +%s
W0427 14:57:46.728] + local current_time=1524841066
W0427 14:57:46.729] + local remaining_time=-5
W0427 14:57:46.729] + [[ -5 -le 0 ]]
W0427 14:57:46.729] + return 1
W0427 14:57:46.729] + fail_test 'Data was not replicated to second node'
W0427 14:57:46.729] + FAILURE_COUNT=1
W0427 14:57:46.729] + echo 'TEST FAILURE: Data was not replicated to second node'

I think we need to wait longer for the data to be replicated.

Later in the test, we see that the data has been replicated, so it's not that the data has been lost.

W0427 15:01:51.853] ++ kubectl run in-cluster-cmd-3797 --namespace=test-cassandra-1524840199-15915 --image=cassandra:latest --restart=Never --rm --stdin=true --attach=true --quiet --limits=cpu=100m,memory=500Mi --requests=cpu=100m,memory=500Mi -- /usr/bin/cqlsh cass-test-nodes 9042 --debug '--execute=CONSISTENCY ALL; SELECT * FROM space1.testtable1'
W0427 15:01:55.800] Using CQL driver: <module 'cassandra' from '/usr/share/cassandra/lib/cassandra-driver-internal-only-3.11.0-bb96859b.zip/cassandra-driver-3.11.0-bb96859b/cassandra/__init__.py'>
W0427 15:01:55.800] Using connect timeout: 5 seconds
W0427 15:01:55.800] Using 'utf-8' encoding
W0427 15:01:55.800] Using ssl: False
W0427 15:01:57.144] + actual='Consistency level set to ALL.
W0427 15:01:57.144] 
W0427 15:01:57.144]  key      | value
W0427 15:01:57.144] ----------+------------
W0427 15:01:57.144]  testkey1 | testvalue1
W0427 15:01:57.144] 
W0427 15:01:57.144] (1 rows)'
W0427 15:01:57.144] + grep --quiet testvalue1

/kind bug

Answer 1 · 2018-04-27T15:13:09.000Z

Looks like we only allow up to 1 minute for data to replicate? Let's bump this to more like 5-10 mins? Depending on how long it usually takes obviously.