[
https://issues.apache.org/jira/browse/CASSANDRA-11598?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15248291#comment-15248291
]
Philip Thompson edited comment on CASSANDRA-11598 at 4/19/16 6:46 PM:
----------------------------------------------------------------------
So there is nothing wrong in the logs for this build, and this test has never
failed on any other job ever. I marked it as flaky in the code, and I'll run it
a few hundred times to see if I can get it to fail again usefully.
The bad news is, this seems isolated to 2.1, or at least, isn't on trunk:
http://cassci.datastax.com/view/Parameterized/job/parameterized_dtest_multiplexer/72/
http://cassci.datastax.com/view/Parameterized/job/parameterized_dtest_multiplexer/71/
was (Author: philipthompson):
So there is nothing wrong in the logs for this build, and this test has never
failed on any other job ever. I marked it as flaky in the code, and I'll run it
a few hundred times to see if I can get it to fail again usefully.
> 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: Test
> Reporter: Jim Witschey
> Assignee: Philip Thompson
> Labels: dtest
>
> 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)
