[CONTROLLER-198] unable to read operational data Created: 07/Mar/14  Updated: 25/Jul/23  Resolved: 09/Apr/14

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

Type: Bug
Reporter: Robert Gallas Assignee: Tony Tkacik
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: PC

External issue ID: 492

 Description   

Hi,

I'm building application using 0.1.2-SNAPSHOT controller distro. Using this distro version, application is not able to read operational data from device.

At around 14.02 application mentioned functionality was working

Part of the log follows:

****************************************************************
2014-03-07 13:27:22.728 CET [md-sal-binding-commit-0] INFO o.o.c.i.d.app.impl.XXXXDeviceAppImpl - Beginning onDataChanged Event in Device Application Impl.
****************************************************************
2014-03-07 13:27:22.730 CET [md-sal-binding-commit-0] WARN o.o.c.i.d.app.impl.XXXXDeviceAppImpl - Unable to read operational data from netconf device Uri [_value=ios-xr-104]
2014-03-07 13:27:22.731 CET [pool-31-thread-1] INFO o.o.c.s.c.n.NetconfDevice#ios-xr-104 - Starting Netconf Client on: /172.23.29.104:830
2014-03-07 13:27:22.732 CET [md-sal-binding-commit-0] WARN o.o.c.i.d.app.impl.XXXXDeviceAppImpl - Unable to read operational data from netconf device Uri [_value=ios-xr-104]
****************************************************************
2014-03-07 13:27:22.893 CET [md-sal-binding-commit-0] INFO o.o.c.i.d.app.impl.XXXXDeviceAppImpl - Beginning onDataChanged Event in Device Application Impl.
2014-03-07 13:27:22.894 CET [pool-31-thread-2] INFO o.o.c.s.c.n.NetconfDevice#ios-xr-105 - Starting Netconf Client on: /172.23.29.105:830
****************************************************************
2014-03-07 13:27:22.897 CET [md-sal-binding-commit-0] WARN o.o.c.i.d.app.impl.XXXXDeviceAppImpl - Unable to read operational data from netconf device Uri [_value=ios-xr-105]
2014-03-07 13:27:22.899 CET [md-sal-binding-commit-0] WARN o.o.c.i.d.app.impl.XXXXDeviceAppImpl - Unable to read operational data from netconf device Uri [_value=ios-xr-105]
2014-03-07 13:27:22.906 CET [ConfigPersister-registrator] INFO o.o.c.n.p.i.o.ConfigPersisterActivator - Configuration Persister initialization completed.
2014-03-07 13:27:35.364 CET [nettyThreadgroupModule$NioEventLoopGroupCloseable-7-2] WARN io.netty.util.ResourceLeakDetector - LEAK: ByteBuf was GC'd before being released correctly.
The following stack trace shows where the leaked object was created, rather than where you failed to release it.
io.netty.util.ResourceLeakException: io.netty.buffer.UnpooledUnsafeDirectByteBuf@e2b510a
at io.netty.util.ResourceLeakDetector$DefaultResourceLeak.<init>(ResourceLeakDetector.java:174) ~[na:na]
at io.netty.util.ResourceLeakDetector.open(ResourceLeakDetector.java:116) ~[na:na]
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.<init>(UnpooledUnsafeDirectByteBuf.java:72) ~[na:na]
at io.netty.buffer.UnpooledByteBufAllocator.newDirectBuffer(UnpooledByteBufAllocator.java:49) ~[na:na]
at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:132) ~[na:na]
at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:123) ~[na:na]
at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:84) ~[na:na]
at io.netty.channel.AdaptiveRecvByteBufAllocator$HandleImpl.allocate(AdaptiveRecvByteBufAllocator.java:104) ~[na:na]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:86) ~[na:na]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:480) ~[na:na]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:447) ~[na:na]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:341) ~[na:na]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:101) ~[na:na]
at java.lang.Thread.run(Thread.java:724) ~[na:1.7.0_25]

No other exception is shown.

Robert

 Comments   
Comment by Robert Gallas [ 10/Mar/14 ]

After further investigation

After controller startup inventory is queried, nodes are tested for augmentation and for particular capability. If this action is performed upon startup, following code ends up with logger.warn message.

NetconfNode netconfNode = value.getAugmentation(NetconfNode.class);
NodeId nodeId = value.getId();

if ( netconfNode == null )

{ netconfNode = dataReader.readOperationalData(netconfNodePath); }

if ( netconfNode == null ) {
logger.warn("Unable to read operational data from netconf device {}", nodeId);
return;
}

On background, yang files are downloaded and codecs are generated. Codecs generation and YANG file download takes time. This probably generates onDataChanged Event which triggers upper code to execute once again. This time, with success.

Issue is that by calling same method with same arguments returns different results for no obvious reason.

Robert

Comment by Tomas Olvecky [ 14/Mar/14 ]

Moving to md-sal as netconf component only deals with netconf (config) server

Comment by Tony Tkacik [ 09/Apr/14 ]

From your logs - Netconf Client did not full Session Negotiation, when your app tried for read of augmentation, which is present only after full negotiation.

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