[CASSANDRA-11598] dtest failure in cql_tracing_test.TestCqlTracing.tracing_simple_test - ASF JIRA

Agile Board

Attach files

Attach Screenshot

Bulk Copy Attachments

Bulk Move Attachments

Voters

Watch issue

Watchers

Create sub-task

Convert to sub-task

Move

Link

Clone

Labels

Update Comment Author

Replace String in Comment

Update Comment Visibility

Delete Comments

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Normal
Resolution: Fixed
Fix Version/s: None
Component/s: Legacy/Tools
Labels:
- dtest

Severity:
Normal

Description

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?

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)

Attachments

Activity

Comment

This comment will be Viewable by All Users Viewable by All Users

Cancel

People

Assignee:: Tom Hobbs Assign to me

Reporter:: Jim Witschey

Authors:: Tom Hobbs

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 18/Apr/16 20:53

Updated:: 16/Apr/19 09:30

Resolved:: 26/May/16 21:08

Agile

View on Board

dtest failure in cql_tracing_test.TestCqlTracing.tracing_simple_test

Details

Description

Attachments

Attachments

Activity

People

Dates

Agile

Slack

Issue deployment