[CONTROLLER-1401] Not able to perform RPC on a controller other than the one on which the shard was initialized. Created: 07/Aug/15  Updated: 20/Jan/16  Resolved: 20/Jan/16

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

Type: Bug
Reporter: Phillip Shea Assignee: Moiz Raja
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All

Attachments: Text File karaf93.log    
External issue ID: 4108
Priority: High

 Description   

Configuration:
3-node cluster
All features installed

This was first noticed in CI (both master and Lithium): https://jenkins.opendaylight.org/controller/job/controller-csit-3node-cds-clustering-all-stable-lithium/

The test is trying to add people using RPC and failing with a 500 error.

The difference between the default org.apache.karaf.features.cfg and the one used in the "all" configuration is as follows:

Default:
#

  1. Comma separated list of features repositories to register by default
    #
    featuresRepositories = mvn:org.apache.karaf.features/standard/3.0.3/xml/features,mvn:org.apache.karaf.features/enterprise/3.0.3/xml/features,mvn:org.ops4j.pax.web/pax-web-features/3.1.4/xml/features,mvn:org.apache.karaf.features/spring/3.0.3/xml/features,mvn:org.opendaylight.integration/features-integration-index/ODL_DISTRIBUTION/xml/features
    #
  2. Comma separated list of features to install at startup
    #
    featuresBoot=config,standard,region,package,kar,ssh,management,odl-restconf,odl-clustering-test-app,odl-netconf-connector-ssh

All:
#

  1. Comma separated list of features repositories to register by default
    #
    featuresRepositories = mvn:org.apache.karaf.features/standard/3.0.3/xml/features,mvn:org.apache.karaf.features/enterprise/3.0.3/xml/features,mvn:org.ops4j.pax.web/pax-web-features/3.1.4/xml/features,mvn:org.apache.karaf.features/spring/3.0.3/xml/features,mvn:org.opendaylight.integration/features-integration-index/ODL_DISTRIBUTION/xml/features,mvn:org.opendaylight.integration/features-integration-test/ODL_DISTRIBUTION/xml/features
    #
  2. Comma separated list of features to install at startup
    #
    featuresBoot=config,standard,region,package,kar,ssh,management,odl-integration-compatible-with-all,odl-restconf,odl-clustering-test-app,odl-netconf-connector-ssh

I was able to reproduce this locally by using the following two POST commands to intialize the shard, then populate it.

http://Controller1:8181/restconf/config
POST
{"people:people":{
"person": [

{ "id": "user0", "gender": "unknown", "age": "0", "address": "0Way, Some Country, Some Zip 0", "contactNo":"some number0" }

]
}}

http://controller2:8181/restconf/operations/people:add-person
POST
{
"input":

{ "people:id":"user999", "people:gender":"Male", "people:address":"San Jose", "people:contactNo":"555-1212", "people:age":"23" }

}

I've attached one of the logs. I'll find a place for the rest.
This message looks interesting:

java.lang.IllegalStateException: Conflicting instruction queue found

as does this one:

java.lang.IllegalStateException: Transaction chain has failed

and this one:

2015-08-07 15:33:04,584 | ERROR | CommitFutures-4 | NetconfDeviceTopologyAdapter | 223 - org.opendaylight.controller.sal-netconf-connector - 1.2.0.Lithium | RemoteDevice

{controller-config}

: TransactionChain(org.opendaylight.controller.md.sal.binding.impl.BindingDOMTransactionChainAdapter@3c9eb5c5) DOM-CHAIN-17-0 FAILED!
OptimisticLockFailedException

{message=Optimistic lock failed., errorList=[RpcError [message=Optimistic lock failed., severity=ERROR, errorType=APPLICATION, tag=resource-denied, applicationTag=null, info=null, cause=org.opendaylight.yangtools.yang.data.api.schema.tree.ConflictingModificationAppliedException: Node was deleted by other transaction.]]}

 Comments   
Comment by Phillip Shea [ 07/Aug/15 ]

Attachment karaf93.log has been added with description: karaf log file

Comment by Phillip Shea [ 07/Aug/15 ]

Log files:

• http://filebin.ca/2BMw8kK3XDik/karaf93.log
• http://filebin.ca/2BMwUbLggwks/karaf93.log.1
• http://filebin.ca/2BMwwOATal4F/karaf94.log
• http://filebin.ca/2BMxF7cRiy1s/karaf95.log

Comment by Phillip Shea [ 07/Aug/15 ]

• http://filebin.ca/2BMw8kK3XDik/karaf93.log
• http://filebin.ca/2BMwUbLggwks/karaf93.log.1
• http://filebin.ca/2BMwwOATal4F/karaf94.log
• http://filebin.ca/2BMxF7cRiy1s/karaf95.log

Comment by Phillip Shea [ 11/Aug/15 ]

Here's a better example than the previously attached logs:

The people shard was initialized on x.x.x.93, then I attempted to use the RPC to add people on x.x.x.94.

You can view it in patebin: http://pastebin.com/d0LZDYYa

Or directly, if you prefer.

2015-08-11 14:49:59,505 | DEBUG | ult-dispatcher-3 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Read leaf node (urn:opendaylight:flow:table:statistics?revision=2013-12-15)packets-looked-up
2015-08-11 14:49:59,505 | DEBUG | ult-dispatcher-3 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Read leaf node (urn:opendaylight:flow:table:statistics?revision=2013-12-15)packets-matched
2015-08-11 14:49:59,505 | DEBUG | ult-dispatcher-3 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Read leaf node (urn:opendaylight:flow:table:statistics?revision=2013-12-15)active-flows
2015-08-11 14:49:59,505 | DEBUG | ult-dispatcher-3 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | End node reached. return
2015-08-11 14:49:59,505 | DEBUG | ult-dispatcher-3 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Read leaf node (urn:opendaylight:flow:inventory?revision=2013-08-19)id
2015-08-11 14:49:59,505 | DEBUG | ult-dispatcher-3 | ShardDataTree | 191 - org.opendaylight.controller.sal-distributed-datastore - 1.2.0.Lithium | Applying foreign transaction null
2015-08-11 14:49:59,508 | DEBUG | ult-dispatcher-3 | ShardDataTree | 191 - org.opendaylight.controller.sal-distributed-datastore - 1.2.0.Lithium | Notifying listeners on candidate org.opendaylight.yangtools.yang.data.impl.schema.tree.InMemoryDataTreeCandidate@7c0e6ed5
2015-08-11 14:49:59,508 | DEBUG | ult-dispatcher-3 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: Persisting ApplyLogEntries with index=4125
2015-08-11 14:49:59,599 | DEBUG | lt-dispatcher-22 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Gossiping to [akka.tcp://odl-cluster-rpc@172.17.10.95:2551]
2015-08-11 14:49:59,600 | DEBUG | lt-dispatcher-22 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Sending bucket versions to [ActorSelection[Anchor(akka.tcp://odl-cluster-rpc@172.17.10.95:2551/), Path(/user/rpc/registry/gossiper)]]
2015-08-11 14:50:00,100 | DEBUG | ult-dispatcher-2 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Gossiping to [akka.tcp://odl-cluster-rpc@172.17.10.93:2551]
2015-08-11 14:50:00,100 | DEBUG | ult-dispatcher-2 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Sending bucket versions to [ActorSelection[Anchor(akka.tcp://odl-cluster-rpc@172.17.10.93:2551/), Path(/user/rpc/registry/gossiper)]]
2015-08-11 14:50:00,600 | DEBUG | lt-dispatcher-19 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Gossiping to [akka.tcp://odl-cluster-rpc@172.17.10.95:2551]
2015-08-11 14:50:00,600 | DEBUG | lt-dispatcher-19 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Sending bucket versions to [ActorSelection[Anchor(akka.tcp://odl-cluster-rpc@172.17.10.95:2551/), Path(/user/rpc/registry/gossiper)]]
2015-08-11 14:50:00,897 | DEBUG | qtp555710480-945 | RestconfImpl | 227 - org.opendaylight.controller.sal-rest-connector - 1.2.0.Lithium | Execution RpcError:
java.util.concurrent.ExecutionException: org.opendaylight.controller.md.sal.dom.api.DOMRpcImplementationNotAvailableException: No implementation of RPC AbsoluteSchemaPath

{path=[(urn:opendaylight:params:xml:ns:yang:controller:config:sal-clustering-it:people?revision=2014-08-18)add-person]}

available
at com.google.common.util.concurrent.Futures$ImmediateFailedCheckedFuture.get(Futures.java:225)[39:com.google.guava:18.0.0]
at org.opendaylight.controller.sal.restconf.impl.RestconfImpl.checkRpcResponse(RestconfImpl.java:468)[227:org.opendaylight.controller.sal-rest-connector:1.2.0.Lithium]
at org.opendaylight.controller.sal.restconf.impl.RestconfImpl.invokeRpc(RestconfImpl.java:456)[227:org.opendaylight.controller.sal-rest-connector:1.2.0.Lithium]
at org.opendaylight.controller.sal.restconf.impl.StatisticsRestconfServiceWrapper.invokeRpc(StatisticsRestconfServiceWrapper.java:81)[227:org.opendaylight.controller.sal-rest-connector:1.2.0.Lithium]
at org.opendaylight.controller.sal.rest.impl.RestconfCompositeWrapper.invokeRpc(RestconfCompositeWrapper.java:53)[227:org.opendaylight.controller.sal-rest-connector:1.2.0.Lithium]
at sun.reflect.GeneratedMethodAccessor320.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.7.0_65]
at java.lang.reflect.Method.invoke(Method.java:606)[:1.7.0_65]
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381)[194:com.sun.jersey.jersey-server:1.17.0]
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)[192:com.sun.jersey.servlet:1.17.0]
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)[192:com.sun.jersey.servlet:1.17.0]
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)[192:com.sun.jersey.servlet:1.17.0]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)[117:org.apache.geronimo.specs.geronimo-servlet_3.0_spec:1.0.0]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1496)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:247)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:210)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:256)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:69)[132:org.ops4j.pax.web.pax-web-jetty:3.1.4]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:240)[132:org.ops4j.pax.web.pax-web-jetty:3.1.4]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:75)[132:org.ops4j.pax.web.pax-web-jetty:3.1.4]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.Server.handle(Server.java:370)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:982)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1043)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)[123:org.eclipse.jetty.aggregate.jetty-all-server:8.1.15.v20140411]
at java.lang.Thread.run(Thread.java:745)[:1.7.0_65]
Caused by: org.opendaylight.controller.md.sal.dom.api.DOMRpcImplementationNotAvailableException: No implementation of RPC AbsoluteSchemaPath

{path=[(urn:opendaylight:params:xml:ns:yang:controller:config:sal-clustering-it:people?revision=2014-08-18)add-person]}

available
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRoutingTable.invokeRpc(DOMRpcRoutingTable.java:183)
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter.invokeRpc(DOMRpcRouter.java:124)
at org.opendaylight.controller.sal.restconf.impl.BrokerFacade.invokeRpc(BrokerFacade.java:172)[227:org.opendaylight.controller.sal-rest-connector:1.2.0.Lithium]
at org.opendaylight.controller.sal.restconf.impl.RestconfImpl.invokeRpc(RestconfImpl.java:451)[227:org.opendaylight.controller.sal-rest-connector:1.2.0.Lithium]
... 54 more
2015-08-11 14:50:00,902 | DEBUG | qtp555710480-945 | estconfDocumentedExceptionMapper | 227 - org.opendaylight.controller.sal-rest-connector - 1.2.0.Lithium | In toResponse: errors: [error-type: application, error-tag: operation-failed, error-message: The operation encountered an unexpected error while executing.error-info: org.opendaylight.controller.md.sal.dom.api.DOMRpcImplementationNotAvailableException: No implementation of RPC AbsoluteSchemaPath

{path=[(urn:opendaylight:params:xml:ns:yang:controller:config:sal-clustering-it:people?revision=2014-08-18)add-person]}

available
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRoutingTable.invokeRpc(DOMRpcRoutingTable.java:183)
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter.invokeRpc(DOMRpcRouter.java:124)
at org.opendaylight.controller.sal.restconf.impl.BrokerFacade.invokeRpc(BrokerFacade.java:172)
at org.opendaylight.controller.sal.restconf.impl.RestconfImpl.invokeRpc(RestconfImpl.java:451)
at org.opendaylight.controller.sal.restconf.impl.StatisticsRestconfServiceWrapper.invokeRpc(StatisticsRestconfServiceWrapper.java:81)
at org.opendaylight.controller.sal.rest.impl.RestconfCompositeWrapper.invokeRpc(RestconfCompositeWrapper.java:53)
at sun.reflect.GeneratedMethodAccessor320.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1496)
at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:247)
at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:210)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82)
at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:256)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:69)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:240)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:75)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
at org.eclipse.jetty.server.Server.handle(Server.java:370)
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:982)
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1043)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
at java.lang.Thread.run(Thread.java:745)
, ]]
2015-08-11 14:50:00,902 | DEBUG | qtp555710480-945 | estconfDocumentedExceptionMapper | 227 - org.opendaylight.controller.sal-rest-connector - 1.2.0.Lithium | Accept headers: []
2015-08-11 14:50:00,902 | DEBUG | qtp555710480-945 | estconfDocumentedExceptionMapper | 227 - org.opendaylight.controller.sal-rest-connector - 1.2.0.Lithium | Using MediaType: application/json
2015-08-11 14:50:01,100 | DEBUG | lt-dispatcher-22 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Gossiping to [akka.tcp://odl-cluster-rpc@172.17.10.93:2551]
2015-08-11 14:50:01,101 | DEBUG | lt-dispatcher-22 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Sending bucket versions to [ActorSelection[Anchor(akka.tcp://odl-cluster-rpc@172.17.10.93:2551/), Path(/user/rpc/registry/gossiper)]]
2015-08-11 14:50:01,599 | DEBUG | lt-dispatcher-22 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Gossiping to [akka.tcp://odl-cluster-rpc@172.17.10.93:2551]
2015-08-11 14:50:01,599 | DEBUG | lt-dispatcher-22 | Gossiper | 190 - org.opendaylight.controller.sal-remoterpc-connector - 1.2.0.Lithium | Sending bucket versions to [ActorSelection[Anchor(akka.tcp://odl-cluster-rpc@172.17.10.93:2551/), Path(/user/rpc/registry/gossiper)]]
2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): handleAppendEntries: AppendEntries [leaderId=member-1-shard-inventory-operational, prevLogIndex=4125, prevLogTerm=5, leaderCommit=4125, replicatedToAllIndex=4124, payloadVersion=3, entries=[Entry

{index=4126, term=5}]]
2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Number of entries to be appended = 1
2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): After cleanup entries to be added from = 4125
2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Append entry to log org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload@16cf94a9
2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: Append log entry and persist Entry{index=4126, term=5}


2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: persist complete Entry

{index=4126, term=5}

2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Log size is now 2
2015-08-11 14:50:01,854 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): handleAppendEntries returning : AppendEntriesReply [success=true, logLastIndex=4126, logLastTerm=5, followerId=member-2-shard-inventory-operational, payloadVersion=3]
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): handleAppendEntries: AppendEntries [leaderId=member-1-shard-inventory-operational, prevLogIndex=4126, prevLogTerm=5, leaderCommit=4126, replicatedToAllIndex=4125, payloadVersion=3, entries=[Entry

{index=4127, term=5}]]
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Number of entries to be appended = 1
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): After cleanup entries to be added from = 4126
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Append entry to log org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload@68f9a2c9
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: Append log entry and persist Entry{index=4127, term=5}


2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: persist complete Entry

{index=4127, term=5}

2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Log size is now 3
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Commit index set to 4126
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): applyLogToStateMachine, appendEntries.getLeaderCommit(): 4126,context.getLastApplied(): 4125, lastIndex(): 4127
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): Setting last applied to 4126
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational (Follower): handleAppendEntries returning : AppendEntriesReply [success=true, logLastIndex=4127, logLastTerm=5, followerId=member-2-shard-inventory-operational, payloadVersion=3]
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: fakeSnapshot purging log to 4125 for term 5
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | Shard | 184 - org.opendaylight.controller.sal-akka-raft - 1.2.0.Lithium | member-2-shard-inventory-operational: Applying state for log index 4126 data org.opendaylight.controller.cluster.datastore.DataTreeCandidatePayload@16cf94a9
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Reading map entry node (urn:opendaylight:flow:inventory?revision=2013-08-19)flow[

{(urn:opendaylight:flow:inventory?revision=2013-08-19)id=#UF$TABLE*0-2}

]
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Reading data container (leaf nodes) nodes
2015-08-11 14:50:01,887 | DEBUG | lt-dispatcher-20 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Read leaf node (urn:opendaylight:flow:inventory?revision=2013-08-19)id
2015-08-11 14:50:01,888 | DEBUG | lt-dispatcher-20 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Read container node (urn:opendaylight:flow:inventory?revision=2013-08-19)match
2015-08-11 14:50:01,888 | DEBUG | lt-dispatcher-20 | NormalizedNodeInputStreamReader | 183 - org.opendaylight.controller.sal-clustering-commons - 1.2.0.Lithium | Reading data container (leaf nodes) nodes

Comment by Colin Dixon [ 19/Jan/16 ]

Jamo, do you know if this is still reproducible? In Beryllium as well?

Comment by Jamo Luhrsen [ 20/Jan/16 ]

(In reply to Colin Dixon from comment #4)
> Jamo, do you know if this is still reproducible? In Beryllium as well?

No, this is no longer failing in the cluster CSIT test we have that saw
it before:

https://jenkins.opendaylight.org/releng/view/controller/job/controller-csit-3node-clustering-only-beryllium

Also, I searched the three controller logs from the last 100% passing
CSIT job and did not find the same Exception (DOMRpcImplementationNotAvailableException)

moving to FIXED

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