You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Jim Witschey (JIRA)" <ji...@apache.org> on 2016/07/13 14:50:20 UTC
[jira] [Commented] (CASSANDRA-11465) dtest failure in
cql_tracing_test.TestCqlTracing.tracing_unknown_impl_test
[ https://issues.apache.org/jira/browse/CASSANDRA-11465?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15375145#comment-15375145 ]
Jim Witschey commented on CASSANDRA-11465:
------------------------------------------
Another failure we're seeing:
http://cassci.datastax.com/job/trunk_dtest/1288/testReport/junit/cql_tracing_test/TestCqlTracing/tracing_unknown_impl_test/
{code}
'/127.0.0.1' not found in "Consistency level set to ALL.\nNow Tracing is enabled\n\nTracing session: 54778be0-3c80-11e6-a333-ef4c703100c3\n\n activity | timestamp | source | source_elapsed | client\n----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------\n Execute CQL3 query | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 0 | 127.0.0.1\n Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, 'Frodo', 'Baggins', 32); [Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 462 | 127.0.0.1\n Preparing statement [Native-Transport-Requests-2] | 2016-06-27 16:00:55.199000 | 127.0.0.1 | 953 | 127.0.0.1\n Determining replicas for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000 | 127.0.0.1 | 1773 | 127.0.0.1\n Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4094 | 127.0.0.1\n Sending MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4117 | 127.0.0.1\n Appending to commitlog [Native-Transport-Requests-2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4270 | 127.0.0.1\n Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000 | 127.0.0.1 | 4758 | 127.0.0.1\n REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 14833 | 127.0.0.1\n Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 15059 | 127.0.0.1\n REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19203 | 127.0.0.1\n Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19379 | 127.0.0.1\n Request complete | 2016-06-27 16:00:55.217557 | 127.0.0.1 | 19557 | 127.0.0.1\n\n\n"
-------------------- >> begin captured logging << --------------------
dtest: DEBUG: cluster ccm directory: /tmp/dtest-RJbUwP
dtest: DEBUG: Custom init_config not found. Setting defaults.
dtest: DEBUG: Done setting configuration options:
{ 'initial_token': None,
'num_tokens': '32',
'phi_convict_threshold': 5,
'range_request_timeout_in_ms': 10000,
'read_request_timeout_in_ms': 10000,
'request_timeout_in_ms': 10000,
'truncate_request_timeout_in_ms': 10000,
'write_request_timeout_in_ms': 10000}
dtest: DEBUG: Consistency level set to ALL.
Now Tracing is enabled
Tracing session: 54778be0-3c80-11e6-a333-ef4c703100c3
activity | timestamp | source | source_elapsed | client
----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, 'Frodo', 'Baggins', 32); [Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 462 | 127.0.0.1
Preparing statement [Native-Transport-Requests-2] | 2016-06-27 16:00:55.199000 | 127.0.0.1 | 953 | 127.0.0.1
Determining replicas for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000 | 127.0.0.1 | 1773 | 127.0.0.1
Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4094 | 127.0.0.1
Sending MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4117 | 127.0.0.1
Appending to commitlog [Native-Transport-Requests-2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4270 | 127.0.0.1
Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000 | 127.0.0.1 | 4758 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 14833 | 127.0.0.1
Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 15059 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19203 | 127.0.0.1
Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19379 | 127.0.0.1
Request complete | 2016-06-27 16:00:55.217557 | 127.0.0.1 | 19557 | 127.0.0.1
--------------------- >> end captured logging << ---------------------
Stacktrace
File "/usr/lib/python2.7/unittest/case.py", line 329, in run
testMethod()
File "/home/automaton/cassandra-dtest/tools.py", line 288, in wrapped
f(obj)
File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 126, in tracing_unknown_impl_test
self.trace(session)
File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 75, in trace
self.assertIn('/127.0.0.1', out)
File "/usr/lib/python2.7/unittest/case.py", line 803, in assertIn
self.fail(self._formatMessage(msg, standardMsg))
File "/usr/lib/python2.7/unittest/case.py", line 410, in fail
raise self.failureException(msg)
'\'/127.0.0.1\' not found in "Consistency level set to ALL.\\nNow Tracing is enabled\\n\\nTracing session: 54778be0-3c80-11e6-a333-ef4c703100c3\\n\\n activity | timestamp | source | source_elapsed | client\\n----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------\\n Execute CQL3 query | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 0 | 127.0.0.1\\n Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, \'Frodo\', \'Baggins\', 32); [Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 462 | 127.0.0.1\\n Preparing statement [Native-Transport-Requests-2] | 2016-06-27 16:00:55.199000 | 127.0.0.1 | 953 | 127.0.0.1\\n Determining replicas for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000 | 127.0.0.1 | 1773 | 127.0.0.1\\n Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4094 | 127.0.0.1\\n Sending MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4117 | 127.0.0.1\\n Appending to commitlog [Native-Transport-Requests-2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4270 | 127.0.0.1\\n Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000 | 127.0.0.1 | 4758 | 127.0.0.1\\n REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 14833 | 127.0.0.1\\n Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 15059 | 127.0.0.1\\n REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19203 | 127.0.0.1\\n Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19379 | 127.0.0.1\\n Request complete | 2016-06-27 16:00:55.217557 | 127.0.0.1 | 19557 | 127.0.0.1\\n\\n\\n"\n-------------------- >> begin captured logging << --------------------\ndtest: DEBUG: cluster ccm directory: /tmp/dtest-RJbUwP\ndtest: DEBUG: Custom init_config not found. Setting defaults.\ndtest: DEBUG: Done setting configuration options:\n{ \'initial_token\': None,\n \'num_tokens\': \'32\',\n \'phi_convict_threshold\': 5,\n \'range_request_timeout_in_ms\': 10000,\n \'read_request_timeout_in_ms\': 10000,\n \'request_timeout_in_ms\': 10000,\n \'truncate_request_timeout_in_ms\': 10000,\n \'write_request_timeout_in_ms\': 10000}\ndtest: DEBUG: Consistency level set to ALL.\nNow Tracing is enabled\n\nTracing session: 54778be0-3c80-11e6-a333-ef4c703100c3\n\n activity | timestamp | source | source_elapsed | client\n----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------\n Execute CQL3 query | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 0 | 127.0.0.1\n Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, \'Frodo\', \'Baggins\', 32); [Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1 | 462 | 127.0.0.1\n Preparing statement [Native-Transport-Requests-2] | 2016-06-27 16:00:55.199000 | 127.0.0.1 | 953 | 127.0.0.1\n Determining replicas for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000 | 127.0.0.1 | 1773 | 127.0.0.1\n Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4094 | 127.0.0.1\n Sending MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4117 | 127.0.0.1\n Appending to commitlog [Native-Transport-Requests-2] | 2016-06-27 16:00:55.202000 | 127.0.0.1 | 4270 | 127.0.0.1\n Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000 | 127.0.0.1 | 4758 | 127.0.0.1\n REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 14833 | 127.0.0.1\n Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000 | 127.0.0.1 | 15059 | 127.0.0.1\n REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19203 | 127.0.0.1\n Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000 | 127.0.0.1 | 19379 | 127.0.0.1\n Request complete | 2016-06-27 16:00:55.217557 | 127.0.0.1 | 19557 | 127.0.0.1\n\n\n\n--------------------- >> end captured logging << ---------------------'
Standard Output
(EE) (EE) (EE)
{code}
We should be seeing all those trace entries. Here's an example of the output from a successful trace in a successful local run:
{code}
activity | timestamp | source | source_elapsed | client
----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2016-07-13 10:47:36.596000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, 'Frodo', 'Baggins', 32); [Native-Transport-Requests-2] | 2016-07-13 10:47:36.596000 | 127.0.0.1 | 240 | 127.0.0.1
Preparing statement [Native-Transport-Requests-2] | 2016-07-13 10:47:36.596000 | 127.0.0.1 | 502 | 127.0.0.1
Determining replicas for mutation [Native-Transport-Requests-2] | 2016-07-13 10:47:36.597000 | 127.0.0.1 | 997 | 127.0.0.1
Sending MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-07-13 10:47:36.597000 | 127.0.0.1 | 1557 | 127.0.0.1
Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-07-13 10:47:36.598000 | 127.0.0.1 | 2138 | 127.0.0.1
MUTATION message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-13 10:47:36.599000 | 127.0.0.2 | 457 | 127.0.0.1
MUTATION message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-13 10:47:36.600000 | 127.0.0.3 | 347 | 127.0.0.1
Appending to commitlog [MutationStage-1] | 2016-07-13 10:47:36.600000 | 127.0.0.1 | 3996 | 127.0.0.1
Adding to users memtable [MutationStage-1] | 2016-07-13 10:47:36.600000 | 127.0.0.1 | 4332 | 127.0.0.1
Appending to commitlog [MutationStage-2] | 2016-07-13 10:47:36.601000 | 127.0.0.2 | 1966 | 127.0.0.1
Adding to users memtable [MutationStage-2] | 2016-07-13 10:47:36.601000 | 127.0.0.2 | 2308 | 127.0.0.1
Appending to commitlog [MutationStage-2] | 2016-07-13 10:47:36.602000 | 127.0.0.3 | 2581 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-07-13 10:47:36.602000 | 127.0.0.1 | 6584 | 127.0.0.1
Enqueuing response to /127.0.0.1 [MutationStage-2] | 2016-07-13 10:47:36.602000 | 127.0.0.2 | 2693 | 127.0.0.1
Adding to users memtable [MutationStage-2] | 2016-07-13 10:47:36.602000 | 127.0.0.3 | 2938 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-13 10:47:36.602000 | 127.0.0.2 | 3008 | 127.0.0.1
Enqueuing response to /127.0.0.1 [MutationStage-2] | 2016-07-13 10:47:36.603000 | 127.0.0.3 | 3278 | 127.0.0.1
Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-07-13 10:47:36.603000 | 127.0.0.1 | 7515 | 127.0.0.1
Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-13 10:47:36.605000 | 127.0.0.3 | 5241 | 127.0.0.1
REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-07-13 10:47:36.605000 | 127.0.0.1 | 9261 | 127.0.0.1
Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-07-13 10:47:36.605000 | 127.0.0.1 | 9484 | 127.0.0.1
Request complete | 2016-07-13 10:47:36.605643 | 127.0.0.1 | 9643 | 127.0.0.1
{code}
> dtest failure in cql_tracing_test.TestCqlTracing.tracing_unknown_impl_test
> --------------------------------------------------------------------------
>
> Key: CASSANDRA-11465
> URL: https://issues.apache.org/jira/browse/CASSANDRA-11465
> Project: Cassandra
> Issue Type: Test
> Reporter: Philip Thompson
> Assignee: Jim Witschey
> Labels: dtest
>
> Failing on the following assert, on trunk only: {{self.assertEqual(len(errs[0]), 1)}}
> Is not failing consistently.
> example failure:
> http://cassci.datastax.com/job/trunk_dtest/1087/testReport/cql_tracing_test/TestCqlTracing/tracing_unknown_impl_test
> Failed on CassCI build trunk_dtest #1087
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)