[
https://issues.apache.org/jira/browse/CASSANDRA-11598?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15248576#comment-15248576
]
Philip Thompson commented on CASSANDRA-11598:
---------------------------------------------
So, to persist what I've said on IRC here:
The entire request is completing, at CL.ALL appropriately. We see the
coordinator trace that it has received the response from each node. But
sometimes we get no trace messages from 127.0.0.2 (and only *ever* 127.0.0.2,
never 127.0.0.3). This only ever happens on 2.1. I have run it hundreds of
times on 2.1, 2.2, and 3.5. Is this something that where we are relying on
tracing to do something it cannot? The specificity of the issue is suspicious.
I'm moving this to the bug queue, so that a dev can authoritatively say "This
should work", or "This should not work".
> 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)
