Operating System: All
Platform: All

Attachment write_transactions.tar has been added with description: karaf and robot log

I see a couple of these in the member 1 log:

safe.akka.slf4j - 2.4.17 | Failed to serialize remote message [class org.opendaylight.controller.cluster.access.concepts.RequestEnvelope] using serializer [class akka.serialization.JavaSerializer]. Transient association error (association remains live)
akka.remote.MessageSerializer$SerializationException: Failed to serialize remote message [class org.opendaylight.controller.cluster.access.concepts.RequestEnvelope] using serializer [class akka.serialization.JavaSerializer].
at akka.remote.MessageSerializer$.serialize(MessageSerializer.scala:61)[210:com.typesafe.akka.remote:2.4.17]
...
Caused by: java.lang.UnsupportedOperationException: Local transaction request CommitLocalTransactionRequest

should never be serialized
at org.opendaylight.controller.cluster.access.commands.AbstractLocalTransactionRequest.externalizableProxy(AbstractLocalTransactionRequest.java:34)[223:org.opendaylight.controller.cds-access-api:1.1.0.SNAPSHOT]
at org.opendaylight.controller.cluster.access.commands.AbstractLocalTransactionRequest.externalizableProxy(AbstractLocalTransactionRequest.java:23)[223:org.opendaylight.controller.cds-access-api:1.1.0.SNAPSHOT]
at org.opendaylight.controller.cluster.access.concepts.Request.externalizableProxy(Request.java:27)[223:org.opendaylight.controller.cds-access-api:1.1.0.SNAPSHOT]
at org.opendaylight.controller.cluster.access.concepts.Message.writeReplace(Message.java:170)[223:org.opendaylight.controller.cds-access-api:1.1.0.SNAPSHOT]

member switched from Leader to Follower shortly before the error:

2017-05-04 10:43:33,364 | INFO | lt-dispatcher-55 | Shard | 219 - org.opendaylight.controller.sal-clustering-commons - 1.5.0.SNAPSHOT | member-1-shard-default-config (Leader) :- Switching from behavior Leader to Follower, election term: 4

Then the front-end reconnected to the new leader:

2017-05-04 10:43:42,271 | INFO | lt-dispatcher-69 | ClientActorBehavior | 224 - org.opendaylight.controller.cds-access-client - 1.1.0.SNAPSHOT | member-1-frontend-datastore-config: replaced connection ReconnectingClientConnection{client=ClientIdentifier

, cookie=0, backend=ShardBackendInfo{actor=Actor[akka.tcp://opendaylight-cluster-data@172.17.0.5:2550/user/shardmanager-config/member-2-shard-default-config#1531829272], sessionId=1, version=BORON, maxMessages=1000, cookie=0, shard=default}}

It looks like the CommitLocalTransactionRequest was initially targeted to go to the local leader and was retried to go to the new remote leader. It seems like we need to somehow change the local request to a remote one in this case.

(In reply to Tom Pantelis from comment #2)
> member switched from Leader to Follower shortly before the error:
>
>
> 2017-05-04 10:43:33,364 | INFO | lt-dispatcher-55 | Shard
> | 219 - org.opendaylight.controller.sal-clustering-commons - 1.5.0.SNAPSHOT
> | member-1-shard-default-config (Leader) :- Switching from behavior Leader
> to Follower, election term: 4
>
> Then the front-end reconnected to the new leader:
>
> 2017-05-04 10:43:42,271 | INFO | lt-dispatcher-69 | ClientActorBehavior
> | 224 - org.opendaylight.controller.cds-access-client - 1.1.0.SNAPSHOT |
> member-1-frontend-datastore-config: replaced connection
> ReconnectingClientConnection{client=ClientIdentifier

, cookie=0,
> backend=ShardBackendInfo{actor=Actor[akka://opendaylight-cluster-data/user/
> shardmanager-config/member-1-shard-default-config#1279384036], sessionId=0,
> version=BORON, maxMessages=1000, cookie=0, shard=default}} with
> ConnectedClientConnection{client=ClientIdentifier

, cookie=0,
> backend=ShardBackendInfo{actor=Actor[akka.tcp://opendaylight-cluster-
> data@172.17.0.5:2550/user/shardmanager-config/member-2-shard-default-
> config#1531829272], sessionId=1, version=BORON, maxMessages=1000, cookie=0,
> shard=default}}
>
> It looks like the CommitLocalTransactionRequest was initially targeted to go
> to the local leader and was retried to go to the new remote leader. It seems
> like we need to somehow change the local request to a remote one in this
> case.

Just want to mention again that write-transaction was called via restconf around 10:43:10.2XX and should have finished within 5-6 seconds time. Time 10:43:09,965 looks too late.

That seems to be a duplicate of CONTROLLER-1644. I'll take a closer look.

(In reply to Peter Gubka from comment #3)
> Just want to mention again that write-transaction was called via restconf
> around 10:43:10.2XX and should have finished within 5-6 seconds time. Time
> 10:43:09,965 looks too late.

Not sure what you mean. I didn't mention time 10:43:09,965. The leader change occurred at 10:43:33 and the error at 10:43:42 which is later than 10:43:10. The serialization error would've timed out the request and failed the transaction.

So this is a standalone transaction facing a local->remote connect. We definitely should be translating the message from local to remote equivalent.

Since we do not have debugs, it is not clear if the message was already in the queue or we are facing a late forward (i.e. the transaction was allocated while reconnect was happening). I would assume the request was in the queue and it timed out.

This is where ProxyHistory$ReconnectCohort.replayRequest() should kick in and route the request to AbstractProxyTransaction.replayRequest(). I will audit the codepaths to see what is going on.

Sorry, that path would be taken by a latecomer request. It seems the trouble lies in RemoteProxyTransaction.handleForwardedRemoteRequest() as it is called from AbstractProxyTransaction.replayMessages(). I will dissect the call paths and untangle the API contract.

There is also another issue in the logs:

2017-05-04 10:42:19,513 | WARN | ult-dispatcher-3 | FrontendReadOnlyTransaction | 226 - org.opendaylight.controller.sal-distributed-datastore - 1.5.0.SNAPSHOT | Rejecting unsupported request TransactionAbortRequest

Which looks like a remote request to close a snapshot.

(In reply to Tom Pantelis from comment #5)
> (In reply to Peter Gubka from comment #3)
> > Just want to mention again that write-transaction was called via restconf
> > around 10:43:10.2XX and should have finished within 5-6 seconds time. Time
> > 10:43:09,965 looks too late.
>
> Not sure what you mean. I didn't mention time 10:43:09,965. The leader
> change occurred at 10:43:33 and the error at 10:43:42 which is later than
> 10:43:10. The serialization error would've timed out the request and failed
> the transaction.

My primary problem which i have is that rpc write-transactions did not return (rest). It started 10:43:10.2XX and should have finished 5-6 seconds later. The leader change (i believe) is just a resulting activity which happened. Just want logs from 10:43:10.2XX not to be overlooked.

(In reply to Robert Varga from comment #9)
> There is also another issue in the logs:
>
> 2017-05-04 10:42:19,513 | WARN | ult-dispatcher-3 |
> FrontendReadOnlyTransaction | 226 -
> org.opendaylight.controller.sal-distributed-datastore - 1.5.0.SNAPSHOT |
> Rejecting unsupported request
> TransactionAbortRequest

>
> Which looks like a remote request to close a snapshot.

What debug logs do you want to be on?

Same behavior is in 1node setup.

Should be reproducible simply.
1) Start odl with tell-based=true
2) Make a POST
http://<ip>:8181/restconf/operations/odl-mdsal-lowlevel-control:write-transactions,
<input xmlns="tag:opendaylight.org,2017:controller:yang:lowlevel:control">
<id>prefix-1</id>
<seconds>5</seconds>
<transactions-per-second>10</transactions-per-second>
<chained-transactions>false</chained-transactions>
</input>

No matter is simple or chained transactions used.

Attachment karaf_log_1.tar.gz.601_simple has been added with description: logs 1node simple

Attachment karaf_log_1.tar.gz.603_chained has been added with description: logs 1node chained

All this above was for module shard test.

On prefix shard test i run similar test, 1 node odl, rpc produce-transactions
url: http://172.17.0.4:8181/restconf/operations/odl-mdsal-lowlevel-control:produce-transactions, data: <input xmlns="tag:opendaylight.org,2017:controller:yang:lowlevel:control">
<id>prefix-1</id>
<seconds>5</seconds>
<transactions-per-second>10</transactions-per-second>
<isolated-transactions>True</isolated-transactions>
</input>, timeout: 65

it finished ok, but insted of 5-6 seconds it took 60s to respond correct results to robot.

And again there is a timeframe when nothing happened for 20s.
2017-05-05 10:23:58,632 | DEBUG | lt-dispatcher-29 | ShardDataTree | 226 - org.opendaylight.controller.sal-distributed-datastore - 1.5.0.SNAPSHOT | member-1-shard-id-ints!-config: Preparing transaction member-1-datastore-Shard-id-ints!-fe-0-chn-5-txn-0-0
2017-05-05 10:24:17,929 | DEBUG | lt-dispatcher-29 | CompositeDataTreeCohort | 226 - org.opendaylight.controller.sal-distributed-datastore - 1.5.0.SNAPSHOT | member-1-datastore-Shard-id-ints!-fe-0-chn-5-txn-0-0: canCommit - candidate: [FAILED toString()]

But finally it responded http status 200 with data {"output":{"insert-tx":28,"delete-tx":21,"all-tx":49}} around 10:24:56

Attachment karaf_log_1.tar.gz has been added with description: prefix shard produce transactions

The fix for TransactionAbortRequest: https://git.opendaylight.org/gerrit/56596

Is this a duplicate of CONTROLLER-1665 or was this a different bug with similar symptom?