Intermittent issue under Boron tests
The fact that this code is executing indicates there is a DOMDataTreeCommitCohort present in BGP somewhere or in the test suite. The TimeoutException indicates the DOMDataTreeCommitCohort implementation didn't respond within 5 sec. So this doesn't appear to be an issue with clustering.
Actually BGPCEP is not using commit cohorts at all, the logs show:
2017-04-12 23:28:38,665 | INFO | entLoopGroup-5-1 | BGPPeer | 195 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.4.SNAPSHOT | Session with peer 10.29.13.222 went up with tables [BgpTableTypeImpl [getAfi()=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, getSafi()=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily]] and Add Path tables []
2017-04-12 23:28:38,694 | INFO | entLoopGroup-5-1 | AbstractBGPSessionNegotiator | 195 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.4.SNAPSHOT | BGP Session with peer [id: 0xa84cc9e7, L:/10.29.13.167:1790 - R:/10.29.13.222:17900] established successfully.
2017-04-12 23:29:44,697 | WARN | on-dispatcher-65 | taTreeNotificationPublisherActor | 176 - org.opendaylight.controller.sal-clustering-commons - 1.4.4.SNAPSHOT | member-1-shard-default-operational: Generation of change events for member-1-shard-default-operational-DTCL-publisher took longer than expected. Elapsed time: 3.106 s
2017-04-12 23:30:08,853 | ERROR | lt-dispatcher-15 | SimpleShardDataTreeCohort | 182 - org.opendaylight.controller.sal-distributed-datastore - 1.4.4.SNAPSHOT | Transaction member-1-datastore-operational-fe-0-chn-7-txn-11752 failed to prepare
java.util.concurrent.TimeoutException: Futures timed out after [5 seconds]
I would assume this was a huge transaction and we just missed the deadline to respond.
Tom, I think we should sync up on the various timers we have in here and make sure they make sense 
Also we should include transaction ID in the DTCL-too-long warning.
Hmm...
It failed here:
org.opendaylight.controller.cluster.datastore.CompositeDataTreeCohort.processResponses(CompositeDataTreeCohort.java:162)[182:org.opendaylight.controller.sal-distributed-datastore:1.4.4.SNAPSHOT]
private void processResponses(final Future<Iterable<Object>> resultsFuture, final State currentState, final State afterState)
throws TimeoutException, ExecutionException {
final Iterable<Object> results;
try
catch (Exception e)
{ successfulFromPrevious = null; Throwables.propagateIfInstanceOf(e, TimeoutException.class); throw Throwables.propagate(e); }If there were no commit cohorts then resultsFuture should be empty and thus complete immediately.
Or am I missing something here?
I agree we need to revisit the various timers. The timeout above is hard-coded at 5 sec 
We have just reproduced this in a single-node scenario with BGP load test. The stack trace is slightly different here, reflecting tell-based-protocol:
java.util.concurrent.TimeoutException: Futures timed out after [5 seconds]
at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219)[150:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:223)[150:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.Await$$anonfun$result$1.apply(package.scala:190)[150:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread$$anon$3.block(ThreadPoolBuilder.scala:167)[154:com.typesafe.akka.actor:2.4.17]
at scala.concurrent.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java:3640)[150:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread.blockOn(ThreadPoolBuilder.scala:165)[154:com.typesafe.akka.actor:2.4.17]
at scala.concurrent.Await$.result(package.scala:190)[150:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.Await.result(package.scala)[150:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at org.opendaylight.controller.cluster.datastore.CompositeDataTreeCohort.processResponses(CompositeDataTreeCohort.java:183)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.CompositeDataTreeCohort.preCommit(CompositeDataTreeCohort.java:146)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.userPreCommit(SimpleShardDataTreeCohort.java:200)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.startPreCommit(ShardDataTree.java:809)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.preCommit(SimpleShardDataTreeCohort.java:113)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction.successfulDirectCanCommit(FrontendReadWriteTransaction.java:202)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction.access$300(FrontendReadWriteTransaction.java:55)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction$5.onSuccess(FrontendReadWriteTransaction.java:190)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction$5.onSuccess(FrontendReadWriteTransaction.java:187)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.successfulCanCommit(SimpleShardDataTreeCohort.java:181)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.lambda$processNextPendingTransaction$0(ShardDataTree.java:717)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPending(ShardDataTree.java:761)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.processNextPendingTransaction(ShardDataTree.java:706)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.ShardDataTree.startCanCommit(ShardDataTree.java:787)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.SimpleShardDataTreeCohort.canCommit(SimpleShardDataTreeCohort.java:103)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction.directCommit(FrontendReadWriteTransaction.java:187)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction.handleCommitLocalTransaction(FrontendReadWriteTransaction.java:254)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.FrontendReadWriteTransaction.handleRequest(FrontendReadWriteTransaction.java:91)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.AbstractFrontendHistory.handleTransactionRequest(AbstractFrontendHistory.java:154)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.LeaderFrontendState.handleTransactionRequest(LeaderFrontendState.java:197)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.Shard.handleRequest(Shard.java:450)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.Shard.handleNonRaftCommand(Shard.java:283)[180:org.opendaylight.controller.sal-distributed-datastore:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.raft.RaftActor.handleCommand(RaftActor.java:270)[174:org.opendaylight.controller.sal-akka-raft:1.5.0.SNAPSHOT]
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedPersistentActor.onReceiveCommand(AbstractUntypedPersistentActor.java:31)[173:org.opendaylight.controller.sal-clustering-commons:1.5.0.SNAPSHOT]
at akka.persistence.UntypedPersistentActor.onReceive(PersistentActor.scala:170)[161:com.typesafe.akka.persistence:2.4.17]
I have just grepped the entire autorelease for cohort registrations in carbon and there is only SFC, which is not installed in this case. It looks rather weird and the code structure makes it really hard to extract any sort of useful information.
I have refactored the code so it is retains actor identities, hence we can actually reason about what went down (if anything). I have also addressed the FIXME, which contains a bypass on empty cohorts, which may actually address this issue, since we do not go through the global execution context in that cases, but return directly.
(In reply to Robert Varga from comment #5)
> I have refactored the code so it is retains actor identities, hence we can
> actually reason about what went down (if anything). I have also addressed
> the FIXME, which contains a bypass on empty cohorts, which may actually
> address this issue, since we do not go through the global execution context
> in that cases, but return directly.
>
> carbon: https://git.opendaylight.org/gerrit/55819
yeah I think that's what's happening - akka/scala futures still go through the global executor even when immediately complete so if the all the executor threads are in use it could timeout. In some other part of the code I first checked if the future was done before adding a callback.
I plan on removing the actor - it really isn't necessary plus we need to track the cohort state per transaction now that we have the pipelining - the current code assumes only one transaction at a time is undergoing 3PC since that's the way it was before pipelining.
boron shortcuts: https://git.opendaylight.org/gerrit/55821
Agreed on killing DataTreeCohortActor. I have filed CONTROLLER-1641 to track that.