Jim Witschey created CASSANDRA-11598:
----------------------------------------
Summary: 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: DS Test Eng
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)
