OFBiz › OFBiz - Notifications

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

_‹ Previous Topic Next Topic _›

Classic

List

Threaded

1 message

Nicolas Malin (Jira)

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

[ https://issues.apache.org/jira/browse/OFBIZ-9725?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Jeffrey Breault updated OFBIZ-9725:
-----------------------------------
Attachment: shortLog.log

Jacques,

When I ran it yesterday I got the attached result ([^shortLog.log]).

The service on my little laptop had the following timing: Sync service [webtools/testService] finished in [127424] milliseconds

I think you may need to increase the number of records that are being inserted from my example to tax your computer more. As I said in my description I am dealing with a table with millions of records being converted. We can have it running if we have it set to a small subsection (get 200 records, convert and save, then get 200 more) for 100 iterations. But if we were to increase that number then it gets the error in the above log.

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