[jira] [Commented] (CASSANDRA-10682) Fix timeouts in BeforeFirstTest

["Stefania (JIRA)" <ji...@apache.org>]

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

Stefania commented on CASSANDRA-10682:
--------------------------------------

The timeout is caused by {{waitOnFuture}} in this method of {{SchemaKeyspace}} which is flushing schema tables:

{code}
    static void flush()
    {
        if (!Boolean.getBoolean("cassandra.unsafesystem"))
            ALL.forEach(table -> FBUtilities.waitOnFuture(getSchemaCFS(table).forceFlush()));
    }
{code}

The flush writer thread terminates due to an uncaught exception, it appears the table folder for _keyspaces_ does not exist (errno 2):

{code}
WARN  [MemtableFlushWriter:1] 2015-11-06 22:57:41,299 open(build/test/cassandra/data:110/system_schema/keyspaces-abac5682dea631c5b535b3d6cffd0fb6, O_RDONLY) failed, errno (2).
ERROR [MemtableFlushWriter:1] 2015-11-06 22:57:41,374 Fatal exception in thread Thread[MemtableFlushWriter:1,5,main]
java.lang.RuntimeException: java.nio.file.NoSuchFileException: build/test/cassandra/data:110/system_schema/keyspaces-abac5682dea631c5b535b3d6cffd0fb6/ma_txn_flush_c88c3670-84d9
-11e5-a504-21b90eeb2985.log
        at org.apache.cassandra.io.util.FileUtils.write(FileUtils.java:607) ~[main/:na]
        at org.apache.cassandra.io.util.FileUtils.appendAndSync(FileUtils.java:588) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogReplica.append(LogReplica.java:66) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogReplicaSet.lambda$null$151(LogReplicaSet.java:186) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogReplicaSet$$Lambda$77/463946743.perform(Unknown Source) ~[na:na]
        at org.apache.cassandra.utils.Throwables.perform(Throwables.java:112) ~[main/:na]
        at org.apache.cassandra.utils.Throwables.perform(Throwables.java:102) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogReplicaSet.append(LogReplicaSet.java:186) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogFile.addRecord(LogFile.java:280) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogFile.abort(LogFile.java:234) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LogTransaction.doAbort(LogTransaction.java:376) ~[main/:na]
        at org.apache.cassandra.utils.concurrent.Transactional$AbstractTransactional.abort(Transactional.java:144) ~[main/:na]
        at org.apache.cassandra.db.lifecycle.LifecycleTransaction.doAbort(LifecycleTransaction.java:234) ~[main/:na]
        at org.apache.cassandra.utils.concurrent.Transactional$AbstractTransactional.abort(Transactional.java:144) ~[main/:na]
        at org.apache.cassandra.utils.concurrent.Transactional$AbstractTransactional.abort(Transactional.java:193) ~[main/:na]
        at org.apache.cassandra.utils.concurrent.Transactional$AbstractTransactional.close(Transactional.java:158) ~[main/:na]
        at org.apache.cassandra.db.Memtable$FlushRunnable.createFlushWriter(Memtable.java:442) ~[main/:na]
        at org.apache.cassandra.db.Memtable$FlushRunnable.writeSortedContents(Memtable.java:366) ~[main/:na]
        at org.apache.cassandra.db.Memtable$FlushRunnable.runMayThrow(Memtable.java:352) ~[main/:na]
        at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) ~[main/:na]
        at com.google.common.util.concurrent.MoreExecutors$DirectExecutorService.execute(MoreExecutors.java:299) ~[guava-18.0.jar:na]
        at org.apache.cassandra.db.ColumnFamilyStore$Flush.run(ColumnFamilyStore.java:1037) ~[main/:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_45]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_45]
        at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_45]
{code}

CASSANDRA-10538 will fix the exception in {{LogTransaction.doAbort()}}. However we then have another uncaught exception in {{Transactional.close()}}, which I propose to address. Further, we then throw the original exception that caused the transaction to be aborted. {{FlushRunnable}} does not seem to attempt to handle exceptions, which means the post flush executor latch is not decreased and the main thread hangs waiting on the futures. I am not sure if this patch should try to handle exceptions in {{FlushRunnable}} so that the post flush executor then runs, I guess the memtable should not be reclaimed either in this case. cc [~aweisberg] and [~slebresne].

Another interesting thing to observe is that there is a commit log replayed in the test log, perhaps we are picking up commit logs of unrelated tests? 

As for the table folder not existing, because it is created when the CFS is opened, I am guessing we need to sync the parent folder. I'm going to run the unit tests on Jenkins a few more times to see if the root cause is solved by sync-ing the parent folder whenever we create a table folder.

> Fix timeouts in BeforeFirstTest
> -------------------------------
>
>                 Key: CASSANDRA-10682
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-10682
>             Project: Cassandra
>          Issue Type: Sub-task
>            Reporter: Stefania
>            Assignee: Stefania
>             Fix For: 3.1
>
>         Attachments: TEST-org.apache.cassandra.db.SinglePartitionSliceCommandTest.log
>
>
> Some unit tests fail with a timeout in {{BeforeFirstTest}}, see for example [here|http://cassci.datastax.com/job/cassandra-3.0_testall/242/testReport/org.apache.cassandra.db/SinglePartitionSliceCommandTest/BeforeFirstTest/]. 
> In the corresponding log file, attached, there is a {{NoSuchFileException}} which might be the cause.



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