Operating System: All
Platform: All

Appeared in ingest-mixed Boron CSIT suite

Similar problem observed when testing locally:
1. run ODL with configured app-peer
2. inject 100k prefixes
3. remove 100k prefixes (one-by-one)
4. unexpected behavior observed in LocRibWriter - calling #get() on empty optional - modification type DELETE, dataBefore absent
The 6 prefixes left in loc-rib

(In reply to Milos Fabian from comment #2)
> Similar problem observed when testing locally:
> 1. run ODL with configured app-peer
> 2. inject 100k prefixes
> 3. remove 100k prefixes (one-by-one)
> 4. unexpected behavior observed in LocRibWriter - calling #get() on empty
> optional - modification type DELETE, dataBefore absent
> The 6 prefixes left in loc-rib

Happening with some very specific prefixes:

2016-08-30 16:36:40,242 | INFO | on-dispatcher-96 | LocRibWriter | 288 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Data before missing for: (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], ChildNode{mod = NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], modificationType=DELETE, childModification={}], oldMeta = null, newMeta = null}
2016-08-30 16:36:40,245 | INFO | on-dispatcher-96 | LocRibWriter | 288 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Data before missing for: (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], ChildNode{mod = NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], modificationType=DELETE, childModification={}], oldMeta = null, newMeta = null}
2016-08-30 16:36:40,250 | INFO | on-dispatcher-96 | LocRibWriter | 288 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Data before missing for: (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], ChildNode{mod = NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], modificationType=DELETE, childModification={}], oldMeta = null, newMeta = null}
2016-08-30 16:36:40,253 | INFO | on-dispatcher-96 | LocRibWriter | 288 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Data before missing for: (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], ChildNode{mod = NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], modificationType=DELETE, childModification={}], oldMeta = null, newMeta = null}
2016-08-30 16:36:40,255 | INFO | on-dispatcher-96 | LocRibWriter | 288 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Data before missing for: (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], ChildNode{mod = NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], modificationType=DELETE, childModification={}], oldMeta = null, newMeta = null}
2016-08-30 16:36:40,274 | INFO | on-dispatcher-96 | LocRibWriter | 288 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Data before missing for: (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], ChildNode{mod = NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], modificationType=DELETE, childModification={}], oldMeta = null, newMeta = null}

The problem addressed to controller/md-sal devs: https://lists.opendaylight.org/pipermail/controller-dev/2016-August/012561.html

Same issue is seen with Beryllium as well. Please refer exception encountered in read-life network environment under high load:

2016-09-01 20:22:04,696 | WARN | lt-dispatcher-42 | AbstractTopologyBuilder | 329 - org.opendaylight.bgpcep.bgp-topology-provider - 0.5.0.Beryllium | Data change org.opendaylight.controller.md.sal.binding.impl.LazyDataTreeModification@963f998 (transaction DOM-CHAIN-10-159563) was not completely propagated to listener org.opendaylight.bgpcep.bgp.topology.provider.LinkstateTopologyBuilder@2976ef9
java.lang.NullPointerException
at org.opendaylight.bgpcep.bgp.topology.provider.UriBuilder.<init>(UriBuilder.java:43)[329:org.opendaylight.bgpcep.bgp-topology-provider:0.5.0.Beryllium]
at org.opendaylight.bgpcep.bgp.topology.provider.LinkstateTopologyBuilder.removeObject(LinkstateTopologyBuilder.java:933)[329:org.opendaylight.bgpcep.bgp-topology-provider:0.5.0.Beryllium]
at org.opendaylight.bgpcep.bgp.topology.provider.LinkstateTopologyBuilder.removeObject(LinkstateTopologyBuilder.java:124)[329:org.opendaylight.bgpcep.bgp-topology-provider:0.5.0.Beryllium]
at org.opendaylight.bgpcep.bgp.topology.provider.AbstractTopologyBuilder.routeChanged(AbstractTopologyBuilder.java:213)[329:org.opendaylight.bgpcep.bgp-topology-provider:0.5.0.Beryllium]
at org.opendaylight.bgpcep.bgp.topology.provider.AbstractTopologyBuilder.onDataTreeChanged(AbstractTopologyBuilder.java:175)[329:org.opendaylight.bgpcep.bgp-topology-provider:0.5.0.Beryllium]
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMDataTreeChangeListenerAdapter.onDataTreeChanged(BindingDOMDataTreeChangeListenerAdapter.java:41)[115:org.opendaylight.controller.sal-binding-broker-impl:1.3.0.Beryllium]
at org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.dataChanged(DataTreeChangeListenerActor.java:53)[140:org.opendaylight.controller.sal-distributed-datastore:1.3.0.Beryllium]
at org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.handleReceive(DataTreeChangeListenerActor.java:37)[140:org.opendaylight.controller.sal-distributed-datastore:1.3.0.Beryllium]
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedActor.onReceive(AbstractUntypedActor.java:34)[136:org.opendaylight.controller.sal-clustering-commons:1.3.0.Beryllium]

Can you report the entire DTCN, from root for this case?

This looks like some badness in the DataTree implementation. Specifically it looks like AbstractModifiedNodeBasedCandidateNode is allocating a ChildNode with no backing metadata.

Now, that child node was resolved to DELETE (in SchemaAwareApplyOperation.apply()), which indicates that the 'before' metadata was supplied to it, while it was not actually present in the tree. This evidence points it squarely at StructuralContainerModificationStrategy#57, which is the only place playing this kind of a trick.

We need logs replicating this issue, with https://git.opendaylight.org/gerrit/48049 applied to the controller and ShardDataTree logging set to TRACE.

We need to see both the modification and the data tree candidate which trigger this behavior.

Attachment karaf.log.tar.gz has been added with description: log

Attachment karaf.log.1.tar.gz has been added with description: log1

Attachment karaf.log.2.tar.gz has been added with description: log2

Attachment karaf.log.3.tar.gz has been added with description: log3

Attachment karaf.log.4.tar.gz has been added with description: log4

Analyzing karaf.log.4, the problem is narrowed down a bit. In this specific case, the route being deleted is: prefix=1.2.120.199/32 path-id=0

The deletion record is correct, as the route is present in parent's oldMeta and it is not present in its newMeta.

The stack trace has a Iterators$8.transform() as the caller of AbstractModifiedNodeBasedCandidateNode.childNode(), which points to its getChildNodes() method, which is logical, as the parent is marked as SUBTREE_MODIFIED and BGP code is traversing it to find out what is going on.

Based on this, the cause seems to be the fact that eventhough the record is in oldMeta's children map, the call AbstractModifiedNodeBasedCandidateNode.childMeta() -> MaterializedContainerNode.getChild() fails to find it – but it is registering it in its children map.

Since the objects in question are supposed to be immutable at this point, I think it is safe to say that the DataTree code itself is correct and the problem lies in one of three components:

• NodeIdentifierWithPredicates
• TrieMap (since we are at a scale where children are tracked using it)
• JVM badness (affecting either one of the above)

Actually, there is a fourth component involved: ImmutableOffsetMap, which is the backing map inside NodeIdentifierWithPredicates.

Ajay, can you check what was the JVM version involved in that, please?

debug patch to eliminate custom maps from the picture: https://git.opendaylight.org/gerrit/48420

tested against u112 and ImmutableMaps, issue still present

Attachment BUG_6577_STEPS.txt has been added with description: Steps to reproduce bug

After additional testing it seems the problem is either in JVM or TrieMap. Specifially, I have added code, which when it encounters this conditions walks through the map's entrySet() and tries to find the corresponding key.

What I am getting is:

2016-11-18 18:00:17,821 | WARN | lt-dispatcher-36 | ctModifiedNodeBasedCandidateNode | 85 - org.opendaylight.yangtools.yang-data-impl - 1.0.2.SNAPSHOT | Missing key is (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], identity 1745067963, hash 1674416874
2016-11-18 18:00:17,825 | WARN | lt-dispatcher-36 | ctModifiedNodeBasedCandidateNode | 85 - org.opendaylight.yangtools.yang-data-impl - 1.0.2.SNAPSHOT | Found matching key (urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], identity 1269043004, hash 1674416874
2016-11-18 18:00:17,825 | WARN | lt-dispatcher-36 | ctModifiedNodeBasedCandidateNode | 85 - org.opendaylight.yangtools.yang-data-impl - 1.0.2.SNAPSHOT | Inverse equals: true
2016-11-18 18:00:17,826 | WARN | lt-dispatcher-36 | ctModifiedNodeBasedCandidateNode | 85 - org.opendaylight.yangtools.yang-data-impl - 1.0.2.SNAPSHOT | Stored lookup: SimpleContainerNode{version=org.opendaylight.yangtools.yang.data.api.schema.tree.spi.Version@267ba74b, data=ImmutableMapEntryNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-route[

], value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)path-id, value=0, attributes={}}, ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)prefix, value=1.2.121.197/32, attributes={}}, ImmutableContainerNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)attributes, value=[ImmutableContainerNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)as-path, value=[], attributes={}}, ImmutableContainerNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)origin, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)value, value=igp, attributes={}}], attributes={}}, ImmutableContainerNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)local-pref, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)pref, value=100, attributes={}}], attributes={}}, ImmutableChoiceNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)c-next-hop, value=[ImmutableContainerNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)ipv4-next-hop, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)global, value=127.0.0.1, attributes={}}], attributes={}}]}, ImmutableContainerNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)multi-exit-disc, value=[ImmutableLeafNode{nodeIdentifier=(urn:opendaylight:params:xml:ns:yang:bgp-inet?revision=2015-03-05)med, value=0, attributes={}}], attributes={}}], attributes={}}], attributes={}}}
2016-11-18 18:00:17,826 | WARN | lt-dispatcher-36 | ctModifiedNodeBasedCandidateNode | 85 - org.opendaylight.yangtools.yang-data-impl - 1.0.2.SNAPSHOT | Normal lookup: null

So the key is present as a different object in the map, they compare as .equals() in both directions and report the same hash code.

When we perform the lookup using the stored key, the map returns a value. When we perform the lookup using our key, the map returns null – which is a violation of java.util.Map contract.

Either the key's identity hash or identity comparison is used somewhere. Looking through TrieMap implementation, I do not see identity hash being used, nor keys being compared in any other way than through .equals().

Next step will be to retry with JDK 1.8.0u60, to see if this problem is present.

Tracked down to https://github.com/romix/java-concurrent-hash-trie-map/blob/master/src/main/java/com/romix/scala/collection/concurrent/TrieMap.java#L464, which looks like a bug. The same code is present in the Scala version of the code at https://github.com/scala/scala/blob/2.12.x/src/library/scala/collection/concurrent/TrieMap.scala#L264.

I am not sure why identity comparison is used herre specifically, and the codepath only ever triggers for read-only trie – hence I guess it is not as well-tested as the read-write case.

upstream: https://github.com/romix/java-concurrent-hash-trie-map/pull/24

scala: https://github.com/scala/scala/pull/5547

Waiting for either an upstream release or helpdesk finish ticket #33071.

ODL-private package seeded.

master: https://git.opendaylight.org/gerrit/48531

boron: https://git.opendaylight.org/gerrit/48611