Mailing-List: contact dev-help@tephra.incubator.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@tephra.incubator.apache.org
Date: Sat, 9 Sep 2017 19:46:02 +0000 (UTC)
From: "Andreas Neumann (JIRA)" <jira@apache.org>
To: dev@tephra.incubator.apache.org
Message-ID: <JIRA.13100060.1504684263000.69922.1504986362281@Atlassian.JIRA>
In-Reply-To: <JIRA.13100060.1504684263000@Atlassian.JIRA>
References: <JIRA.13100060.1504684263000@Atlassian.JIRA> <JIRA.13100060.1504684263207@jira-lw-us.apache.org>
Subject: [jira] [Commented] (TEPHRA-253) TransactionProcessorTest is
 sometimes flaky
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
archived-at: Sat, 09 Sep 2017 19:46:10 -0000


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

Andreas Neumann commented on TEPHRA-253:
----------------------------------------

Suspicion confirmed. After changing travis to dump the standard output of the test case, I see:
{noformat}
2017-09-09 19:18:16,851 - INFO  [main:o.a.h.h.r.RegionCoprocessorHost@196] - Load coprocessor org.apache.tephra.hbase.coprocessor.TransactionProcessor from HTD of TestRegionScanner successfully.
2017-09-09 19:18:16,868 - INFO  [StoreOpener-fc704aec719b675f06e5d7bd12da85f0-1:o.a.h.h.r.c.CompactionConfiguration@85] - size [134217728, 9223372036854775807); files [3, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point 2684354560; delete expired; major period 604800000, major jitter 0.500000
2017-09-09 19:18:16,883 - INFO  [main:o.a.h.h.r.HRegion@644] - Onlined fc704aec719b675f06e5d7bd12da85f0; next sequenceid=1
2017-09-09 19:18:16,883 - INFO  [main:o.a.t.h.c.TransactionProcessorTest@178] - Coprocessor is using transaction state: null
2017-09-09 19:18:16,926 - INFO  [main:o.a.t.h.c.TransactionProcessorTest@192] - Flushing region TestRegionScanner,,1504984696824.fc704aec719b675f06e5d7bd12da85f0.
2017-09-09 19:18:16,960 - INFO  [HDFSTransactionStateStorage STARTING:o.a.t.p.HDFSTransactionStateStorage@109] - Using snapshot dir /home/travis/build/apache/incubator-tephra/tephra-hbase-compat-0.96/target/junit6493752557205114158/junit8165179254738335598
2017-09-09 19:18:16,981 - INFO  [TransactionStateCache STARTING:o.a.t.p.HDFSTransactionStateStorage@185] - Read encoded transaction snapshot of 84 bytes
2017-09-09 19:18:16,984 - INFO  [TransactionStateCache STARTING:o.a.t.c.TransactionStateCache@166] - Transaction state reloaded with snapshot from 1504984695267
2017-09-09 19:18:17,393 - INFO  [main:o.a.h.h.r.DefaultStoreFlusher@88] - Flushed, sequenceid=37, memsize=5.9 K, hasBloomFilter=true, into tmp file hdfs://localhost:53322/home/travis/build/apache/incubator-tephra/tephra-hbase-compat-0.96/target/junit6493752557205114158/junit7077794411994061305/hbase/data/default/TestRegionScanner/fc704aec719b675f06e5d7bd12da85f0/.tmp/6e813e3b7af94e13afc9dc1303dda3f8
2017-09-09 19:18:17,415 - INFO  [main:o.a.h.h.r.HStore@770] - Added hdfs://localhost:53322/home/travis/build/apache/incubator-tephra/tephra-hbase-compat-0.96/target/junit6493752557205114158/junit7077794411994061305/hbase/data/default/TestRegionScanner/fc704aec719b675f06e5d7bd12da85f0/f/6e813e3b7af94e13afc9dc1303dda3f8, entries=36, sequenceid=37, filesize=2.2 K
2017-09-09 19:18:17,416 - INFO  [main:o.a.h.h.r.HRegion@1708] - Finished memstore flush of ~5.9 K/6048, currentsize=0/0 for region TestRegionScanner,,1504984696824.fc704aec719b675f06e5d7bd12da85f0. in 489ms, sequenceid=37, compaction requested=false
{noformat}
Clearly, the flush begins before the transaction state is loaded. 

> TransactionProcessorTest is sometimes flaky
> -------------------------------------------
>
>                 Key: TEPHRA-253
>                 URL: https://issues.apache.org/jira/browse/TEPHRA-253
>             Project: Tephra
>          Issue Type: Bug
>    Affects Versions: 0.12.0-incubating
>            Reporter: Andreas Neumann
>            Assignee: Andreas Neumann
>             Fix For: 0.13.0-incubating
>
>
> The test sometimes fails as follows:
> {noformat}
> Running org.apache.tephra.hbase.coprocessor.TransactionProcessorTest
> Tests run: 6, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 7.741 sec <<< FAILURE!
> testFamilyDeleteTimestamp(org.apache.tephra.hbase.coprocessor.TransactionProcessorTest)  Time elapsed: 1.526 sec
> testTransactionStateCache(org.apache.tephra.hbase.coprocessor.TransactionProcessorTest)  Time elapsed: 0.053 sec
> testDataJanitorRegionScanner(org.apache.tephra.hbase.coprocessor.TransactionProcessorTest)  Time elapsed: 0.288 sec  <<< FAILURE!
> org.junit.internal.ArrayComparisonFailure: arrays first differed at element [3]; expected:<4> but was:<1>
> 	at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:50)
> 	at org.junit.Assert.internalArrayEquals(Assert.java:473)
> 	at org.junit.Assert.assertArrayEquals(Assert.java:294)
> 	at org.junit.Assert.assertArrayEquals(Assert.java:305)
> 	at org.apache.tephra.hbase.coprocessor.TransactionProcessorTest.assertKeyValueMatches(TransactionProcessorTest.java:593)
> 	at org.apache.tephra.hbase.coprocessor.TransactionProcessorTest.assertKeyValueMatches(TransactionProcessorTest.java:585)
> 	at org.apache.tephra.hbase.coprocessor.TransactionProcessorTest.testDataJanitorRegionScanner(TransactionProcessorTest.java:190)
> {noformat}
> It is not clear what is causing this, most likely the region server did not have an up-to-date transaction state snapshot at the time of the lfush (that might be due to TEPHRA-239 orTEPHRA-249, or it might be a condition where flush() has no effect because the region is already flushing, 
> Let's observe this and gather more information when/if it happens again. 


--
This message was sent by Atlassian JIRA
(v6.4.14#64029)