moqui / moqui-framework

Use Moqui Framework to build enterprise applications based on Java. It includes tools for databases (relational, graph, document), local and web services, web and other UI with screens and forms, security, file/resource access, scripts, templates, l10n, caching, logging, search, rules, workflow, multi-instance, and integration.
http://www.moqui.org
Other
279 stars 200 forks source link

Transaction rollback failed #297

Closed lightning-pro closed 6 years ago

lightning-pro commented 6 years ago

Test Procedure 1) use the popc to place an order, will console some errors in console window seems due to the data inconsistent 2) use the popc admin app to approve the order then create shipment. it will fail to create the shipment, then it will try to rollback, but fail to rollback. then no matter what page link I go , keep failed, success, failed ,success... just keep the transaction roll back error display. it seems the error is caused by the elasticsearch

below is the error log

11:49:38.421 WARN 4074868-4013 o.m.i.w.MoquiServlet In MoquiServlet.service there is already an ExecutionContext for user john.doe (from 4013:qtp214074868-4013) in this thread (4013:qtp214074868-4013), destroying 11:49:38.421 WARN 4074868-4013 o.moqui.i.c.TransactionFacadeImpl Thread ending with a transaction in place. Trying to commit. 11:49:38.421 WARN 4074868-4013 o.moqui.i.c.TransactionFacadeImpl Transaction rollback for [Commit failed, rolling back to clean up]. Here is the current location: org.moqui.BaseException: Rollback location at org.moqui.impl.context.TransactionFacadeImpl.rollback(TransactionFacadeImpl.groovy:434) ~[moqui-framework-2.1.1-rc1.jar:2.1.1-rc1] at org.moqui.impl.context.TransactionFacadeImpl.commit(TransactionFacadeImpl.groovy:400) ~[moqui-framework-2.1.1-rc1.jar:2.1.1-rc1] at org.moqui.impl.context.TransactionFacadeImpl.destroyAllInThread(TransactionFacadeImpl.groovy:97) ~[moqui-framework-2.1.1-rc1.jar:2.1.1-rc1] at org.moqui.impl.context.ExecutionContextImpl.destroy(ExecutionContextImpl.java:224) ~[moqui-framework-2.1.1-rc1.jar:2.1.1-rc1] at org.moqui.impl.webapp.MoquiServlet.service(MoquiServlet.groovy:81) ~[moqui-framework-2.1.1-rc1.jar:2.1.1-rc1] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[moqui_temp4422661084092017992execlib_javax.servlet-api-3.1.0.jar.:3.1.0]

2017-12-16 11:49:38.427:WARN:oejs.HttpChannel:qtp214074868-4013: /apps/PopcAdmin/Order/FindOrder.vuet org.moqui.context.TransactionException: Could not rollback transaction at org.moqui.impl.context.TransactionFacadeImpl.rollback(TransactionFacadeImpl.groovy:440) at org.moqui.impl.context.TransactionFacadeImpl.commit(TransactionFacadeImpl.groovy:400) at org.moqui.impl.context.TransactionFacadeImpl.destroyAllInThread(TransactionFacadeImpl.groovy:97) at org.moqui.impl.context.ExecutionContextImpl.destroy(ExecutionContextImpl.java:224) at org.moqui.impl.webapp.MoquiServlet.service(MoquiServlet.groovy:81) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.ebaysf.web.cors.CORSFilter.handleNonCORS(CORSFilter.java:437) at org.ebaysf.web.cors.CORSFilter.doFilter(CORSFilter.java:172) at com.hazelcast.web.WebFilter.doFilter(WebFilter.java:287) at org.moqui.elasticsearch.ElasticRequestLogFilter.doFilter(ElasticRequestLogFilter.groovy:107) at java.lang.Thread.run(Thread.java:748) Caused by: java.lang.IllegalStateException: Transaction is committing - adding a new participant is not allowed at com.atomikos.icatch.imp.TxTerminatingStateHandler.reject(TxTerminatingStateHandler.java:48) at com.atomikos.icatch.imp.TxTerminatingStateHandler.rollbackWithStateCheck(TxTerminatingStateHandler.java:99) at com.atomikos.icatch.imp.CompositeTransactionImp.doRollback(CompositeTransactionImp.java:201) at com.atomikos.icatch.imp.CompositeTransactionImp.rollback(CompositeTransactionImp.java:314) at com.atomikos.icatch.jta.TransactionImp.rollback(TransactionImp.java:199) at com.atomikos.icatch.jta.TransactionManagerImp.rollback(TransactionManagerImp.java:426) at com.atomikos.icatch.jta.UserTransactionManager.rollback(UserTransactionManager.java:198) at org.moqui.impl.context.TransactionFacadeImpl.rollback(TransactionFacadeImpl.groovy:438) at org.moqui.impl.context.TransactionFacadeImpl.commit(TransactionFacadeImpl.groovy:400) at org.moqui.impl.context.TransactionFacadeImpl.destroyAllInThread(TransactionFacadeImpl.groovy:97) at org.moqui.impl.context.ExecutionContextImpl.destroy(ExecutionContextImpl.java:224) at org.moqui.impl.webapp.MoquiServlet.service(MoquiServlet.groovy:81) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650) at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:206) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.ebaysf.web.cors.CORSFilter.handleNonCORS(CORSFilter.java:437) at org.ebaysf.web.cors.CORSFilter.doFilter(CORSFilter.java:172) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at com.hazelcast.web.WebFilter.doFilter(WebFilter.java:287) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629) at org.moqui.elasticsearch.ElasticRequestLogFilter.doFilter(ElasticRequestLogFilter.groovy:107) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:527) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:561) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:104) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597) at java.lang.Thread.run(Thread.java:748)

jonesde commented 6 years ago

There isn't much information to go on here, steps to reproduce for example, as in:

https://github.com/moqui/moqui-framework/wiki/Issue-and-Pull-Request-Guide

What do you see that leads you to believe it is related to ElasticSearch? I see that you have Hazelcast installed, and some sort of CORS filter.

Which version of Moqui are you using, and what additional components do you have in place? You can see these in the System app on its dashboard screen.

A partial log like this is also only so helpful. There are some red flags like the first message about MoquiServlet finding an ExecutionContext object in place in the thread and the next message about an active transaction in place and trying to commit it, something messed up before this.

jonesde commented 6 years ago

Any updates on this?

I'm unable to reproduce it but looking at the stack in the log message there is some funny behavior around failing to commit and I modified the behavior slightly so that it only tries to rollback when a commit is not successful if the TX status is active or marked rollback only.

Overall from the log messages before the big error with the stack trace as well as the it looks like something like the ExecutionContext and transaction aren't cleaned up (closed) in the thread, or perhaps the ExecutionContext was being used in another thread which will cause issues.

jonesde commented 6 years ago

Closing as part of general cleanup for the move to HiveMind and for no activity on this issue. If this comes up again feel free to create a request on moqui.org. For more information see:

https://www.moqui.org/m/docs/moqui/Community+Guide