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 < paul.carter-br...@smilecoms.com>: > 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.PhaseInterceptorChain.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.JDBC4Connection@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.doForAll(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.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.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.PhaseInterceptorChain.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 <rmannibu...@gmail.com> > 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" <rmannibu...@gmail.com> 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.SoapActionInInterceptor@ > > 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.GeneratedMethodAccessor138.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@41aa4e75 > > >> 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 < > > >> paul.carter-br...@smilecoms.com> 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" < > > rmannibu...@gmail.com> > > >> > 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 > > >> <paul.carter-brown@smilecoms.c > > >> > 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 < > > rmannibu...@gmail.com> > > >> > > 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 > > >> > > <paul.carter-brown@smilecoms.c > > >> > > > 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" < > > >> > rmannibu...@gmail.com > > >> > > > > > >> > > > > 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 < > > >> > > rmannibu...@gmail.com > > >> > > > > > > >> > > > > > > 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/rmannibucau> | > > JavaEE > > >> > > > Factory > > >> > > > > > > > <https://javaeefactory-rmannibucau.rhcloud.com> > > >> > > > > > > > > > >> > > > > > > > 2017-04-26 16:45 GMT+02:00 Paul Carter-Brown < > > >> > > > > > > > paul.carter-br...@smilecoms.com>: > > >> > > > > > > > > > >> > > > > > > > > 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.DelegatingMethodAccessorImpl.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.jdbc.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.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.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.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) > > >> > > > > > > > > > > >> > > > > > > > > 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 SmileConnectionLifecycleInterceptor > > >> 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 < > > >> > > > > > > > > paul.carter-br...@smilecoms.com> 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" < > > >> > > > > rmannibu...@gmail.com> > > >> > > > > > > > > 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.MessagePartInfo, 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/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-04-26 12:59 GMT+02:00 Paul Carter-Brown < > > >> > > > > > > > > >> paul.carter-br...@smilecoms.com>: > > >> > > > > > > > > >> > > >> > > > > > > > > >> > 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 > > >> > > > > > > > > paul.carter-br...@smilecoms.com > > >> > > > > > > > > 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 > > >> > > > > > > paul.carter-br...@smilecoms.com > > >> > > > > > > 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 > > >> > > paul.carter-br...@smilecoms.com > > >> > > 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 > > >> paul.carter-br...@smilecoms.com > > >> 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 > paul.carter-br...@smilecoms.com > 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> > >
