You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@ofbiz.apache.org by "Jacques Le Roux (JIRA)" <ji...@apache.org> on 2017/09/15 15:27:00 UTC
[jira] [Commented] (OFBIZ-9725) Transaction Timeout in
JavaEventHandler
[ https://issues.apache.org/jira/browse/OFBIZ-9725?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16168020#comment-16168020 ]
Jacques Le Roux commented on OFBIZ-9725:
----------------------------------------
Hi Jeffrey,
Could you please confirm the same exists using the trunk or the last supported release branch: R16.11? Unfortunately the R14.12 branch has never and will never been released so has never and will never been supported. This does not mean that we don't care, but it would be much more easier for us to know if you cross the same kind of issue using trunk or R16.
Thanks
> Transaction Timeout in JavaEventHandler
> ---------------------------------------
>
> Key: OFBIZ-9725
> URL: https://issues.apache.org/jira/browse/OFBIZ-9725
> Project: OFBiz
> Issue Type: Bug
> Components: framework/webtools
> Affects Versions: Release Branch 14.12
> Environment: Red Hat Enterprise Linux, release branch 14.12
> Reporter: Jeffrey Breault
>
> I have a service that is scheduled using the webtools scheduler.
> I am attempting to use the following service definition
> {noformat}
> <service name="myCustomService" engine="java" transaction-timeout="36000" require-new-transaction="true"
> location="my.package" invoke="myCustomService" auth="true">
> <description>Run this very long function</description>
> </service>
> {noformat}
> The function in question is getting data from an oracle database and sanitizing the records and then inserting them into a postgresql database. There are millions of records in the oracle database and I am grabbing the records in batches of 200, sanitizing them then committing them using a GenericValue.create() method. This continues for 100 iterations.
> Using verbose logging we have the following log messages to indicate that the transaction timeout is being used...
> {noformat}
> 2017-09-15 06:30:48,372 |http-bio-8443-exec-8 |ServiceDispatcher |D| [ServiceDispatcher.runSync] : invoking service myCustomService [my.package/myCustomService] (java)
> 2017-09-15 06:30:48,372 |http-bio-8443-exec-8 |TransactionUtil |D| Current status : No Transaction (6)
> 2017-09-15 06:30:48,372 |http-bio-8443-exec-8 |TransactionUtil |D| Set transaction timeout to : 36000 seconds
> 2017-09-15 06:30:48,372 |http-bio-8443-exec-8 |TransactionUtil |D| Transaction begun
> {noformat}
> {noformat}
> 2017-09-15 06:49:36,444 |http-bio-8443-exec-4 |MigrationServices |I| Ending myCustomService ::: 2017-09-15T06:49:36.444
> 2017-09-15 06:49:36,444 |http-bio-8443-exec-4 |ModelService |D| [ModelService.validate] : {myCustomService} : Validating context - {responseMessage=success}
> 2017-09-15 06:49:36,444 |http-bio-8443-exec-4 |ModelService |D| [ModelService.validate] : required fields -
> 2017-09-15 06:49:36,444 |http-bio-8443-exec-4 |ModelService |D| [ModelService.validate] : {myCustomService} : (OUT) Required - 0 / 0
> 2017-09-15 06:49:36,444 |http-bio-8443-exec-4 |ModelService |D| [ModelService.validate] : {myCustomService} : (OUT) Optional - 1 / 8
> 2017-09-15 06:49:36,444 |http-bio-8443-exec-4 |TransactionUtil |D| Current status : Transaction Active (0)
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |TransactionUtil |D| Transaction committed
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |Converters |D| Getting converter: java.lang.String->java.lang.Long
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |Converters |D| Getting converter: java.lang.String->java.lang.Long
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |ServiceDispatcher |T| Sync service [webtools/myCustomService] finished in [552515] milliseconds
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |ServiceDispatcher |D| Sync service [webtools/myCustomService] finished with response [{responseMessage=success}]
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |JavaEventHandler |D| [Event Return]: sync_success
> 2017-09-15 06:49:36,482 |http-bio-8443-exec-4 |TransactionUtil |D| Current status : Transaction Active (0)
> 2017-09-15 06:49:36,491 |http-bio-8443-exec-4 |TransactionUtil |W| In getSetRollbackOnlyCause no stack placeholder was in place, here is the current location:
> java.lang.Exception: Current Stack Trace
> at org.ofbiz.entity.transaction.TransactionUtil.getSetRollbackOnlyCause(TransactionUtil.java:840) [ofbiz-base.jar!/:?]
> at org.ofbiz.entity.transaction.TransactionUtil.commit(TransactionUtil.java:261) [ofbiz-base.jar!/:?]
> at org.ofbiz.entity.transaction.TransactionUtil.commit(TransactionUtil.java:234) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.event.JavaEventHandler.invoke(JavaEventHandler.java:115) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.event.JavaEventHandler.invoke(JavaEventHandler.java:80) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.RequestHandler.runEvent(RequestHandler.java:763) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.RequestHandler.doRequest(RequestHandler.java:476) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.ControlServlet.doGet(ControlServlet.java:210) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.ControlServlet.doPost(ControlServlet.java:89) [ofbiz-base.jar!/:?]
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:646) [servlet-api-3.0.jar:?]
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [servlet-api-3.0.jar:?]
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.ofbiz.webapp.control.ContextFilter.doFilter(ContextFilter.java:349) [ofbiz-base.jar!/:?]
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardContextValve.__invoke(StandardContextValve.java:122) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
> 2017-09-15 06:49:36,511 |http-bio-8443-exec-4 |JavaEventHandler |E| null
> org.ofbiz.entity.transaction.GenericTransactionException: Roll back error (with no rollbackOnly cause found), could not commit transaction, was rolled back instead: java.lang.Exception: Transaction has timed out (Transaction has timed out)
> at org.ofbiz.entity.transaction.TransactionUtil.commit(TransactionUtil.java:273) ~[ofbiz-base.jar!/:?]
> at org.ofbiz.entity.transaction.TransactionUtil.commit(TransactionUtil.java:234) ~[ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.event.JavaEventHandler.invoke(JavaEventHandler.java:115) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.event.JavaEventHandler.invoke(JavaEventHandler.java:80) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.RequestHandler.runEvent(RequestHandler.java:763) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.RequestHandler.doRequest(RequestHandler.java:476) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.ControlServlet.doGet(ControlServlet.java:210) [ofbiz-base.jar!/:?]
> at org.ofbiz.webapp.control.ControlServlet.doPost(ControlServlet.java:89) [ofbiz-base.jar!/:?]
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:646) [servlet-api-3.0.jar:?]
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) [servlet-api-3.0.jar:?]
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.ofbiz.webapp.control.ContextFilter.doFilter(ContextFilter.java:349) [ofbiz-base.jar!/:?]
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardContextValve.__invoke(StandardContextValve.java:122) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) [tomcat-7.0.65-catalina.jar:7.0.65]
> at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
> at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-7.0.65-tomcat-coyote.jar:7.0.65]
> at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
> Caused by: java.lang.Exception: Transaction has timed out
> at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:266) ~[geronimo-transaction-3.1.1.jar:3.1.1]
> at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252) ~[geronimo-transaction-3.1.1.jar:3.1.1]
> at org.ofbiz.entity.transaction.TransactionUtil.commit(TransactionUtil.java:248) ~[ofbiz-base.jar!/:?]
> ... 30 more
> {noformat}
> So, I have the transaction timeout set to 36,000 seconds and the job finishes in 552,515 milliseconds (about 9.2 minutes), but then the JavaEventHandler's finally clause hits a commit and that causes a timeout
> {code:java}
> private String invoke(String eventPath, String eventMethod, Class<?> eventClass, Class<?>[] paramTypes, Object[] params) throws EventHandlerException {
> boolean beganTransaction = false;
> if (eventClass == null) {
> throw new EventHandlerException("Error invoking event, the class " + eventPath + " was not found");
> }
> if (eventPath == null || eventMethod == null) {
> throw new EventHandlerException("Invalid event method or path; call initialize()");
> }
> Debug.logVerbose("[Processing]: JAVA Event", module);
> try {
> beganTransaction = TransactionUtil.begin();
> Method m = eventClass.getMethod(eventMethod, paramTypes);
> String eventReturn = (String) m.invoke(null, params);
> if (Debug.verboseOn()) Debug.logVerbose("[Event Return]: " + eventReturn, module);
> return eventReturn;
> } catch (java.lang.reflect.InvocationTargetException e) {
> Throwable t = e.getTargetException();
> if (t != null) {
> Debug.logError(t, "Problems Processing Event", module);
> throw new EventHandlerException("Problems processing event: " + t.toString(), t);
> } else {
> Debug.logError(e, "Problems Processing Event", module);
> throw new EventHandlerException("Problems processing event: " + e.toString(), e);
> }
> } catch (Exception e) {
> Debug.logError(e, "Problems Processing Event", module);
> throw new EventHandlerException("Problems processing event: " + e.toString(), e);
> } finally {
> try {
> TransactionUtil.commit(beganTransaction);
> } catch (GenericTransactionException e) {
> Debug.logError(e, module);
> }
> }
> }
> {code}
> It appears that the invoking of my service creates a default timeout transaction (using GeronimoTransactionFactory's default timeout of 60 seconds) Which is then suspended by my request-new-transaction and uses my custom timeout parameter. When the service is finished the commit occurs and the default transaction resumes, and is then committed, which causes the stack-trace.
> This is an error in our production environment so I would like a patch to be created if at all possible.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)