You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Alex Petrov (JIRA)" <ji...@apache.org> on 2016/07/14 09:09:21 UTC
[jira] [Comment Edited] (CASSANDRA-12193) dtest failure in
upgrade_tests.cql_tests.TestCQLNodes3RF3_Upgrade_current_2_1_x_To_indev_3_0_x.noncomposite_static_cf_test
[ https://issues.apache.org/jira/browse/CASSANDRA-12193?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15376621#comment-15376621 ]
Alex Petrov edited comment on CASSANDRA-12193 at 7/14/16 9:09 AM:
------------------------------------------------------------------
I've reproduced it locally.
{code}
From the upgraded node alone:
cqlsh:ks> select * from users;
userid | age | firstname | lastname
--------------------------------------+-----+-----------+----------
f47ac10b-58cc-4372-a567-0e02b2c3d479 | 33 | Samwise | Gamgee
550e8400-e29b-41d4-a716-446655440000 | 32 | Frodo | Baggins
(2 rows)
From the upgraded node in presence of older nodes (for several minutes after the startup)
cqlsh:ks> select * from users;
userid | age | firstname | lastname
--------------------------------------+------+-----------+----------
f47ac10b-58cc-4372-a567-0e02b2c3d479 | null | null | null
f47ac10b-58cc-4372-a567-0e02b2c3d479 | null | null | null
f47ac10b-58cc-4372-a567-0e02b2c3d479 | null | null | null
550e8400-e29b-41d4-a716-446655440000 | null | null | null
550e8400-e29b-41d4-a716-446655440000 | null | null | null
550e8400-e29b-41d4-a716-446655440000 | null | null | null
{code}
Tracing information:
{code}
activity | timestamp | source | source_elapsed | client
-------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2016-07-14 11:04:24.276000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing select * from users; [Native-Transport-Requests-1] | 2016-07-14 11:04:24.276000 | 127.0.0.1 | 237 | 127.0.0.1
Preparing statement [Native-Transport-Requests-1] | 2016-07-14 11:04:24.277000 | 127.0.0.1 | 376 | 127.0.0.1
Computing ranges to query [Native-Transport-Requests-1] | 2016-07-14 11:04:24.277000 | 127.0.0.1 | 667 | 127.0.0.1
Submitting range requests on 769 ranges with a concurrency of 112 (0.9 rows per range expected) [Native-Transport-Requests-1] | 2016-07-14 11:04:24.277000 | 127.0.0.1 | 1252 | 127.0.0.1
Enqueuing request to /127.0.0.3 [Native-Transport-Requests-1] | 2016-07-14 11:04:24.281000 | 127.0.0.1 | 4656 | 127.0.0.1
Submitted 1 concurrent range requests [Native-Transport-Requests-1] | 2016-07-14 11:04:24.281000 | 127.0.0.1 | 4886 | 127.0.0.1
Sending RANGE_SLICE message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-07-14 11:04:24.281000 | 127.0.0.1 | 5067 | 127.0.0.1
RANGE_SLICE message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:04:24.282000 | 127.0.0.3 | 42 | 127.0.0.1
Executing seq scan across 1 sstables for (min(-9223372036854775808), min(-9223372036854775808)] [SharedPool-Worker-1] | 2016-07-14 11:04:24.285000 | 127.0.0.3 | 807 | 127.0.0.1
Scanned 2 rows and matched 2 [SharedPool-Worker-1] | 2016-07-14 11:04:24.286000 | 127.0.0.3 | 2706 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-07-14 11:04:24.286000 | 127.0.0.1 | 9487 | 127.0.0.1
Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-07-14 11:04:24.286000 | 127.0.0.1 | 10017 | 127.0.0.1
Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-07-14 11:04:24.287000 | 127.0.0.3 | 2749 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:04:24.288000 | 127.0.0.3 | 3091 | 127.0.0.1
Request complete | 2016-07-14 11:04:24.286485 | 127.0.0.1 | 10485 | 127.0.0.1
after ~2 min after startup
userid | age | firstname | lastname
--------------------------------------+-----+-----------+----------
f47ac10b-58cc-4372-a567-0e02b2c3d479 | 33 | Samwise | Gamgee
f47ac10b-58cc-4372-a567-0e02b2c3d479 | 33 | Samwise | Gamgee
f47ac10b-58cc-4372-a567-0e02b2c3d479 | 33 | Samwise | Gamgee
550e8400-e29b-41d4-a716-446655440000 | 32 | Frodo | Baggins
550e8400-e29b-41d4-a716-446655440000 | 32 | Frodo | Baggins
550e8400-e29b-41d4-a716-446655440000 | 32 | Frodo | Baggins
(6 rows)
Tracing session: 6d7d32f0-49a2-11e6-a54f-d3a89180649d
activity | timestamp | source | source_elapsed | client
-------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2016-07-14 11:07:45.183000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing select * from users ; [Native-Transport-Requests-1] | 2016-07-14 11:07:45.183000 | 127.0.0.1 | 189 | 127.0.0.1
Preparing statement [Native-Transport-Requests-1] | 2016-07-14 11:07:45.183000 | 127.0.0.1 | 356 | 127.0.0.1
Computing ranges to query [Native-Transport-Requests-1] | 2016-07-14 11:07:45.184000 | 127.0.0.1 | 643 | 127.0.0.1
Submitting range requests on 769 ranges with a concurrency of 112 (0.9 rows per range expected) [Native-Transport-Requests-1] | 2016-07-14 11:07:45.184000 | 127.0.0.1 | 1369 | 127.0.0.1
Enqueuing request to /127.0.0.1 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.188000 | 127.0.0.1 | 5083 | 127.0.0.1
Enqueuing request to /127.0.0.2 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.188000 | 127.0.0.1 | 5324 | 127.0.0.1
Sending RANGE_SLICE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.188000 | 127.0.0.1 | 5403 | 127.0.0.1
Enqueuing request to /127.0.0.3 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.188000 | 127.0.0.1 | 5440 | 127.0.0.1
Submitted 1 concurrent range requests [Native-Transport-Requests-1] | 2016-07-14 11:07:45.188000 | 127.0.0.1 | 5540 | 127.0.0.1
Sending RANGE_SLICE message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-07-14 11:07:45.188000 | 127.0.0.1 | 5588 | 127.0.0.1
Sending RANGE_SLICE message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-07-14 11:07:45.189000 | 127.0.0.1 | 5672 | 127.0.0.1
RANGE_SLICE message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.189000 | 127.0.0.1 | 6017 | 127.0.0.1
Executing seq scan across 1 sstables for (min(-9223372036854775808), min(-9223372036854775808)] [ReadStage-2] | 2016-07-14 11:07:45.189000 | 127.0.0.1 | 6263 | 127.0.0.1
Read 2 live and 0 tombstone cells [ReadStage-2] | 2016-07-14 11:07:45.190000 | 127.0.0.1 | 7169 | 127.0.0.1
Enqueuing response to /127.0.0.1 [ReadStage-2] | 2016-07-14 11:07:45.190000 | 127.0.0.1 | 7316 | 127.0.0.1
RANGE_SLICE message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.191000 | 127.0.0.3 | 51 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.191000 | 127.0.0.1 | 8033 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.192000 | 127.0.0.1 | 8737 | 127.0.0.1
RANGE_SLICE message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.192000 | 127.0.0.2 | 83 | 127.0.0.1
Processing response from /127.0.0.1 [RequestResponseStage-3] | 2016-07-14 11:07:45.193000 | 127.0.0.1 | 10217 | 127.0.0.1
Executing seq scan across 1 sstables for (min(-9223372036854775808), min(-9223372036854775808)] [SharedPool-Worker-1] | 2016-07-14 11:07:45.194000 | 127.0.0.3 | 1198 | 127.0.0.1
Scanned 2 rows and matched 2 [SharedPool-Worker-1] | 2016-07-14 11:07:45.195000 | 127.0.0.3 | 4173 | 127.0.0.1
Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-07-14 11:07:45.196000 | 127.0.0.3 | 4247 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-07-14 11:07:45.196000 | 127.0.0.1 | 12634 | 127.0.0.1
Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-07-14 11:07:45.196000 | 127.0.0.1 | 12775 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.199000 | 127.0.0.3 | 4970 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-07-14 11:07:45.200000 | 127.0.0.1 | 16874 | 127.0.0.1
Processing response from /127.0.0.2 [RequestResponseStage-2] | 2016-07-14 11:07:45.200000 | 127.0.0.1 | 17056 | 127.0.0.1
Executing seq scan across 1 sstables for (min(-9223372036854775808), min(-9223372036854775808)] [SharedPool-Worker-1] | 2016-07-14 11:07:45.208000 | 127.0.0.2 | 1522 | 127.0.0.1
Scanned 2 rows and matched 2 [SharedPool-Worker-1] | 2016-07-14 11:07:45.208000 | 127.0.0.2 | 6974 | 127.0.0.1
Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-07-14 11:07:45.209000 | 127.0.0.2 | 7040 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.209000 | 127.0.0.2 | 7496 | 127.0.0.1
Sending read-repair-mutation to /127.0.0.1 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.212000 | 127.0.0.1 | 29353 | 127.0.0.1
Sending read-repair-mutation to /127.0.0.3 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.213000 | 127.0.0.1 | 30385 | 127.0.0.1
Sending READ_REPAIR message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.213000 | 127.0.0.1 | 30407 | 127.0.0.1
Sending read-repair-mutation to /127.0.0.2 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.213000 | 127.0.0.1 | 30562 | 127.0.0.1
Sending READ_REPAIR message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-07-14 11:07:45.213000 | 127.0.0.1 | 30604 | 127.0.0.1
READ_REPAIR message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.214000 | 127.0.0.3 | 15 | 127.0.0.1
Sending READ_REPAIR message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-07-14 11:07:45.214000 | 127.0.0.1 | 30692 | 127.0.0.1
READ_REPAIR message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.214000 | 127.0.0.1 | 30917 | 127.0.0.1
Appending to commitlog [MutationStage-2] | 2016-07-14 11:07:45.214000 | 127.0.0.1 | 31011 | 127.0.0.1
Adding to users memtable [MutationStage-2] | 2016-07-14 11:07:45.214000 | 127.0.0.1 | 31119 | 127.0.0.1
Sending read-repair-mutation to /127.0.0.1 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.214000 | 127.0.0.1 | 31207 | 127.0.0.1
Sending read-repair-mutation to /127.0.0.3 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.214000 | 127.0.0.1 | 31329 | 127.0.0.1
Sending read-repair-mutation to /127.0.0.2 [Native-Transport-Requests-1] | 2016-07-14 11:07:45.214001 | 127.0.0.1 | 31444 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-07-14 11:07:45.215000 | 127.0.0.1 | 37 | 127.0.0.1
READ_REPAIR message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:07:45.215000 | 127.0.0.2 | 14 | 127.0.0.1
Processing response from /127.0.0.3 [RequestResponseStage-1] | 2016-07-14 11:07:45.215000 | 127.0.0.1 | 314 | 127.0.0.1
Appending to commitlog [SharedPool-Worker-6] | 2016-07-14 11:07:45.215000 | 127.0.0.2 | 319 | 127.0.0.1
Adding to users memtable [SharedPool-Worker-6] | 2016-07-14 11:07:45.215000 | 127.0.0.2 | 716 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-07-14 11:07:45.216000 | 127.0.0.1 | 12 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.216000 | 127.0.0.2 | 1685 | 127.0.0.1
Processing response from /127.0.0.2 [RequestResponseStage-2] | 2016-07-14 11:07:45.216000 | 127.0.0.1 | 218 | 127.0.0.1
Appending to commitlog [SharedPool-Worker-1] | 2016-07-14 11:07:45.217000 | 127.0.0.3 | 98 | 127.0.0.1
Adding to users memtable [SharedPool-Worker-1] | 2016-07-14 11:07:45.220000 | 127.0.0.3 | 209 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.221000 | 127.0.0.3 | 576 | 127.0.0.1
Sending READ_REPAIR message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:07:45.224000 | 127.0.0.1 | -- | 127.0.0.1
Request complete | 2016-07-14 11:07:45.214616 | 127.0.0.1 | 31616 | 127.0.0.1
{code}
(node1 is upgraded)
was (Author: ifesdjeen):
I've reproduced it locally, and it seems that the nodes eventually recover (takes a couple of minutes)
{code}
From the upgraded node alone:
cqlsh:ks> select * from users;
userid | age | firstname | lastname
--------------------------------------+-----+-----------+----------
f47ac10b-58cc-4372-a567-0e02b2c3d479 | 33 | Samwise | Gamgee
550e8400-e29b-41d4-a716-446655440000 | 32 | Frodo | Baggins
(2 rows)
From the upgraded node in presence of older nodes:
cqlsh:ks> select * from users;
userid | age | firstname | lastname
--------------------------------------+------+-----------+----------
f47ac10b-58cc-4372-a567-0e02b2c3d479 | null | null | null
f47ac10b-58cc-4372-a567-0e02b2c3d479 | null | null | null
f47ac10b-58cc-4372-a567-0e02b2c3d479 | null | null | null
550e8400-e29b-41d4-a716-446655440000 | null | null | null
550e8400-e29b-41d4-a716-446655440000 | null | null | null
550e8400-e29b-41d4-a716-446655440000 | null | null | null
{code}
Tracing information:
{code}
activity | timestamp | source | source_elapsed | client
-------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2016-07-14 11:04:24.276000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing select * from users; [Native-Transport-Requests-1] | 2016-07-14 11:04:24.276000 | 127.0.0.1 | 237 | 127.0.0.1
Preparing statement [Native-Transport-Requests-1] | 2016-07-14 11:04:24.277000 | 127.0.0.1 | 376 | 127.0.0.1
Computing ranges to query [Native-Transport-Requests-1] | 2016-07-14 11:04:24.277000 | 127.0.0.1 | 667 | 127.0.0.1
Submitting range requests on 769 ranges with a concurrency of 112 (0.9 rows per range expected) [Native-Transport-Requests-1] | 2016-07-14 11:04:24.277000 | 127.0.0.1 | 1252 | 127.0.0.1
Enqueuing request to /127.0.0.3 [Native-Transport-Requests-1] | 2016-07-14 11:04:24.281000 | 127.0.0.1 | 4656 | 127.0.0.1
Submitted 1 concurrent range requests [Native-Transport-Requests-1] | 2016-07-14 11:04:24.281000 | 127.0.0.1 | 4886 | 127.0.0.1
Sending RANGE_SLICE message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-07-14 11:04:24.281000 | 127.0.0.1 | 5067 | 127.0.0.1
RANGE_SLICE message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-14 11:04:24.282000 | 127.0.0.3 | 42 | 127.0.0.1
Executing seq scan across 1 sstables for (min(-9223372036854775808), min(-9223372036854775808)] [SharedPool-Worker-1] | 2016-07-14 11:04:24.285000 | 127.0.0.3 | 807 | 127.0.0.1
Scanned 2 rows and matched 2 [SharedPool-Worker-1] | 2016-07-14 11:04:24.286000 | 127.0.0.3 | 2706 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-07-14 11:04:24.286000 | 127.0.0.1 | 9487 | 127.0.0.1
Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-07-14 11:04:24.286000 | 127.0.0.1 | 10017 | 127.0.0.1
Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-07-14 11:04:24.287000 | 127.0.0.3 | 2749 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-14 11:04:24.288000 | 127.0.0.3 | 3091 | 127.0.0.1
Request complete | 2016-07-14 11:04:24.286485 | 127.0.0.1 | 10485 | 127.0.0.1
{code}
(node1 is upgraded)
> dtest failure in upgrade_tests.cql_tests.TestCQLNodes3RF3_Upgrade_current_2_1_x_To_indev_3_0_x.noncomposite_static_cf_test
> --------------------------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-12193
> URL: https://issues.apache.org/jira/browse/CASSANDRA-12193
> Project: Cassandra
> Issue Type: Bug
> Reporter: Sean McCarthy
> Assignee: Alex Petrov
> Labels: dtest
> Attachments: node1.log, node1_debug.log, node1_gc.log, node2.log, node3.log
>
>
> example failure:
> http://cassci.datastax.com/job/upgrade_tests-all/59/testReport/upgrade_tests.cql_tests/TestCQLNodes3RF3_Upgrade_current_2_1_x_To_indev_3_0_x/noncomposite_static_cf_test
> Failed on CassCI build upgrade_tests-all #59
> {code}
> Stacktrace
> File "/usr/lib/python2.7/unittest/case.py", line 329, in run
> testMethod()
> File "/home/automaton/cassandra-dtest/upgrade_tests/cql_tests.py", line 146, in noncomposite_static_cf_test
> [UUID('550e8400-e29b-41d4-a716-446655440000'), 32, 'Frodo', 'Baggins']])
> File "/home/automaton/cassandra-dtest/assertions.py", line 162, in assert_all
> assert list_res == expected, "Expected {} from {}, but got {}".format(expected, query, list_res)
> "Expected [[UUID('f47ac10b-58cc-4372-a567-0e02b2c3d479'), 33, 'Samwise', 'Gamgee'], [UUID('550e8400-e29b-41d4-a716-446655440000'), 32, 'Frodo', 'Baggins']] from SELECT * FROM users, but got [[UUID('f47ac10b-58cc-4372-a567-0e02b2c3d479'), 33, 'Samwise', 'Gamgee'], [UUID('f47ac10b-58cc-4372-a567-0e02b2c3d479'), 33, 'Samwise', 'Gamgee'], [UUID('f47ac10b-58cc-4372-a567-0e02b2c3d479'), 33, 'Samwise', 'Gamgee'], [UUID('550e8400-e29b-41d4-a716-446655440000'), 32, 'Frodo', 'Baggins'], [UUID('550e8400-e29b-41d4-a716-446655440000'), 32, 'Frodo', 'Baggins'], [UUID('550e8400-e29b-41d4-a716-446655440000'), 32, 'Frodo', 'Baggins']]
> {code}
> Related failure:
> http://cassci.datastax.com/job/upgrade_tests-all/59/testReport/upgrade_tests.cql_tests/TestCQLNodes3RF3_Upgrade_current_2_2_x_To_head_trunk/noncomposite_static_cf_test/
> http://cassci.datastax.com/job/upgrade_tests-all/59/testReport/upgrade_tests.cql_tests/TestCQLNodes2RF1_Upgrade_current_2_2_x_To_indev_3_0_x/noncomposite_static_cf_test/
> http://cassci.datastax.com/job/upgrade_tests-all/59/testReport/upgrade_tests.cql_tests/TestCQLNodes3RF3_Upgrade_current_2_2_x_To_indev_3_0_x/noncomposite_static_cf_test/
> http://cassci.datastax.com/job/upgrade_tests-all/59/testReport/upgrade_tests.cql_tests/TestCQLNodes3RF3_Upgrade_current_2_1_x_To_head_trunk/noncomposite_static_cf_test/
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)