ofbiz-notifications mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jeffrey Breault (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (OFBIZ-9725) Transaction Timeout in JavaEventHandler
Date Fri, 15 Sep 2017 22:28:00 GMT

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

Jeffrey Breault updated OFBIZ-9725:
-----------------------------------
    Affects Version/s: Release Branch 16.11

> 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
>            Reporter: Jeffrey Breault
>         Attachments: management.zip
>
>
> 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)

Mime
View raw message