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, JAXBAttachmentSchemaValidationHack]
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.SmileConnectionLifecycleInterceptor.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, JAXBAttachmentSchemaValidationHack]
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>
