Skip to content
This repository was archived by the owner on Apr 4, 2023. It is now read-only.

Spurious test failure: Data was not replicated to second node #343

Open
wallrj opened this issue Apr 27, 2018 · 1 comment
Open

Spurious test failure: Data was not replicated to second node #343

wallrj opened this issue Apr 27, 2018 · 1 comment
Labels
area/test kind/bug

Comments

@wallrj
Copy link
Member

wallrj commented Apr 27, 2018

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
@wallrj wallrj mentioned this issue Apr 27, 2018
Merged
@munnerz
Copy link
Contributor

munnerz commented Apr 27, 2018

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.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
area/test kind/bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@munnerz @wallrj @jetstack-bot