[NETCONF-781] HTTP ERROR 500 Request failed on restconf POST Created: 20/May/21  Updated: 31/May/21  Resolved: 31/May/21

Status: Resolved
Project: netconf
Component/s: restconf-nb
Affects Version/s: 1.13.1, 1.13.2
Fix Version/s: 2.0.0, 1.13.3

Type: Bug Priority: Medium
Reporter: Marek Zaťko Assignee: Robert Varga
Resolution: Done Votes: 0
Labels: pt
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File karaf.log    
Issue Links:
Relates
relates to NETCONF-773 Refactor restconf-nb wiring Confirmed

 Description   

In Sillicon release, restconf POST to topology netconf results in Error 500 Request failed. response, in logs the following exception is thrown Caused by: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-0-chn-5-txn-0-0 is not ready yet.
Steps to reproduce:

  • download silicon release
  • ./karaf clean
  • feature:install odl-netconf-topology odl-restconf-nb-rfc8040
  • restconf POST on http://127.0.0.1:8181/rests/data/network-topology:network-topology with payload: 
    {
  "topology": [
    {
      "topology-id": "put-test-topology"
    }
  ]
}
  • this results in: 
    <html>

<head>
	<meta http-equiv="Content-Type" content="text/html;charset=utf-8" />
	<title>Error 500 Request failed.</title>
</head>

<body>
	<h2>HTTP ERROR 500 Request failed.</h2>
	<table>
		<tr>
			<th>URI:</th>
			<td>/rests/data/network-topology:network-topology</td>
		</tr>
		<tr>
			<th>STATUS:</th>
			<td>500</td>
		</tr>
		<tr>
			<th>MESSAGE:</th>
			<td>Request failed.</td>
		</tr>
		<tr>
			<th>SERVLET:</th>
			<td>org.glassfish.jersey.servlet.ServletContainer</td>
		</tr>
	</table>
</body>
</html>

    which is unexpected since the data should be POSTED just fine.

Logs from karaf:

21:18:43.970 INFO [Blueprint Event Dispatcher: 1] Blueprint container for bundle org.opendaylight.netconf.restconf-nb-rfc8040_1.13.1 [279] was successfully created
21:18:46.095 INFO [qtp664704439-692] Authentication is now enabled
21:18:46.097 INFO [qtp664704439-692] Authentication Manager activated
21:18:46.308 WARN [qtp664704439-692] /rests/data/network-topology:network-topology
javax.servlet.ServletException: javax.servlet.ServletException: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-3-txn-0-0 is not ready yet
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:90) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.Server.handle(Server.java:501) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) [bundleFile:9.4.31.v20200723]
	at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: javax.servlet.ServletException: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-3-txn-0-0 is not ready yet
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:432) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:342) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:229) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1402) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:319) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:273) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) ~[?:?]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:226) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:567) ~[?:?]
	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:602) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1377) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:507) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1292) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[?:?]
	... 12 more
Caused by: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-3-txn-0-0 is not ready yet
	at org.opendaylight.controller.cluster.datastore.TransactionChainProxy$Allocated.checkReady(TransactionChainProxy.java:86) ~[?:?]
	at org.opendaylight.controller.cluster.datastore.TransactionChainProxy.newReadOnlyTransaction(TransactionChainProxy.java:158) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.DOMBrokerReadOnlyTransaction.createTransaction(DOMBrokerReadOnlyTransaction.java:52) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.DOMBrokerReadOnlyTransaction.createTransaction(DOMBrokerReadOnlyTransaction.java:21) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.AbstractDOMBrokerTransaction.getSubtransaction(AbstractDOMBrokerTransaction.java:56) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.DOMBrokerReadOnlyTransaction.exists(DOMBrokerReadOnlyTransaction.java:42) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.transactions.BatchedExistenceCheck.start(BatchedExistenceCheck.java:46) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.transactions.MdsalRestconfTransaction.create(MdsalRestconfTransaction.java:84) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.utils.PostDataTransactionUtil.makePost(PostDataTransactionUtil.java:183) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.utils.PostDataTransactionUtil.submitData(PostDataTransactionUtil.java:98) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.utils.PostDataTransactionUtil.postData(PostDataTransactionUtil.java:71) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.services.impl.RestconfDataServiceImpl.postData(RestconfDataServiceImpl.java:356) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.services.impl.RestconfDataServiceImpl.postData(RestconfDataServiceImpl.java:343) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.services.wrapper.ServicesWrapper.postData(ServicesWrapper.java:128) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:76) ~[?:?]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:148) ~[?:?]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:191) ~[?:?]
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:200) ~[?:?]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:103) ~[?:?]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:493) ~[?:?]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:415) ~[?:?]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:104) ~[?:?]
	at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:277) ~[?:?]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:272) ~[?:?]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:268) ~[?:?]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:316) ~[?:?]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:298) ~[?:?]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:268) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:289) ~[?:?]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:256) ~[?:?]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:703) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:416) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:342) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:229) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1402) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:319) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:273) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) ~[?:?]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:226) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:567) ~[?:?]
	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:602) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1377) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:507) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1292) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[?:?]
	... 12 more
21:18:46.340 WARN [qtp664704439-692] unhandled due to prior sendError
javax.servlet.ServletException: javax.servlet.ServletException: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-3-txn-0-0 is not ready yet
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:90) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.Server.handle(Server.java:501) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) [bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) [bundleFile:9.4.31.v20200723]
	at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: javax.servlet.ServletException: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-3-txn-0-0 is not ready yet
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:432) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:342) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:229) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1402) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:319) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:273) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) ~[?:?]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:226) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:567) ~[?:?]
	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:602) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1377) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:507) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1292) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[?:?]
	... 12 more
Caused by: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-3-txn-0-0 is not ready yet
	at org.opendaylight.controller.cluster.datastore.TransactionChainProxy$Allocated.checkReady(TransactionChainProxy.java:86) ~[?:?]
	at org.opendaylight.controller.cluster.datastore.TransactionChainProxy.newReadOnlyTransaction(TransactionChainProxy.java:158) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.DOMBrokerReadOnlyTransaction.createTransaction(DOMBrokerReadOnlyTransaction.java:52) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.DOMBrokerReadOnlyTransaction.createTransaction(DOMBrokerReadOnlyTransaction.java:21) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.AbstractDOMBrokerTransaction.getSubtransaction(AbstractDOMBrokerTransaction.java:56) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.DOMBrokerReadOnlyTransaction.exists(DOMBrokerReadOnlyTransaction.java:42) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.transactions.BatchedExistenceCheck.start(BatchedExistenceCheck.java:46) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.transactions.MdsalRestconfTransaction.create(MdsalRestconfTransaction.java:84) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.utils.PostDataTransactionUtil.makePost(PostDataTransactionUtil.java:183) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.utils.PostDataTransactionUtil.submitData(PostDataTransactionUtil.java:98) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.utils.PostDataTransactionUtil.postData(PostDataTransactionUtil.java:71) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.services.impl.RestconfDataServiceImpl.postData(RestconfDataServiceImpl.java:356) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.rests.services.impl.RestconfDataServiceImpl.postData(RestconfDataServiceImpl.java:343) ~[?:?]
	at org.opendaylight.restconf.nb.rfc8040.services.wrapper.ServicesWrapper.postData(ServicesWrapper.java:128) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:76) ~[?:?]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:148) ~[?:?]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:191) ~[?:?]
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:200) ~[?:?]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:103) ~[?:?]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:493) ~[?:?]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:415) ~[?:?]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:104) ~[?:?]
	at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:277) ~[?:?]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:272) ~[?:?]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:268) ~[?:?]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:316) ~[?:?]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:298) ~[?:?]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:268) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:289) ~[?:?]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:256) ~[?:?]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:703) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:416) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:342) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:229) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1402) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:319) ~[?:?]
	at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:273) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) ~[?:?]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) ~[?:?]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) ~[?:?]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) ~[?:?]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) ~[?:?]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:226) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:567) ~[?:?]
	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:602) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.31.v20200723]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1377) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:507) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1292) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[?:?]
	... 12 more

In a case of XML payload it works fine and data is POSTED fine, because the BatchedExistenceCheck is skipped in that case.

 Comments   
Comment by Charalampos Kaidos [ 28/May/21 ]

I have the same issue on my data models and I have managed to narrow it down. It happens when I POST to a container that contains a list. If I PUT the same container, there is no problem. Also if I POST a container that contains a container that contains a list there is no error either.

Example

Data model:

container credentials {
  container snmp {
    container v2c {
      list community {
        key community;
        leaf community {
          type string;
        }
      }
    }
  }
}

If I POST at /rests/data/identification:credentials/snmp/v2c the data:

{
  "community": [
    {
      "community": "ssd"
    }
  ]
}

Then I get the 500 error and the suspicious DEBUG logs are:

12:25:37.965 DEBUG [qtp1515961087-699] Write Tx: member-1-datastore-config-fe-1-chn-26-txn-0-0 allocated with snapshot org.opendaylight.yangtools.yang.data.api.schema.tree.spi.Version@44050d9d
12:25:37.965 DEBUG [qtp1515961087-699] Tx: member-1-datastore-config-fe-1-chn-26-txn-0-0 Merge: /(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials:ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials, value=[ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)snmp, value=[ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)v2c, value=[ImmutableMapNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)community, value=[]}]}]}]}
12:25:37.966 DEBUG [qtp1515961087-699] Tx: member-1-datastore-config-fe-1-chn-26-txn-0-0 Merge: /(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials:ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials, value=[ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)snmp, value=[ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)v2c, value=[]}]}]}
12:25:37.966 DEBUG [qtp1515961087-699] sendError HttpChannelState@6baca566{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
12:25:37.966 DEBUG [qtp1515961087-699] Leaving scope org.eclipse.jetty.server.session.SessionHandler798801461==dftMaxIdleSec=300 dispatch=REQUEST, async=false, session=Session@6b105718{id=node01dykt6o046u4s1io8bx7etw4il2,x=node01dykt6o046u4s1io8bx7etw4il2.node0,req=1,res=true}, oldsession=null, oldsessionhandler=null
12:25:37.966 WARN [qtp1515961087-699] /rests/data/identification:credentials/snmp/v2c
javax.servlet.ServletException: javax.servlet.ServletException: java.lang.IllegalStateException: Previous transaction member-1-datastore-config-fe-1-chn-26-txn-0-0 is not ready yet
...

But if I post at /rests/data/identification:credentials/snmp the data:

{
  "v2c": {
    "community": [
      {
        "community": "ssd"
      }
    ]
  }
}

Then everything works fine and get 201. The logs in this case:

12:34:58.138 DEBUG [qtp1515961087-918] Write Tx: member-1-datastore-config-fe-1-chn-27-txn-0-0 allocated with snapshot org.opendaylight.yangtools.yang.data.api.schema.tree.spi.Version@44050d9d
12:34:58.138 DEBUG [qtp1515961087-918] Tx: member-1-datastore-config-fe-1-chn-27-txn-0-0 Read: /(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials/snmp/v2c
12:34:58.138 DEBUG [qtp1515961087-918] Tx: member-1-datastore-config-fe-1-chn-27-txn-0-0 Merge: /(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials:ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials, value=[ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)snmp, value=[]}]}
12:34:58.139 DEBUG [qtp1515961087-918] Tx: member-1-datastore-config-fe-1-chn-27-txn-0-0 Write: /(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)credentials/snmp/v2c:ImmutableContainerNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)v2c, value=[ImmutableMapNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)community, value=[ImmutableMapEntryNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)community[{(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)community=ssd}], value=[ImmutableLeafNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)community, value=ssd}]}]}]}
12:34:58.139 DEBUG [qtp1515961087-918] Tx member-1-datastore-config-fe-1-chn-27-txn-0-0 Readying 1 components for commit
12:34:58.139 DEBUG [qtp1515961087-918] Tx member-1-datastore-config-fe-1-chn-27-txn-0-0 Readying transaction for shard default
12:34:58.139 DEBUG [qtp1515961087-918] Total modifications on Tx member-1-datastore-config-fe-1-chn-27-txn-0-0 = [ 2 ]
...

What I see in the logs is that the list data are missing in the first request ({identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)v2c, value=[]}), but are present in the second request ({identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)v2c, value=[ImmutableMapNode{identifier=(urn:opendaylight:params:xml:ns:yang:identification?revision=2017-09-12)community...)

This breaks many of out requests from external systems and prohibits us to upgrade from Aluminium.

Comment by Robert Varga [ 31/May/21 ]

I need a full stack trace for that ISE – otherwise I cannot identify the offender.

Comment by Charalampos Kaidos [ 31/May/21 ]

karaf.log

 I attached the whole karaf.log. The offending request logs start at line 2773 while the stacktrace is at line 2989.

Comment by Robert Varga [ 31/May/21 ]

Ah, right, that is the same thing. I misread the proposition in "from Aluminium"

Comment by Robert Varga [ 31/May/21 ]

The 2.0.0 was fixed as part of NETCONF-773 refactors.

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