[
https://issues.apache.org/jira/browse/OFBIZ-9725?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jacques Le Roux closed OFBIZ-9725.
----------------------------------
Resolution: Fixed
Fix Version/s: 16.11.04
Thanks for your detailled report Jeffrey,
I have fixed the issue (more a quiproquo) in trunk at revision: 1809741 by
adding an indication of the limited duration for services run this way. For
longer services, as you did, sheduling a job is the way. Sorry, I have no
intent of prodiving a way to shedule them using a Temporal Expression. But I'll
provide the enhanced way in OFBIZ-9726
Tough it could be done in older releases, I only backported in R16.11 at
r1809742
> 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
> Assignee: Jacques Le Roux
> Fix For: 16.11.04
>
> 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)
