Interesting since it tends to comfort the timeout issue. Can you try putting some aggressive db timeout? Or transaction manager timeout - default is 10mn, way too high for http.
If still an issue I d apprecoate a small github project with a failling arquillian test with your idea if possible. Le 1 mai 2017 23:53, "Paul Carter-Brown" <[email protected]> a écrit : > Hi Romain, > > I'm struggling to think of a way to test this as it would involve modifying > code in TomEE core as part of the test. I found an easy-enough way is to > have a JAW-WS service with CMP that does some DB changes. Then at the end > of the business method just before returning, sleep for say 20s. When you > call the service, during those 20s, shut down the database. You should see > that although the commit fails due to the DB having gone away, the SOAP > service will respond successfully. > > On 1 May 2017 at 21:29, Romain Manni-Bucau <[email protected]> wrote: > > > then it should happen also with hsqldb and you can probably share a small > > sample on github. Main challenge is to write a small failling test. Will > > try to have a look in the week. > > > > PS: thought to a case it can happen and is not abnormal: a timeout. If > you > > timeout the EJB method is not cancelled so you get the response before > the > > commit but this is "normal". > > > > > > Romain Manni-Bucau > > @rmannibucau <https://twitter.com/rmannibucau> | Blog > > <https://blog-rmannibucau.rhcloud.com> | Old Blog > > <http://rmannibucau.wordpress.com> | Github <https://github.com/ > > rmannibucau> | > > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory > > <https://javaeefactory-rmannibucau.rhcloud.com> > > > > 2017-05-01 21:18 GMT+02:00 Paul Carter-Brown < > > [email protected]>: > > > > > Hi Romain, > > > > > > I modifed that class as follows: > > > > > > public void commit() throws ApplicationException, SystemException { > > > // only commit if we started the transaction > > > log.warn("In commit - sleeping for 3000ms"); > > > try { > > > Thread.sleep(3000); > > > } catch (Exception e) { > > > log.warn("Error in sleep"); > > > } > > > log.warn("Woke up from sleep"); > > > if (clientTx == null) { > > > log.warn("In commit - clientTx is null"); > > > completeTransaction(currentTx); > > > } else { > > > log.warn("In commit - clientTx is not null"); > > > fireNonTransactionalCompletion(); > > > } > > > } > > > > > > Here is the timing of the wireshark request/response: > > > 462 20:35:11.046374 10.0.1.57 -> 10.0.1.57 HTTP/XML 2124 POST > > > /IM/IdentityManager HTTP/1.1 > > > 464 20:35:11.082010 10.0.1.57 -> 10.0.1.57 HTTP/XML 384 HTTP/1.1 > > 200 > > > > > > My JMeter client reported a response time of 52ms on the SOAP call. > > > > > > And the TomEE logs: > > > > > > 2017/05/01 20:35:11.046 FINE > > > [TomEE-Exec-12][206][org.apache.cxf.phase.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 <[email protected]> > > > wrote: > > > > > > > Ps: > > > > https://github.com/apache/tomee/blob/master/container/ > > > > openejb-core/src/main/java/org/apache/openejb/core/ > > > > transaction/TxRequired.java > > > > > > > > Le 29 avr. 2017 09:55, "Romain Manni-Bucau" <[email protected]> > a > > > > écrit : > > > > > > > > > Should be before. You can put breakpoint/logs in TxPolicy and your > > ejb > > > > > > > > > > Le 29 avr. 2017 00:44, "Paul Carter-Brown" > > > <paul.carter-brown@smilecoms. > > > > > com> a écrit : > > > > > > > > > >> Hi Romain, > > > > >> > > > > >> A quick update. I put cxf logging on and for a typical message > > > exchange > > > > >> for > > > > >> a JAX-WS service backed by an EJB.At the same time I ran a > wireshark > > > on > > > > >> the > > > > >> server to see the network traffic. This is for a single call under > > no > > > > >> concurrency so you can easily verify yourself with any SOAP > service > > in > > > > >> TomEE: > > > > >> > > > > >> 1438 00:09:05.510294 10.0.1.57 -> 10.0.1.57 HTTP/XML 1223 > POST > > > > >> /IM/IdentityManager HTTP/1.1 > > > > >> 1439 00:09:05.510436 10.0.1.57 -> 10.0.1.57 TCP 68 mcreport > > > > > > 40929 > > > > >> [ACK] Seq=1721 Ack=7983 Win=323456 Len=0 TSval=70303912 > > TSecr=70303912 > > > > >> 1440 00:09:05.527410 10.0.1.57 -> 10.0.1.57 HTTP/XML 1852 > > > HTTP/1.1 > > > > >> 200 > > > > >> 1441 00:09:05.527453 10.0.1.57 -> 10.0.1.57 TCP 68 40929 > > > > > mcreport > > > > >> [ACK] Seq=7983 Ack=3505 Win=178944 Len=0 TSval=70303916 > > TSecr=70303916 > > > > >> > > > > >> So at 00:09:05.510 the server got the request. Here are the server > > > logs > > > > >> verifying this: > > > > >> > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase. > > PhaseInterceptorChain.add] > > > > >> |Adding interceptor > > > > >> org.apache.cxf.transport.https.CertConstraintsInterceptor@ > 64623f81 > > to > > > > >> phase > > > > >> pre-stream > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.outputChainToLog] > > > > >> |Chain org.apache.cxf.phase.PhaseInterceptorChain@713d71d3 was > > > created. > > > > >> Current flow: > > > > >> receive [PolicyInInterceptor, SaajInFaultInterceptor, > > > > >> AttachmentInInterceptor] > > > > >> pre-stream [CertConstraintsInterceptor] > > > > >> post-stream [StaxInInterceptor] > > > > >> read [SAAJPreInInterceptor, WSDLGetInterceptor, > > > > ReadHeadersInterceptor, > > > > >> SoapActionInInterceptor, StartBodyInterceptor] > > > > >> pre-protocol [SAAJInInterceptor] > > > > >> post-protocol [CheckFaultInterceptor, > > JAXBAttachmentSchemaValidation > > > > >> Hack] > > > > >> unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor] > > > > >> pre-logical [OneWayProcessorInterceptor] > > > > >> post-logical [WrapperClassInInterceptor] > > > > >> pre-invoke [SwAInInterceptor, HolderInInterceptor] > > > > >> invoke [ServiceInvokerInterceptor] > > > > >> post-invoke [SaajInInterceptor, OutgoingChainInterceptor] > > > > >> > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.ws.policy.PolicyInInterceptor@1e78ace6 > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.openejb.server.cxf.client.SaajInFaultInterceptor@ > > 1338d078 > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.interceptor.AttachmentInInterceptor@5dea89fc > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.transport.https.CertConstraintsInterceptor@ > 64623f81 > > > > >> 2017/04/29 00:09:05.510 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.interceptor.StaxInInterceptor@647520af > > > > >> 2017/04/29 00:09:05.511 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase. > > PhaseInterceptorChain.add] > > > > >> |Adding interceptor > > > > >> org.apache.cxf.interceptor.StaxInEndingInterceptor@39dd4830 to > > phase > > > > >> pre-invoke > > > > >> 2017/04/29 00:09:05.511 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.outputChainToLog] > > > > >> |Chain org.apache.cxf.phase.PhaseInterceptorChain@713d71d3 was > > > > modified. > > > > >> Current flow: > > > > >> receive [PolicyInInterceptor, SaajInFaultInterceptor, > > > > >> AttachmentInInterceptor] > > > > >> pre-stream [CertConstraintsInterceptor] > > > > >> post-stream [StaxInInterceptor] > > > > >> read [SAAJPreInInterceptor, WSDLGetInterceptor, > > > > ReadHeadersInterceptor, > > > > >> SoapActionInInterceptor, StartBodyInterceptor] > > > > >> pre-protocol [SAAJInInterceptor] > > > > >> post-protocol [CheckFaultInterceptor, > > JAXBAttachmentSchemaValidation > > > > >> Hack] > > > > >> unmarshal [DocLiteralInInterceptor, SoapHeaderInterceptor] > > > > >> pre-logical [OneWayProcessorInterceptor] > > > > >> post-logical [WrapperClassInInterceptor] > > > > >> pre-invoke [StaxInEndingInterceptor, SwAInInterceptor, > > > > >> HolderInInterceptor] > > > > >> invoke [ServiceInvokerInterceptor] > > > > >> post-invoke [SaajInInterceptor, OutgoingChainInterceptor] > > > > >> > > > > >> 2017/04/29 00:09:05.511 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.binding.soap.saaj.SAAJInInterceptor$SAAJPreIn > > > > >> Interceptor@6c33f463 > > > > >> 2017/04/29 00:09:05.511 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.frontend.WSDLGetInterceptor@11c0446f > > > > >> 2017/04/29 00:09:05.511 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.binding.soap.interceptor. > > > ReadHeadersInterceptor@be15cc5 > > > > >> 2017/04/29 00:09:05.511 FINE > > > > >> [TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorC > > > > >> hain.doIntercept] > > > > >> |Invoking handleMessage on interceptor > > > > >> org.apache.cxf.binding.soap.interceptor.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 < > > > > >> [email protected]> wrote: > > > > >> > > > > >> > For sure. I will start by pulling openejb source and digging in > > for > > > > >> > possible causes. A few log lines here and there and im sure i > can > > > find > > > > >> it > > > > >> > > > > > >> > Paul > > > > >> > > > > > >> > Sent from my phone. Message may be brief and contain typos. > > > > >> > > > > > >> > > > > > >> > On 27 Apr 2017 10:25 a.m., "Romain Manni-Bucau" < > > > > [email protected]> > > > > >> > wrote: > > > > >> > > > > > >> > ant / gradle are other options but something not IDE related > > please > > > > (or > > > > >> you > > > > >> > take the risk noone will be able to run it ;)) > > > > >> > > > > > >> > > > > > >> > Romain Manni-Bucau > > > > >> > @rmannibucau <https://twitter.com/rmannibucau> | Blog > > > > >> > <https://blog-rmannibucau.rhcloud.com> | Old Blog > > > > >> > <http://rmannibucau.wordpress.com> | Github < > > > > >> https://github.com/rmannibuca > > > > >> > u> | > > > > >> > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE > > Factory > > > > >> > <https://javaeefactory-rmannibucau.rhcloud.com> > > > > >> > > > > > >> > 2017-04-27 9:48 GMT+02:00 Paul Carter-Brown > > > > >> <[email protected] > > > > >> > om > > > > >> > >: > > > > >> > > > > > >> > > Will see what I can do to reproduce for you. Maven and I do > not > > > get > > > > >> one > > > > >> > > well :-( > > > > >> > > > > > > >> > > > > > > >> > > > > > > >> > > On 27 April 2017 at 09:30, Romain Manni-Bucau < > > > > [email protected]> > > > > >> > > wrote: > > > > >> > > > > > > >> > > > Ok, at that point maybe try to reproduce it on a small > sample > > on > > > > >> > github - > > > > >> > > > goal is to share with us your setup more or less but not > > > > >> confidential > > > > >> > > data. > > > > >> > > > > > > > >> > > > You can use: > > > > >> > > > > > > > >> > > > <dependency> > > > > >> > > > <groupId>com.wix</groupId> > > > > >> > > > <artifactId>wix-embedded-mysql</artifactId> > > > > >> > > > <version>2.1.4</version> > > > > >> > > > </dependency> > > > > >> > > > > > > > >> > > > And in java: > > > > >> > > > > > > > >> > > > > > > > >> > > > EmbeddedMysql.anEmbeddedMysql(MysqldConfig > > > > >> > > > .aMysqldConfig(Version.v5_7_17) > > > > >> > > > .withPort(Integer.parseInt(port)) > > > > >> > > > .withUser("user", "pass") > > > > >> > > > .build()); > > > > >> > > > final EmbeddedMysql mysql = builder.start() > > > > >> > > > .addSchema(SchemaConfig. > > aSchemaConfig("test").build()); > > > > >> > > > > > > > >> > > > > > > > >> > > > To write a test with a running MySQL (first time you launch > it > > > > >> > downloads > > > > >> > > > mysql so it can be a bit long but then it is cached. > > > > >> > > > > > > > >> > > > This way we could grab it locally and investigate a bit > more. > > > > >> > > > > > > > >> > > > Romain Manni-Bucau > > > > >> > > > @rmannibucau <https://twitter.com/rmannibucau> | Blog > > > > >> > > > <https://blog-rmannibucau.rhcloud.com> | Old Blog > > > > >> > > > <http://rmannibucau.wordpress.com> | Github < > > > > >> > > https://github.com/rmannibuca > > > > >> > > > u> | > > > > >> > > > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE > > > > Factory > > > > >> > > > <https://javaeefactory-rmannibucau.rhcloud.com> > > > > >> > > > > > > > >> > > > 2017-04-27 6:06 GMT+02:00 Paul Carter-Brown > > > > >> > > <[email protected] > > > > >> > > > om > > > > >> > > > >: > > > > >> > > > > > > > >> > > > > No. Autocommit is off > > > > >> > > > > > > > > >> > > > > Paul > > > > >> > > > > > > > > >> > > > > Sent from my phone. Message may be brief and contain > typos. > > > > >> > > > > > > > > >> > > > > > > > > >> > > > > On 27 Apr 2017 12:47 a.m., "Romain Manni-Bucau" < > > > > >> > [email protected] > > > > >> > > > > > > > >> > > > > wrote: > > > > >> > > > > > > > > >> > > > > > Are you in autocommit mode? > > > > >> > > > > > > > > > >> > > > > > Le 26 avr. 2017 22:37, "Paul Carter-Brown" > > > > >> > > > <paul.carter-brown@smilecoms. > > > > >> > > > > > com> > > > > >> > > > > > a écrit : > > > > >> > > > > > > > > > >> > > > > > > Hi, > > > > >> > > > > > > > > > > >> > > > > > > Unfortunately, the same result with dbcp2. I also > turned > > > on > > > > >> mysql > > > > >> > > > > general > > > > >> > > > > > > query log and can see the commit come through after > the > > > > select > > > > >> > > comes > > > > >> > > > in > > > > >> > > > > > on > > > > >> > > > > > > another connection: > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > 2017-04-26T19:46:22.243742Z 20038 Query INSERT INTO > > > > >> > > > > > > SmileDB.customer_profile ... <removed> > > > > >> > > > > > > 2017-04-26T19:46:22.245984Z 20038 Query SELECT > > > > >> LAST_INSERT_ID() > > > > >> > > > > > > 2017-04-26T19:46:22.291193Z 20038 Query select > > > > >> > > @@session.tx_read_only > > > > >> > > > > > > 2017-04-26T19:46:22.317914Z 20031 Query SET > > > > >> autocommit=0 > > > > >> > > > > > > 2017-04-26T19:46:22.318088Z 20031 Query > SELECT > > * > > > > FROM > > > > >> > > > > > > SmileDB.customer_profile WHERE > > CUSTOMER_PROFILE_ID=1267253 > > > > AND > > > > >> > > > > > STATUS='AC' > > > > >> > > > > > > 2017-04-26T19:46:22.372481Z 20038 Query commit > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > And here is the log of the lifecycle listener getting > > > commit > > > > >> > > called: > > > > >> > > > > > > > > > > >> > > > > > > 2017/04/26 21:46:22.293 FINE > > [TomEE-Exec-31][301][com. > > > > >> > > > > > > smilecoms.commons.base.lifecycle. > > > > SmileConnectionLifecycleInt > > > > >> erc > > > > >> > > > > > > eptor.commit] > > > > >> > > > > > > |Commit called > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > On 26 April 2017 at 17:12, Romain Manni-Bucau < > > > > >> > > [email protected] > > > > >> > > > > > > > > >> > > > > > > wrote: > > > > >> > > > > > > > > > > >> > > > > > > > maybe switch to dbcp pool to see if it behaves the > > same, > > > > if > > > > >> not > > > > >> > > can > > > > >> > > > > be > > > > >> > > > > > an > > > > >> > > > > > > > equals/hashcode issue > > > > >> > > > > > > > > > > > >> > > > > > > > > > > > >> > > > > > > > Romain Manni-Bucau > > > > >> > > > > > > > @rmannibucau <https://twitter.com/rmannibucau> | > > Blog > > > > >> > > > > > > > <https://blog-rmannibucau.rhcloud.com> | Old Blog > > > > >> > > > > > > > <http://rmannibucau.wordpress.com> | Github < > > > > >> > > > > > > https://github.com/rmannibuca > > > > >> > > > > > > > u> | > > > > >> > > > > > > > LinkedIn <https://www.linkedin.com/in/rmannibucau> > | > > > > JavaEE > > > > >> > > > Factory > > > > >> > > > > > > > <https://javaeefactory-rmannibucau.rhcloud.com> > > > > >> > > > > > > > > > > > >> > > > > > > > 2017-04-26 16:45 GMT+02:00 Paul Carter-Brown < > > > > >> > > > > > > > [email protected]>: > > > > >> > > > > > > > > > > > >> > > > > > > > > Hi Romain, > > > > >> > > > > > > > > > > > > >> > > > > > > > > In order to better understand the commit timing, I > > > have > > > > >> put > > > > >> > > some > > > > >> > > > > > > logging > > > > >> > > > > > > > in > > > > >> > > > > > > > > a custom MySQL ConnectionLifecycleInterceptor so > > that > > > I > > > > >> can > > > > >> > do > > > > >> > > a > > > > >> > > > > > stack > > > > >> > > > > > > > > trace when commit is called and see where it's > > called > > > > >> > relative > > > > >> > > to > > > > >> > > > > the > > > > >> > > > > > > > SOAP > > > > >> > > > > > > > > service invocation. I also put a > Thread.sleep(1000) > > in > > > > the > > > > >> > > commit > > > > >> > > > > > > method > > > > >> > > > > > > > of > > > > >> > > > > > > > > my ConnectionLifecycleInterceptor to see how it > > > > influenced > > > > >> > the > > > > >> > > > > > response > > > > >> > > > > > > > > going back to the client. Whats very strange is > that > > > the > > > > >> > 1000ms > > > > >> > > > > sleep > > > > >> > > > > > > > does > > > > >> > > > > > > > > result in the response taking almost 1000ms > longer. > > I > > > > say > > > > >> > > almost, > > > > >> > > > > > > because > > > > >> > > > > > > > > again when running with multiple threads, I can > get > > a > > > > >> > situation > > > > >> > > > > where > > > > >> > > > > > > the > > > > >> > > > > > > > > response beats the completion of the commit. I > > cannot > > > > >> create > > > > >> > > this > > > > >> > > > > > when > > > > >> > > > > > > > the > > > > >> > > > > > > > > client has only one thread. Here is a log snippet > > > > showing > > > > >> the > > > > >> > > > > > scenario: > > > > >> > > > > > > > > > > > > >> > > > > > > > > 1) Here is our ConnectionLifecycleInterceptor > > getting > > > > the > > > > >> > > commit > > > > >> > > > > call > > > > >> > > > > > > and > > > > >> > > > > > > > > logging the stack before sleeping for 1000ms. Its > > > > >> committing > > > > >> > a > > > > >> > > > new > > > > >> > > > > > row > > > > >> > > > > > > > with > > > > >> > > > > > > > > ID 615867 > > > > >> > > > > > > > > 2017/04/26 16:22:50.592 FINE > > > > >> > > > > > > > > [TomEE-Exec-15][207][com.smile > > > > >> coms.commons.base.lifecycle. > > > > >> > > > > > > > > SmileConnectionLifecycleInterceptor.commit] > > > > >> > > > > > > > > |Commit called > > > > >> > > > > > > > > 2017/04/26 16:22:50.593 FINE > > > > >> > > > > > > > > [TomEE-Exec-15][207][com.smile > > > > >> coms.commons.base.lifecycle. > > > > >> > > > > > > > > SmileConnectionLifecycleInterceptor.commit] > > > > >> > > > > > > > > |Stack in commit. Sleeping now: > > > > >> > > > > > > > > java.lang.Exception > > > > >> > > > > > > > > at > > > > >> > > > > > > > > com.smilecoms.commons.base.lifecycle. > > > > >> > > > > SmileConnectionLifecycleInterc > > > > >> > > > > > > > > eptor.commit(SmileConnectionLifecycleInterc > > > > eptor.java:32) > > > > >> > > > > > > > > at com.mysql.jdbc.ConnectionImpl$ > > > > >> > > > > > > 2.forEach(ConnectionImpl.java: > > > > >> > > > > > > > > 1593) > > > > >> > > > > > > > > at com.mysql.jdbc.ConnectionImpl$ > > > > >> > > > > > > 2.forEach(ConnectionImpl.java: > > > > >> > > > > > > > > 1592) > > > > >> > > > > > > > > at com.mysql.jdbc.IterateBlock. > > > > >> > > > > > doForAll(IterateBlock.java:61) > > > > >> > > > > > > > > at com.mysql.jdbc.ConnectionImpl. > > > > >> > > > > > > commit(ConnectionImpl.java:159 > > > > >> > > > > > > > 9) > > > > >> > > > > > > > > at sun.reflect. > GeneratedMethodAccessor137. > > > > >> > > invoke(Unknown > > > > >> > > > > > > Source) > > > > >> > > > > > > > > at > > > > >> > > > > > > > > sun.reflect.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 < > > > > >> > > > > > > > > [email protected]> wrote: > > > > >> > > > > > > > > > > > > >> > > > > > > > > > Thought so. Let me try and create a reproducable > > > test > > > > >> case > > > > >> > > and > > > > >> > > > > let > > > > >> > > > > > > you > > > > >> > > > > > > > > > know what i find > > > > >> > > > > > > > > > > > > > >> > > > > > > > > > Paul > > > > >> > > > > > > > > > > > > > >> > > > > > > > > > Sent from my phone. Message may be brief and > > contain > > > > >> typos. > > > > >> > > > > > > > > > > > > > >> > > > > > > > > > > > > > >> > > > > > > > > > On 26 Apr 2017 13:35, "Romain Manni-Bucau" < > > > > >> > > > > [email protected]> > > > > >> > > > > > > > > wrote: > > > > >> > > > > > > > > > > > > > >> > > > > > > > > >> Hi > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> Shouldn't be possible since it would assume > this > > > > flow: > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> thread1. start tx | thread2. - > > > > >> > > > > > > > > >> thread1. create the entry | thread2. - > > > > >> > > > > > > > > >> thread1. serialize the entry | thread2. - > > > > >> > > > > > > > > >> thread1. commit tx | thread2. - > find > > > the > > > > >> > entry > > > > >> > > > > > > > > >> thread1. | > thread2. > > - > > > > >> fails > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> The commit will happen > > > > >> > > > > > > > > >> in org.apache.openejb.server.cxf. > > > > >> > > ejb.EjbMethodInvoker#invoke > > > > >> > > > > > where > > > > >> > > > > > > > the > > > > >> > > > > > > > > >> serialization happens after > > > > >> > > > > > > > > >> in org.apache.cxf.jaxb.io. > > > DataWriterImpl#write(java. > > > > >> > > > > lang.Object, > > > > >> > > > > > > > > >> org.apache.cxf.service.model.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 < > > > > >> > > > > > > > > >> [email protected]>: > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > >> > Hi > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > I have a call flow as follows in tomee: > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > 1. Client calls jaxws service that adds a row > > > into > > > > >> mysql > > > > >> > > > > table. > > > > >> > > > > > > EJB > > > > >> > > > > > > > is > > > > >> > > > > > > > > >> > using JTA with eclipselink JPA entity bean. > > > Seevice > > > > >> > > returns > > > > >> > > > > the > > > > >> > > > > > > > > primary > > > > >> > > > > > > > > >> key > > > > >> > > > > > > > > >> > of the row just added. > > > > >> > > > > > > > > >> > 2. Client uses returned soap message that > > > contains > > > > >> the > > > > >> > > > primary > > > > >> > > > > > key > > > > >> > > > > > > > and > > > > >> > > > > > > > > >> > calls a second service that does a select for > > the > > > > >> row in > > > > >> > > > > > question. > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > The service in 1 and 2 is in the same tomee > > > > instance > > > > >> and > > > > >> > > > > caching > > > > >> > > > > > > in > > > > >> > > > > > > > > jpa > > > > >> > > > > > > > > >> is > > > > >> > > > > > > > > >> > disabled. Tx isolation isread committed. > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > Under high load and concurrency doing about > > 1000 > > > > tps > > > > >> i > > > > >> > get > > > > >> > > > > > about a > > > > >> > > > > > > > 20% > > > > >> > > > > > > > > >> > failure rate where the service at stage 2 > > cannot > > > > find > > > > >> > the > > > > >> > > > row > > > > >> > > > > > > > inserted > > > > >> > > > > > > > > >> at > > > > >> > > > > > > > > >> > stage 1. The row is inserted at some stage > as i > > > do > > > > >> see > > > > >> > it > > > > >> > > in > > > > >> > > > > the > > > > >> > > > > > > db. > > > > >> > > > > > > > > >> Its as > > > > >> > > > > > > > > >> > though service 1 is returning prior to the > > > database > > > > >> > having > > > > >> > > > > > > committed > > > > >> > > > > > > > > the > > > > >> > > > > > > > > >> > data. My understanding is that this should > not > > be > > > > >> > possible > > > > >> > > > as > > > > >> > > > > it > > > > >> > > > > > > > would > > > > >> > > > > > > > > >> > create all sorts of inconsistencies. Is what > i > > am > > > > >> > > observing > > > > >> > > > > > > expected > > > > >> > > > > > > > > >> > behaviour? > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > Paul > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > Sent from my phone. Message may be brief and > > > > contain > > > > >> > > typos. > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > -- > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > This email is subject to the disclaimer of > > Smile > > > > >> > > > > Communications > > > > >> > > > > > at > > > > >> > > > > > > > > >> > http://www.smilecoms.com/home/ > > email-disclaimer/ > > > < > > > > >> > > > > > > > > >> http://www.smilecoms.com/ > > > > >> > > > > > > > > >> > disclaimer> > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > > > > > >> > > > > > > > > >> > > > > >> > > > > > > > > > > > > > >> > > > > > > > > > > > > >> > > > > > > > > > > > > >> > > > > > > > > -- > > > > >> > > > > > > > > > > > > >> > > > > > > > > *Paul Carter-Brown* > > > > >> > > > > > > > > > > > > >> > > > > > > > > *Group Chief Information Officer* > > > > >> > > > > > > > > > > > > >> > > > > > > > > *Smile Communications Pty (Ltd) * > > > > >> > > > > > > > > Smile +234 (0) 702 000 1234 > > > > >> > > > > > > > > Mobile +27 (0) 83 4427 179 > > > > >> > > > > > > > > Skype PaulC-B > > > > >> > > > > > > > > [email protected] > > > > >> > > > > > > > > www.smilecoms.com > > > > >> > > > > > > > > > > > > >> > > > > > > > > -- > > > > >> > > > > > > > > > > > > >> > > > > > > > > > > > > >> > > > > > > > > This email is subject to the disclaimer of Smile > > > > >> > Communications > > > > >> > > > at > > > > >> > > > > > > > > http://www.smilecoms.com/home/email-disclaimer/ < > > > > >> > > > > > > > http://www.smilecoms.com/ > > > > >> > > > > > > > > disclaimer> > > > > >> > > > > > > > > > > > > >> > > > > > > > > > > > > >> > > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > -- > > > > >> > > > > > > > > > > >> > > > > > > *Paul Carter-Brown* > > > > >> > > > > > > > > > > >> > > > > > > *Group Chief Information Officer* > > > > >> > > > > > > > > > > >> > > > > > > *Smile Communications Pty (Ltd) * > > > > >> > > > > > > Smile +234 (0) 702 000 1234 <+234%20702%20000%201234> > > > > >> > > > > > > Mobile +27 (0) 83 4427 179 > > > > >> > > > > > > Skype PaulC-B > > > > >> > > > > > > [email protected] > > > > >> > > > > > > www.smilecoms.com > > > > >> > > > > > > > > > > >> > > > > > > -- > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > This email is subject to the disclaimer of Smile > > > > >> Communications > > > > >> > at > > > > >> > > > > > > http://www.smilecoms.com/home/email-disclaimer/ < > > > > >> > > > > > http://www.smilecoms.com/ > > > > >> > > > > > > disclaimer> > > > > >> > > > > > > > > > > >> > > > > > > > > > > >> > > > > > > > > > >> > > > > > > > > >> > > > > -- > > > > >> > > > > > > > > >> > > > > > > > > >> > > > > This email is subject to the disclaimer of Smile > > > Communications > > > > at > > > > >> > > > > http://www.smilecoms.com/home/email-disclaimer/ < > > > > >> > > > http://www.smilecoms.com/ > > > > >> > > > > disclaimer> > > > > >> > > > > > > > > >> > > > > > > > > >> > > > > > > > >> > > > > > > >> > > > > > > >> > > > > > > >> > > -- > > > > >> > > > > > > >> > > *Paul Carter-Brown* > > > > >> > > > > > > >> > > *Group Chief Information Officer* > > > > >> > > > > > > >> > > *Smile Communications Pty (Ltd) * > > > > >> > > Smile +234 (0) 702 000 1234 <+234%20702%20000%201234> > > > > >> > > Mobile +27 (0) 83 4427 179 > > > > >> > > Skype PaulC-B > > > > >> > > [email protected] > > > > >> > > www.smilecoms.com > > > > >> > > > > > > >> > > -- > > > > >> > > > > > > >> > > > > > > >> > > This email is subject to the disclaimer of Smile > Communications > > at > > > > >> > > http://www.smilecoms.com/home/email-disclaimer/ < > > > > >> > http://www.smilecoms.com/ > > > > >> > > disclaimer> > > > > >> > > > > > > >> > > > > > > >> > > > > > >> > > > > > >> > > > > > >> > > > > >> > > > > >> -- > > > > >> > > > > >> *Paul Carter-Brown* > > > > >> > > > > >> *Group Chief Information Officer* > > > > >> > > > > >> *Smile Communications Pty (Ltd) * > > > > >> Smile +234 (0) 702 000 1234 > > > > >> Mobile +27 (0) 83 4427 179 > > > > >> Skype PaulC-B > > > > >> [email protected] > > > > >> www.smilecoms.com > > > > >> > > > > >> -- > > > > >> > > > > >> > > > > >> This email is subject to the disclaimer of Smile Communications at > > > > >> http://www.smilecoms.com/home/email-disclaimer/ < > > > > >> http://www.smilecoms.com/disclaimer> > > > > >> > > > > >> > > > > > > > > > > > > > > > > -- > > > > > > *Paul Carter-Brown* > > > > > > *Group Chief Information Officer* > > > > > > *Smile Communications Pty (Ltd) * > > > Smile +234 (0) 702 000 1234 > > > Mobile +27 (0) 83 4427 179 > > > Skype PaulC-B > > > [email protected] > > > www.smilecoms.com > > > > > > -- > > > > > > > > > This email is subject to the disclaimer of Smile Communications at > > > http://www.smilecoms.com/home/email-disclaimer/ < > > http://www.smilecoms.com/ > > > disclaimer> > > > > > > > > > > > > -- > > *Paul Carter-Brown* > > *Group Chief Information Officer* > > *Smile Communications Pty (Ltd) * > Smile +234 (0) 702 000 1234 > Mobile +27 (0) 83 4427 179 > Skype PaulC-B > [email protected] > www.smilecoms.com > > -- > > > This email is subject to the disclaimer of Smile Communications at > http://www.smilecoms.com/home/email-disclaimer/ <http://www.smilecoms.com/ > disclaimer> > >
