[jira] [Comment Edited] (OFBIZ-9725) Transaction Timeout in JavaEventHandler

[Nicolas Malin (Jira)]

    [ https://issues.apache.org/jira/browse/OFBIZ-9725?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16169903#comment-16169903 ]

Jacques Le Roux edited comment on OFBIZ-9725 at 9/18/17 11:28 AM:
------------------------------------------------------------------

bq. . I'm guessing this is an async vs sync issue?
Yes, I guess so (did not check yet). But I think we can improve that, or then warn the user about this possible issue.

bq. This also leads me to anther questions. is there a plan at the moment to allow for scheduling long running services using Temporal Events?Caused by: java.sql.SQLRecoverableException: IO Error: Connection reset
Wait you said above that it was OK when using
bq. schedule service (without time parameters)
And I think it's OK to do so. So I see no reasons for your question, please explain if I'm misunderstanding.
Anyway,  for a custom project I have developed a feature which allows to follow the progress of a long running job by increasing a progress bar. It allows also to set some related parameters and report detailled errors or success. We want to contribute this feature to OFBiz and I'll hopefull work in it before Christmas. It works already in the custom project since February... I'll create a Jira for that!


was (Author: jacques.le.roux):
bq. . I'm guessing this is an async vs sync issue?
Yes, I guess so (did not check yet). But I think we can improve that, or then warn the user about this possible issue.

bq. This also leads me to anther questions. is there a plan at the moment to allow for scheduling long running services using Temporal Events?Caused by: java.sql.SQLRecoverableException: IO Error: Connection reset
Wait you said above that it was OK when using
bq. schedule service (without time parameters)
And I think it's OK to do so. So I see no reasons for your question, please explain if I'm misunderstanding.
Anyway,  for a custom project I have developed a feature which allows to follow the progress of a long running job by increasing a progress bar. It allows also to set some related parameters. We want to contribute this feature to OFBiz and I'll hopefull work in it before Christmas. It works already in the custom project since February... I'll create a Jira for that!

> 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, Release Branch 16.11
>         Environment: Red Hat Enterprise Linux, release branch 14.12
> Ubuntu 17.04, release branch 16.11.03
>            Reporter: Jeffrey Breault
>         Attachments: management-trunk.zip, management.zip, ofbiz.log, shortLog.log, TestingServices.java
>
>
> 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)