[NETCONF-439] NETCONF request hangs when rpc-rply has invalid xml Created: 07/Jul/17  Updated: 15/Mar/19  Resolved: 17/Jul/17

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

Type: Bug
Reporter: Alexis de Talhouët Assignee: Alexis de Talhouët
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All


External issue ID: 8824

 Description   

I’m sending an RPC to a netconf device, the rpc-reply has a typo in the xml (the open element is apppack-download-statu but the close one is apppack-download-statu), hence ODL is throwing a fatal error but the exception is probably not propagated properly, as the RESTCONF request hangs indefinitely.
See logs bellow:

2017-06-08 12:59:14,715 | TRACE | upCloseable-3-13 | NetconfDeviceCommunicator | 289 - org.opendaylight.netconf.sal-netconf-connector - 1.4.3.Boron-SR3 | Finished sending request <rpc message-id="m-1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<request-appid-application-package-download/>
</rpc>

2017-06-08 12:59:14,730 | TRACE | NioProcessor-16 | AsyncSshHandlerReader | 124 - org.opendaylight.netconf.netty-util - 1.1.3.Boron-SR3 | Reading message on channel: ChannelSubsystem[id=0, recipient=0], message: <nc:rpc-reply xmlns:nc="urn:ietf:params:xml:ns:netconf:base:1.0" xmlns:junos="http://xml.juniper.net/junos/15.1X49/junos" message-id="m-1" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">

2017-06-08 12:59:14,896 | TRACE | NioProcessor-16 | AsyncSshHandlerReader | 124 - org.opendaylight.netconf.netty-util - 1.1.3.Boron-SR3 | Reading message on channel: ChannelSubsystem[id=0, recipient=0], message: <apppack-download-statu xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
<apppack-download-status-detail>Please use command
"request services application-identification download status" to check download status
</apppack-download-status-detail>
</apppack-download-status>
</nc:rpc-reply>
]]>]]>

2017-06-08 12:59:14,896 | TRACE | upCloseable-3-13 | NetconfXMLToMessageDecoder | 124 - org.opendaylight.netconf.netty-util - 1.1.3.Boron-SR3 | Received to decode: 0a3c6e633a7270632d7265706c7920786d6c6e733a6e633d2275726e3a696574663a706172616d733a786d6c3a6e733a6e6574636f6e663a626173653a312e302220786d6c6e733a6a756e6f733d22687474703a2f2f786d6c2e6a756e697065722e6e65742f6a756e6f732f31352e315834392f6a756e6f7322206d6573736167652d69643d226d2d312220786d6c6e733d2275726e3a696574663a706172616d733a786d6c3a6e733a6e6574636f6e663a626173653a312e30223e0a3c6170707061636b2d646f776e6c6f61642d7374617475730820786d6c6e733d2275726e3a696574663a706172616d733a786d6c3a6e733a6e6574636f6e663a626173653a312e30223e0a3c6170707061636b2d646f776e6c6f61642d7374617475732d64657461696c3e506c656173652075736520636f6d6d616e640a092272657175657374207365727669636573206170706c69636174696f6e2d6964656e74696669636174696f6e20646f776e6c6f6164207374617475732220746f20636865636b20646f776e6c6f6164207374617475730a3c2f6170707061636b2d646f776e6c6f61642d7374617475732d64657461696c3e0a3c2f6170707061636b2d646f776e6c6f61642d7374617475733e0a3c2f6e633a7270632d7265706c793e0a
2017-06-08 12:59:14,896 | WARN | upCloseable-3-13 | NetconfXMLToMessageDecoder | 124 - org.opendaylight.netconf.netty-util - 1.1.3.Boron-SR3 | XML message with unwanted leading bytes detected. Discarded the 1 leading byte(s): '0a'
[Fatal Error] :2:25: Element type "apppack-download-status" must be followed by either attribute specifications, ">" or "/>".
2017-06-08 12:59:14,897 | WARN | upCloseable-3-13 | DefaultChannelPipeline | 77 - io.netty.common - 4.0.44.Final | An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.codec.DecoderException: org.xml.sax.SAXParseException: Element type "apppack-download-status" must be followed by either attribute specifications, ">" or "/>".
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:442)[79:io.netty.codec:4.0.44.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)[79:io.netty.codec:4.0.44.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:357)[78:io.netty.transport:4.0.44.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:343)[78:io.netty.transport:4.0.44.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:336)[78:io.netty.transport:4.0.44.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)[79:io.netty.codec:4.0.44.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:280)[79:io.netty.codec:4.0.44.Final]
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:396)[79:io.netty.codec:4.0.44.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)[79:io.netty.codec:4.0.44.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:357)[78:io.netty.transport:4.0.44.Final]
at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:35)[78:io.netty.transport:4.0.44.Final]
at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:348)[78:io.netty.transport:4.0.44.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:399)[77:io.netty.common:4.0.44.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:446)[78:io.netty.transport:4.0.44.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)[77:io.netty.common:4.0.44.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)[77:io.netty.common:4.0.44.Final]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Caused by: org.xml.sax.SAXParseException: Element type "apppack-download-status" must be followed by either attribute specifications, ">" or "/>".
at org.apache.xerces.parsers.DOMParser.parse(Unknown Source)[:]
at org.apache.xerces.jaxp.DocumentBuilderImpl.parse(Unknown Source)[:]
at javax.xml.parsers.DocumentBuilder.parse(Unknown Source)[:2.6.0]
at org.opendaylight.controller.config.util.xml.XmlUtil.readXmlToDocument(XmlUtil.java:108)[114:org.opendaylight.controller.config-util:0.5.3.Boron-SR3]
at org.opendaylight.netconf.nettyutil.handler.NetconfXMLToMessageDecoder.decode(NetconfXMLToMessageDecoder.java:70)[124:org.opendaylight.netconf.netty-util:1.1.3.Boron-SR3]
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)[79:io.netty.codec:4.0.44.Final]
... 16 more



 Comments   
Comment by Alexis de Talhouët [ 07/Jul/17 ]

Analysis has shown the exception was swallow by Netty thread and was never explicitly handle and propagate to the caller thread.
To fix this, we catch the exception in the decoder handler, and if exception occurs, we put it in the NetconfMessage, responsible to transmit info from Netty world to RESTCONF world.

Proposed fix: https://git.opendaylight.org/gerrit/#/c/60096/

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