[CONTROLLER-1445] Having empty-containers make NormalizedNodeInputStreamReader go beserk Created: 06/Nov/15  Updated: 17/Nov/15  Resolved: 17/Nov/15

Status: Resolved
Project: controller
Component/s: clustering
Affects Version/s: Beryllium
Fix Version/s: None

Type: Bug
Reporter: Shuva Jyoti Kar Assignee: Tom Pantelis
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: Linux
Platform: Other

External issue ID: 4590
Priority: High

 Description   

Version Used : Lithium Stable release. Planning to repeat this on Beryllium master – will update on the same.
Cluster : Single-node - restart-with-persistent-data scenario

Test Case (this case is very specific to Openflow inventory model, but this could be a generic issue)
1. Create a group as following via RESTCONF in Config DS (please note that ‘Buckets’ is made intentionally empty)
2. Shutdown controller gracefully or ungracefully
3. Restart the controller
4. Try to read the group from inventory nodes Config DS
5. Read Operation would hang
6. All shards become unrecoverable and reach notinitialized state. All journals to be wiped and controller to be restarted clean-slate

Empty-bucket group addition case
RESTCONF URL :
http://localhost:8080/restconf/config/opendaylight-inventory:nodes/node/openflow:1/group/1

Operation : PUT

Body :
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<group xmlns="urn:opendaylight:flow:inventory">
<group-type>group-indirect</group-type>
<buckets>
<!—EMPTY CONTAINER 
</buckets>
<barrier>false</barrier>
<group-name>Foo1</group-name>
<group-id>1</group-id>
</group>

Exception seen on the logs during RESTART (where NormalizedNodeInputStreamReader kicks-in)

2015-11-05 04:10:44,317 | DEBUG | ult-dispatcher-7 | NormalizedNodeInputStreamReader | 218 - org.opendaylight.controller.sal-clustering-commons - 1.2.1.SNAPSHOT | Muthu: Reading map entry node MAP_ENTRY_NODE qName (urn:opendaylight:inventory?revision=2013-08-19)node keyValueMap

{(urn:opendaylight:inventory?revision=2013-08-19)id=openflow:1}

2015-11-05 04:10:44,318 | ERROR | ult-dispatcher-7 | DataTreeCandidatePayload | 226 - org.opendaylight.controller.sal-distributed-datastore - 1.2.1.SNAPSHOT | Muthu : Exception in SUBTREE_MODIFIED case of parseCandidate ModifiedDataTreeCandidateNode {}
com.google.common.util.concurrent.UncheckedExecutionException: java.lang.IllegalArgumentException: Revision 'urn:opendaylight:inventory'is not in a supported format
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)[108:com.google.guava:18.0.0]
at org.opendaylight.controller.cluster.datastore.node.utils.QNameFactory.create(QNameFactory.java:36)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readQName(NormalizedNodeInputStreamReader.java:245)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readNormalizedNodeInternal(NormalizedNodeInputStreamReader.java:142)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.addDataContainerChildren(NormalizedNodeInputStreamReader.java:399)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readNodeIdentifierDependentNode(NormalizedNodeInputStreamReader.java:188)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readNormalizedNodeInternal(NormalizedNodeInputStreamReader.java:151)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.addDataContainerChildren(NormalizedNodeInputStreamReader.java:399)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readNodeIdentifierDependentNode(NormalizedNodeInputStreamReader.java:213)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readNormalizedNodeInternal(NormalizedNodeInputStreamReader.java:151)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.stream.NormalizedNodeInputStreamReader.readNormalizedNode(NormalizedNodeInputStreamReader.java:86)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload.readNode(DataTreeCandidatePayload.java:156)[226:org.opendaylight.controller.sal-distributed-datastore:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload.readChildren(DataTreeCandidatePayload.java:127)[226:org.opendaylight.controller.sal-distributed-datastore:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload.parseCandidate(DataTreeCandidatePayload.java:175)[226:org.opendaylight.controller.sal-distributed-datastore:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload.getCandidate(DataTreeCandidatePayload.java:203)[226:org.opendaylight.controller.sal-distributed-datastore:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.ShardRecoveryCoordinator.appendRecoveredLogEntry(ShardRecoveryCoordinator.java:70)[226:org.opendaylight.controller.sal-distributed-datastore:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.raft.RaftActorRecoverySupport.batchRecoveredLogEntry(RaftActorRecoverySupport.java:162)[219:org.opendaylight.controller.sal-akka-raft:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.raft.RaftActorRecoverySupport.onRecoveredApplyLogEntries(RaftActorRecoverySupport.java:141)[219:org.opendaylight.controller.sal-akka-raft:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.raft.RaftActorRecoverySupport.handleRecoveryMessage(RaftActorRecoverySupport.java:54)[219:org.opendaylight.controller.sal-akka-raft:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.raft.RaftActor.handleRecover(RaftActor.java:160)[219:org.opendaylight.controller.sal-akka-raft:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedPersistentActor.onReceiveRecover(AbstractUntypedPersistentActor.java:48)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.Shard.onReceiveRecover(Shard.java:213)[226:org.opendaylight.controller.sal-distributed-datastore:1.2.1.SNAPSHOT]
at akka.persistence.UntypedPersistentActor$$anonfun$receiveRecover$1.applyOrElse(Eventsourced.scala:433)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at scala.runtime.AbstractPartialFunction$mcVL$sp.apply$mcVL$sp(AbstractPartialFunction.scala:33)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.runtime.AbstractPartialFunction$mcVL$sp.apply(AbstractPartialFunction.scala:33)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.runtime.AbstractPartialFunction$mcVL$sp.apply(AbstractPartialFunction.scala:25)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at akka.persistence.Eventsourced$$anonfun$akka$persistence$Eventsourced$$recoveryBehavior$1.applyOrElse(Eventsourced.scala:168)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$class.runReceive(Recovery.scala:48)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.UntypedPersistentActor.runReceive(Eventsourced.scala:428)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$State$$anonfun$processPersistent$1.apply(Recovery.scala:33)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$State$$anonfun$processPersistent$1.apply(Recovery.scala:33)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$class.withCurrentPersistent(Recovery.scala:185)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.UntypedPersistentActor.withCurrentPersistent(Eventsourced.scala:428)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$State$class.processPersistent(Recovery.scala:33)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$$anon$1.processPersistent(Recovery.scala:104)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$$anon$1.aroundReceive(Recovery.scala:110)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Recovery$class.aroundReceive(Recovery.scala:265)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.UntypedPersistentActor.akka$persistence$Eventsourced$$super$aroundReceive(Eventsourced.scala:428)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Eventsourced$$anon$1.aroundReceive(Eventsourced.scala:35)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.Eventsourced$class.aroundReceive(Eventsourced.scala:369)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.persistence.UntypedPersistentActor.aroundReceive(Eventsourced.scala:428)[216:com.typesafe.akka.persistence.experimental:2.3.10]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516)[211:com.typesafe.akka.actor:2.3.10]
at akka.actor.ActorCell.invoke(ActorCell.scala:487)[211:com.typesafe.akka.actor:2.3.10]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:254)[211:com.typesafe.akka.actor:2.3.10]
at akka.dispatch.Mailbox.run(Mailbox.scala:221)[211:com.typesafe.akka.actor:2.3.10]
at akka.dispatch.Mailbox.exec(Mailbox.scala:231)[211:com.typesafe.akka.actor:2.3.10]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.pollAndExecAll(ForkJoinPool.java:1253)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1346)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[208:org.scala-lang.scala-library:2.10.4.v20140209-180020-VFINAL-b66a39653b]
Caused by: java.lang.IllegalArgumentException: Revision 'urn:opendaylight:inventory'is not in a supported format
at org.opendaylight.yangtools.yang.common.QName.parseRevision(QName.java:351)[110:org.opendaylight.yangtools.yang-common:0.7.1.SNAPSHOT]
at org.opendaylight.yangtools.yang.common.QName.create(QName.java:279)[110:org.opendaylight.yangtools.yang-common:0.7.1.SNAPSHOT]
at org.opendaylight.yangtools.yang.common.QName.create(QName.java:127)[110:org.opendaylight.yangtools.yang-common:0.7.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.QNameFactory$1.load(QNameFactory.java:29)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.node.utils.QNameFactory$1.load(QNameFactory.java:26)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)[108:com.google.guava:18.0.0]
... 54 more
Caused by: java.text.ParseException: Unparseable date: "urn:opendaylight:inventory"
at java.text.DateFormat.parse(DateFormat.java:357)[:1.7.0_65]
at org.opendaylight.yangtools.yang.common.QName.parseRevision(QName.java:349)[110:org.opendaylight.yangtools.yang-common:0.7.1.SNAPSHOT]
... 62 more
2015-11-05 04:10:44,319 | ERROR | ult-dispatcher-7 | DataTreeCandidatePayload | 226 - org.opendaylight.controller.sal-distributed-datastore - 1.2.1.SNAPSHOT | Muthu: RotNode is NULL !!!

 Comments   
Comment by Tony Tkacik [ 06/Nov/15 ]

Seems some code / binary change in clustering recovery changed binary format

Revision 'urn:opendaylight:inventory'is not in a supported format
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)[108:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)[108:com.google.guava:18.0.0]
at org.opendaylight.controller.cluster.datastore.node.utils.QNameFactory.create(QNameFactory.java:36)[218:org.opendaylight.controller.sal-clustering-commons:1.2.1.SNAPSHOT]

Points at trying to parse namespace as revision.

Comment by Muthukumaran Kothandaraman [ 06/Nov/15 ]

Looks like what Tony says closely resembles debugging observation

In NormalizedInputStreamReader.java

private String readCodedString() throws IOException {
byte valueType = input.readByte();
if(valueType == NormalizedNodeOutputStreamWriter.IS_CODE_VALUE)

{ return codedStringMap.get(input.readInt()); }

else if(valueType == NormalizedNodeOutputStreamWriter.IS_STRING_VALUE)

{ String value = input.readUTF().intern(); codedStringMap.put(Integer.valueOf(codedStringMap.size()), value); return value; }

return null;
}

THIS METHOD ALWAYS RETURNS NULL -

As a consequence, in below case,
localName becomes NULL
namespace becomes NULL
revision becomes urn:opendaylight:inventory

private QName readQName() throws IOException {
// Read in the same sequence of writing
String localName = readCodedString();
String namespace = readCodedString();
String revision = readCodedString();

String qName;
if(!Strings.isNullOrEmpty(revision))

{ qName = reusableStringBuilder.append('(').append(namespace).append(REVISION_ARG). append(revision).append(')').append(localName).toString(); }

else

{ qName = reusableStringBuilder.append('(').append(namespace).append(')'). append(localName).toString(); }

reusableStringBuilder.delete(0, reusableStringBuilder.length());
return QNameFactory.create(qName);
}

Since revision does not contain data, this results in
com.google.common.util.concurrent.UncheckedExecutionException: java.lang.IllegalArgumentException: Revision 'urn:opendaylight:inventory'is not in a supported format

Comment by Tony Tkacik [ 06/Nov/15 ]

Could you attach payload with which you are observing error?

Also is this reproducible on Beryllium master and released Lithium (NOT SRs)

Comment by Muthukumaran Kothandaraman [ 06/Nov/15 ]

(In reply to Tony Tkacik from comment #3)
> Could you attach payload with which you are observing error?
>
> Also is this reproducible on Beryllium master and released Lithium (NOT SRs)

Payload is following (only group needs to be created - no flows) :
===================================================================
RESTCONF URL :
http://localhost:8080/restconf/config/opendaylight-inventory:nodes/node/openflow:1/group/1

Operation : PUT

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<group xmlns="urn:opendaylight:flow:inventory">
<group-type>group-indirect</group-type>
<buckets>
<!—EMPTY CONTAINER -->
</buckets>
<barrier>false</barrier>
<group-name>Foo1</group-name>
<group-id>1</group-id>
</group>

Tested Release : Lithium Stable

One observation is that NormalizedNodeInputStreamReader.java has no changes since Lithium Stable release. So, I suspect that it should be reproducible in Beryllium master too.

I will verify and confirm as soon as possible with Beryllium

Comment by Tom Pantelis [ 09/Nov/15 ]

I was not able to reproduce this on the latest Li SR3. I didn't install the entire openflowplugin but I copied the relevant yang models to my controller build.

I first did PUT to http://localhost:8181/restconf/config/opendaylight-inventory:nodes/node/openflow:1

<node xmlns="urn:opendaylight:inventory">
<id>openflow:1</id>
</node>

Then I PUT to http://localhost:8181/restconf/config/opendaylight-inventory:nodes/node/openflow:1/group/1

<group xmlns="urn:opendaylight:flow:inventory">
<group-type>group-indirect</group-type>
<buckets></buckets>
<barrier>false</barrier>
<group-name>foo</group-name>
<group-id>1</group-id>
</group>

On restart, the data recovered fine.

According to the bug description, my steps look to be equivalent unless I missed something.

Can you try to reproduce with Li SR3?

Comment by Moiz Raja [ 17/Nov/15 ]

Not an issue

Generated at Wed Feb 07 19:55:34 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.