cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Philip Thompson (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-11598) dtest failure in cql_tracing_test.TestCqlTracing.tracing_simple_test
Date Tue, 19 Apr 2016 20:35:25 GMT

    [ 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)

Mime
View raw message