Uploaded image for project: 'netconf'
  1. netconf
  2. NETCONF-222

Netty LEAK error leads to RemoteNetconfCommand unable to to establish internal connection to netconf server for client: 127.0.0.1

    XMLWordPrintable

Details

    • Bug
    • Status: Resolved
    • Resolution: Won't Do
    • None
    • None
    • netconf
    • None

    • Operating System: All
      Platform: All

    • 6107

    Description

      OS: 64-bit Linux 2.6.32 guested in VirtualBox on a 64-bit Windows Server 2008R2

      ODL version: Lithium-SR3

      Problem description:

      During the loading of 00-nettty.xml in the booting of ODL controller, Netty's ResourceLeakDetector reported a LEAK error as the following:

      2016-06-23 17:02:59,433 | ERROR | config-pusher | ResourceLeakDetector | 95 - io.netty.common - 4.0.26.Final | | LEAK: HashedWheelTimer.release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, specify the JVM option '-Dio.netty.leakDetectionLevel=advanced' or call ResourceLeakDetector.setLevel() See http://netty.io/wiki/reference-counted-objects.html for more information.

      However 00-netty.xml was still loaded successfully. But later in the connection from ODL's internal netconf client to internal netconf server, ODL's RemoteNetconfCommand reported a failure as the following:

      2016-06-23 17:05:58,196 | WARN | entLoopGroup-4-1 | RemoteNetconfCommand | 297 - org.opendaylight.controller.netconf-ssh - 0.3.3.Lithium-SR3 | | Unable to establish internal connection to netconf server for client: 127.0.0.1

      After our hacking of netty, the failure is because of a map naming LocalChannelRegistry.boundChannels in netty had no element of "local:netconf" as normal. It seems that netty internal data structure was destroyed or not correctly maintained because of the LEAK error reported above this failure. But who caused the LEAK？We don't know.

      Full karaf.log:

      2016-06-23 17:02:35,108 | INFO | config-pusher | ConfigPusherImpl | 110 - org.opendaylight.controller.config-persister-impl - 0.3.3.Lithium-SR3 | | Pushing configuration snapshot 00-netty.xml(xxx,xxx)
      2016-06-23 17:02:44,181 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.aaa.authn-sts_0.2.3.Lithium-SR3 [204]] to http service
      2016-06-23 17:02:46,046 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.aaa.idmlight_0.2.3.Lithium-SR3 [208]] to http service
      2016-06-23 17:02:46,558 | INFO | pool-5-thread-1 | WebApplicationImpl | 194 - com.sun.jersey.jersey-server - 1.17.0 | | Initiating Jersey application, version 'Jersey: 1.17 01/17/2013 03:31 PM'
      2016-06-23 17:02:46,893 | INFO | pool-5-thread-1 | DeferredResourceConfig | 194 - com.sun.jersey.jersey-server - 1.17.0 | | Instantiated the Application class org.opendaylight.aaa.idm.IdmLightApplication
      2016-06-23 17:02:47,131 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.aaa.authn-federation_0.2.3.Lithium-SR3 [217]] to http service
      2016-06-23 17:02:51,698 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.controller.sal-rest-connector_1.2.3.Lithium-SR3 [221]] to http service
      2016-06-23 17:02:51,777 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.loader.implementation_0.2.3.Lithium-SR3 [225]] to http service
      2016-06-23 17:02:51,785 | INFO | pool-5-thread-3 | WebApplicationImpl | 194 - com.sun.jersey.jersey-server - 1.17.0 | | Initiating Jersey application, version 'Jersey: 1.17 01/17/2013 03:31 PM'
      2016-06-23 17:02:51,812 | INFO | Event Dispatcher | DluxLoader | 225 - org.opendaylight.dlux.loader.implementation - 0.2.3.Lithium-SR3 | | DluxLoader Service initialization complete.
      2016-06-23 17:02:51,867 | INFO | pool-5-thread-3 | DeferredResourceConfig | 194 - com.sun.jersey.jersey-server - 1.17.0 | | Instantiated the Application class org.opendaylight.controller.sal.rest.impl.RestconfApplication
      2016-06-23 17:02:51,869 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/app/core
      2016-06-23 17:02:51,870 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.core_0.2.3.Lithium-SR3 [226]] to http service
      2016-06-23 17:02:51,878 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for core
      2016-06-23 17:02:51,945 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/login
      2016-06-23 17:02:51,945 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.login_0.2.3.Lithium-SR3 [227]] to http service
      2016-06-23 17:02:51,970 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for login
      2016-06-23 17:02:52,008 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/authentification
      2016-06-23 17:02:52,009 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.authentication_0.2.3.Lithium-SR3 [228]] to http service
      2016-06-23 17:02:52,021 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for authentication
      2016-06-23 17:02:52,047 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/navigation
      2016-06-23 17:02:52,048 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.navigation_0.2.3.Lithium-SR3 [229]] to http service
      2016-06-23 17:02:52,060 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for navigation
      2016-06-23 17:02:52,095 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/topbar
      2016-06-23 17:02:52,095 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.topbar_0.2.3.Lithium-SR3 [230]] to http service
      2016-06-23 17:02:52,115 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for topbar
      2016-06-23 17:02:52,149 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/general
      2016-06-23 17:02:52,150 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.general_0.2.3.Lithium-SR3 [231]] to http service
      2016-06-23 17:02:52,179 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for general
      2016-06-23 17:02:52,214 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/app/topology
      2016-06-23 17:02:52,214 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.topology_0.2.3.Lithium-SR3 [233]] to http service
      2016-06-23 17:02:52,244 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for topology
      2016-06-23 17:02:52,300 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/app/node
      2016-06-23 17:02:52,300 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.node_0.2.3.Lithium-SR3 [234]] to http service
      2016-06-23 17:02:52,316 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for node
      2016-06-23 17:02:54,102 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.controller.sal-rest-docgen_1.2.3.Lithium-SR3 [235]] to http service
      2016-06-23 17:02:54,145 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/app/yangui
      2016-06-23 17:02:54,145 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.yangui_0.2.3.Lithium-SR3 [236]] to http service
      2016-06-23 17:02:54,152 | INFO | pool-5-thread-2 | WebApplicationImpl | 194 - com.sun.jersey.jersey-server - 1.17.0 | | Initiating Jersey application, version 'Jersey: 1.17 01/17/2013 03:31 PM'
      2016-06-23 17:02:54,184 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for yangui
      2016-06-23 17:02:54,220 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/yangutils
      2016-06-23 17:02:54,223 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.yangutils_0.2.3.Lithium-SR3 [237]] to http service
      2016-06-23 17:02:54,228 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for yangutils
      2016-06-23 17:02:54,293 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/sigmatopology
      2016-06-23 17:02:54,293 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.sigmatopology_0.2.3.Lithium-SR3 [238]] to http service
      2016-06-23 17:02:54,341 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for sigmatopology
      2016-06-23 17:02:54,365 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/app/yangvisualizer
      2016-06-23 17:02:54,365 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.yangvisualizer_0.2.3.Lithium-SR3 [239]] to http service
      2016-06-23 17:02:54,391 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for yangvisualizer
      2016-06-23 17:02:54,722 | INFO | Event Dispatcher | RegionsPersistenceImpl | 250 - org.apache.karaf.region.persist - 3.0.3 | | Loading region digraph persistence
      2016-06-23 17:02:54,775 | INFO | pool-5-thread-2 | DeferredResourceConfig | 194 - com.sun.jersey.jersey-server - 1.17.0 | | Instantiated the Application class org.opendaylight.controller.sal.rest.doc.jaxrs.ApiDocApplication
      2016-06-23 17:02:54,800 | INFO | Event Dispatcher | RegionsPersistenceImpl | 250 - org.apache.karaf.region.persist - 3.0.3 | | initializing region digraph from etc/regions-config.xml
      2016-06-23 17:02:55,366 | INFO | Event Dispatcher | NetconfTCPActivator | 295 - org.opendaylight.controller.netconf-tcp - 0.3.3.Lithium-SR3 | | Starting TCP netconf server at /127.0.0.1:8383
      2016-06-23 17:02:55,798 | INFO | Event Dispatcher | SecurityUtils | 118 - org.apache.sshd.core - 0.14.0 | | BouncyCastle already registered as a JCE provider
      2016-06-23 17:02:56,578 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering resources for url /src/common/layout
      2016-06-23 17:02:56,578 | INFO | Event Dispatcher | HttpServiceFactoryImpl | 174 - org.ops4j.pax.web.pax-web-runtime - 3.1.4 | | Binding bundle: [org.opendaylight.dlux.common.layout_0.2.3.Lithium-SR3 [232]] to http service
      2016-06-23 17:02:56,590 | INFO | Event Dispatcher | DluxModule | 224 - org.opendaylight.dlux.loader - 0.2.3.Lithium-SR3 | | Registering angularJS and requireJs modules for layout
      2016-06-23 17:02:59,433 | ERROR | config-pusher | ResourceLeakDetector | 95 - io.netty.common - 4.0.26.Final | | LEAK: HashedWheelTimer.release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, specify the JVM option '-Dio.netty.leakDetectionLevel=advanced' or call ResourceLeakDetector.setLevel() See http://netty.io/wiki/reference-counted-objects.html for more information.
      2016-06-23 17:02:59,488 | INFO | config-pusher | ConfigPusherImpl | 110 - org.opendaylight.controller.config-persister-impl - 0.3.3.Lithium-SR3 | | Successfully pushed configuration snapshot 00-netty.xml(xxx,xxx)

      2016-06-23 17:06:08,258 | DEBUG | oupCloseable-5-1 | ProtocolSessionPromise | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.ProtocolSessionPromise.connect(ProtocolSessionPromise.java:55) | Promise ProtocolSessionPromise@712253c6(incomplete) attempting connect /127.0.0.1:1830 for 2000ms
      2016-06-23 17:06:08,265 | DEBUG | oupCloseable-5-1 | AbstractDispatcher | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.AbstractDispatcher.createClient(AbstractDispatcher.java:201) | Client created.
      2016-06-23 17:06:08,360 | INFO | o-group-thread-8 | ServerSession | 118 - org.apache.sshd.core - 0.14.0 | | Server session created from /127.0.0.1:41459
      2016-06-23 17:06:08,363 | INFO | NioProcessor-3 | ClientSessionImpl | 118 - org.apache.sshd.core - 0.14.0 | | Client session created
      2016-06-23 17:06:08,370 | INFO | NioProcessor-3 | ClientSessionImpl | 118 - org.apache.sshd.core - 0.14.0 | | Start flagging packets as pending until key exchange is done
      2016-06-23 17:06:08,371 | INFO | NioProcessor-3 | ClientSessionImpl | 118 - org.apache.sshd.core - 0.14.0 | | Server version string: SSH-2.0-SSHD-CORE-0.14.0
      2016-06-23 17:06:10,510 | WARN | NioProcessor-3 | AcceptAllServerKeyVerifier | 118 - org.apache.sshd.core - 0.14.0 | | Server at /127.0.0.1:1830 presented unverified RSA key: a0:7c:73:f0:ae:bd:6a:42:ff:85:5d:c9:a9:cf:34:5f
      2016-06-23 17:06:10,581 | INFO | NioProcessor-3 | ClientSessionImpl | 118 - org.apache.sshd.core - 0.14.0 | | Dequeing pending packets
      2016-06-23 17:06:10,590 | INFO | NioProcessor-3 | ClientUserAuthServiceNew | 118 - org.apache.sshd.core - 0.14.0 | | Received SSH_MSG_USERAUTH_FAILURE
      2016-06-23 17:06:10,596 | INFO | NioProcessor-3 | UserAuthKeyboardInteractive | 118 - org.apache.sshd.core - 0.14.0 | | Received Password authentication en-US
      2016-06-23 17:06:10,686 | INFO | o-group-thread-5 | ServerUserAuthService | 118 - org.apache.sshd.core - 0.14.0 | | Session admin@/127.0.0.1:41459 authenticated
      2016-06-23 17:06:10,687 | INFO | NioProcessor-3 | ClientUserAuthServiceNew | 118 - org.apache.sshd.core - 0.14.0 | | Received SSH_MSG_USERAUTH_SUCCESS
      2016-06-23 17:06:10,692 | DEBUG | oupCloseable-5-2 | ProtocolSessionPromise | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.ProtocolSessionPromise$BootstrapConnectListener.operationComplete(ProtocolSessionPromise.java:95) | Promise ProtocolSessionPromise@712253c6(incomplete) connection resolved
      2016-06-23 17:06:10,693 | DEBUG | oupCloseable-5-2 | ProtocolSessionPromise | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.ProtocolSessionPromise$BootstrapConnectListener.operationComplete(ProtocolSessionPromise.java:118) | Promise ProtocolSessionPromise@712253c6(incomplete) connection successful
      2016-06-23 17:06:10,694 | DEBUG | oupCloseable-5-2 | AbstractSessionNegotiator | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.AbstractSessionNegotiator.channelActive(AbstractSessionNegotiator.java:79) | Starting session negotiation on channel [id: 0x37ccf37e]
      2016-06-23 17:06:10,698 | WARN | entLoopGroup-4-2 | RemoteNetconfCommand | 297 - org.opendaylight.controller.netconf-ssh - 0.3.3.Lithium-SR3 | | Unable to establish internal connection to netconf server for client: 127.0.0.1
      2016-06-23 17:06:10,713 | DEBUG | oupCloseable-5-2 | ReconnectPromise | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.ReconnectPromise$ClosedChannelHandler.channelInactive(ReconnectPromise.java:118) | Connection to /127.0.0.1:1830 was dropped during negotiation, reattempting
      2016-06-23 17:06:10,713 | DEBUG | oupCloseable-5-2 | ReconnectPromise | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.ReconnectPromise$ClosedChannelHandler.channelInactive(ReconnectPromise.java:121) | Reconnecting after connection to /127.0.0.1:1830 was dropped
      2016-06-23 17:06:18,400 | DEBUG | pool-15-thread-1 | AbstractSessionNegotiator | 97 - org.opendaylight.controller.protocol-framework - 0.6.3.Lithium-SR3 | org.opendaylight.protocol.framework.AbstractSessionNegotiator.negotiationFailed(AbstractSessionNegotiator.java:51) | Negotiation on channel [id: 0x94a5f38f] failed
      java.lang.IllegalStateException: Session was not established after HashedWheelTimer$HashedWheelTimeout(deadline: 101358660 ns ago, task: org.opendaylight.controller.netconf.nettyutil.AbstractNetconfSessionNegotiator$2@65695f20)
      at org.opendaylight.controller.netconf.nettyutil.AbstractNetconfSessionNegotiator$2.run(AbstractNetconfSessionNegotiator.java:129)[115:org.opendaylight.controller.netconf-netty-util:0.3.3.Lithium-SR3]
      at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:581)[95:io.netty.common:4.0.26.Final]
      at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:655)[95:io.netty.common:4.0.26.Final]
      at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:367)[95:io.netty.common:4.0.26.Final]
      at java.lang.Thread.run(Thread.java:744)[:1.7.0_51]

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            Unassigned Unassigned
            yin.kangqian@zte.com.cn Kangqian Yin
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: