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] [Commented] (OFBIZ-9725) Transaction Timeout in JavaEventHandler
Date Sun, 17 Sep 2017 22:32:02 GMT

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

Mime
View raw message