Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 6198F200CE7 for ; Sat, 16 Sep 2017 13:51:08 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 603951609D5; Sat, 16 Sep 2017 11:51:08 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 531BF1609D4 for ; Sat, 16 Sep 2017 13:51:07 +0200 (CEST) Received: (qmail 15232 invoked by uid 500); 16 Sep 2017 11:51:06 -0000 Mailing-List: contact notifications-help@ofbiz.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@ofbiz.apache.org Delivered-To: mailing list notifications@ofbiz.apache.org Received: (qmail 15223 invoked by uid 99); 16 Sep 2017 11:51:06 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Sat, 16 Sep 2017 11:51:06 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 137991845E2 for ; Sat, 16 Sep 2017 11:51:06 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -99.202 X-Spam-Level: X-Spam-Status: No, score=-99.202 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, RP_MATCHES_RCVD=-0.001, SPF_PASS=-0.001, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id woHKJ_G2h6lT for ; Sat, 16 Sep 2017 11:51:03 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTP id 42A845FB40 for ; Sat, 16 Sep 2017 11:51:02 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id E790BE0DB8 for ; Sat, 16 Sep 2017 11:51:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 2E6AD25385 for ; Sat, 16 Sep 2017 11:51:00 +0000 (UTC) Date: Sat, 16 Sep 2017 11:51:00 +0000 (UTC) From: "Jeffrey Breault (JIRA)" To: notifications@ofbiz.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (OFBIZ-9725) Transaction Timeout in JavaEventHandler MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Sat, 16 Sep 2017 11:51:08 -0000 [ https://issues.apache.org/jira/browse/OFBIZ-9725?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16168896#comment-16168896 ] Jeffrey Breault edited comment on OFBIZ-9725 at 9/16/17 11:50 AM: ------------------------------------------------------------------ Jacques: I apologize for the mixup. this file should be better. [^management.zip] was (Author: jbreault): Jacques: I apologize for the mixup. this file should be better. > 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} > location="my.package" invoke="myCustomService" auth="true"> > Run this very long function > > {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)