[CONTROLLER-1759] IncompatibleClassChangeError in RPC test Created: 25/Aug/17  Updated: 12/Sep/17  Resolved: 12/Sep/17

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

Type: Bug
Reporter: Vratko Polak Assignee: Vratko Polak
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: File 2017-09-07_odl1_karaf.log.xz    
External issue ID: 9057

 Description   

This is a symptom of failing CSIT for 3 nodes, so I guess it is a clustering bug, but it might be something else (we do not have corresponding 1 node test).

This happens on current Nitrogen builds. As the test is stable and passing on Carbon, this is a regression, so marking as a blocker.
The test is POSTing to /restconf/operations/odl-mdsal-lowlevel-control:register-constant

Here [0] is the robot failure, but there are other similar failures in other suites of the same job as well. Copy of the exception:
<h3>Caused by:</h3><pre>java.lang.IncompatibleClassChangeError: Found interface org.opendaylight.controller.md.sal.dom.api.DOMRpcProviderService, but class was expected
at Proxy5ab9ec75_2c92_4df8_b126_e6d91912628f.registerRpcImplementation(Unknown Source)
at org.opendaylight.controller.clustering.it.provider.impl.GetConstantService.registerNew(GetConstantService.java:56)
at org.opendaylight.controller.clustering.it.provider.MdsalLowLevelTestProvider.registerConstant(MdsalLowLevelTestProvider.java:659)
at org.opendaylight.yangtools.yang.binding.util.RpcMethodInvokerWithInput.invokeOn(RpcMethodInvokerWithInput.java:31)
at org.opendaylight.yangtools.yang.binding.util.AbstractMappedRpcInvoker.invokeRpc(AbstractMappedRpcInvoker.java:52)
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMRpcImplementationAdapter.invoke(BindingDOMRpcImplementationAdapter.java:83)
at org.opendaylight.controller.md.sal.binding.impl.BindingDOMRpcImplementationAdapter.invokeRpc(BindingDOMRpcImplementationAdapter.java:70)
at org.opendaylight.controller.md.sal.dom.broker.impl.GlobalDOMRpcRoutingTableEntry.invokeRpc(GlobalDOMRpcRoutingTableEntry.java:39)
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRoutingTable.invokeRpc(DOMRpcRoutingTable.java:177)
at org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter.invokeRpc(DOMRpcRouter.java:95)
at Proxy7f9198a0_bcf0_44ab_8a48_2db0343a74e3.invokeRpc(Unknown Source)
at Proxy2b8289b4_2213_46fd_8efc_30ea6f431b94.invokeRpc(Unknown Source)
at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.invokeRpc(BrokerFacade.java:511)
at org.opendaylight.netconf.sal.restconf.impl.RestconfImpl.invokeRpc(RestconfImpl.java:469)
at org.opendaylight.netconf.sal.restconf.impl.StatisticsRestconfServiceWrapper.invokeRpc(StatisticsRestconfServiceWrapper.java:83)
at org.opendaylight.netconf.sal.rest.impl.RestconfCompositeWrapper.invokeRpc(RestconfCompositeWrapper.java:64)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
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:790)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:257)
at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:220)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:83)
at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:301)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.opendaylight.aaa.filterchain.filters.CustomFilterAdapter.doFilter(CustomFilterAdapter.java:83)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:118)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:287)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at org.eclipse.jetty.server.Server.handle(Server.java:499)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
at java.lang.Thread.run(Thread.java:748)

Sandbox shows [1] the same error happens even without preceding reset suite, so it is unlikely to be caused just by ODL booting up slowly. But I have not looked very deeply, perhaps the bootup process did get stuck somewhere.

Karaf.log [2] does not show much detail even on DEBUG level (but I am not sure whether the "lagging entries" lines are relevant):
2017-08-25 12:08:19,798 | INFO | nsole user karaf | core | 112 - org.apache.karaf.log.core - 4.0.9 | ROBOT MESSAGE: Starting test Register_Rpc_On_Each_Node
2017-08-25 12:08:20,006 | DEBUG | rd-dispatcher-42 | SyncStatusTracker | 192 - org.opendaylight.controller.sal-akka-raft - 1.6.0.SNAPSHOT | member-1-shard-inventory-operational: Lagging 0 entries behind leader and reached member-3-shard-inventory-operational (of expected -1)
2017-08-25 12:08:20,016 | DEBUG | rd-dispatcher-42 | SyncStatusTracker | 192 - org.opendaylight.controller.sal-akka-raft - 1.6.0.SNAPSHOT | member-1-shard-entity-ownership-operational: Lagging 0 entries behind leader and reached member-3-shard-entity-ownership-operational (of expected 15)
2017-08-25 12:08:20,036 | DEBUG | tp1028272125-129 | MdsalLowLevelTestProvider | 214 - org.opendaylight.controller.samples.clustering-it-provider - 1.6.0.SNAPSHOT | Received register-constant rpc, input: RegisterConstantInput{getConstant=constant-1, augmentations={}}
2017-08-25 12:08:20,037 | DEBUG | tp1028272125-129 | GetConstantService | 214 - org.opendaylight.controller.samples.clustering-it-provider - 1.6.0.SNAPSHOT | Registering get-constant service, constant value: constant-1
2017-08-25 12:08:20,047 | DEBUG | rd-dispatcher-42 | SyncStatusTracker | 192 - org.opendaylight.controller.sal-akka-raft - 1.6.0.SNAPSHOT | member-1-shard-topology-operational: Lagging 0 entries behind leader and reached member-3-shard-topology-operational (of expected -1)
2017-08-25 12:08:20,040 | ERROR | tp1028272125-129 | ContainerResponse | 33 - com.sun.jersey.jersey-server - 1.17.0 | The exception contained within MappableContainerException could not be mapped to a response, re-throwing to the HTTP container
java.lang.IncompatibleClassChangeError: Found interface org.opendaylight.controller.md.sal.dom.api.DOMRpcProviderService, but class was expected

[0] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-only-nitrogen/124/log.html.gz#s1-s2-t1-k2-k1-k1-k1-k1-k3-k1-k4-k7-k1
[1] https://logs.opendaylight.org/sandbox/jenkins091/controller-csit-3node-clustering-only-nitrogen/4/log.html.gz#s1-t1-k2-k1-k1-k1-k1-k3-k1-k4-k7-k1
[2] https://logs.opendaylight.org/sandbox/jenkins091/controller-csit-3node-clustering-only-nitrogen/4/odl1_karaf.log.gz

 Comments   
Comment by Kit Lou [ 29/Aug/17 ]

We should verify with the next Nitrogen RC build as many carbon related patches have been merged.

Comment by Tom Pantelis [ 31/Aug/17 ]

IncompatibleClassChangeError indicates a binary incompatibility or maybe a class loader issue, ie perhaps bundle(s) are being refreshed/restarted. This is not a clustering issue. Unfortunately the link at [2] no longer exists. In the future it would be better to attach log files to the bug (assuming they're not too big).

Comment by Vratko Polak [ 06/Sep/17 ]

The controller clustering job is not seeing this symptom for some time now. Marking as fixed.

Comment by Vratko Polak [ 06/Sep/17 ]

Oops sorry, I was looking at wring job. The IncompatibleClassChangeError [3] is still there.

[3] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-all-nitrogen/137/log.html.gz#s1-s2-t1-k2-k1-k1-k1-k1-k3-k1-k4-k7-k1

Comment by Vratko Polak [ 06/Sep/17 ]

> perhaps bundle(s) are being refreshed/restarted

No restarts, and there are only two lines for refreshes, considered benign so far:

2017-09-06 03:35:32,175 | INFO | pool-2-thread-1 | FeaturesServiceImpl | 6 - org.apache.karaf.features.core - 4.0.9 | org.apache.servicemix.bundles.jasypt/1.9.2.1 (Should be wired to: javax.servlet-api/3.1.0 (through [org.apache.servicemix.bundles.jasypt/1.9.2.1] osgi.wiring.package; filter:="(osgi.wiring.package=javax.servlet)"; resolution:=optional))
2017-09-06 03:35:32,175 | INFO | pool-2-thread-1 | FeaturesServiceImpl | 6 - org.apache.karaf.features.core - 4.0.9 | org.ops4j.pax.jdbc.config/1.0.1 (Wired to org.apache.servicemix.bundles.jasypt/1.9.2.1 which is being refreshed)

Comment by Vratko Polak [ 07/Sep/17 ]

I have run a single test on Sandbox with a lot of debugs, but I do not see much relevant in the karaf log [4]. Perhaps something is wring with blueprint initialization? Here is the part just before the failure:

2017-09-07 10:08:15,360 | DEBUG | egister-constant | HttpInput | 147 - org.eclipse.jetty.util - 9.2.19.v20160908 | HttpInputOverHTTP@71ab47b8 eof EOF
2017-09-07 10:08:15,361 | DEBUG | egister-constant | ServiceRecipe | 71 - org.apache.aries.blueprint.core - 1.7.1 | Retrieving service for bundle org.opendaylight.netconf.sal-rest-connector_1.6.0.SNAPSHOT [265] and service registration

{org.opendaylight.controller.md.sal.dom.api.DOMRpcService, org.opendaylight.controller.md.sal.dom.api.DOMRpcProviderService}={osgi.service.blueprint.compname=domRpcRouter, type=default, service.id=204, service.bundleid=197, service.scope=bundle}
2017-09-07 10:08:15,361 | DEBUG | egister-constant | ServiceRecipe | 71 - org.apache.aries.blueprint.core - 1.7.1 | Method entry: getService, args org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter@3f26a886
2017-09-07 10:08:15,362 | DEBUG | egister-constant | ProxySubclassGenerator | 79 - org.apache.aries.proxy.impl - 1.0.5 | Method entry: isProxySubclass, args [class org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter]
2017-09-07 10:08:15,362 | DEBUG | egister-constant | ProxySubclassGenerator | 79 - org.apache.aries.proxy.impl - 1.0.5 | Method exit: isProxySubclass, returning false
2017-09-07 10:08:15,362 | DEBUG | egister-constant | ServiceRecipe | 71 - org.apache.aries.blueprint.core - 1.7.1 | Method exit: getService, returning org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter@3f26a886
2017-09-07 10:08:15,367 | DEBUG | egister-constant | MdsalLowLevelTestProvider | 214 - org.opendaylight.controller.samples.clustering-it-provider - 1.6.0.SNAPSHOT | Received register-constant rpc, input: RegisterConstantInput{getConstant=constant-1, augmentations={}}
2017-09-07 10:08:15,368 | DEBUG | egister-constant | GetConstantService | 214 - org.opendaylight.controller.samples.clustering-it-provider - 1.6.0.SNAPSHOT | Registering get-constant service, constant value: constant-1
2017-09-07 10:08:15,368 | DEBUG | egister-constant | ServiceRecipe | 71 - org.apache.aries.blueprint.core - 1.7.1 | Retrieving service for bundle org.opendaylight.controller.samples.clustering-it-provider_1.6.0.SNAPSHOT [214] and service registration {org.opendaylight.controller.md.sal.dom.api.DOMRpcService, org.opendaylight.controller.md.sal.dom.api.DOMRpcProviderService}

=

{osgi.service.blueprint.compname=domRpcRouter, type=default, service.id=204, service.bundleid=197, service.scope=bundle}

2017-09-07 10:08:15,368 | DEBUG | egister-constant | ServiceRecipe | 71 - org.apache.aries.blueprint.core - 1.7.1 | Method entry: getService, args org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter@3f26a886
2017-09-07 10:08:15,368 | DEBUG | egister-constant | ProxySubclassGenerator | 79 - org.apache.aries.proxy.impl - 1.0.5 | Method entry: isProxySubclass, args [class org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter]
2017-09-07 10:08:15,368 | DEBUG | egister-constant | ProxySubclassGenerator | 79 - org.apache.aries.proxy.impl - 1.0.5 | Method exit: isProxySubclass, returning false
2017-09-07 10:08:15,368 | DEBUG | egister-constant | ServiceRecipe | 71 - org.apache.aries.blueprint.core - 1.7.1 | Method exit: getService, returning org.opendaylight.controller.md.sal.dom.broker.impl.DOMRpcRouter@3f26a886
2017-09-07 10:08:15,371 | ERROR | egister-constant | ContainerResponse | 33 - com.sun.jersey.jersey-server - 1.17.0 | The exception contained within MappableContainerException could not be mapped to a response, re-throwing to the HTTP container
java.lang.IncompatibleClassChangeError: Found interface org.opendaylight.controller.md.sal.dom.api.DOMRpcProviderService, but class was expected
at Proxyfaa05c95_48d9_49a4_811b_15f5a563e722.registerRpcImplementation(Unknown Source)
at org.opendaylight.controller.clustering.it.provider.impl.GetConstantService.registerNew(GetConstantService.java:56)
at org.opendaylight.controller.clustering.it.provider.MdsalLowLevelTestProvider.registerConstant(MdsalLowLevelTestProvider.java:659)

[4] https://logs.opendaylight.org/sandbox/jenkins091/controller-csit-3node-clustering-only-nitrogen/3/odl1_karaf.log.gz

Comment by Vratko Polak [ 07/Sep/17 ]

> it would be better to attach log files to the bug

XZ compression was enough for [4], attached.

Comment by Vratko Polak [ 07/Sep/17 ]

Attachment 2017-09-07_odl1_karaf.log.xz has been added with description: XZ compressed karaf log

Comment by Vratko Polak [ 07/Sep/17 ]

Currently, I think this is related to a recent change [5] which moves registerRpcImplementation method to be a default method of DOMRpcProviderService interface. For some reason, clustering-test-app when built is picking a codebase where registerRpcImplementation is still a method of DOMRpcRouter class.

Partial revert [6] if the said change fixes [7] this Bug on Sandbox.

I have verified that CONTROLLER-1767 is not the source of the misalignment, now I am testing if a pom improvement [8] is a fix.

[5] https://git.opendaylight.org/gerrit/#/c/51035/11/opendaylight/md-sal/sal-dom-api/src/main/java/org/opendaylight/controller/md/sal/dom/api/DOMRpcProviderService.java
[6] https://git.opendaylight.org/gerrit/#/c/62851/1
[7] https://jenkins.opendaylight.org/sandbox/job/controller-csit-3node-clustering-only-nitrogen/7/
[8] https://git.opendaylight.org/gerrit/#/c/62857/1

Comment by Vratko Polak [ 07/Sep/17 ]

> if a pom improvement [8] is a fix.

It is not.

> Partial revert [6]

Sorry, it is a full revert (now patch set 2). Currently my candidate for the fix, waiting for review.

Comment by Vratko Polak [ 08/Sep/17 ]

I have found another consequence of this Bug. Singleton service suites tend to crash JVM.

Robot symptom is [9] "Connection reset by peer", the cause is printed to stderr [10] identifying it as this Bug:

Uncaught error from thread [opendaylight-cluster-data-akka.actor.default-dispatcher-6] shutting down JVM since 'akka.jvm-exit-on-fatal-error' is enabled for ActorSystem[opendaylight-cluster-data]
java.lang.IncompatibleClassChangeError: Found interface org.opendaylight.controller.md.sal.dom.api.DOMRpcProviderService, but class was expected
at Proxy016acb09_fc0b_4f4c_b32d_0cf74e946f5d.registerRpcImplementation(Unknown Source)
at org.opendaylight.controller.clustering.it.provider.impl.SingletonGetConstantService.instantiateServiceInstance(SingletonGetConstantService.java:99)

The fix [6] makes the suites pass [11] again.

[9] https://logs.opendaylight.org/releng/jenkins092/controller-csit-3node-clustering-all-nitrogen/141/log.html.gz#s1-s10-t1-k3-k1-k3-k1-k3-k1-k3-k1
[10] https://logs.opendaylight.org/sandbox/jenkins091/controller-csit-3node-clustering-only-nitrogen/9/odl1_karaf_console.log.gz
[11] https://jenkins.opendaylight.org/sandbox/job/controller-csit-3node-clustering-only-nitrogen/13/

Comment by Kit Lou [ 08/Sep/17 ]

Vratko, Does this mean merging [6] will address this blocker? Thanks!

Comment by Vratko Polak [ 12/Sep/17 ]

> merging [6] will address this blocker?

Yes, and it is merged now.

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