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 <rmannibu...@gmail.com> 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 < > 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> > > > > > -- *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>
