Operating System: All
Platform: All

Today, the writer has timed out [2] on restconf level, without returning a timeout error on its own. Karaf.log [3] shows no suspicious message within the test case duration (between 03:01:22,254 and 03:02:52,753).

Note that the run was still without a potential fix [4].

[2] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/692/archives/log.html.gz#s1-s24-t1-k2-k8
[3] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/692/archives/odl2_karaf.log.gz
[4] https://git.opendaylight.org/gerrit/56874

This is still happening. The good news is that now only one writer reports this error [5], others pass (albeit with lower performance as they wait for submits).

[5] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/694/archives/log.html.gz#s1-s36-t3-k2-k13

In another scenario (the previous one has listener and moves leader gracefully, this one has no listener but isolates the leader for a brief time, both scenarios have 3 transaction writers and 2 of them finish correctly now; module-based shards with tell-based protocol) something similar [6] happened.

But the exceptions are slightly different. The graceful movement response starts with:
{"errors":{"error":[{"error-type":"application","error-tag":"operation-failed","error-message":"Unexpected-exception","error-info":"java.util.concurrent.TimeoutException: Timeout waiting for task.\n\tat com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:269)\n\tat com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:96)\n\tat com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:69)\n\tat org.opendaylight.yangtools.util.concurrent.MappingCheckedFuture.get(MappingCheckedFuture.java:85)\n\tat

The brief isolation response starts with:
{"errors":{"error":[{"error-type":"application","error-tag":"operation-failed","error-message":"Unexpected-exception","error-info":"java.util.concurrent.ExecutionException: TransactionCommitFailedException

\n\tat com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:299)\n\tat com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:272)\n\tat com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:96)\n\tat org.opendaylight.controller.clustering.it.provider.impl.WriteTransactionsHandler.maybeFinish(WriteTransactionsHandler.java:238)\n\tat org.opendaylight.controller.clustering.it.provider.impl.WriteTransactionsHandler.run(WriteTransactionsHandler.java:112)\n\tat

[6] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/694/archives/log.html.gz#s1-s28-t1-k2-k25-k1-k2-k3-k1-k1

Vratko, please add comment when you have new run, thank you

This is still happening. In a recent Sandbox test [7] (which failed to upload archive with logs) one writer failed with "TimeoutException: Timeout waiting for task" (as opposed to RequestTimeoutException), one finished successfully, and one overstepped the generous (440s) timeout for Restconf response.

This was the brief isolation scenario (module-based shards, tell-based protocol), with [8] codebase.

[7] https://jenkins.opendaylight.org/sandbox/job/controller-csit-3node-clustering-only-carbon/6/robot/report/log.html#s1-s10-t1-k2-k25-k1-k1
[8] https://git.opendaylight.org/gerrit/#/c/57698/3

2017-06-01 23:37:21,958 | INFO | h for user karaf | command | 265 - org.apache.karaf.log.command - 3.0.8 | ROBOT MESSAGE: Starting test Local_Leader_Shutdown
2017-06-01 23:37:27,553 | INFO | qtp10706451-296 | ClusterAdminRpcService | 201 - org.opendaylight.controller.sal-cluster-admin-impl - 1.5.1.SNAPSHOT | Removing replica for shard default memberName member-2, datastoreType Config
2017-06-01 23:37:27,569 | INFO | lt-dispatcher-19 | ClusterAdminRpcService | 201 - org.opendaylight.controller.sal-cluster-admin-impl - 1.5.1.SNAPSHOT | Successfully removed replica for shard default
2017-06-01 23:37:36,439 | INFO | ult-dispatcher-4 | tActorServerConfigurationSupport | 193 - org.opendaylight.controller.sal-akka-raft - 1.5.1.SNAPSHOT | member-2-shard-default-config: ServerConfigurationPayload [serverConfig=[ServerInfo [id=member-1-shard-default-config, isVoting=true], ServerInfo [id=member-3-shard-default-config, isVoting=true]]] has been successfully replicated to a majority of followers
2017-06-01 23:37:36,445 | INFO | ult-dispatcher-4 | ShardManager | 199 - org.opendaylight.controller.sal-distributed-datastore - 1.5.1.SNAPSHOT | shard-manager-config: Received LeaderStateChanged message: LeaderStateChanged [memberId=member-2-shard-default-config, leaderId=null, leaderPayloadVersion=5]
2017-06-01 23:37:38,659 | INFO | lt-dispatcher-32 | ClientActorBehavior | 197 - org.opendaylight.controller.cds-access-client - 1.1.1.SNAPSHOT | member-2-frontend-datastore-config: connection ConnectedClientConnection{client=ClientIdentifier

, cookie=0, backend=ShardBackendInfo{actor=Actorakka://opendaylight-cluster-data/user/shardmanager-config/member-2-shard-default-config#-579249557, sessionId=0, version=BORON, maxMessages=1000, cookie=0, shard=default, dataTree present=true}} reconnecting as ReconnectingClientConnection{client=ClientIdentifier

, cookie=0, backend=ShardBackendInfo{actor=Actorakka://opendaylight-cluster-data/user/shardmanager-config/member-2-shard-default-config#-579249557, sessionId=0, version=BORON, maxMessages=1000, cookie=0, shard=default, dataTree present=true}} throttle delay from 6 to 5 seconds
2017-06-01 23:40:15,167 | ERROR | pool-30-thread-1 | WriteTransactionsHandler | 256 - org.opendaylight.controller.samples.clustering-it-provider - 1.5.1.SNAPSHOT | Write transactions failed.
java.util.concurrent.TimeoutException: Timeout waiting for task.
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:269)[57:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:96)[57:com.google.guava:18.0.0]
at org.opendaylight.controller.clustering.it.provider.impl.WriteTransactionsHandler.maybeFinish(WriteTransactionsHandler.java:238)[256:org.opendaylight.controller.samples.clustering-it-provider:1.5.1.SNAPSHOT]
at org.opendaylight.controller.clustering.it.provider.impl.WriteTransactionsHandler.run(WriteTransactionsHandler.java:112)[256:org.opendaylight.controller.samples.clustering-it-provider:1.5.1.SNAPSHOT]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-06-01 23:40:15,367 | INFO | qtp10706451-308 | ClusterAdminRpcService | 201 - org.opendaylight.controller.sal-cluster-admin-impl - 1.5.1.SNAPSHOT | Adding replica for shard default

The karaf log segment above is from Sandbox running against 57996/5 with cherry-picked 57699/5.

The scenario uses a module-based shard (default-config) with tell-based protocol. The transaction writer is started on the leader member, then remove-shard-replica is called. A similar test case (writer on a follower, still calling remove-shard-replica on the leader) passed (the writer finished without reporting any failure).

Similar failure happened on recent RelEng run [9], but karaf.log [10] segment between 13:53:54,938 and 13:56:47,140 shows UnreachableMember happened.

[9] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/733/log.html.gz#s1-s20-t1-k2-k10-k1
[10] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/733/odl1_karaf.log.gz

This symptom re-appeared, it now happens [11] consistently but only in one test case. It tests module-based shards (tell based protocol) with single writer started on a follower, but then cluster-admin:make-leader-local attempts to move the leader to the writer member. The test expects writer to finish writing successfully.

The full writer response:
{"errors":{"error":[

]}}

[11] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/750/log.html.gz#s1-s24-t5-k2-k10

> consistently but only in one test case

Now I would say 50% of the time, still in only one [12] test case.
The response message is now more specific: "Final submit was timed out by the test provider or was interrupted".

The writer took 160 seconds to respond.

Few suspicious lines from writer member karaf.log [13] since 07:45:22,131 follow. The first one is especially confusing, since the connection is now reconnected to the new (local, member-2) leader, but it is still reporting NotLeaderException from the previous (remote, member-1) leader.

2017-06-21 07:45:38,519 | INFO | lt-dispatcher-20 | ClientActorBehavior | 197 - org.opendaylight.controller.cds-access-client - 1.1.1.SNAPSHOT | member-2-frontend-datastore-config: connection ConnectedClientConnection{client=ClientIdentifier

, cookie=0, backend=ShardBackendInfo{actor=Actorakka://opendaylight-cluster-data/user/shardmanager-config/member-2-shard-default-config#494504499, sessionId=1, version=BORON, maxMessages=1000, cookie=0, shard=default, dataTree present=true}} indicated no leadership, reconnecting it
org.opendaylight.controller.cluster.access.commands.NotLeaderException: Actor Actorakka://opendaylight-cluster-data/user/shardmanager-config/member-1-shard-default-config#-1667137708 is not the current leader

2017-06-21 07:45:38,624 | ERROR | lt-dispatcher-22 | OneForOneStrategy | 174 - com.typesafe.akka.slf4j - 2.4.18 | Transaction member-2-datastore-config-fe-0-chn-4-txn-5365-0 has already been sealed
java.lang.IllegalStateException: Transaction member-2-datastore-config-fe-0-chn-4-txn-5365-0 has already been sealed
at com.google.common.base.Preconditions.checkState(Preconditions.java:197)[57:com.google.guava:18.0.0]
at org.opendaylight.controller.cluster.databroker.actors.dds.AbstractProxyTransaction.checkNotSealed(AbstractProxyTransaction.java:363)[199:org.opendaylight.controller.sal-distributed-datastore:1.5.1.SNAPSHOT]

2017-06-21 07:45:38,657 | INFO | ult-dispatcher-5 | ClientActorBehavior | 197 - org.opendaylight.controller.cds-access-client - 1.1.1.SNAPSHOT | member-2-frontend-datastore-config: Ignoring unknown response Envelope{sessionId=1, txSequence=1, message=TransactionPurgeResponse{target=member-2-datastore-config-fe-0-chn-4-txn-5346-0, sequence=0}}

2017-06-21 07:48:18,136 | WARN | pool-30-thread-1 | WriteTransactionsHandler | 257 - org.opendaylight.controller.samples.clustering-it-provider - 1.5.1.SNAPSHOT | Future #5362/7971 not completed yet

[12] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/756/log.html.gz#s1-s24-t5-k2-k10
[13] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/756/odl2_karaf.log.gz

> the connection is now reconnected to the new (local, member-2) leader,
> but it is still reporting NotLeaderException from the previous (remote, member-1) leader.

Comparing log messages to code, I think that is a case of multiple FailureEnvelope from the same old backend.

Specifically, this [14] line confirms the connection to the new backend is established, but then this [15] line says the repeated message from the old backend is causing reconnect on the new connection.

In karaf.log [16] both log messages occur at 09:14:37,757.

In theory, spurious reconnects should not cause system test failures, so there is something to fix in other parts of the code as well.
But limiting reconnects (for example by having sessionId in FailureEnvelope and comparing it to the current value) would be helpful.

A cosmetic remark: ReconnectingClientConnection probably only needs to know maxMessages value; printing the whole ShardBackendInfo pointing to the old backend is slightly confusing, as that is not the backend ODL is likely to connect to.

[14] https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=blob;f=opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java;h=554ffe97c77ae7c3011daca2a28c22f660a20e78;hb=refs/heads/stable/carbon#l307
[15] https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=blob;f=opendaylight/md-sal/cds-access-client/src/main/java/org/opendaylight/controller/cluster/access/client/ClientActorBehavior.java;h=554ffe97c77ae7c3011daca2a28c22f660a20e78;hb=refs/heads/stable/carbon#l177
[16] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/761/odl2_karaf.log.gz

https://git.opendaylight.org/gerrit/59527

After rework of transaction writer, the error message [17] is different, but I believe it is the same bug. Now it happened on releng when the old leader got remove-shard-replica, and the single writer was on the member which stayed follower.

The new writer response:
{"errors":{"error":[

]}}

The karaf.log [18] reports 2011 futures as not completed, nothing else is visible on INFO level.

[17] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/765/log.html.gz#s1-s20-t3-k2-k8
[18] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-carbon/765/odl1_karaf.log.gz