You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Tyler Hobbs (JIRA)" <ji...@apache.org> on 2016/05/26 20:34:13 UTC
[jira] [Commented] (CASSANDRA-11598) dtest failure in
cql_tracing_test.TestCqlTracing.tracing_simple_test
[ https://issues.apache.org/jira/browse/CASSANDRA-11598?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15302867#comment-15302867 ]
Tyler Hobbs commented on CASSANDRA-11598:
-----------------------------------------
We definitely _should_ be getting trace entries from the 127.0.0.2 node, but it _is_ responding to the request and everything else looks normal. So, this problem seems to be isolated to tracing. Given that this is only a problem on 2.1 and we're only making critical fixes to 2.1 now, I think it's best to simply skip this test on 2.1. Spending too much time digging into 2.1 tracing quirks isn't worth it.
Do you agree, [~philipthompson]?
> dtest failure in cql_tracing_test.TestCqlTracing.tracing_simple_test
> --------------------------------------------------------------------
>
> Key: CASSANDRA-11598
> URL: https://issues.apache.org/jira/browse/CASSANDRA-11598
> Project: Cassandra
> Issue Type: Bug
> Components: Tools
> Reporter: Jim Witschey
> Assignee: Tyler Hobbs
> Labels: dtest
> Fix For: 2.1.x
>
>
> example failure:
> http://cassci.datastax.com/job/cassandra-2.1_offheap_dtest/330/testReport/cql_tracing_test/TestCqlTracing/tracing_simple_test
> Failed on CassCI build cassandra-2.1_offheap_dtest #330 - 2.1.14-tentative
> {{' 127.0.0.2 '}} isn't in the trace, but it looks like {{'\127.0.0.2 '}} is -- should we change the regex here?
> {code}
> Error Message
> ' 127.0.0.2 ' not found in 'Consistency level set to ALL.\nNow Tracing is enabled\n\n firstname | lastname\n-----------+----------\n Frodo | Baggins\n\n(1 rows)\n\nTracing session: 0268da20-0328-11e6-b014-53144f0dba91\n\n activity | timestamp | source | source_elapsed\n-----------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------\n Execute CQL3 query | 2016-04-15 16:35:05.538000 | 127.0.0.1 | 0\n READ message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-04-15 16:35:05.540000 | 127.0.0.3 | 47\n Parsing SELECT firstname, lastname FROM ks.users WHERE userid = 550e8400-e29b-41d4-a716-446655440000; [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 88\n Preparing statement [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 355\n reading digest from /127.0.0.2 [SharedPool-Worker-2] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1245\n Executing single-partition query on users [SharedPool-Worker-3] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1249\n Acquiring sstable references [SharedPool-Worker-3] | 2016-04-15 16:35:05.545000 | 127.0.0.1 | 1265\n Executing single-partition query on users [SharedPool-Worker-1] | 2016-04-15 16:35:05.546000 | 127.0.0.3 | 369\n Merging memtable tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.546000 | 127.0.0.1 | 1302\n reading digest from /127.0.0.3 [SharedPool-Worker-2] | 2016-04-15 16:35:05.547000 | 127.0.0.1 | 1338\n Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.548000 | 127.0.0.1 | 1403\n Acquiring sstable references [SharedPool-Worker-1] | 2016-04-15 16:35:05.549000 | 127.0.0.3 | 392\n Merging data from memtables and 0 sstables [SharedPool-Worker-3] | 2016-04-15 16:35:05.549000 | 127.0.0.1 | 1428\n Read 1 live and 0 tombstone cells [SharedPool-Worker-3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1509\n Sending READ message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1780\n Sending READ message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-04-15 16:35:05.551000 | 127.0.0.1 | 3748\n REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-04-15 16:35:05.552000 | 127.0.0.1 | 4454\n Merging memtable tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.553000 | 127.0.0.3 | 453\n Processing response from /127.0.0.3 [SharedPool-Worker-4] | 2016-04-15 16:35:05.553000 | 127.0.0.1 | 5110\n REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-04-15 16:35:05.554000 | 127.0.0.1 | 6892\n Processing response from /127.0.0.2 [SharedPool-Worker-4] | 2016-04-15 16:35:05.555000 | 127.0.0.1 | 7099\n Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.556000 | 127.0.0.3 | 596\n Merging data from memtables and 0 sstables [SharedPool-Worker-1] | 2016-04-15 16:35:05.559000 | 127.0.0.3 | 620\n Read 1 live and 0 tombstone cells [SharedPool-Worker-1] | 2016-04-15 16:35:05.560000 | 127.0.0.3 | 741\n Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-04-15 16:35:05.562000 | 127.0.0.3 | 1265\n Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-04-15 16:35:05.564000 | 127.0.0.3 | 1892\n Request complete | 2016-04-15 16:35:05.545435 | 127.0.0.1 | 7435\n\n\n'
> -------------------- >> begin captured logging << --------------------
> dtest: DEBUG: cluster ccm directory: /mnt/tmp/dtest-hfIRwY
> dtest: DEBUG: Custom init_config not found. Setting defaults.
> dtest: DEBUG: Done setting configuration options:
> { 'initial_token': None,
> 'memtable_allocation_type': 'offheap_objects',
> '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
> firstname | lastname
> -----------+----------
> Frodo | Baggins
> (1 rows)
> Tracing session: 0268da20-0328-11e6-b014-53144f0dba91
> activity | timestamp | source | source_elapsed
> -----------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------
> Execute CQL3 query | 2016-04-15 16:35:05.538000 | 127.0.0.1 | 0
> READ message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-04-15 16:35:05.540000 | 127.0.0.3 | 47
> Parsing SELECT firstname, lastname FROM ks.users WHERE userid = 550e8400-e29b-41d4-a716-446655440000; [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 88
> Preparing statement [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 355
> reading digest from /127.0.0.2 [SharedPool-Worker-2] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1245
> Executing single-partition query on users [SharedPool-Worker-3] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1249
> Acquiring sstable references [SharedPool-Worker-3] | 2016-04-15 16:35:05.545000 | 127.0.0.1 | 1265
> Executing single-partition query on users [SharedPool-Worker-1] | 2016-04-15 16:35:05.546000 | 127.0.0.3 | 369
> Merging memtable tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.546000 | 127.0.0.1 | 1302
> reading digest from /127.0.0.3 [SharedPool-Worker-2] | 2016-04-15 16:35:05.547000 | 127.0.0.1 | 1338
> Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.548000 | 127.0.0.1 | 1403
> Acquiring sstable references [SharedPool-Worker-1] | 2016-04-15 16:35:05.549000 | 127.0.0.3 | 392
> Merging data from memtables and 0 sstables [SharedPool-Worker-3] | 2016-04-15 16:35:05.549000 | 127.0.0.1 | 1428
> Read 1 live and 0 tombstone cells [SharedPool-Worker-3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1509
> Sending READ message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1780
> Sending READ message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-04-15 16:35:05.551000 | 127.0.0.1 | 3748
> REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-04-15 16:35:05.552000 | 127.0.0.1 | 4454
> Merging memtable tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.553000 | 127.0.0.3 | 453
> Processing response from /127.0.0.3 [SharedPool-Worker-4] | 2016-04-15 16:35:05.553000 | 127.0.0.1 | 5110
> REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-04-15 16:35:05.554000 | 127.0.0.1 | 6892
> Processing response from /127.0.0.2 [SharedPool-Worker-4] | 2016-04-15 16:35:05.555000 | 127.0.0.1 | 7099
> Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.556000 | 127.0.0.3 | 596
> Merging data from memtables and 0 sstables [SharedPool-Worker-1] | 2016-04-15 16:35:05.559000 | 127.0.0.3 | 620
> Read 1 live and 0 tombstone cells [SharedPool-Worker-1] | 2016-04-15 16:35:05.560000 | 127.0.0.3 | 741
> Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-04-15 16:35:05.562000 | 127.0.0.3 | 1265
> Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-04-15 16:35:05.564000 | 127.0.0.3 | 1892
> Request complete | 2016-04-15 16:35:05.545435 | 127.0.0.1 | 7435
> --------------------- >> end captured logging << ---------------------
> Stacktrace
> File "/usr/lib/python2.7/unittest/case.py", line 329, in run
> testMethod()
> File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 97, in tracing_simple_test
> self.trace(session)
> File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 85, in trace
> self.assertIn(' 127.0.0.2 ', 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.2 ' not found in 'Consistency level set to ALL.\\nNow Tracing is enabled\\n\\n firstname | lastname\\n-----------+----------\\n Frodo | Baggins\\n\\n(1 rows)\\n\\nTracing session: 0268da20-0328-11e6-b014-53144f0dba91\\n\\n activity | timestamp | source | source_elapsed\\n-----------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------\\n Execute CQL3 query | 2016-04-15 16:35:05.538000 | 127.0.0.1 | 0\\n READ message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-04-15 16:35:05.540000 | 127.0.0.3 | 47\\n Parsing SELECT firstname, lastname FROM ks.users WHERE userid = 550e8400-e29b-41d4-a716-446655440000; [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 88\\n Preparing statement [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 355\\n reading digest from /127.0.0.2 [SharedPool-Worker-2] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1245\\n Executing single-partition query on users [SharedPool-Worker-3] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1249\\n Acquiring sstable references [SharedPool-Worker-3] | 2016-04-15 16:35:05.545000 | 127.0.0.1 | 1265\\n Executing single-partition query on users [SharedPool-Worker-1] | 2016-04-15 16:35:05.546000 | 127.0.0.3 | 369\\n Merging memtable tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.546000 | 127.0.0.1 | 1302\\n reading digest from /127.0.0.3 [SharedPool-Worker-2] | 2016-04-15 16:35:05.547000 | 127.0.0.1 | 1338\\n Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.548000 | 127.0.0.1 | 1403\\n Acquiring sstable references [SharedPool-Worker-1] | 2016-04-15 16:35:05.549000 | 127.0.0.3 | 392\\n Merging data from memtables and 0 sstables [SharedPool-Worker-3] | 2016-04-15 16:35:05.549000 | 127.0.0.1 | 1428\\n Read 1 live and 0 tombstone cells [SharedPool-Worker-3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1509\\n Sending READ message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1780\\n Sending READ message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-04-15 16:35:05.551000 | 127.0.0.1 | 3748\\n REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-04-15 16:35:05.552000 | 127.0.0.1 | 4454\\n Merging memtable tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.553000 | 127.0.0.3 | 453\\n Processing response from /127.0.0.3 [SharedPool-Worker-4] | 2016-04-15 16:35:05.553000 | 127.0.0.1 | 5110\\n REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-04-15 16:35:05.554000 | 127.0.0.1 | 6892\\n Processing response from /127.0.0.2 [SharedPool-Worker-4] | 2016-04-15 16:35:05.555000 | 127.0.0.1 | 7099\\n Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.556000 | 127.0.0.3 | 596\\n Merging data from memtables and 0 sstables [SharedPool-Worker-1] | 2016-04-15 16:35:05.559000 | 127.0.0.3 | 620\\n Read 1 live and 0 tombstone cells [SharedPool-Worker-1] | 2016-04-15 16:35:05.560000 | 127.0.0.3 | 741\\n Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-04-15 16:35:05.562000 | 127.0.0.3 | 1265\\n Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-04-15 16:35:05.564000 | 127.0.0.3 | 1892\\n Request complete | 2016-04-15 16:35:05.545435 | 127.0.0.1 | 7435\\n\\n\\n'\n-------------------- >> begin captured logging << --------------------\ndtest: DEBUG: cluster ccm directory: /mnt/tmp/dtest-hfIRwY\ndtest: DEBUG: Custom init_config not found. Setting defaults.\ndtest: DEBUG: Done setting configuration options:\n{ 'initial_token': None,\n 'memtable_allocation_type': 'offheap_objects',\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\n firstname | lastname\n-----------+----------\n Frodo | Baggins\n\n(1 rows)\n\nTracing session: 0268da20-0328-11e6-b014-53144f0dba91\n\n activity | timestamp | source | source_elapsed\n-----------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------\n Execute CQL3 query | 2016-04-15 16:35:05.538000 | 127.0.0.1 | 0\n READ message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-04-15 16:35:05.540000 | 127.0.0.3 | 47\n Parsing SELECT firstname, lastname FROM ks.users WHERE userid = 550e8400-e29b-41d4-a716-446655440000; [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 88\n Preparing statement [SharedPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 355\n reading digest from /127.0.0.2 [SharedPool-Worker-2] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1245\n Executing single-partition query on users [SharedPool-Worker-3] | 2016-04-15 16:35:05.542000 | 127.0.0.1 | 1249\n Acquiring sstable references [SharedPool-Worker-3] | 2016-04-15 16:35:05.545000 | 127.0.0.1 | 1265\n Executing single-partition query on users [SharedPool-Worker-1] | 2016-04-15 16:35:05.546000 | 127.0.0.3 | 369\n Merging memtable tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.546000 | 127.0.0.1 | 1302\n reading digest from /127.0.0.3 [SharedPool-Worker-2] | 2016-04-15 16:35:05.547000 | 127.0.0.1 | 1338\n Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.548000 | 127.0.0.1 | 1403\n Acquiring sstable references [SharedPool-Worker-1] | 2016-04-15 16:35:05.549000 | 127.0.0.3 | 392\n Merging data from memtables and 0 sstables [SharedPool-Worker-3] | 2016-04-15 16:35:05.549000 | 127.0.0.1 | 1428\n Read 1 live and 0 tombstone cells [SharedPool-Worker-3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1509\n Sending READ message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-04-15 16:35:05.550000 | 127.0.0.1 | 1780\n Sending READ message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-04-15 16:35:05.551000 | 127.0.0.1 | 3748\n REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-04-15 16:35:05.552000 | 127.0.0.1 | 4454\n Merging memtable tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.553000 | 127.0.0.3 | 453\n Processing response from /127.0.0.3 [SharedPool-Worker-4] | 2016-04-15 16:35:05.553000 | 127.0.0.1 | 5110\n REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-04-15 16:35:05.554000 | 127.0.0.1 | 6892\n Processing response from /127.0.0.2 [SharedPool-Worker-4] | 2016-04-15 16:35:05.555000 | 127.0.0.1 | 7099\n Skipped 0/0 non-slice-intersecting sstables, included 0 due to tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.556000 | 127.0.0.3 | 596\n Merging data from memtables and 0 sstables [SharedPool-Worker-1] | 2016-04-15 16:35:05.559000 | 127.0.0.3 | 620\n Read 1 live and 0 tombstone cells [SharedPool-Worker-1] | 2016-04-15 16:35:05.560000 | 127.0.0.3 | 741\n Enqueuing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-04-15 16:35:05.562000 | 127.0.0.3 | 1265\n Sending REQUEST_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-04-15 16:35:05.564000 | 127.0.0.3 | 1892\n Request complete | 2016-04-15 16:35:05.545435 | 127.0.0.1 | 7435\n\n\n\n--------------------- >> end captured logging << ---------------------"
> Standard Output
> (EE) (EE) (EE) (EE)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)