cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jim Witschey (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-11465) dtest failure in cql_tracing_test.TestCqlTracing.tracing_unknown_impl_test
Date Wed, 13 Jul 2016 14:50:20 GMT

    [ https://issues.apache.org/jira/browse/CASSANDRA-11465?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15375145#comment-15375145
] 

Jim Witschey commented on CASSANDRA-11465:
------------------------------------------

Another failure we're seeing:

http://cassci.datastax.com/job/trunk_dtest/1288/testReport/junit/cql_tracing_test/TestCqlTracing/tracing_unknown_impl_test/

{code}
'/127.0.0.1' not found in "Consistency level set to ALL.\nNow Tracing is enabled\n\nTracing
session: 54778be0-3c80-11e6-a333-ef4c703100c3\n\n activity                               
                                                                                         
                                   | timestamp                  | source    | source_elapsed
| client\n----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------\n
                                                                                         
                                                        Execute CQL3 query | 2016-06-27 16:00:55.198000
| 127.0.0.1 |              0 | 127.0.0.1\n Parsing INSERT INTO ks.users (userid, firstname,
lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, 'Frodo', 'Baggins', 32); [Native-Transport-Requests-2]
| 2016-06-27 16:00:55.198000 | 127.0.0.1 |            462 | 127.0.0.1\n                  
                                                                                         
       Preparing statement [Native-Transport-Requests-2] | 2016-06-27 16:00:55.199000 | 127.0.0.1
|            953 | 127.0.0.1\n                                                           
                                          Determining replicas for mutation [Native-Transport-Requests-2]
| 2016-06-27 16:00:55.200000 | 127.0.0.1 |           1773 | 127.0.0.1\n                  
                                                                     Sending MUTATION message
to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-06-27 16:00:55.202000 | 127.0.0.1
|           4094 | 127.0.0.1\n                                                           
                            Sending MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2]
| 2016-06-27 16:00:55.202000 | 127.0.0.1 |           4117 | 127.0.0.1\n                  
                                                                                         
    Appending to commitlog [Native-Transport-Requests-2] | 2016-06-27 16:00:55.202000 | 127.0.0.1
|           4270 | 127.0.0.1\n                                                           
                                                   Adding to users memtable [Native-Transport-Requests-2]
| 2016-06-27 16:00:55.203000 | 127.0.0.1 |           4758 | 127.0.0.1\n                  
                                                          REQUEST_RESPONSE message received
from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-06-27 16:00:55.213000 | 127.0.0.1
|          14833 | 127.0.0.1\n                                                           
                                             Processing response from /127.0.0.3 [RequestResponseStage-4]
| 2016-06-27 16:00:55.213000 | 127.0.0.1 |          15059 | 127.0.0.1\n                  
                                                          REQUEST_RESPONSE message received
from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-06-27 16:00:55.217000 | 127.0.0.1
|          19203 | 127.0.0.1\n                                                           
                                             Processing response from /127.0.0.2 [RequestResponseStage-1]
| 2016-06-27 16:00:55.217000 | 127.0.0.1 |          19379 | 127.0.0.1\n                  
                                                                                         
                                        Request complete | 2016-06-27 16:00:55.217557 | 127.0.0.1
|          19557 | 127.0.0.1\n\n\n"
-------------------- >> begin captured logging << --------------------
dtest: DEBUG: cluster ccm directory: /tmp/dtest-RJbUwP
dtest: DEBUG: Custom init_config not found. Setting defaults.
dtest: DEBUG: Done setting configuration options:
{   'initial_token': None,
    '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

Tracing session: 54778be0-3c80-11e6-a333-ef4c703100c3

 activity                                                                                
                                                                            | timestamp  
               | source    | source_elapsed | client
----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
                                                                                         
                                                         Execute CQL3 query | 2016-06-27 16:00:55.198000
| 127.0.0.1 |              0 | 127.0.0.1
 Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000,
'Frodo', 'Baggins', 32); [Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1
|            462 | 127.0.0.1
                                                                                         
                          Preparing statement [Native-Transport-Requests-2] | 2016-06-27 16:00:55.199000
| 127.0.0.1 |            953 | 127.0.0.1
                                                                                         
            Determining replicas for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000
| 127.0.0.1 |           1773 | 127.0.0.1
                                                                                        Sending
MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-06-27 16:00:55.202000
| 127.0.0.1 |           4094 | 127.0.0.1
                                                                                        Sending
MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000
| 127.0.0.1 |           4117 | 127.0.0.1
                                                                                         
                       Appending to commitlog [Native-Transport-Requests-2] | 2016-06-27 16:00:55.202000
| 127.0.0.1 |           4270 | 127.0.0.1
                                                                                         
                     Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000
| 127.0.0.1 |           4758 | 127.0.0.1
                                                                             REQUEST_RESPONSE
message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-06-27 16:00:55.213000
| 127.0.0.1 |          14833 | 127.0.0.1
                                                                                         
               Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000
| 127.0.0.1 |          15059 | 127.0.0.1
                                                                             REQUEST_RESPONSE
message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-06-27 16:00:55.217000
| 127.0.0.1 |          19203 | 127.0.0.1
                                                                                         
               Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000
| 127.0.0.1 |          19379 | 127.0.0.1
                                                                                         
                                                           Request complete | 2016-06-27 16:00:55.217557
| 127.0.0.1 |          19557 | 127.0.0.1



--------------------- >> end captured logging << ---------------------
Stacktrace

  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/home/automaton/cassandra-dtest/tools.py", line 288, in wrapped
    f(obj)
  File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 126, in tracing_unknown_impl_test
    self.trace(session)
  File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 75, in trace
    self.assertIn('/127.0.0.1', 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.1\' not found in "Consistency level set to ALL.\\nNow Tracing is enabled\\n\\nTracing
session: 54778be0-3c80-11e6-a333-ef4c703100c3\\n\\n activity                             
                                                                                         
                                     | timestamp                  | source    | source_elapsed
| client\\n----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------\\n
                                                                                         
                                                        Execute CQL3 query | 2016-06-27 16:00:55.198000
| 127.0.0.1 |              0 | 127.0.0.1\\n Parsing INSERT INTO ks.users (userid, firstname,
lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, \'Frodo\', \'Baggins\', 32);
[Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1 |            462 |
127.0.0.1\\n                                                                             
                                      Preparing statement [Native-Transport-Requests-2] |
2016-06-27 16:00:55.199000 | 127.0.0.1 |            953 | 127.0.0.1\\n                   
                                                                                  Determining
replicas for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000 | 127.0.0.1
|           1773 | 127.0.0.1\\n                                                          
                             Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3]
| 2016-06-27 16:00:55.202000 | 127.0.0.1 |           4094 | 127.0.0.1\\n                 
                                                                      Sending MUTATION message
to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000 | 127.0.0.1
|           4117 | 127.0.0.1\\n                                                          
                                                      Appending to commitlog [Native-Transport-Requests-2]
| 2016-06-27 16:00:55.202000 | 127.0.0.1 |           4270 | 127.0.0.1\\n                 
                                                                                         
   Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000 | 127.0.0.1
|           4758 | 127.0.0.1\\n                                                          
                  REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3]
| 2016-06-27 16:00:55.213000 | 127.0.0.1 |          14833 | 127.0.0.1\\n                 
                                                                                       Processing
response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000 | 127.0.0.1
|          15059 | 127.0.0.1\\n                                                          
                  REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2]
| 2016-06-27 16:00:55.217000 | 127.0.0.1 |          19203 | 127.0.0.1\\n                 
                                                                                       Processing
response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000 | 127.0.0.1
|          19379 | 127.0.0.1\\n                                                          
                                                                                         
Request complete | 2016-06-27 16:00:55.217557 | 127.0.0.1 |          19557 | 127.0.0.1\\n\\n\\n"\n--------------------
>> begin captured logging << --------------------\ndtest: DEBUG: cluster ccm directory:
/tmp/dtest-RJbUwP\ndtest: DEBUG: Custom init_config not found. Setting defaults.\ndtest: DEBUG:
Done setting configuration options:\n{   \'initial_token\': None,\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\nTracing session: 54778be0-3c80-11e6-a333-ef4c703100c3\n\n activity 
                                                                                         
                                                                 | timestamp             
    | source    | source_elapsed | client\n----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------\n
                                                                                         
                                                        Execute CQL3 query | 2016-06-27 16:00:55.198000
| 127.0.0.1 |              0 | 127.0.0.1\n Parsing INSERT INTO ks.users (userid, firstname,
lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000, \'Frodo\', \'Baggins\', 32);
[Native-Transport-Requests-2] | 2016-06-27 16:00:55.198000 | 127.0.0.1 |            462 |
127.0.0.1\n                                                                              
                                     Preparing statement [Native-Transport-Requests-2] | 2016-06-27
16:00:55.199000 | 127.0.0.1 |            953 | 127.0.0.1\n                               
                                                                      Determining replicas
for mutation [Native-Transport-Requests-2] | 2016-06-27 16:00:55.200000 | 127.0.0.1 |    
      1773 | 127.0.0.1\n                                                                 
                      Sending MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3]
| 2016-06-27 16:00:55.202000 | 127.0.0.1 |           4094 | 127.0.0.1\n                  
                                                                     Sending MUTATION message
to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-06-27 16:00:55.202000 | 127.0.0.1
|           4117 | 127.0.0.1\n                                                           
                                                     Appending to commitlog [Native-Transport-Requests-2]
| 2016-06-27 16:00:55.202000 | 127.0.0.1 |           4270 | 127.0.0.1\n                  
                                                                                         
  Adding to users memtable [Native-Transport-Requests-2] | 2016-06-27 16:00:55.203000 | 127.0.0.1
|           4758 | 127.0.0.1\n                                                           
                 REQUEST_RESPONSE message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3]
| 2016-06-27 16:00:55.213000 | 127.0.0.1 |          14833 | 127.0.0.1\n                  
                                                                                      Processing
response from /127.0.0.3 [RequestResponseStage-4] | 2016-06-27 16:00:55.213000 | 127.0.0.1
|          15059 | 127.0.0.1\n                                                           
                 REQUEST_RESPONSE message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2]
| 2016-06-27 16:00:55.217000 | 127.0.0.1 |          19203 | 127.0.0.1\n                  
                                                                                      Processing
response from /127.0.0.2 [RequestResponseStage-1] | 2016-06-27 16:00:55.217000 | 127.0.0.1
|          19379 | 127.0.0.1\n                                                           
                                                                                         Request
complete | 2016-06-27 16:00:55.217557 | 127.0.0.1 |          19557 | 127.0.0.1\n\n\n\n---------------------
>> end captured logging << ---------------------'
Standard Output

(EE)  (EE)  (EE)  
{code}

We should be seeing all those trace entries. Here's an example of the output from a successful
trace in a successful local run:

{code}
 activity                                                                                
                                                                            | timestamp  
               | source    | source_elapsed | client
----------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
                                                                                         
                                                         Execute CQL3 query | 2016-07-13 10:47:36.596000
| 127.0.0.1 |              0 | 127.0.0.1
 Parsing INSERT INTO ks.users (userid, firstname, lastname, age) VALUES (550e8400-e29b-41d4-a716-446655440000,
'Frodo', 'Baggins', 32); [Native-Transport-Requests-2] | 2016-07-13 10:47:36.596000 | 127.0.0.1
|            240 | 127.0.0.1
                                                                                         
                          Preparing statement [Native-Transport-Requests-2] | 2016-07-13 10:47:36.596000
| 127.0.0.1 |            502 | 127.0.0.1
                                                                                         
            Determining replicas for mutation [Native-Transport-Requests-2] | 2016-07-13 10:47:36.597000
| 127.0.0.1 |            997 | 127.0.0.1
                                                                                        Sending
MUTATION message to /127.0.0.2 [MessagingService-Outgoing-/127.0.0.2] | 2016-07-13 10:47:36.597000
| 127.0.0.1 |           1557 | 127.0.0.1
                                                                                        Sending
MUTATION message to /127.0.0.3 [MessagingService-Outgoing-/127.0.0.3] | 2016-07-13 10:47:36.598000
| 127.0.0.1 |           2138 | 127.0.0.1
                                                                                     MUTATION
message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-13 10:47:36.599000
| 127.0.0.2 |            457 | 127.0.0.1
                                                                                     MUTATION
message received from /127.0.0.1 [MessagingService-Incoming-/127.0.0.1] | 2016-07-13 10:47:36.600000
| 127.0.0.3 |            347 | 127.0.0.1
                                                                                         
                                   Appending to commitlog [MutationStage-1] | 2016-07-13 10:47:36.600000
| 127.0.0.1 |           3996 | 127.0.0.1
                                                                                         
                                 Adding to users memtable [MutationStage-1] | 2016-07-13 10:47:36.600000
| 127.0.0.1 |           4332 | 127.0.0.1
                                                                                         
                                   Appending to commitlog [MutationStage-2] | 2016-07-13 10:47:36.601000
| 127.0.0.2 |           1966 | 127.0.0.1
                                                                                         
                                 Adding to users memtable [MutationStage-2] | 2016-07-13 10:47:36.601000
| 127.0.0.2 |           2308 | 127.0.0.1
                                                                                         
                                   Appending to commitlog [MutationStage-2] | 2016-07-13 10:47:36.602000
| 127.0.0.3 |           2581 | 127.0.0.1
                                                                             REQUEST_RESPONSE
message received from /127.0.0.2 [MessagingService-Incoming-/127.0.0.2] | 2016-07-13 10:47:36.602000
| 127.0.0.1 |           6584 | 127.0.0.1
                                                                                         
                         Enqueuing response to /127.0.0.1 [MutationStage-2] | 2016-07-13 10:47:36.602000
| 127.0.0.2 |           2693 | 127.0.0.1
                                                                                         
                                 Adding to users memtable [MutationStage-2] | 2016-07-13 10:47:36.602000
| 127.0.0.3 |           2938 | 127.0.0.1
                                                                                Sending REQUEST_RESPONSE
message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-13 10:47:36.602000
| 127.0.0.2 |           3008 | 127.0.0.1
                                                                                         
                         Enqueuing response to /127.0.0.1 [MutationStage-2] | 2016-07-13 10:47:36.603000
| 127.0.0.3 |           3278 | 127.0.0.1
                                                                                         
               Processing response from /127.0.0.2 [RequestResponseStage-1] | 2016-07-13 10:47:36.603000
| 127.0.0.1 |           7515 | 127.0.0.1
                                                                                Sending REQUEST_RESPONSE
message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2016-07-13 10:47:36.605000
| 127.0.0.3 |           5241 | 127.0.0.1
                                                                             REQUEST_RESPONSE
message received from /127.0.0.3 [MessagingService-Incoming-/127.0.0.3] | 2016-07-13 10:47:36.605000
| 127.0.0.1 |           9261 | 127.0.0.1
                                                                                         
               Processing response from /127.0.0.3 [RequestResponseStage-4] | 2016-07-13 10:47:36.605000
| 127.0.0.1 |           9484 | 127.0.0.1
                                                                                         
                                                           Request complete | 2016-07-13 10:47:36.605643
| 127.0.0.1 |           9643 | 127.0.0.1

{code}

> dtest failure in cql_tracing_test.TestCqlTracing.tracing_unknown_impl_test
> --------------------------------------------------------------------------
>
>                 Key: CASSANDRA-11465
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-11465
>             Project: Cassandra
>          Issue Type: Test
>            Reporter: Philip Thompson
>            Assignee: Jim Witschey
>              Labels: dtest
>
> Failing on the following assert, on trunk only: {{self.assertEqual(len(errs[0]), 1)}}
> Is not failing consistently.
> example failure:
> http://cassci.datastax.com/job/trunk_dtest/1087/testReport/cql_tracing_test/TestCqlTracing/tracing_unknown_impl_test
> Failed on CassCI build trunk_dtest #1087



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message