[NETCONF-349] Metadata not present for modification Created: 14/Feb/17  Updated: 15/Mar/19  Resolved: 20/Feb/17

Status: Resolved
Project: netconf
Component/s: netconf
Affects Version/s: None
Fix Version/s: None

Type: Bug
Reporter: Jan Srnicek Assignee: Miroslav Kovac
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: Linux
Platform: PC

Attachments: File extended-debug-logs.tar.gz     Zip Archive honeycomb-failed-debug.zip    
External issue ID: 7791

 Description   

While using folowing chain of messages

<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-2">
<lock>
<target>
<candidate/>
</target>
</lock>
</rpc>
]]>]]>

<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-3">
<get-config>
<source>
<running/>
</source>
<filter xmlns:ns0="urn:ietf:params:xml:ns:netconf:base:1.0" ns0:type="subtree">
<vpp xmlns="urn:opendaylight:params:xml:ns:yang:v3po">
<bridge-domains>
<bridge-domain>
<name>testBD2</name>
</bridge-domain>
</bridge-domains>
</vpp>
</filter>
</get-config>
</rpc>
]]>]]>

<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-4">
<edit-config>
<target>
<candidate/>
</target>
<config>
<vpp xmlns="urn:opendaylight:params:xml:ns:yang:v3po">
<bridge-domains/>
</vpp>
</config>
</edit-config>
</rpc>
]]>]]>

<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-5">
<edit-config>
<target>
<candidate/>
</target>
<default-operation>none</default-operation>
<config>
<vpp xmlns="urn:opendaylight:params:xml:ns:yang:v3po">
<bridge-domains>
<bridge-domain xmlns:a="urn:ietf:params:xml:ns:netconf:base:1.0" a:operation="replace">
<name>testBD2</name>
<forward>false</forward>
<learn>false</learn>
<unknown-unicast-flood>false</unknown-unicast-flood>
<arp-termination>false</arp-termination>
<flood>true</flood>
</bridge-domain>
</bridge-domains>
</vpp>
</config>
</edit-config>
</rpc>
]]>]]>

<rpc xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="m-6">
<commit/>
</rpc>
]]>]]>

Exception is thrown

java.lang.IllegalArgumentException: Metadata not available for modification NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:v3po?revision=2016-12-14)bridge-domain, modificationType=TOUCH, childModification={(urn:opendaylight:params:xml:ns:yang:v3po?revision=2016-12-14)bridge-domain[

{(urn:opendaylight:params:xml:ns:yang:v3po?revision=2016-12-14)name=testBD2}

]=NodeModification [identifier=(urn:opendaylight:params:xml:ns:yang:v3po?revision=2016-12-14)bridge-domain[

{(urn:opendaylight:params:xml:ns:yang:v3po?revision=2016-12-14)name=testBD2}

], modificationType=WRITE, childModification={}]}]
at com.google.common.base.Preconditions.checkArgument(Preconditions.java:145) ~[guava-18.0.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:198) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:139) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:252) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.applyMerge(AbstractNodeContainerModificationStrategy.java:170) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:213) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.StructuralContainerModificationStrategy.apply(StructuralContainerModificationStrategy.java:71) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:139) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.applyWrite(AbstractNodeContainerModificationStrategy.java:113) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:210) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.StructuralContainerModificationStrategy.apply(StructuralContainerModificationStrategy.java:71) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:139) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:252) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:200) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.RootModificationApplyOperation.apply(RootModificationApplyOperation.java:78) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractDataTreeTip.prepare(AbstractDataTreeTip.java:53) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractDataTreeTip.prepare(AbstractDataTreeTip.java:20) ~[yang-data-impl-1.0.2-Boron-SR2.jar:na]
at io.fd.honeycomb.data.impl.PersistingDataTreeAdapter.prepare(PersistingDataTreeAdapter.java:168) ~[data-impl-1.17.01-SNAPSHOT.jar:na]
at io.fd.honeycomb.data.impl.ModifiableDataTreeManager$ConfigSnapshot.commit(ModifiableDataTreeManager.java:103) ~[data-impl-1.17.01-SNAPSHOT.jar:na]
at io.fd.honeycomb.data.impl.WriteTransaction.submit(WriteTransaction.java:136) ~[data-impl-1.17.01-SNAPSHOT.jar:na]
at io.fd.honeycomb.data.impl.ReadWriteTransaction.submit(ReadWriteTransaction.java:76) ~[data-impl-1.17.01-SNAPSHOT.jar:na]
at org.opendaylight.netconf.mdsal.connector.TransactionProvider.commitTransaction(TransactionProvider.java:80) ~[mdsal-netconf-connector-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.mdsal.connector.ops.Commit.handleWithNoSubsequentOperations(Commit.java:39) ~[mdsal-netconf-connector-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.util.mapping.AbstractSingletonNetconfOperation.handle(AbstractSingletonNetconfOperation.java:26) ~[netconf-util-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.util.mapping.AbstractNetconfOperation.handle(AbstractNetconfOperation.java:101) ~[netconf-util-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.impl.osgi.NetconfOperationRouterImpl$NetconfOperationExecution.execute(NetconfOperationRouterImpl.java:182) ~[netconf-impl-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.impl.osgi.NetconfOperationRouterImpl.executeOperationWithHighestPriority(NetconfOperationRouterImpl.java:111) ~[netconf-impl-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.impl.osgi.NetconfOperationRouterImpl.onNetconfMessage(NetconfOperationRouterImpl.java:84) ~[netconf-impl-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.impl.NetconfServerSessionListener.processDocument(NetconfServerSessionListener.java:122) [netconf-impl-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.impl.NetconfServerSessionListener.onMessage(NetconfServerSessionListener.java:87) [netconf-impl-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.impl.NetconfServerSessionListener.onMessage(NetconfServerSessionListener.java:33) [netconf-impl-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.nettyutil.AbstractNetconfSession.handleMessage(AbstractNetconfSession.java:64) [netconf-netty-util-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.netconf.nettyutil.AbstractNetconfSession.handleMessage(AbstractNetconfSession.java:35) [netconf-netty-util-1.1.2-Boron-SR2.jar:na]
at org.opendaylight.protocol.framework.AbstractProtocolSession.channelRead0(AbstractProtocolSession.java:53) [protocol-framework-0.8.2-Boron-SR2.jar:na]
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293) [netty-codec-4.0.37.Final.jar:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267) [netty-codec-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293) [netty-codec-4.0.37.Final.jar:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267) [netty-codec-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1280) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:890) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:564) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:505) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:419) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:391) [netty-transport-4.0.37.Final.jar:4.0.37.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112) [netty-common-4.0.37.Final.jar:4.0.37.Final]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]

This occurs on last(commit) message. From model perspective , the data is perfectly fine(passes trought restconf with no problem).

Bug present in BORON-SR2

 Comments   
Comment by Jan Srnicek [ 14/Feb/17 ]

Attachment honeycomb-failed-debug.zip has been added with description: Full debug log

Comment by Vratko Polak [ 14/Feb/17 ]

> io.fd.honeycomb.data.impl.ReadWriteTransaction.submit(ReadWriteTransaction.java:76)

Can you add a LOG there and report the full content of delegateWriteTx (both from Netconf and Restconf call).

Comment by Jan Srnicek [ 16/Feb/17 ]

Attachment extended-debug-logs.tar.gz has been added with description: Debug log with transaction data from netconf/restconf

Comment by Vratko Polak [ 16/Feb/17 ]

> Created attachment 1591 [details]

Looking at the log, I assume the Netconf request started to be processed at 2017-02-13 07:46:41.859.
There are multiple warnings suggesting something went wrong with parsing the netconf messages. Example warnings:

WARN o.o.n.n.h.NetconfXMLToMessageDecoder - XML message
with unwanted leading bytes detected. Discarded the 1 leading byte(s): '0a'

WARN o.o.n.i.u.DeserializerExceptionHandler - An excepti
on occurred during message handling
io.netty.handler.codec.DecoderException: org.xml.sax.SAXParseException; lineNumber: 3; columnNumber: 1;
XML document structures must start and end within the same entity.

WARN o.o.n.i.u.DeserializerExceptionHandler - An exception occurred during message handling
io.netty.handler.codec.DecoderException: org.xml.sax.SAXParseException; lineNumber: 1; columnNumber: 2; The markup in the document preceding the root element must be well-formed.

WARN o.o.n.i.u.DeserializerExceptionHandler - An exception occurred during message handling
io.netty.handler.codec.DecoderException: org.xml.sax.SAXParseException; lineNumber: 1; columnNumber: 1; Content is not allowed in prolog.

WARN o.o.n.n.h.NetconfXMLToMessageDecoder - XML message with unwanted leading bytes detected. Discarded the 32 leading byte(s): '6d733a786d6c3a6e733a6e6574636f6e663a626173653a312e3022206d657373'

WARN o.o.n.n.h.NetconfXMLToMessageDecoder - XML message with unwanted leading bytes detected. Discarded the 64 leading byte(s): '6d733a786d6c3a6e733a6e6574636f6e663a626173653a312e3022206d6573736167652d69643d226d2d36223e0a3c636f6d6d69742f3e0a3c2f7270633e0a0a'

WARN o.o.n.i.u.DeserializerExceptionHandler - An exception occurred during message handling
io.netty.handler.codec.DecoderException: org.xml.sax.SAXParseException; lineNumber: 5; columnNumber: 2; The markup in the document following the root element must be well-formed.

By the way, '6d733a786d6c3a6e733a6e6574636f6e663a626173653a312e3022206d657373' is hex of 'ms:xml:ns:netconf:base:1.0" mess' and '6d733a786d6c3a6e733a6e6574636f6e663a626173653a312e3022206d6573736167652d69643d226d2d36223e0a3c636f6d6d69742f3e0a3c2f7270633e0a0a' is hex of 'ms:xml:ns:netconf:base:1.0" message-id="m-6">\n<commit/>\n</rpc>\n\n'.

Netconf parsing errors may explain why netconf NodeModification has "bridge-domain" as an identifier (with name=testBD2 for ChildModification), instead of "data" (with "vpp" as ChildModification) as is Restconf log.

That means this looks like a Netconf bug, not related to Yangtools, Mdsal, Clustering nor Honeycomb.

Comment by Vratko Polak [ 16/Feb/17 ]

I can confirm that this Bug is present on Boron-SR2, but not in Carbon snapshot.
It seems installing a feature with needed Yang modules (e.g. odl-vbd-rest) is all that is needed to reproduce this within netconf-mdsal suite.

Comment by Vratko Polak [ 16/Feb/17 ]

Updated suite: https://git.opendaylight.org/gerrit/51964
Not tested yet due to infra issues.

Comment by Vratko Polak [ 17/Feb/17 ]

I tried to use (Boron-SR2) netconf-connector to connect to ODL mdsal netconf northbound, just to see what the generated netconf message looks like.

Steps to reproduce:

  • Start ODL with odl-restconf, odl-vbd, odl-netconf-mdsal and odl-netconf-connector-ssh features.
  • Create netconf connection:
    $ curl -v -u 'admin:admin' -X PUT -H "Content-Type:application/json" -d '
    Unknown macro: {"network-topology}

    ' 127.0.0.1:8181/restconf/config/network-topology:network-topology/topology/topology-netconf/node/mdsal

  • Send restconf request to be translated to netconf message:
    $ curl -v -u 'admin:admin' -X PUT -H "Content-Type:application/json" -d '{"v3po:vpp":{"bridge-domains":
    Unknown macro: {"bridge-domain"}

    }}' 127.0.0.1:8181/restconf/config/network-topology:network-topology/topology/topology-netconf/node/mdsal/yang-ext:mount/v3po:vpp

Here is what TRACE logs showed as the main message:
<rpc message-id="m-2" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<edit-config>
<target>
<candidate/>
</target>
<default-operation>none</default-operation>
<config>
<vpp xmlns="urn:opendaylight:params:xml:ns:yang:v3po" xmlns:a="urn:ietf:params:xml:ns:netconf:base:1.0" a:operation="replace">
<bridge-domains>
<bridge-domain>
<name>testBD2</name>
<unknown-unicast-flood>false</unknown-unicast-flood>
<arp-termination>false</arp-termination>
<flood>true</flood>
<forward>false</forward>
<learn>false</learn>
</bridge-domain>
</bridge-domains>
</vpp>
</config>
</edit-config>
</rpc>

The only relevant difference seem to be the placement of ' xmlns:a="urn:ietf:params:xml:ns:netconf:base:1.0" a:operation="replace"'.
In the original description it is on <bridge-domain>, in the generated message it is on <vpp> element.

I am not sure what your use case is (who creates the original message). If Honeycomb gets messages from ODL, this Bug should not be visible. So lesser severity maybe?

Of course, ODL should be able to parse the original message as well, so there is still a Bug to fix in Boron-SR3. I will try to replicate "a:operation" placement using car/people modes so that Netconf mdsal suite does not need VPP Yang models to detect this Bug.

Comment by Vratko Polak [ 17/Feb/17 ]

> I will try to replicate "a:operation" placement
> using car/people models so that Netconf mdsal suite
> does not need VPP Yang models to detect this Bug.

https://git.opendaylight.org/gerrit/#/c/51964/8

Comment by Vratko Polak [ 17/Feb/17 ]

It seems this was already fixed in Boron snapshot.
https://logs.opendaylight.org/sandbox/jenkins091/netconf-csit-1node-userfeatures-only-boron/11/archives/log.html.gz#s1-s2-s1-t44

Will retest with the original VBD model.

Comment by Vratko Polak [ 17/Feb/17 ]

> Will retest with the original VBD model.

Yup, looks fixed to me (on current ODL Boron snapshot build).
https://logs.opendaylight.org/sandbox/jenkins091/netconf-csit-1node-userfeatures-only-boron/12/archives/log.html.gz#s1-s2-s1-t47

Comment by Jan Srnicek [ 20/Feb/17 ]

Verified, tested with SNAPSHOT versions, and error doesn't show

Generated at Wed Feb 07 20:14:47 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.