Return-Path: X-Original-To: apmail-cassandra-commits-archive@www.apache.org Delivered-To: apmail-cassandra-commits-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 1AF2C19EC7 for ; Mon, 18 Apr 2016 20:53:28 +0000 (UTC) Received: (qmail 88871 invoked by uid 500); 18 Apr 2016 20:53:26 -0000 Delivered-To: apmail-cassandra-commits-archive@cassandra.apache.org Received: (qmail 88798 invoked by uid 500); 18 Apr 2016 20:53:26 -0000 Mailing-List: contact commits-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cassandra.apache.org Delivered-To: mailing list commits@cassandra.apache.org Received: (qmail 88017 invoked by uid 99); 18 Apr 2016 20:53:26 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 18 Apr 2016 20:53:25 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id D651D2C1F60 for ; Mon, 18 Apr 2016 20:53:25 +0000 (UTC) Date: Mon, 18 Apr 2016 20:53:25 +0000 (UTC) From: "Jim Witschey (JIRA)" To: commits@cassandra.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (CASSANDRA-11598) dtest failure in cql_tracing_test.TestCqlTracing.tracing_simple_test MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 Jim Witschey created CASSANDRA-11598: ---------------------------------------- Summary: dtest failure in cql_tracing_test.TestCqlTracing.trac= ing_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/c= ql_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 '}} i= s -- should we change the regex here? {code} Error Message ' 127.0.0.2 ' not found in 'Consistency level set to ALL.\nNow Tracing is e= nabled\n\n firstname | lastname\n-----------+----------\n Frodo | Bagg= ins\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 SEL= ECT firstname, lastname FROM ks.users WHERE userid =3D 550e8400-e29b-41d4-a= 716-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-0= 4-15 16:35:05.542000 | 127.0.0.1 | 1249\n = Acquiring sstable referen= ces [SharedPool-Worker-3] | 2016-04-15 16:35:05.545000 | 127.0.0.1 | = 1265\n Exec= uting single-partition query on users [SharedPool-Worker-1] | 2016-04-15 16= :35:05.546000 | 127.0.0.3 | 369\n = Merging memtable tombstones [Sh= aredPool-Worker-3] | 2016-04-15 16:35:05.546000 | 127.0.0.1 | 130= 2\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 [SharedPoo= l-Worker-3] | 2016-04-15 16:35:05.548000 | 127.0.0.1 | 1403\n = Acqui= ring 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-Worke= r-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 S= ending 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 [Messag= ingService-Outgoing-/127.0.0.2] | 2016-04-15 16:35:05.551000 | 127.0.0.1 | = 3748\n REQUEST_RESPONSE messag= e 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 tombston= es [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-Inc= oming-/127.0.0.2] | 2016-04-15 16:35:05.554000 | 127.0.0.1 | 6892= \n Proces= sing response from /127.0.0.2 [SharedPool-Worker-4] | 2016-04-15 16:35:05.5= 55000 | 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 me= mtables 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 respons= e to /127.0.0.1 [SharedPool-Worker-1] | 2016-04-15 16:35:05.562000 | 127.0.= 0.3 | 1265\n Sending REQUES= T_RESPONSE message to /127.0.0.1 [MessagingService-Outgoing-/127.0.0.1] | 2= 016-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.538= 000 | 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.540= 000 | 127.0.0.3 | 47 Parsing SELECT firstname, lastname FROM ks.users WHERE userid =3D 550e8400= -e29b-41d4-a716-446655440000; [SharedPool-Worker-2] | 2016-04-15 16:35:05.5= 40000 | 127.0.0.1 | 88 = Preparing statement [SharedPool-Worker-2] | 2016-04-15 16:35:05.540= 000 | 127.0.0.1 | 355 rea= ding digest from /127.0.0.2 [SharedPool-Worker-2] | 2016-04-15 16:35:05.542= 000 | 127.0.0.1 | 1245 Executing sing= le-partition query on users [SharedPool-Worker-3] | 2016-04-15 16:35:05.542= 000 | 127.0.0.1 | 1249 A= cquiring sstable references [SharedPool-Worker-3] | 2016-04-15 16:35:05.545= 000 | 127.0.0.1 | 1265 Executing sing= le-partition query on users [SharedPool-Worker-1] | 2016-04-15 16:35:05.546= 000 | 127.0.0.3 | 369 = Merging memtable tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.546= 000 | 127.0.0.1 | 1302 rea= ding digest from /127.0.0.3 [SharedPool-Worker-2] | 2016-04-15 16:35:05.547= 000 | 127.0.0.1 | 1338 Skipped 0/0 non-slice-intersecting sstables, i= ncluded 0 due to tombstones [SharedPool-Worker-3] | 2016-04-15 16:35:05.548= 000 | 127.0.0.1 | 1403 A= cquiring sstable references [SharedPool-Worker-1] | 2016-04-15 16:35:05.549= 000 | 127.0.0.3 | 392 Merging data fr= om memtables and 0 sstables [SharedPool-Worker-3] | 2016-04-15 16:35:05.549= 000 | 127.0.0.1 | 1428 Read 1= live and 0 tombstone cells [SharedPool-Worker-3] | 2016-04-15 16:35:05.550= 000 | 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.550= 000 | 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.551= 000 | 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.552= 000 | 127.0.0.1 | 4454 = Merging memtable tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.553= 000 | 127.0.0.3 | 453 Processi= ng response from /127.0.0.3 [SharedPool-Worker-4] | 2016-04-15 16:35:05.553= 000 | 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.554= 000 | 127.0.0.1 | 6892 Processi= ng response from /127.0.0.2 [SharedPool-Worker-4] | 2016-04-15 16:35:05.555= 000 | 127.0.0.1 | 7099 Skipped 0/0 non-slice-intersecting sstables, i= ncluded 0 due to tombstones [SharedPool-Worker-1] | 2016-04-15 16:35:05.556= 000 | 127.0.0.3 | 596 Merging data fr= om memtables and 0 sstables [SharedPool-Worker-1] | 2016-04-15 16:35:05.559= 000 | 127.0.0.3 | 620 Read 1= live and 0 tombstone cells [SharedPool-Worker-1] | 2016-04-15 16:35:05.560= 000 | 127.0.0.3 | 741 Enque= uing response to /127.0.0.1 [SharedPool-Worker-1] | 2016-04-15 16:35:05.562= 000 | 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.564= 000 | 127.0.0.3 | 1892 = Request complete | 2016-04-15 16:35:05.545= 435 | 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 t= racing_simple_test self.trace(session) File "/home/automaton/cassandra-dtest/cql_tracing_test.py", line 85, in t= race 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-53144= f0dba91\\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-In= coming-/127.0.0.1] | 2016-04-15 16:35:05.540000 | 127.0.0.3 | 4= 7\\n Parsing SELECT firstname, lastname FROM ks.users WHERE userid =3D 550e= 8400-e29b-41d4-a716-446655440000; [SharedPool-Worker-2] | 2016-04-15 16:35:= 05.540000 | 127.0.0.1 | 88\\n = Preparing statement [Share= dPool-Worker-2] | 2016-04-15 16:35:05.540000 | 127.0.0.1 | 355\\= n re= ading digest from /127.0.0.2 [SharedPool-Worker-2] | 2016-04-15 16:35:05.54= 2000 | 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 = Acqui= ring 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-Work= er-1] | 2016-04-15 16:35:05.546000 | 127.0.0.3 | 369\\n = Merging m= emtable 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] | 20= 16-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 [MessagingSer= vice-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 1= 6: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 | 4= 454\\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 [Share= dPool-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.55= 4000 | 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, inclu= ded 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-Work= er-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 [Me= ssagingService-Outgoing-/127.0.0.1] | 2016-04-15 16:35:05.564000 | 127.0.0.= 3 | 1892\\n = Request complete | 20= 16-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_co= nfig not found. Setting defaults.\ndtest: DEBUG: Done setting configuration= options:\n{ 'initial_token': None,\n 'memtable_allocation_type': 'off= heap_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: C= onsistency level set to ALL.\nNow Tracing is enabled\n\n firstname | lastna= me\n-----------+----------\n Frodo | Baggins\n\n(1 rows)\n\nTracing se= ssion: 0268da20-0328-11e6-b014-53144f0dba91\n\n activity = = | timestamp | source | source_ela= psed\n---------------------------------------------------------------------= --------------------------------------------------------+------------------= ----------+-----------+----------------\n = Exe= cute 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.540= 000 | 127.0.0.3 | 47\n Parsing SELECT firstname, lastname FROM = ks.users WHERE userid =3D 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] | 2= 016-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 sst= ables, included 0 due to tombstones [SharedPool-Worker-3] | 2016-04-15 16:3= 5:05.548000 | 127.0.0.1 | 1403\n = Acquiring sstable references [Shar= edPool-Worker-1] | 2016-04-15 16:35:05.549000 | 127.0.0.3 | 392\= n Merging data f= rom memtables and 0 sstables [SharedPool-Worker-3] | 2016-04-15 16:35:05.54= 9000 | 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 [M= essagingService-Incoming-/127.0.0.3] | 2016-04-15 16:35:05.552000 | 127.0.0= .1 | 4454\n = Merging memtable tombstones [SharedPool-Worker-1] | 20= 16-04-15 16:35:05.553000 | 127.0.0.3 | 453\n = Processing response from /12= 7.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-1= 5 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 ssta= bles, 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 [Share= dPool-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.560= 000 | 127.0.0.3 | 741\n = Enqueuing response to /127.0.0.1 [SharedPool-W= orker-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 | 1= 27.0.0.3 | 1892\n = Request complet= e | 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) =20 {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)