[jira] [Commented] (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=16169447#comment-16169447 ]

Jeffrey Breault commented on OFBIZ-9725:
----------------------------------------

Jacques,

I have not attempted creating the job using TemporalExpressions as of yet.  Your example does work, but only because it does not exceed the one minute timeout from the default GeronimoTransactionFactory.

If you would please try to increase the amount of items being inserted so that the job takes longer than one minute (but less than the 36,000 seconds as indicated by my service definition), I believe that you will get the same exception I had received.

I will look into creating a TemporalExpression right now and see if it also creates the same exception.  

> 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)