issue with this example is you catch the exception so the jta transaction is not rolledback, modified it to throw a runtime exception and make the tx failing and it works it seems
Romain Manni-Bucau @rmannibucau <https://twitter.com/rmannibucau> | Blog <https://blog-rmannibucau.rhcloud.com> | Old Blog <http://rmannibucau.wordpress.com> | Github <https://github.com/rmannibucau> | LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory <https://javaeefactory-rmannibucau.rhcloud.com> 2017-05-02 12:34 GMT+02:00 Paul Carter-Brown < [email protected]>: > Hi Romain, > > I set the MySQL connection timeout to 2 seconds and did a sleep for 3 > seconds at the end of the business method. > > The result was that the business method still returned the primary key of > the new row successfully yet after that there was an exception committing > the TX and the row was not actually written to the DB. > > 2017/05/02 12:19:53.354 WARNING [TomEE-Exec-33][307][org.apache.cxf.phase. > PhaseInterceptorChain.doDefaultLogging] |Application { > http://xml.smilecoms.com/IM}IM#{http://xml.smilecoms.com/IM}AddCustomer > has thrown exception, unwinding now > org.apache.cxf.interceptor.Fault: javax.transaction.SystemException: > Error during two phase commit: Error during two phase commit while invoking > public abstract com.smilecoms.xml.schema.im.PlatformInteger > com.smilecoms.xml.im.IMSoap.addCustomer(com.smilecoms.xml.schema.im.Customer) > throws com.smilecoms.xml.im.IMError with params [ > com.smilecoms.xml.schema.im.Customer@5950a117]. > at org.apache.cxf.service.invoker.AbstractInvoker. > createFault(AbstractInvoker.java:166) > at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.createFault( > AbstractJAXWSMethodInvoker.java:267) > at org.apache.openejb.server.cxf.ejb.EjbMethodInvoker. > preEjbInvoke(EjbMethodInvoker.java:165) > at org.apache.openejb.server.cxf.ejb.EjbMethodInvoker.invoke( > EjbMethodInvoker.java:82) > at org.apache.cxf.service.invoker.AbstractInvoker. > invoke(AbstractInvoker.java:74) > at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1. > run(ServiceInvokerInterceptor.java:59) > at java.util.concurrent.Executors$RunnableAdapter. > call(Executors.java:511) > at java.util.concurrent.FutureTask.run(FutureTask.java:266) > at org.apache.cxf.interceptor.ServiceInvokerInterceptor$2. > run(ServiceInvokerInterceptor.java:126) > at org.apache.cxf.workqueue.SynchronousExecutor.execute( > SynchronousExecutor.java:37) > at org.apache.cxf.interceptor.ServiceInvokerInterceptor. > handleMessage(ServiceInvokerInterceptor.java:131) > at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept( > PhaseInterceptorChain.java:308) > at org.apache.cxf.transport.ChainInitiationObserver.onMessage( > ChainInitiationObserver.java:121) > at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke( > AbstractHTTPDestination.java:262) > at org.apache.openejb.server.cxf.CxfWsContainer.onMessage( > CxfWsContainer.java:85) > at org.apache.openejb.server.webservices.WsServlet.service( > WsServlet.java:98) > at org.apache.catalina.core.ApplicationFilterChain. > internalDoFilter(ApplicationFilterChain.java:230) > at org.apache.catalina.core.ApplicationFilterChain.doFilter( > ApplicationFilterChain.java:165) > at org.apache.catalina.core.StandardWrapperValve.invoke( > StandardWrapperValve.java:198) > at org.apache.catalina.core.StandardContextValve.invoke( > StandardContextValve.java:96) > at org.apache.catalina.core.StandardHostValve.invoke( > StandardHostValve.java:140) > at org.apache.catalina.valves.ErrorReportValve.invoke( > ErrorReportValve.java:79) > at org.apache.tomee.catalina.OpenEJBSecurityListener$ > RequestCapturer.invoke(OpenEJBSecurityListener.java:97) > at org.apache.catalina.core.StandardEngineValve.invoke( > StandardEngineValve.java:87) > at org.apache.catalina.connector.CoyoteAdapter.service( > CoyoteAdapter.java:349) > at org.apache.coyote.http11.Http11Processor.service( > Http11Processor.java:783) > at org.apache.coyote.AbstractProcessorLight.process( > AbstractProcessorLight.java:66) > at org.apache.coyote.AbstractProtocol$ConnectionHandler.process( > AbstractProtocol.java:798) > at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor. > doRun(NioEndpoint.java:1434) > at org.apache.tomcat.util.net.SocketProcessorBase.run( > SocketProcessorBase.java:49) > at java.util.concurrent.ThreadPoolExecutor.runWorker( > ThreadPoolExecutor.java:1142) > at java.util.concurrent.ThreadPoolExecutor$Worker.run( > ThreadPoolExecutor.java:617) > at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run( > TaskThread.java:61) > at java.lang.Thread.run(Thread.java:745) > Caused by: org.apache.openejb.SystemException: > javax.transaction.SystemException: > Error during two phase commit: Error during two phase commit > at org.apache.openejb.core.transaction.JtaTransactionPolicy. > completeTransaction(JtaTransactionPolicy.java:364) > at org.apache.openejb.core.transaction.TxRequired.commit( > TxRequired.java:76) > at org.apache.openejb.core.transaction.EjbTransactionUtil. > afterInvoke(EjbTransactionUtil.java:77) > at org.apache.openejb.core.stateless.StatelessContainer._ > invoke(StatelessContainer.java:271) > at org.apache.openejb.core.stateless.StatelessContainer. > invoke(StatelessContainer.java:212) > at org.apache.openejb.server.cxf.ejb.EjbMethodInvoker. > preEjbInvoke(EjbMethodInvoker.java:125) > ... 31 more > Caused by: javax.transaction.SystemException: Error during two phase > commit > at org.apache.geronimo.transaction.manager.TransactionImpl. > commitResource(TransactionImpl.java:683) > at org.apache.geronimo.transaction.manager.TransactionImpl.commit( > TransactionImpl.java:305) > at org.apache.geronimo.transaction.manager. > TransactionManagerImpl.commit(TransactionManagerImpl.java:252) > at org.apache.openejb.core.transaction.JtaTransactionPolicy. > completeTransaction(JtaTransactionPolicy.java:331) > ... 36 more > Caused by: javax.transaction.xa.XAException > at org.apache.openejb.resource.jdbc.managed.local. > LocalXAResource.commit(LocalXAResource.java:134) > at org.apache.geronimo.transaction.manager.TransactionImpl. > commitResource(TransactionImpl.java:627) > ... 39 more > Caused by: java.sql.SQLException: Could not retrieve transation read-only > status server > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:877) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:873) > at com.mysql.jdbc.ConnectionImpl.isReadOnly(ConnectionImpl. > java:3629) > at com.mysql.jdbc.ConnectionImpl.isReadOnly(ConnectionImpl. > java:3598) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke( > NativeMethodAccessorImpl.java:62) > at sun.reflect.DelegatingMethodAccessorImpl.invoke( > DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:498) > at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke( > ProxyConnection.java:126) > at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke( > JdbcInterceptor.java:108) > at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke( > DisposableConnectionFacade.java:81) > at com.sun.proxy.$Proxy61.isReadOnly(Unknown Source) > at org.apache.openejb.resource.jdbc.managed.local. > LocalXAResource.commit(LocalXAResource.java:130) > ... 40 more > Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: > Communications link failure > > > Attached is a basic test project with an EJB. I based it on an existing > TomEE example on github. The example shows that the EJB returns > successfully even though the commit should have failed. > > > > > On 2 May 2017 at 07:59, Romain Manni-Bucau <[email protected]> wrote: > >> Interesting since it tends to comfort the timeout issue. >> >> Can you try putting some aggressive db timeout? Or transaction manager >> timeout - default is 10mn, way too high for http. >> >> If still an issue I d apprecoate a small github project with a failling >> arquillian test with your idea if possible. >> >> Le 1 mai 2017 23:53, "Paul Carter-Brown" <[email protected] >> > >> a écrit : >> >> > Hi Romain, >> > >> > I'm struggling to think of a way to test this as it would involve >> modifying >> > code in TomEE core as part of the test. I found an easy-enough way is to >> > have a JAW-WS service with CMP that does some DB changes. Then at the >> end >> > of the business method just before returning, sleep for say 20s. When >> you >> > call the service, during those 20s, shut down the database. You should >> see >> > that although the commit fails due to the DB having gone away, the SOAP >> > service will respond successfully. >> > >> > On 1 May 2017 at 21:29, Romain Manni-Bucau <[email protected]> >> wrote: >> > >> > > then it should happen also with hsqldb and you can probably share a >> small >> > > sample on github. Main challenge is to write a small failling test. >> Will >> > > try to have a look in the week. >> > > >> > > PS: thought to a case it can happen and is not abnormal: a timeout. If >> > you >> > > timeout the EJB method is not cancelled so you get the response before >> > the >> > > commit but this is "normal". >> > > >> > > >> > > Romain Manni-Bucau >> > > @rmannibucau <https://twitter.com/rmannibucau> | Blog >> > > <https://blog-rmannibucau.rhcloud.com> | Old Blog >> > > <http://rmannibucau.wordpress.com> | Github <https://github.com/ >> > > rmannibucau> | >> > > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory >> > > <https://javaeefactory-rmannibucau.rhcloud.com> >> > > >> > > 2017-05-01 21:18 GMT+02:00 Paul Carter-Brown < >> > > [email protected]>: >> > > >> > > > Hi Romain, >> > > > >> > > > I modifed that class as follows: >> > > > >> > > > public void commit() throws ApplicationException, SystemException { >> > > > // only commit if we started the transaction >> > > > log.warn("In commit - sleeping for 3000ms"); >> > > > try { >> > > > Thread.sleep(3000); >> > > > } catch (Exception e) { >> > > > log.warn("Error in sleep"); >> > > > } >> > > > log.warn("Woke up from sleep"); >> > > > if (clientTx == null) { >> > > > log.warn("In commit - clientTx is null"); >> > > > completeTransaction(currentTx); >> > > > } else { >> > > > log.warn("In commit - clientTx is not null"); >> > > > fireNonTransactionalCompletion(); >> > > > } >> > > > } >> > > > >> > > > Here is the timing of the wireshark request/response: >> > > > 462 20:35:11.046374 10.0.1.57 -> 10.0.1.57 HTTP/XML 2124 POST >> > > > /IM/IdentityManager HTTP/1.1 >> > > > 464 20:35:11.082010 10.0.1.57 -> 10.0.1.57 HTTP/XML 384 >> HTTP/1.1 >> > > 200 >> > > > >> > > > My JMeter client reported a response time of 52ms on the SOAP call. >> > > > >> > > > And the TomEE logs: >> > > > >> > > > 2017/05/01 20:35:11.046 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorCh >> ain.add] >> > > > |Adding interceptor >> > > > org.apache.cxf.transport.https.CertConstraintsInterceptor@3a37dedb >> to >> > > > phase >> > > > pre-stream >> > > > 2017/05/01 20:35:11.047 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > outputChainToLog] >> > > > |Chain org.apache.cxf.phase.PhaseInterceptorChain@16d0091a was >> > created. >> > > > Current flow: >> > > > receive [PolicyInInterceptor, SaajInFaultInterceptor, >> > > > AttachmentInInterceptor] >> > > > pre-stream [CertConstraintsInterceptor] >> > > > post-stream [StaxInInterceptor] >> > > > read [SAAJPreInInterceptor, WSDLGetInterceptor, >> > ReadHeadersInterceptor, >> > > > SoapActionInInterceptor, StartBodyInterceptor] >> > > > pre-protocol [SAAJInInterceptor] >> > > > post-protocol [CheckFaultInterceptor, >> JAXBAttachmentSchemaValidation >> > > > Hack] >> > > > unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor] >> > > > pre-logical [OneWayProcessorInterceptor] >> > > > post-logical [WrapperClassInInterceptor] >> > > > pre-invoke [SwAInInterceptor, HolderInInterceptor] >> > > > invoke [ServiceInvokerInterceptor] >> > > > post-invoke [SaajInInterceptor, OutgoingChainInterceptor] >> > > > >> > > > ...... (further logs of incoming processing) >> > > > >> > > > 2017/05/01 20:35:11.081 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor$ >> > > > SoapOutEndingInterceptor@1f0dd756 >> > > > 2017/05/01 20:35:11.081 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.cxf.binding.soap.saaj.SAAJOutInterceptor$ >> > > > SAAJOutEndingInterceptor@720f2664 >> > > > 2017/05/01 20:35:11.081 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.cxf.interceptor.StaxOutEndingInterceptor@3b5f0e7e >> > > > 2017/05/01 20:35:11.081 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.cxf.interceptor.MessageSenderInterceptor$ >> > > > MessageSenderEndingInterceptor@6ae1d81a >> > > > >> > > > *2017/05/01 20:35:11.082 WARNING >> > > > [TomEE-Exec-12][206][org.apache.openejb.core. >> > > > transaction.TxRequired.commit] >> > > > |In commit - sleeping for 3000ms* >> > > > *2017/05/01 20:35:14.082 WARNING >> > > > [TomEE-Exec-12][206][org.apache.openejb.core. >> > > > transaction.TxRequired.commit] >> > > > |Woke up from sleep* >> > > > 2017/05/01 20:35:14.082 WARNING >> > > > [TomEE-Exec-12][206][org.apache.openejb.core. >> > > > transaction.TxRequired.commit] >> > > > |In commit - clientTx is null >> > > > 2017/05/01 20:35:14.083 FINE >> > > > [TomEE-Exec-12][206][com.smilecoms.commons.base.lifecycle. >> > > > SmileConnectionLifecycleInterceptor.transactionBegun] >> > > > |TransactionBegun called on [com.mysql.jdbc.JDBC4Connectio >> n@7d0cc890] >> > > > 2017/05/01 20:35:14.083 FINE >> > > > [TomEE-Exec-12][206][com.smilecoms.commons.base.lifecycle. >> > > > SmileConnectionLifecycleInterceptor.commit] >> > > > |Commit called on [com.mysql.jdbc.JDBC4Connection@7d0cc890] >> > > > 2017/05/01 20:35:14.083 FINE >> > > > [TomEE-Exec-12][206][com.smilecoms.commons.base.lifecycle. >> > > > SmileConnectionLifecycleInterceptor.commit] >> > > > |Stack: >> > > > java.lang.Exception >> > > > at >> > > > com.smilecoms.commons.base.lifecycle.SmileConnectionLifecycleInterc >> > > > eptor.commit(SmileConnectionLifecycleInterceptor.java:34) >> > > > at com.mysql.jdbc.ConnectionImpl$ >> > 2.forEach(ConnectionImpl.java: >> > > > 1593) >> > > > at com.mysql.jdbc.ConnectionImpl$ >> > 2.forEach(ConnectionImpl.java: >> > > > 1592) >> > > > at com.mysql.jdbc.IterateBlock.do >> ForAll(IterateBlock.java:61) >> > > > at com.mysql.jdbc.ConnectionImpl. >> commit(ConnectionImpl.java: >> > > 1599) >> > > > at sun.reflect.GeneratedMethodAccessor145.invoke(Unknown >> > Source) >> > > > at >> > > > sun.reflect.DelegatingMethodAccessorImpl.invoke( >> > > > DelegatingMethodAccessorImpl.java:43) >> > > > at java.lang.reflect.Method.invoke(Method.java:498) >> > > > at >> > > > org.apache.tomcat.jdbc.pool.ProxyConnection.invoke( >> > > > ProxyConnection.java:126) >> > > > at >> > > > org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke( >> > > > JdbcInterceptor.java:108) >> > > > at >> > > > org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke( >> > > > DisposableConnectionFacade.java:81) >> > > > at com.sun.proxy.$Proxy58.commit(Unknown Source) >> > > > at >> > > > org.apache.openejb.resource.jdbc.managed.local.LocalXAResour >> ce.commit( >> > > > LocalXAResource.java:131) >> > > > at >> > > > org.apache.geronimo.transaction.manager.TransactionImpl. >> > commitResource( >> > > > TransactionImpl.java:627) >> > > > at >> > > > org.apache.geronimo.transaction.manager.TransactionImpl.commit( >> > > > TransactionImpl.java:305) >> > > > at >> > > > org.apache.geronimo.transaction.manager.TransactionManagerIm >> pl.commit( >> > > > TransactionManagerImpl.java:252) >> > > > at >> > > > org.apache.openejb.core.transaction.JtaTransactionPolicy. >> > > > completeTransaction(JtaTransactionPolicy.java:331) >> > > > at >> > > > org.apache.openejb.core.transaction.TxRequired.commit( >> > > TxRequired.java:91) >> > > > at >> > > > org.apache.openejb.core.transaction.EjbTransactionUtil.afterInvoke( >> > > > EjbTransactionUtil.java:77) >> > > > at >> > > > org.apache.openejb.core.stateless.StatelessContainer._ >> > > > invoke(StatelessContainer.java:271) >> > > > at >> > > > org.apache.openejb.core.stateless.StatelessContainer. >> > > > invoke(StatelessContainer.java:212) >> > > > at >> > > > org.apache.openejb.server.cxf.ejb.EjbMethodInvoker. >> > > > preEjbInvoke(EjbMethodInvoker.java:125) >> > > > at >> > > > org.apache.openejb.server.cxf.ejb.EjbMethodInvoker.invoke( >> > > > EjbMethodInvoker.java:82) >> > > > at >> > > > org.apache.cxf.interceptor.ServiceInvokerInterceptor$1. >> > > > run(ServiceInvokerInterceptor.java:59) >> > > > at >> > > > java.util.concurrent.Executors$RunnableAdapter. >> > call(Executors.java:511) >> > > > at java.util.concurrent.FutureTask.run(FutureTask.java:266) >> > > > at >> > > > org.apache.cxf.interceptor.ServiceInvokerInterceptor$2. >> > > > run(ServiceInvokerInterceptor.java:126) >> > > > at >> > > > org.apache.cxf.workqueue.SynchronousExecutor.execute( >> > > > SynchronousExecutor.java:37) >> > > > at >> > > > org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage( >> > > > ServiceInvokerInterceptor.java:131) >> > > > at >> > > > org.apache.cxf.phase.PhaseInterceptorChain.doIntercept( >> > > > PhaseInterceptorChain.java:308) >> > > > at >> > > > org.apache.cxf.transport.ChainInitiationObserver.onMessage( >> > > > ChainInitiationObserver.java:121) >> > > > at >> > > > org.apache.cxf.transport.http.AbstractHTTPDestination.invoke( >> > > > AbstractHTTPDestination.java:262) >> > > > at >> > > > org.apache.openejb.server.cxf.CxfWsContainer.onMessage( >> > > > CxfWsContainer.java:85) >> > > > at >> > > > org.apache.openejb.server.webservices.WsServlet.service( >> > > WsServlet.java:98) >> > > > at >> > > > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter( >> > > > ApplicationFilterChain.java:230) >> > > > at >> > > > org.apache.catalina.core.ApplicationFilterChain.doFilter( >> > > > ApplicationFilterChain.java:165) >> > > > at >> > > > org.apache.catalina.core.StandardWrapperValve.invoke( >> > > > StandardWrapperValve.java:198) >> > > > at >> > > > org.apache.catalina.core.StandardContextValve.invoke( >> > > > StandardContextValve.java:96) >> > > > at >> > > > org.apache.catalina.core.StandardHostValve.invoke( >> > > > StandardHostValve.java:140) >> > > > at >> > > > org.apache.catalina.valves.ErrorReportValve.invoke( >> > > > ErrorReportValve.java:79) >> > > > at >> > > > org.apache.tomee.catalina.OpenEJBSecurityListener$ >> > > RequestCapturer.invoke( >> > > > OpenEJBSecurityListener.java:97) >> > > > at >> > > > org.apache.catalina.core.StandardEngineValve.invoke( >> > > > StandardEngineValve.java:87) >> > > > at >> > > > org.apache.catalina.connector.CoyoteAdapter.service( >> > > > CoyoteAdapter.java:349) >> > > > at >> > > > org.apache.coyote.http11.Http11Processor.service( >> > > Http11Processor.java:783) >> > > > at >> > > > org.apache.coyote.AbstractProcessorLight.process( >> > > > AbstractProcessorLight.java:66) >> > > > at >> > > > org.apache.coyote.AbstractProtocol$ConnectionHandler.process( >> > > > AbstractProtocol.java:798) >> > > > at >> > > > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor. >> > > > doRun(NioEndpoint.java:1434) >> > > > at >> > > > org.apache.tomcat.util.net.SocketProcessorBase.run( >> > > > SocketProcessorBase.java:49) >> > > > at >> > > > java.util.concurrent.ThreadPoolExecutor.runWorker( >> > > > ThreadPoolExecutor.java:1142) >> > > > at >> > > > java.util.concurrent.ThreadPoolExecutor$Worker.run( >> > > > ThreadPoolExecutor.java:617) >> > > > at >> > > > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run( >> > > > TaskThread.java:61) >> > > > at java.lang.Thread.run(Thread.java:745) >> > > > >> > > > 2017/05/01 20:35:14.084 FINE >> > > > [TomEE-Exec-12][206][com.smilecoms.commons.base.lifecycle. >> > > > SmileConnectionLifecycleInterceptor.transactionCompleted] >> > > > |TransactionCompleted called on [com.mysql.jdbc. >> > JDBC4Connection@7d0cc890 >> > > ] >> > > > 2017/05/01 20:35:14.084 WARNING >> > > > [TomEE-Exec-12][206][org.apache.openejb.core.transaction. >> TxRequired. >> > > > getCurrentTransaction] >> > > > |In getCurrentTransaction >> > > > 2017/05/01 20:35:14.084 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.openejb.server.cxf.client.SaajInInterceptor@3374eec1 >> > > > 2017/05/01 20:35:14.085 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.cxf.interceptor.OutgoingChainInterceptor@62316059 >> > > > 2017/05/01 20:35:14.085 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorCh >> ain.add] >> > > > |Adding interceptor >> > > > org.apache.cxf.transport.https.CertConstraintsInterceptor@3a37dedb >> to >> > > > phase >> > > > pre-stream >> > > > 2017/05/01 20:35:14.085 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > outputChainToLog] >> > > > |Chain org.apache.cxf.phase.PhaseInterceptorChain@301c8187 was >> > created. >> > > > Current flow: >> > > > receive [PolicyInInterceptor, SaajInFaultInterceptor, >> > > > AttachmentInInterceptor] >> > > > pre-stream [CertConstraintsInterceptor] >> > > > post-stream [StaxInInterceptor] >> > > > read [SAAJPreInInterceptor, WSDLGetInterceptor, >> > ReadHeadersInterceptor, >> > > > SoapActionInInterceptor, StartBodyInterceptor] >> > > > pre-protocol [SAAJInInterceptor] >> > > > post-protocol [CheckFaultInterceptor, >> JAXBAttachmentSchemaValidation >> > > > Hack] >> > > > unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor] >> > > > pre-logical [OneWayProcessorInterceptor] >> > > > post-logical [WrapperClassInInterceptor] >> > > > pre-invoke [SwAInInterceptor, HolderInInterceptor] >> > > > invoke [ServiceInvokerInterceptor] >> > > > post-invoke [SaajInInterceptor, OutgoingChainInterceptor] >> > > > >> > > > 2017/05/01 20:35:14.085 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.cxf.ws.policy.PolicyInInterceptor@6c760041 >> > > > 2017/05/01 20:35:14.085 FINE >> > > > [TomEE-Exec-12][206][org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept] >> > > > |Invoking handleMessage on interceptor >> > > > org.apache.openejb.server.cxf.client.SaajInFaultInterceptor@4d50ee8 >> > > > >> > > > >> > > > So this 100% confirms that the transaction is committed after the >> > > response >> > > > has been sent. I think this bug has major implications on ACID >> > > compliance. >> > > > I also checked on 7.0.2 and found the same behavior. >> > > > >> > > > Paul >> > > > >> > > > On 29 April 2017 at 09:57, Romain Manni-Bucau < >> [email protected]> >> > > > wrote: >> > > > >> > > > > Ps: >> > > > > https://github.com/apache/tomee/blob/master/container/ >> > > > > openejb-core/src/main/java/org/apache/openejb/core/ >> > > > > transaction/TxRequired.java >> > > > > >> > > > > Le 29 avr. 2017 09:55, "Romain Manni-Bucau" < >> [email protected]> >> > a >> > > > > écrit : >> > > > > >> > > > > > Should be before. You can put breakpoint/logs in TxPolicy and >> your >> > > ejb >> > > > > > >> > > > > > Le 29 avr. 2017 00:44, "Paul Carter-Brown" >> > > > <paul.carter-brown@smilecoms. >> > > > > > com> a écrit : >> > > > > > >> > > > > >> Hi Romain, >> > > > > >> >> > > > > >> A quick update. I put cxf logging on and for a typical message >> > > > exchange >> > > > > >> for >> > > > > >> a JAX-WS service backed by an EJB.At the same time I ran a >> > wireshark >> > > > on >> > > > > >> the >> > > > > >> server to see the network traffic. This is for a single call >> under >> > > no >> > > > > >> concurrency so you can easily verify yourself with any SOAP >> > service >> > > in >> > > > > >> TomEE: >> > > > > >> >> > > > > >> 1438 00:09:05.510294 10.0.1.57 -> 10.0.1.57 HTTP/XML 1223 >> > POST >> > > > > >> /IM/IdentityManager HTTP/1.1 >> > > > > >> 1439 00:09:05.510436 10.0.1.57 -> 10.0.1.57 TCP 68 >> mcreport >> > > >> > > > > 40929 >> > > > > >> [ACK] Seq=1721 Ack=7983 Win=323456 Len=0 TSval=70303912 >> > > TSecr=70303912 >> > > > > >> 1440 00:09:05.527410 10.0.1.57 -> 10.0.1.57 HTTP/XML 1852 >> > > > HTTP/1.1 >> > > > > >> 200 >> > > > > >> 1441 00:09:05.527453 10.0.1.57 -> 10.0.1.57 TCP 68 40929 >> > >> > > > > mcreport >> > > > > >> [ACK] Seq=7983 Ack=3505 Win=178944 Len=0 TSval=70303916 >> > > TSecr=70303916 >> > > > > >> >> > > > > >> So at 00:09:05.510 the server got the request. Here are the >> server >> > > > logs >> > > > > >> verifying this: >> > > > > >> >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase. >> > > PhaseInterceptorChain.add] >> > > > > >> |Adding interceptor >> > > > > >> org.apache.cxf.transport.https.CertConstraintsInterceptor@ >> > 64623f81 >> > > to >> > > > > >> phase >> > > > > >> pre-stream >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.outputChainToLog] >> > > > > >> |Chain org.apache.cxf.phase.PhaseInterceptorChain@713d71d3 was >> > > > created. >> > > > > >> Current flow: >> > > > > >> receive [PolicyInInterceptor, SaajInFaultInterceptor, >> > > > > >> AttachmentInInterceptor] >> > > > > >> pre-stream [CertConstraintsInterceptor] >> > > > > >> post-stream [StaxInInterceptor] >> > > > > >> read [SAAJPreInInterceptor, WSDLGetInterceptor, >> > > > > ReadHeadersInterceptor, >> > > > > >> SoapActionInInterceptor, StartBodyInterceptor] >> > > > > >> pre-protocol [SAAJInInterceptor] >> > > > > >> post-protocol [CheckFaultInterceptor, >> > > JAXBAttachmentSchemaValidation >> > > > > >> Hack] >> > > > > >> unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor] >> > > > > >> pre-logical [OneWayProcessorInterceptor] >> > > > > >> post-logical [WrapperClassInInterceptor] >> > > > > >> pre-invoke [SwAInInterceptor, HolderInInterceptor] >> > > > > >> invoke [ServiceInvokerInterceptor] >> > > > > >> post-invoke [SaajInInterceptor, OutgoingChainInterceptor] >> > > > > >> >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.ws.policy.PolicyInInterceptor@1e78ace6 >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.openejb.server.cxf.client.SaajInFaultInterceptor@ >> > > 1338d078 >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.interceptor.AttachmentInInterceptor@5dea89fc >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.transport.https.CertConstraintsInterceptor@ >> > 64623f81 >> > > > > >> 2017/04/29 00:09:05.510 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.interceptor.StaxInInterceptor@647520af >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase. >> > > PhaseInterceptorChain.add] >> > > > > >> |Adding interceptor >> > > > > >> org.apache.cxf.interceptor.StaxInEndingInterceptor@39dd4830 to >> > > phase >> > > > > >> pre-invoke >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.outputChainToLog] >> > > > > >> |Chain org.apache.cxf.phase.PhaseInterceptorChain@713d71d3 was >> > > > > modified. >> > > > > >> Current flow: >> > > > > >> receive [PolicyInInterceptor, SaajInFaultInterceptor, >> > > > > >> AttachmentInInterceptor] >> > > > > >> pre-stream [CertConstraintsInterceptor] >> > > > > >> post-stream [StaxInInterceptor] >> > > > > >> read [SAAJPreInInterceptor, WSDLGetInterceptor, >> > > > > ReadHeadersInterceptor, >> > > > > >> SoapActionInInterceptor, StartBodyInterceptor] >> > > > > >> pre-protocol [SAAJInInterceptor] >> > > > > >> post-protocol [CheckFaultInterceptor, >> > > JAXBAttachmentSchemaValidation >> > > > > >> Hack] >> > > > > >> unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor] >> > > > > >> pre-logical [OneWayProcessorInterceptor] >> > > > > >> post-logical [WrapperClassInInterceptor] >> > > > > >> pre-invoke [StaxInEndingInterceptor, SwAInInterceptor, >> > > > > >> HolderInInterceptor] >> > > > > >> invoke [ServiceInvokerInterceptor] >> > > > > >> post-invoke [SaajInInterceptor, OutgoingChainInterceptor] >> > > > > >> >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.saaj.SAAJInInterceptor$SAAJPreIn >> > > > > >> Interceptor@6c33f463 >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.frontend.WSDLGetInterceptor@11c0446f >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.interceptor. >> > > > ReadHeadersInterceptor@be15cc5 >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.interceptor.SoapActionInIntercep >> tor@ >> > > > > 79836009 >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.interceptor. >> > > StartBodyInterceptor@70afa3ac >> > > > > >> 2017/04/29 00:09:05.511 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.saaj.SAAJInInterceptor@3d12954e >> > > > > >> ..... >> > > > > >> >> > > > > >> Now lets look at the server logs around the time the response >> goes >> > > > back >> > > > > >> and >> > > > > >> also see where the commit was issued: >> > > > > >> >> > > > > >> 2017/04/29 00:09:05.523 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.jaxws.handler.logical.LogicalHandlerOutInterc >> > > > > >> eptor@128bf90f >> > > > > >> 2017/04/29 00:09:05.523 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.wsdl.interceptors.BareOutInterceptor@62b3ecb1 >> > > > > >> 2017/04/29 00:09:05.524 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.jaxws.handler.soap.SOAPHandlerInterceptor$1@ >> > 900b115 >> > > > > >> *2017/04/29 00:09:05.527 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor$S >> > > > > >> oapOutEndingInterceptor@10aa05f4* >> > > > > >> 2017/04/29 00:09:05.527 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.binding.soap.saaj.SAAJOutInterceptor$SAAJOutE >> > > > > >> ndingInterceptor@66cac58b >> > > > > >> 2017/04/29 00:09:05.527 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.interceptor.StaxOutEndingInterceptor@3304ff7d >> > > > > >> 2017/04/29 00:09:05.527 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.interceptor.MessageSenderInterceptor$MessageS >> > > > > >> enderEndingInterceptor@674adcf8 >> > > > > >> 2017/04/29 00:09:05.529 FINE >> > > > > >> [TomEE-Exec-30][224][com.smilecoms.commons.base.lifecycle.S >> > > > > >> mileConnectionLifecycleInterceptor.commit] >> > > > > >> |Commit called on [com.mysql.jdbc.JDBC4Connection@314c8b4a] >> > > > > >> 2017/04/29 00:09:05.529 FINE >> > > > > >> [TomEE-Exec-30][224][com.smilecoms.commons.base.lifecycle.S >> > > > > >> mileConnectionLifecycleInterceptor.commit] >> > > > > >> |Stack: >> > > > > >> java.lang.Exception >> > > > > >> at >> > > > > >> com.smilecoms.commons.base.lifecycle.SmileConnectionLifecycl >> > > > > >> eInterceptor.commit(SmileConnectionLifecycleInterceptor. >> java:34) >> > > > > >> at com.mysql.jdbc.ConnectionImpl$ >> > > > 2.forEach(ConnectionImpl.java: >> > > > > >> 1593) >> > > > > >> at com.mysql.jdbc.ConnectionImpl$ >> > > > 2.forEach(ConnectionImpl.java: >> > > > > >> 1592) >> > > > > >> at com.mysql.jdbc.IterateBlock. >> > > doForAll(IterateBlock.java:61) >> > > > > >> at com.mysql.jdbc.ConnectionImpl. >> > > commit(ConnectionImpl.java: >> > > > > 1599) >> > > > > >> at sun.reflect.GeneratedMethodAcc >> essor138.invoke(Unknown >> > > > > Source) >> > > > > >> at >> > > > > >> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMe >> > > > > >> thodAccessorImpl.java:43) >> > > > > >> at java.lang.reflect.Method.invoke(Method.java:498) >> > > > > >> at >> > > > > >> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConn >> > > > > >> ection.java:126) >> > > > > >> at >> > > > > >> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInter >> > > > > >> ceptor.java:108) >> > > > > >> at >> > > > > >> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invok >> > > > > >> e(DisposableConnectionFacade.java:81) >> > > > > >> at com.sun.proxy.$Proxy58.commit(Unknown Source) >> > > > > >> at >> > > > > >> org.apache.openejb.resource.jdbc.managed.local.LocalXAResour >> > > > > >> ce.commit(LocalXAResource.java:131) >> > > > > >> at >> > > > > >> org.apache.geronimo.transaction.manager.TransactionImpl.comm >> > > > > >> itResource(TransactionImpl.java:627) >> > > > > >> at >> > > > > >> org.apache.geronimo.transaction.manager.TransactionImpl. >> > > > > >> commit(TransactionImpl.java:305) >> > > > > >> at >> > > > > >> org.apache.geronimo.transaction.manager.TransactionManagerIm >> > > > > >> pl.commit(TransactionManagerImpl.java:252) >> > > > > >> at >> > > > > >> org.apache.openejb.core.transaction.JtaTransactionPolicy.com >> > > > > >> pleteTransaction(JtaTransactionPolicy.java:331) >> > > > > >> at >> > > > > >> org.apache.openejb.core.transaction.TxRequired.commit( >> > > > > TxRequired.java:76) >> > > > > >> at >> > > > > >> org.apache.openejb.core.transaction.EjbTransactionUtil.after >> > > > > >> Invoke(EjbTransactionUtil.java:77) >> > > > > >> at >> > > > > >> org.apache.openejb.core.stateless.StatelessContainer._invoke >> > > > > >> (StatelessContainer.java:271) >> > > > > >> at >> > > > > >> org.apache.openejb.core.stateless.StatelessContainer.invoke( >> > > > > >> StatelessContainer.java:212) >> > > > > >> at >> > > > > >> org.apache.openejb.server.cxf.ejb.EjbMethodInvoker.preEjbInv >> > > > > >> oke(EjbMethodInvoker.java:125) >> > > > > >> at >> > > > > >> org.apache.openejb.server.cxf.ejb.EjbMethodInvoker.invoke(Ej >> > > > > >> bMethodInvoker.java:82) >> > > > > >> at >> > > > > >> org.apache.cxf.service.invoker.AbstractInvoker.invoke( >> > > > > >> AbstractInvoker.java:74) >> > > > > >> at >> > > > > >> org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run( >> > > > > >> ServiceInvokerInterceptor.java:59) >> > > > > >> at >> > > > > >> java.util.concurrent.Executors$RunnableAdapter. >> > > > call(Executors.java:511) >> > > > > >> at java.util.concurrent.FutureTask.run(FutureTask. >> > java:266) >> > > > > >> at >> > > > > >> org.apache.cxf.interceptor.ServiceInvokerInterceptor$2.run( >> > > > > >> ServiceInvokerInterceptor.java:126) >> > > > > >> at >> > > > > >> org.apache.cxf.workqueue.SynchronousExecutor.execute(Synchro >> > > > > >> nousExecutor.java:37) >> > > > > >> at >> > > > > >> org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleM >> > > > > >> essage(ServiceInvokerInterceptor.java:131) >> > > > > >> at >> > > > > >> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(Phase >> > > > > >> InterceptorChain.java:308) >> > > > > >> at >> > > > > >> org.apache.cxf.transport.ChainInitiationObserver.onMessage(C >> > > > > >> hainInitiationObserver.java:121) >> > > > > >> at >> > > > > >> org.apache.cxf.transport.http.AbstractHTTPDestination.invoke >> > > > > >> (AbstractHTTPDestination.java:262) >> > > > > >> at >> > > > > >> org.apache.openejb.server.cxf.CxfWsContainer.onMessage(CxfWs >> > > > > >> Container.java:85) >> > > > > >> at >> > > > > >> org.apache.openejb.server.webservices.WsServlet.service(WsSe >> > > > > >> rvlet.java:98) >> > > > > >> at >> > > > > >> org.apache.catalina.core.ApplicationFilterChain.internalDoFi >> > > > > >> lter(ApplicationFilterChain.java:230) >> > > > > >> at >> > > > > >> org.apache.catalina.core.ApplicationFilterChain.doFilter(App >> > > > > >> licationFilterChain.java:165) >> > > > > >> at >> > > > > >> org.apache.catalina.core.StandardWrapperValve.invoke(Standar >> > > > > >> dWrapperValve.java:198) >> > > > > >> at >> > > > > >> org.apache.catalina.core.StandardContextValve.invoke(Standar >> > > > > >> dContextValve.java:96) >> > > > > >> at >> > > > > >> org.apache.catalina.core.StandardHostValve.invoke(StandardHo >> > > > > >> stValve.java:140) >> > > > > >> at >> > > > > >> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorRepo >> > > > > >> rtValve.java:79) >> > > > > >> at >> > > > > >> org.apache.tomee.catalina.OpenEJBSecurityListener$RequestCap >> > > > > >> turer.invoke(OpenEJBSecurityListener.java:97) >> > > > > >> at >> > > > > >> org.apache.catalina.core.StandardEngineValve.invoke(Standard >> > > > > >> EngineValve.java:87) >> > > > > >> at >> > > > > >> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAd >> > > > > >> apter.java:349) >> > > > > >> at >> > > > > >> org.apache.coyote.http11.Http11Processor.service(Http11Proce >> > > > > >> ssor.java:783) >> > > > > >> at >> > > > > >> org.apache.coyote.AbstractProcessorLight.process(AbstractPro >> > > > > >> cessorLight.java:66) >> > > > > >> at >> > > > > >> org.apache.coyote.AbstractProtocol$ConnectionHandler. >> > > > > >> process(AbstractProtocol.java:798) >> > > > > >> at >> > > > > >> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun >> > > > > >> (NioEndpoint.java:1434) >> > > > > >> at >> > > > > >> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketPro >> > > > > >> cessorBase.java:49) >> > > > > >> at >> > > > > >> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool >> > > > > >> Executor.java:1142) >> > > > > >> at >> > > > > >> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo >> > > > > >> lExecutor.java:617) >> > > > > >> at >> > > > > >> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable. >> > > > > >> run(TaskThread.java:61) >> > > > > >> at java.lang.Thread.run(Thread.java:745) >> > > > > >> >> > > > > >> 2017/04/29 00:09:05.529 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.openejb.server.cxf.client.SaajInInterceptor@41aa4 >> e75 >> > > > > >> 2017/04/29 00:09:05.530 FINE >> > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC >> > > > > >> hain.doIntercept] >> > > > > >> |Invoking handleMessage on interceptor >> > > > > >> org.apache.cxf.interceptor.OutgoingChainInterceptor@564ef482 >> > > > > >> >> > > > > >> >> > > > > >> From what I can gather from the source, the SOAP document is >> > flushed >> > > > on >> > > > > >> the >> > > > > >> socket in SoapOutEndingInterceptor which I have put in bold. >> This >> > > also >> > > > > >> corresponds with the wireshark timing >> > > > > >> >> > > > > >> The class looks like this: >> > > > > >> >> > > > > >> public class SoapOutEndingInterceptor extends >> > > AbstractSoapInterceptor >> > > > { >> > > > > >> 269 public SoapOutEndingInterceptor() { >> > > > > >> 270 super(SoapOutEndingInterceptor. >> > class.getName(), >> > > > > >> Phase.WRITE_ENDING); 271 } >> > > > > >> 272 >> > > > > >> 273 public void handleMessage(SoapMessage message) >> > > throws >> > > > > >> Fault { >> > > > > >> 274 SoapVersion soapVersion = >> > message.getVersion(); >> > > > > >> 275 try { >> > > > > >> 276 XMLStreamWriter xtw = >> > > > > >> message.getContent(XMLStreamWriter.class); >> > > > > >> 277 if (xtw != null) { >> > > > > >> 278 xtw.writeEndElement(); >> > > > > >> 279 // Write Envelope end element >> > > > > >> 280 xtw.writeEndElement(); 281 >> > > > > >> xtw.writeEndDocument(); >> > > > > >> 282 >> > > > > >> 283 xtw.flush(); >> > > > > >> 284 } >> > > > > >> 285 } catch (XMLStreamException e) { >> > > > > >> 286 throw new SoapFault(new >> > > > > >> org.apache.cxf.common.i18n.Message("XML_WRITE_EXC", BUNDLE), >> e, >> > > > > >> 287 >> > > soapVersion.getSender()); >> > > > > >> 288 } >> > > > > >> 289 } >> > > > > >> 290 } >> > > > > >> >> > > > > >> >> > > > > >> The commit is only called via MessageSenderInterceptor but from >> > the >> > > > > stack >> > > > > >> trace I can't quite work out how ServiceInvokerInterceptor is >> > called >> > > > > from >> > > > > >> MessageSenderInterceptor so I can't explain the stack trace of >> the >> > > > > commit >> > > > > >> call unless it's some fancy context switching and use of >> > completable >> > > > > >> futures >> > > > > >> >> > > > > >> Any ideas what's going on? >> > > > > >> >> > > > > >> >> > > > > >> Paul >> > > > > >> >> > > > > >> On 27 April 2017 at 10:39, Paul Carter-Brown < >> > > > > >> [email protected]> wrote: >> > > > > >> >> > > > > >> > For sure. I will start by pulling openejb source and digging >> in >> > > for >> > > > > >> > possible causes. A few log lines here and there and im sure i >> > can >> > > > find >> > > > > >> it >> > > > > >> > >> > > > > >> > Paul >> > > > > >> > >> > > > > >> > Sent from my phone. Message may be brief and contain typos. >> > > > > >> > >> > > > > >> > >> > > > > >> > On 27 Apr 2017 10:25 a.m., "Romain Manni-Bucau" < >> > > > > [email protected]> >> > > > > >> > wrote: >> > > > > >> > >> > > > > >> > ant / gradle are other options but something not IDE related >> > > please >> > > > > (or >> > > > > >> you >> > > > > >> > take the risk noone will be able to run it ;)) >> > > > > >> > >> > > > > >> > >> > > > > >> > Romain Manni-Bucau >> > > > > >> > @rmannibucau <https://twitter.com/rmannibucau> | Blog >> > > > > >> > <https://blog-rmannibucau.rhcloud.com> | Old Blog >> > > > > >> > <http://rmannibucau.wordpress.com> | Github < >> > > > > >> https://github.com/rmannibuca >> > > > > >> > u> | >> > > > > >> > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE >> > > Factory >> > > > > >> > <https://javaeefactory-rmannibucau.rhcloud.com> >> > > > > >> > >> > > > > >> > 2017-04-27 9:48 GMT+02:00 Paul Carter-Brown >> > > > > >> <[email protected] >> > > > > >> > om >> > > > > >> > >: >> > > > > >> > >> > > > > >> > > Will see what I can do to reproduce for you. Maven and I do >> > not >> > > > get >> > > > > >> one >> > > > > >> > > well :-( >> > > > > >> > > >> > > > > >> > > >> > > > > >> > > >> > > > > >> > > On 27 April 2017 at 09:30, Romain Manni-Bucau < >> > > > > [email protected]> >> > > > > >> > > wrote: >> > > > > >> > > >> > > > > >> > > > Ok, at that point maybe try to reproduce it on a small >> > sample >> > > on >> > > > > >> > github - >> > > > > >> > > > goal is to share with us your setup more or less but not >> > > > > >> confidential >> > > > > >> > > data. >> > > > > >> > > > >> > > > > >> > > > You can use: >> > > > > >> > > > >> > > > > >> > > > <dependency> >> > > > > >> > > > <groupId>com.wix</groupId> >> > > > > >> > > > <artifactId>wix-embedded-mysql</artifactId> >> > > > > >> > > > <version>2.1.4</version> >> > > > > >> > > > </dependency> >> > > > > >> > > > >> > > > > >> > > > And in java: >> > > > > >> > > > >> > > > > >> > > > >> > > > > >> > > > EmbeddedMysql.anEmbeddedMysql(MysqldConfig >> > > > > >> > > > .aMysqldConfig(Version.v5_7_17) >> > > > > >> > > > .withPort(Integer.parseInt(port)) >> > > > > >> > > > .withUser("user", "pass") >> > > > > >> > > > .build()); >> > > > > >> > > > final EmbeddedMysql mysql = builder.start() >> > > > > >> > > > .addSchema(SchemaConfig. >> > > aSchemaConfig("test").build()); >> > > > > >> > > > >> > > > > >> > > > >> > > > > >> > > > To write a test with a running MySQL (first time you >> launch >> > it >> > > > > >> > downloads >> > > > > >> > > > mysql so it can be a bit long but then it is cached. >> > > > > >> > > > >> > > > > >> > > > This way we could grab it locally and investigate a bit >> > more. >> > > > > >> > > > >> > > > > >> > > > Romain Manni-Bucau >> > > > > >> > > > @rmannibucau <https://twitter.com/rmannibucau> | Blog >> > > > > >> > > > <https://blog-rmannibucau.rhcloud.com> | Old Blog >> > > > > >> > > > <http://rmannibucau.wordpress.com> | Github < >> > > > > >> > > https://github.com/rmannibuca >> > > > > >> > > > u> | >> > > > > >> > > > LinkedIn <https://www.linkedin.com/in/rmannibucau> | >> JavaEE >> > > > > Factory >> > > > > >> > > > <https://javaeefactory-rmannibucau.rhcloud.com> >> > > > > >> > > > >> > > > > >> > > > 2017-04-27 6:06 GMT+02:00 Paul Carter-Brown >> > > > > >> > > <[email protected] >> > > > > >> > > > om >> > > > > >> > > > >: >> > > > > >> > > > >> > > > > >> > > > > No. Autocommit is off >> > > > > >> > > > > >> > > > > >> > > > > Paul >> > > > > >> > > > > >> > > > > >> > > > > Sent from my phone. Message may be brief and contain >> > typos. >> > > > > >> > > > > >> > > > > >> > > > > >> > > > > >> > > > > On 27 Apr 2017 12:47 a.m., "Romain Manni-Bucau" < >> > > > > >> > [email protected] >> > > > > >> > > > >> > > > > >> > > > > wrote: >> > > > > >> > > > > >> > > > > >> > > > > > Are you in autocommit mode? >> > > > > >> > > > > > >> > > > > >> > > > > > Le 26 avr. 2017 22:37, "Paul Carter-Brown" >> > > > > >> > > > <paul.carter-brown@smilecoms. >> > > > > >> > > > > > com> >> > > > > >> > > > > > a écrit : >> > > > > >> > > > > > >> > > > > >> > > > > > > Hi, >> > > > > >> > > > > > > >> > > > > >> > > > > > > Unfortunately, the same result with dbcp2. I also >> > turned >> > > > on >> > > > > >> mysql >> > > > > >> > > > > general >> > > > > >> > > > > > > query log and can see the commit come through after >> > the >> > > > > select >> > > > > >> > > comes >> > > > > >> > > > in >> > > > > >> > > > > > on >> > > > > >> > > > > > > another connection: >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > 2017-04-26T19:46:22.243742Z 20038 Query INSERT INTO >> > > > > >> > > > > > > SmileDB.customer_profile ... <removed> >> > > > > >> > > > > > > 2017-04-26T19:46:22.245984Z 20038 Query SELECT >> > > > > >> LAST_INSERT_ID() >> > > > > >> > > > > > > 2017-04-26T19:46:22.291193Z 20038 Query select >> > > > > >> > > @@session.tx_read_only >> > > > > >> > > > > > > 2017-04-26T19:46:22.317914Z 20031 Query >> SET >> > > > > >> autocommit=0 >> > > > > >> > > > > > > 2017-04-26T19:46:22.318088Z 20031 Query >> > SELECT >> > > * >> > > > > FROM >> > > > > >> > > > > > > SmileDB.customer_profile WHERE >> > > CUSTOMER_PROFILE_ID=1267253 >> > > > > AND >> > > > > >> > > > > > STATUS='AC' >> > > > > >> > > > > > > 2017-04-26T19:46:22.372481Z 20038 Query commit >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > And here is the log of the lifecycle listener >> getting >> > > > commit >> > > > > >> > > called: >> > > > > >> > > > > > > >> > > > > >> > > > > > > 2017/04/26 21:46:22.293 FINE >> > > [TomEE-Exec-31][301][com. >> > > > > >> > > > > > > smilecoms.commons.base.lifecycle. >> > > > > SmileConnectionLifecycleInt >> > > > > >> erc >> > > > > >> > > > > > > eptor.commit] >> > > > > >> > > > > > > |Commit called >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > On 26 April 2017 at 17:12, Romain Manni-Bucau < >> > > > > >> > > [email protected] >> > > > > >> > > > > >> > > > > >> > > > > > > wrote: >> > > > > >> > > > > > > >> > > > > >> > > > > > > > maybe switch to dbcp pool to see if it behaves >> the >> > > same, >> > > > > if >> > > > > >> not >> > > > > >> > > can >> > > > > >> > > > > be >> > > > > >> > > > > > an >> > > > > >> > > > > > > > equals/hashcode issue >> > > > > >> > > > > > > > >> > > > > >> > > > > > > > >> > > > > >> > > > > > > > Romain Manni-Bucau >> > > > > >> > > > > > > > @rmannibucau <https://twitter.com/rmannibucau> | >> > > Blog >> > > > > >> > > > > > > > <https://blog-rmannibucau.rhcloud.com> | Old >> Blog >> > > > > >> > > > > > > > <http://rmannibucau.wordpress.com> | Github < >> > > > > >> > > > > > > https://github.com/rmannibuca >> > > > > >> > > > > > > > u> | >> > > > > >> > > > > > > > LinkedIn <https://www.linkedin.com/in/r >> mannibucau> >> > | >> > > > > JavaEE >> > > > > >> > > > Factory >> > > > > >> > > > > > > > <https://javaeefactory-rmannibucau.rhcloud.com> >> > > > > >> > > > > > > > >> > > > > >> > > > > > > > 2017-04-26 16:45 GMT+02:00 Paul Carter-Brown < >> > > > > >> > > > > > > > [email protected]>: >> > > > > >> > > > > > > > >> > > > > >> > > > > > > > > Hi Romain, >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > In order to better understand the commit >> timing, I >> > > > have >> > > > > >> put >> > > > > >> > > some >> > > > > >> > > > > > > logging >> > > > > >> > > > > > > > in >> > > > > >> > > > > > > > > a custom MySQL ConnectionLifecycleInterceptor >> so >> > > that >> > > > I >> > > > > >> can >> > > > > >> > do >> > > > > >> > > a >> > > > > >> > > > > > stack >> > > > > >> > > > > > > > > trace when commit is called and see where it's >> > > called >> > > > > >> > relative >> > > > > >> > > to >> > > > > >> > > > > the >> > > > > >> > > > > > > > SOAP >> > > > > >> > > > > > > > > service invocation. I also put a >> > Thread.sleep(1000) >> > > in >> > > > > the >> > > > > >> > > commit >> > > > > >> > > > > > > method >> > > > > >> > > > > > > > of >> > > > > >> > > > > > > > > my ConnectionLifecycleInterceptor to see how it >> > > > > influenced >> > > > > >> > the >> > > > > >> > > > > > response >> > > > > >> > > > > > > > > going back to the client. Whats very strange is >> > that >> > > > the >> > > > > >> > 1000ms >> > > > > >> > > > > sleep >> > > > > >> > > > > > > > does >> > > > > >> > > > > > > > > result in the response taking almost 1000ms >> > longer. >> > > I >> > > > > say >> > > > > >> > > almost, >> > > > > >> > > > > > > because >> > > > > >> > > > > > > > > again when running with multiple threads, I can >> > get >> > > a >> > > > > >> > situation >> > > > > >> > > > > where >> > > > > >> > > > > > > the >> > > > > >> > > > > > > > > response beats the completion of the commit. I >> > > cannot >> > > > > >> create >> > > > > >> > > this >> > > > > >> > > > > > when >> > > > > >> > > > > > > > the >> > > > > >> > > > > > > > > client has only one thread. Here is a log >> snippet >> > > > > showing >> > > > > >> the >> > > > > >> > > > > > scenario: >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > 1) Here is our ConnectionLifecycleInterceptor >> > > getting >> > > > > the >> > > > > >> > > commit >> > > > > >> > > > > call >> > > > > >> > > > > > > and >> > > > > >> > > > > > > > > logging the stack before sleeping for 1000ms. >> Its >> > > > > >> committing >> > > > > >> > a >> > > > > >> > > > new >> > > > > >> > > > > > row >> > > > > >> > > > > > > > with >> > > > > >> > > > > > > > > ID 615867 >> > > > > >> > > > > > > > > 2017/04/26 16:22:50.592 FINE >> > > > > >> > > > > > > > > [TomEE-Exec-15][207][com.smile >> > > > > >> coms.commons.base.lifecycle. >> > > > > >> > > > > > > > > SmileConnectionLifecycleInterceptor.commit] >> > > > > >> > > > > > > > > |Commit called >> > > > > >> > > > > > > > > 2017/04/26 16:22:50.593 FINE >> > > > > >> > > > > > > > > [TomEE-Exec-15][207][com.smile >> > > > > >> coms.commons.base.lifecycle. >> > > > > >> > > > > > > > > SmileConnectionLifecycleInterceptor.commit] >> > > > > >> > > > > > > > > |Stack in commit. Sleeping now: >> > > > > >> > > > > > > > > java.lang.Exception >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > com.smilecoms.commons.base.lifecycle. >> > > > > >> > > > > SmileConnectionLifecycleInterc >> > > > > >> > > > > > > > > eptor.commit(SmileConnectionLifecycleInterc >> > > > > eptor.java:32) >> > > > > >> > > > > > > > > at com.mysql.jdbc.ConnectionImpl$ >> > > > > >> > > > > > > 2.forEach(ConnectionImpl.java: >> > > > > >> > > > > > > > > 1593) >> > > > > >> > > > > > > > > at com.mysql.jdbc.ConnectionImpl$ >> > > > > >> > > > > > > 2.forEach(ConnectionImpl.java: >> > > > > >> > > > > > > > > 1592) >> > > > > >> > > > > > > > > at com.mysql.jdbc.IterateBlock. >> > > > > >> > > > > > doForAll(IterateBlock.java:61) >> > > > > >> > > > > > > > > at com.mysql.jdbc.ConnectionImpl. >> > > > > >> > > > > > > commit(ConnectionImpl.java:159 >> > > > > >> > > > > > > > 9) >> > > > > >> > > > > > > > > at sun.reflect. >> > GeneratedMethodAccessor137. >> > > > > >> > > invoke(Unknown >> > > > > >> > > > > > > Source) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > sun.reflect.DelegatingMethodAc >> cessorImpl.invoke( >> > > > > >> > > > > > > > > DelegatingMethodAccessorImpl.java:43) >> > > > > >> > > > > > > > > at java.lang.reflect.Method.invok >> > > > > >> e(Method.java:498) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomcat.jdbc.pool. >> > ProxyConnection.invoke( >> > > > > >> > > > > > > > > ProxyConnection.java:126) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomcat.jdbc.pool. >> > JdbcInterceptor.invoke( >> > > > > >> > > > > > > > > JdbcInterceptor.java:108) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomcat.jdbc.pool.Di >> > > > > >> sposableConnectionFacade.invok >> > > > > >> > e( >> > > > > >> > > > > > > > > DisposableConnectionFacade.java:81) >> > > > > >> > > > > > > > > at com.sun.proxy.$Proxy58.commit( >> Unknown >> > > > > Source) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.resource.jd >> bc.managed.local. >> > > > > >> > > > > > LocalXAResource.commit( >> > > > > >> > > > > > > > > LocalXAResource.java:131) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.geronimo.transaction.manager. >> > > > > TransactionImpl. >> > > > > >> > > > > > > commitResource( >> > > > > >> > > > > > > > > TransactionImpl.java:627) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.geronimo.transaction.manager. >> > > > > >> > > TransactionImpl.commit( >> > > > > >> > > > > > > > > TransactionImpl.java:305) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.geronimo.transaction.manager. >> > > > > >> > > > > > TransactionManagerImpl.commit( >> > > > > >> > > > > > > > > TransactionManagerImpl.java:252) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.core.transaction. >> > > > > JtaTransactionPolicy. >> > > > > >> > > > > > > > > completeTransaction( >> > JtaTransactionPolicy.java:331) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.core.transa >> > > > > >> ction.TxRequired.commit(TxRequ >> > > > > >> > > > > > > > ired.java:76) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.core.transaction. >> > > > EjbTransactionUtil. >> > > > > >> > > > > afterInvoke( >> > > > > >> > > > > > > > > EjbTransactionUtil.java:77) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.core. >> > > > stateless.StatelessContainer._ >> > > > > >> > > > > > > > > invoke(StatelessContainer.java:271) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.core. >> > > stateless.StatelessContainer. >> > > > > >> > > > > > > > > invoke(StatelessContainer.java:212) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.server.cxf. >> > ejb.EjbMethodInvoker. >> > > > > >> > > > > > > > > preEjbInvoke(EjbMethodInvoker.java:125) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.server.cxf. >> > > > > >> ejb.EjbMethodInvoker.invoke( >> > > > > >> > > > > > > > > EjbMethodInvoker.java:82) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.service.invoker >> .AbstractInvoker. >> > > > > >> > > > > > > > > invoke(AbstractInvoker.java:74) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.interceptor. >> > > > ServiceInvokerInterceptor$1. >> > > > > >> > > > > > > > > run(ServiceInvokerInterceptor.java:59) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > java.util.concurrent.Executors >> $RunnableAdapter. >> > > > > >> > > > > > > call(Executors.java:511) >> > > > > >> > > > > > > > > at java.util.concurrent.FutureTas >> > > > > >> k.run(FutureTask. >> > > > > >> > > > > java:266) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.interceptor. >> > > > ServiceInvokerInterceptor$2. >> > > > > >> > > > > > > > > run(ServiceInvokerInterceptor.java:126) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.workqueue. >> > > SynchronousExecutor.execute( >> > > > > >> > > > > > > > > SynchronousExecutor.java:37) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.interceptor. >> > > ServiceInvokerInterceptor. >> > > > > >> > > > > handleMessage( >> > > > > >> > > > > > > > > ServiceInvokerInterceptor.java:131) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.phase.PhaseInterceptorChain. >> > > > doIntercept( >> > > > > >> > > > > > > > > PhaseInterceptorChain.java:308) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.transport.Chain >> > > > > >> InitiationObserver.onMessage( >> > > > > >> > > > > > > > > ChainInitiationObserver.java:121) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.cxf.transport.http. >> > > > > >> AbstractHTTPDestination.invoke >> > > > > >> > ( >> > > > > >> > > > > > > > > AbstractHTTPDestination.java:262) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.server.cxf. >> > > > CxfWsContainer.onMessage( >> > > > > >> > > > > > > > > CxfWsContainer.java:85) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.openejb.server.webs >> > > > > >> ervices.WsServlet.service(WsSe >> > > > > >> > > > > > > > rvlet.java:98) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.core.Appli >> > > > > >> cationFilterChain.internalDoFi >> > > > > >> > > > lter( >> > > > > >> > > > > > > > > ApplicationFilterChain.java:230) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.core.Appli >> cationFilterChain. >> > > > > doFilter( >> > > > > >> > > > > > > > > ApplicationFilterChain.java:165) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.core. >> > > StandardWrapperValve.invoke( >> > > > > >> > > > > > > > > StandardWrapperValve.java:198) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.core. >> > > StandardContextValve.invoke( >> > > > > >> > > > > > > > > StandardContextValve.java:96) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.core. >> > StandardHostValve.invoke( >> > > > > >> > > > > > > > > StandardHostValve.java:140) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.valves. >> > ErrorReportValve.invoke( >> > > > > >> > > > > > > > > ErrorReportValve.java:79) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomee.catalina.Open >> > > > > >> EJBSecurityListener$RequestCap >> > > > > >> > > > > > > > turer.invoke( >> > > > > >> > > > > > > > > OpenEJBSecurityListener.java:97) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.core. >> > > StandardEngineValve.invoke( >> > > > > >> > > > > > > > > StandardEngineValve.java:87) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.catalina.connector. >> > > CoyoteAdapter.service( >> > > > > >> > > > > > > > > CoyoteAdapter.java:349) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.coyote.http11.Http1 >> > > > > >> 1Processor.service(Http11Proce >> > > > > >> > > > > > > > ssor.java:783) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.coyote.AbstractProc >> essorLight.process( >> > > > > >> > > > > > > > > AbstractProcessorLight.java:66) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.coyote.AbstractProtocol$ >> > > ConnectionHandler. >> > > > > >> > process( >> > > > > >> > > > > > > > > AbstractProtocol.java:798) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomcat.util.net. >> > > > NioEndpoint$SocketProcessor. >> > > > > >> > > > > > > > > doRun(NioEndpoint.java:1434) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomcat.util.net. >> > SocketProcessorBase.run( >> > > > > >> > > > > > > > > SocketProcessorBase.java:49) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > java.util.concurrent. >> > ThreadPoolExecutor.runWorker( >> > > > > >> > > > > > > > > ThreadPoolExecutor.java:1142) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > java.util.concurrent. >> > ThreadPoolExecutor$Worker.run( >> > > > > >> > > > > > > > > ThreadPoolExecutor.java:617) >> > > > > >> > > > > > > > > at >> > > > > >> > > > > > > > > org.apache.tomcat.util.threads.TaskThread$ >> > > > > >> > > WrappingRunnable.run( >> > > > > >> > > > > > > > > TaskThread.java:61) >> > > > > >> > > > > > > > > at java.lang.Thread.run(Thread.ja >> va:745) >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > 2) Now here is the clients request being >> processed >> > > in >> > > > > our >> > > > > >> EJB >> > > > > >> > > > > looking >> > > > > >> > > > > > > for >> > > > > >> > > > > > > > > the row that was created above but is not >> finished >> > > > > >> committing >> > > > > >> > > > yet. >> > > > > >> > > > > > The >> > > > > >> > > > > > > > row >> > > > > >> > > > > > > > > with ID 615867 is not found. >> > > > > >> > > > > > > > > 2017/04/26 16:22:51.588 FINE >> > > > > >> > > > > > > > > [TomEE-Exec-10][202][com. >> > > > smilecoms.im.IdentityManager. >> > > > > >> > > > > getCustomers] >> > > > > >> > > > > > > > > |Looking up a single customer with ID [615867] >> > > > > >> > > > > > > > > 3) Here is the sleep having finished. >> > > > > >> > > > > > > > > 2017/04/26 16:22:51.594 FINE >> > > > > >> > > > > > > > > [TomEE-Exec-15][207][com.smile >> > > > > >> coms.commons.base.lifecycle. >> > > > > >> > > > > > > > > SmileConnectionLifecycleInterceptor.commit] >> > > > > >> > > > > > > > > |Commit sleep finished >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > I would expect that only after 2017/04/26 >> > > 16:22:51.594 >> > > > > >> would >> > > > > >> > > the >> > > > > >> > > > > > client >> > > > > >> > > > > > > > > receive the SOAP response to the insert but >> > clearly >> > > > that >> > > > > >> is >> > > > > >> > not >> > > > > >> > > > the >> > > > > >> > > > > > > case. >> > > > > >> > > > > > > > > It is slowed down by the sleep but there still >> > seems >> > > > to >> > > > > be >> > > > > >> > some >> > > > > >> > > > > race >> > > > > >> > > > > > > > > condition where it somehow can still beat the >> > commit >> > > > > >> > returning. >> > > > > >> > > > If >> > > > > >> > > > > > the >> > > > > >> > > > > > > > > commit were called after sending the response >> or >> > in >> > > > > >> parallel >> > > > > >> > to >> > > > > >> > > > > doing >> > > > > >> > > > > > > so >> > > > > >> > > > > > > > > then I would have expected the 1000ms sleep to >> not >> > > > > impact >> > > > > >> the >> > > > > >> > > > > > response >> > > > > >> > > > > > > > time >> > > > > >> > > > > > > > > of the service. Very very strange.... >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > Here is the code snippet of my >> > > > > >> SmileConnectionLifecycleInterc >> > > > > >> > > > > eptor: >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > public class SmileConnectionLifecycleInterc >> eptor >> > > > > >> implements >> > > > > >> > > > > > > > > ConnectionLifecycleInterceptor { >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > private static final Logger log = >> > > > > >> > > > > > > > > LoggerFactory.getLogger( >> > > > SmileConnectionLifecycleInterc >> > > > > >> > > > > eptor.class); >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > @Override >> > > > > >> > > > > > > > > public boolean commit() throws >> SQLException { >> > > > > >> > > > > > > > > log.debug("Commit called"); >> > > > > >> > > > > > > > > log.debug("Stack in commit. Sleeping >> now: >> > ", >> > > > new >> > > > > >> > > > > > Exception()); >> > > > > >> > > > > > > > > try { >> > > > > >> > > > > > > > > Thread.sleep(1000); >> > > > > >> > > > > > > > > } catch (Exception e) { >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > } >> > > > > >> > > > > > > > > log.debug("Commit sleep finished"); >> > > > > >> > > > > > > > > return true; >> > > > > >> > > > > > > > > } >> > > > > >> > > > > > > > > ... >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > Any thoughts? >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > Paul >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > On 26 April 2017 at 13:50, Paul Carter-Brown < >> > > > > >> > > > > > > > > [email protected]> wrote: >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > > Thought so. Let me try and create a >> reproducable >> > > > test >> > > > > >> case >> > > > > >> > > and >> > > > > >> > > > > let >> > > > > >> > > > > > > you >> > > > > >> > > > > > > > > > know what i find >> > > > > >> > > > > > > > > > >> > > > > >> > > > > > > > > > Paul >> > > > > >> > > > > > > > > > >> > > > > >> > > > > > > > > > Sent from my phone. Message may be brief and >> > > contain >> > > > > >> typos. >> > > > > >> > > > > > > > > > >> > > > > >> > > > > > > > > > >> > > > > >> > > > > > > > > > On 26 Apr 2017 13:35, "Romain Manni-Bucau" < >> > > > > >> > > > > [email protected]> >> > > > > >> > > > > > > > > wrote: >> > > > > >> > > > > > > > > > >> > > > > >> > > > > > > > > >> Hi >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> Shouldn't be possible since it would assume >> > this >> > > > > flow: >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> thread1. start tx | >> thread2. - >> > > > > >> > > > > > > > > >> thread1. create the entry | thread2. - >> > > > > >> > > > > > > > > >> thread1. serialize the entry | thread2. - >> > > > > >> > > > > > > > > >> thread1. commit tx | thread2. - >> > find >> > > > the >> > > > > >> > entry >> > > > > >> > > > > > > > > >> thread1. | >> > thread2. >> > > - >> > > > > >> fails >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> The commit will happen >> > > > > >> > > > > > > > > >> in org.apache.openejb.server.cxf. >> > > > > >> > > ejb.EjbMethodInvoker#invoke >> > > > > >> > > > > > where >> > > > > >> > > > > > > > the >> > > > > >> > > > > > > > > >> serialization happens after >> > > > > >> > > > > > > > > >> in org.apache.cxf.jaxb.io. >> > > > DataWriterImpl#write(java. >> > > > > >> > > > > lang.Object, >> > > > > >> > > > > > > > > >> org.apache.cxf.service.model.M >> essagePartInfo, >> > T) >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> Only case it should be possible to happen >> is if >> > > you >> > > > > >> > wrapped >> > > > > >> > > > > jaxws >> > > > > >> > > > > > > > > >> servlet/layer with a custom transaction >> > > management >> > > > > >> > (through >> > > > > >> > > a >> > > > > >> > > > > > filter >> > > > > >> > > > > > > > for >> > > > > >> > > > > > > > > >> instance) which would start/commit outside >> > > default >> > > > > >> JAXWS >> > > > > >> > > > > handling. >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> Romain Manni-Bucau >> > > > > >> > > > > > > > > >> @rmannibucau <https://twitter.com/rmannibuc >> au> >> > | >> > > > > Blog >> > > > > >> > > > > > > > > >> <https://blog-rmannibucau.rhcloud.com> | >> Old >> > > Blog >> > > > > >> > > > > > > > > >> <http://rmannibucau.wordpress.com> | >> Github < >> > > > > >> > > > > > > > > >> https://github.com/rmannibucau> | >> > > > > >> > > > > > > > > >> LinkedIn <https://www.linkedin.com/in/ >> > > rmannibucau> >> > > > | >> > > > > >> > JavaEE >> > > > > >> > > > > > Factory >> > > > > >> > > > > > > > > >> <https://javaeefactory-rmannib >> ucau.rhcloud.com >> > > >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> 2017-04-26 12:59 GMT+02:00 Paul >> Carter-Brown < >> > > > > >> > > > > > > > > >> [email protected]>: >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > >> > Hi >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > I have a call flow as follows in tomee: >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > 1. Client calls jaxws service that adds a >> row >> > > > into >> > > > > >> mysql >> > > > > >> > > > > table. >> > > > > >> > > > > > > EJB >> > > > > >> > > > > > > > is >> > > > > >> > > > > > > > > >> > using JTA with eclipselink JPA entity >> bean. >> > > > Seevice >> > > > > >> > > returns >> > > > > >> > > > > the >> > > > > >> > > > > > > > > primary >> > > > > >> > > > > > > > > >> key >> > > > > >> > > > > > > > > >> > of the row just added. >> > > > > >> > > > > > > > > >> > 2. Client uses returned soap message that >> > > > contains >> > > > > >> the >> > > > > >> > > > primary >> > > > > >> > > > > > key >> > > > > >> > > > > > > > and >> > > > > >> > > > > > > > > >> > calls a second service that does a select >> for >> > > the >> > > > > >> row in >> > > > > >> > > > > > question. >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > The service in 1 and 2 is in the same >> tomee >> > > > > instance >> > > > > >> and >> > > > > >> > > > > caching >> > > > > >> > > > > > > in >> > > > > >> > > > > > > > > jpa >> > > > > >> > > > > > > > > >> is >> > > > > >> > > > > > > > > >> > disabled. Tx isolation isread committed. >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > Under high load and concurrency doing >> about >> > > 1000 >> > > > > tps >> > > > > >> i >> > > > > >> > get >> > > > > >> > > > > > about a >> > > > > >> > > > > > > > 20% >> > > > > >> > > > > > > > > >> > failure rate where the service at stage 2 >> > > cannot >> > > > > find >> > > > > >> > the >> > > > > >> > > > row >> > > > > >> > > > > > > > inserted >> > > > > >> > > > > > > > > >> at >> > > > > >> > > > > > > > > >> > stage 1. The row is inserted at some stage >> > as i >> > > > do >> > > > > >> see >> > > > > >> > it >> > > > > >> > > in >> > > > > >> > > > > the >> > > > > >> > > > > > > db. >> > > > > >> > > > > > > > > >> Its as >> > > > > >> > > > > > > > > >> > though service 1 is returning prior to the >> > > > database >> > > > > >> > having >> > > > > >> > > > > > > committed >> > > > > >> > > > > > > > > the >> > > > > >> > > > > > > > > >> > data. My understanding is that this should >> > not >> > > be >> > > > > >> > possible >> > > > > >> > > > as >> > > > > >> > > > > it >> > > > > >> > > > > > > > would >> > > > > >> > > > > > > > > >> > create all sorts of inconsistencies. Is >> what >> > i >> > > am >> > > > > >> > > observing >> > > > > >> > > > > > > expected >> > > > > >> > > > > > > > > >> > behaviour? >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > Paul >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > Sent from my phone. Message may be brief >> and >> > > > > contain >> > > > > >> > > typos. >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > -- >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > This email is subject to the disclaimer of >> > > Smile >> > > > > >> > > > > Communications >> > > > > >> > > > > > at >> > > > > >> > > > > > > > > >> > http://www.smilecoms.com/home/ >> > > email-disclaimer/ >> > > > < >> > > > > >> > > > > > > > > >> http://www.smilecoms.com/ >> > > > > >> > > > > > > > > >> > disclaimer> >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> > >> > > > > >> > > > > > > > > >> >> > > > > >> > > > > > > > > > >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > -- >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > *Paul Carter-Brown* >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > *Group Chief Information Officer* >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > *Smile Communications Pty (Ltd) * >> > > > > >> > > > > > > > > Smile +234 (0) 702 000 1234 >> > > > > >> > > > > > > > > Mobile +27 (0) 83 4427 179 >> > > > > >> > > > > > > > > Skype PaulC-B >> > > > > >> > > > > > > > > [email protected] >> > > > > >> > > > > > > > > www.smilecoms.com >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > -- >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > This email is subject to the disclaimer of >> Smile >> > > > > >> > Communications >> > > > > >> > > > at >> > > > > >> > > > > > > > > http://www.smilecoms.com/home/ >> email-disclaimer/ < >> > > > > >> > > > > > > > http://www.smilecoms.com/ >> > > > > >> > > > > > > > > disclaimer> >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> > > > > >> > > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > -- >> > > > > >> > > > > > > >> > > > > >> > > > > > > *Paul Carter-Brown* >> > > > > >> > > > > > > >> > > > > >> > > > > > > *Group Chief Information Officer* >> > > > > >> > > > > > > >> > > > > >> > > > > > > *Smile Communications Pty (Ltd) * >> > > > > >> > > > > > > Smile +234 (0) 702 000 1234 >> <+234%20702%20000%201234> >> > > > > >> > > > > > > Mobile +27 (0) 83 4427 179 >> > > > > >> > > > > > > Skype PaulC-B >> > > > > >> > > > > > > [email protected] >> > > > > >> > > > > > > www.smilecoms.com >> > > > > >> > > > > > > >> > > > > >> > > > > > > -- >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > > This email is subject to the disclaimer of Smile >> > > > > >> Communications >> > > > > >> > at >> > > > > >> > > > > > > http://www.smilecoms.com/home/email-disclaimer/ < >> > > > > >> > > > > > http://www.smilecoms.com/ >> > > > > >> > > > > > > disclaimer> >> > > > > >> > > > > > > >> > > > > >> > > > > > > >> > > > > >> > > > > > >> > > > > >> > > > > >> > > > > >> > > > > -- >> > > > > >> > > > > >> > > > > >> > > > > >> > > > > >> > > > > This email is subject to the disclaimer of Smile >> > > > Communications >> > > > > at >> > > > > >> > > > > http://www.smilecoms.com/home/email-disclaimer/ < >> > > > > >> > > > http://www.smilecoms.com/ >> > > > > >> > > > > disclaimer> >> > > > > >> > > > > >> > > > > >> > > > > >> > > > > >> > > > >> > > > > >> > > >> > > > > >> > > >> > > > > >> > > >> > > > > >> > > -- >> > > > > >> > > >> > > > > >> > > *Paul Carter-Brown* >> > > > > >> > > >> > > > > >> > > *Group Chief Information Officer* >> > > > > >> > > >> > > > > >> > > *Smile Communications Pty (Ltd) * >> > > > > >> > > Smile +234 (0) 702 000 1234 <+234%20702%20000%201234> >> > > > > >> > > Mobile +27 (0) 83 4427 179 >> > > > > >> > > Skype PaulC-B >> > > > > >> > > [email protected] >> > > > > >> > > www.smilecoms.com >> > > > > >> > > >> > > > > >> > > -- >> > > > > >> > > >> > > > > >> > > >> > > > > >> > > This email is subject to the disclaimer of Smile >> > Communications >> > > at >> > > > > >> > > http://www.smilecoms.com/home/email-disclaimer/ < >> > > > > >> > http://www.smilecoms.com/ >> > > > > >> > > disclaimer> >> > > > > >> > > >> > > > > >> > > >> > > > > >> > >> > > > > >> > >> > > > > >> > >> > > > > >> >> > > > > >> >> > > > > >> -- >> > > > > >> >> > > > > >> *Paul Carter-Brown* >> > > > > >> >> > > > > >> *Group Chief Information Officer* >> > > > > >> >> > > > > >> *Smile Communications Pty (Ltd) * >> > > > > >> Smile +234 (0) 702 000 1234 >> > > > > >> Mobile +27 (0) 83 4427 179 >> > > > > >> Skype PaulC-B >> > > > > >> [email protected] >> > > > > >> www.smilecoms.com >> > > > > >> >> > > > > >> -- >> > > > > >> >> > > > > >> >> > > > > >> This email is subject to the disclaimer of Smile >> Communications at >> > > > > >> http://www.smilecoms.com/home/email-disclaimer/ < >> > > > > >> http://www.smilecoms.com/disclaimer> >> > > > > >> >> > > > > >> >> > > > > >> > > > >> > > > >> > > > >> > > > -- >> > > > >> > > > *Paul Carter-Brown* >> > > > >> > > > *Group Chief Information Officer* >> > > > >> > > > *Smile Communications Pty (Ltd) * >> > > > Smile +234 (0) 702 000 1234 >> > > > Mobile +27 (0) 83 4427 179 >> > > > Skype PaulC-B >> > > > [email protected] >> > > > www.smilecoms.com >> > > > >> > > > -- >> > > > >> > > > >> > > > This email is subject to the disclaimer of Smile Communications at >> > > > http://www.smilecoms.com/home/email-disclaimer/ < >> > > http://www.smilecoms.com/ >> > > > disclaimer> >> > > > >> > > > >> > > >> > >> > >> > >> > -- >> > >> > *Paul Carter-Brown* >> > >> > *Group Chief Information Officer* >> > >> > *Smile Communications Pty (Ltd) * >> > Smile +234 (0) 702 000 1234 >> > Mobile +27 (0) 83 4427 179 >> > Skype PaulC-B >> > [email protected] >> > www.smilecoms.com >> > >> > -- >> > >> > >> > This email is subject to the disclaimer of Smile Communications at >> > http://www.smilecoms.com/home/email-disclaimer/ < >> http://www.smilecoms.com/ >> > disclaimer> >> > >> > >> > > > > -- > > *Paul Carter-Brown* > > *Group Chief Information Officer* > > *Smile Communications Pty (Ltd) * > Smile +234 (0) 702 000 1234 > Mobile +27 (0) 83 4427 179 > Skype PaulC-B > [email protected] > www.smilecoms.com > > This email is subject to the disclaimer of Smile Communications at > http://www.smilecoms.com/home/email-disclaimer/ > <http://www.smilecoms.com/disclaimer> > >
