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.PhaseInterceptorChain.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, JAXBAttachmentSchemaValidationHack]
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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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, JAXBAttachmentSchemaValidationHack]
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.PhaseInterceptorChain.doIntercept]
|Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.saaj.SAAJInInterceptor$SAAJPreInInterceptor@6c33f463
2017/04/29 00:09:05.511 FINE
[TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.doIntercept]
|Invoking handleMessage on interceptor
org.apache.cxf.jaxws.handler.logical.LogicalHandlerOutInterceptor@128bf90f
2017/04/29 00:09:05.523 FINE
[TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorChain.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.PhaseInterceptorChain.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.PhaseInterceptorChain.doIntercept]
|Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor$SoapOutEndingInterceptor@10aa05f4*
2017/04/29 00:09:05.527 FINE
[TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorChain.doIntercept]
|Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.saaj.SAAJOutInterceptor$SAAJOutEndingInterceptor@66cac58b
2017/04/29 00:09:05.527 FINE
[TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorChain.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.PhaseInterceptorChain.doIntercept]
|Invoking handleMessage on interceptor
org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor@674adcf8
2017/04/29 00:09:05.529 FINE
[TomEE-Exec-30][224][com.smilecoms.commons.base.lifecycle.SmileConnectionLifecycleInterceptor.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.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.GeneratedMethodAccessor138.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: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.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/04/29 00:09:05.529 FINE
[TomEE-Exec-30][224][org.apache.cxf.phase.PhaseInterceptorChain.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.PhaseInterceptorChain.doIntercept]
|Invoking handleMessage on interceptor
org.apache.cxf.interceptor.OutgoingChainInterceptor@564ef482
>From what I can gather from the source, the SOAP document is flushed on the
socket in SoapOutEndingInterceptor which I have put in bold. This also
corresponds with the wireshark timing
The class looks like this:
public class SoapOutEndingInterceptor extends AbstractSoapInterceptor {
269 public SoapOutEndingInterceptor() {
270 super(SoapOutEndingInterceptor.class.getName(),
Phase.WRITE_ENDING); 271 }
272
273 public void handleMessage(SoapMessage message) throws Fault {
274 SoapVersion soapVersion = message.getVersion();
275 try {
276 XMLStreamWriter xtw =
message.getContent(XMLStreamWriter.class);
277 if (xtw != null) {
278 xtw.writeEndElement();
279 // Write Envelope end element
280 xtw.writeEndElement(); 281
xtw.writeEndDocument();
282
283 xtw.flush();
284 }
285 } catch (XMLStreamException e) {
286 throw new SoapFault(new
org.apache.cxf.common.i18n.Message("XML_WRITE_EXC", BUNDLE), e,
287 soapVersion.getSender());
288 }
289 }
290 }
The commit is only called via MessageSenderInterceptor but from the stack
trace I can't quite work out how ServiceInvokerInterceptor is called from
MessageSenderInterceptor so I can't explain the stack trace of the commit
call unless it's some fancy context switching and use of completable futures
Any ideas what's going on?
Paul
On 27 April 2017 at 10:39, Paul Carter-Brown <
paul.carter-br...@smilecoms.com> wrote:
> For sure. I will start by pulling openejb source and digging in for
> possible causes. A few log lines here and there and im sure i can find it
>
> Paul
>
> Sent from my phone. Message may be brief and contain typos.
>
>
> On 27 Apr 2017 10:25 a.m., "Romain Manni-Bucau" <rmannibu...@gmail.com>
> wrote:
>
> ant / gradle are other options but something not IDE related please (or you
> take the risk noone will be able to run it ;))
>
>
> Romain Manni-Bucau
> @rmannibucau <https://twitter.com/rmannibucau> | Blog
> <https://blog-rmannibucau.rhcloud.com> | Old Blog
> <http://rmannibucau.wordpress.com> | Github <https://github.com/rmannibuca
> u> |
> LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory
> <https://javaeefactory-rmannibucau.rhcloud.com>
>
> 2017-04-27 9:48 GMT+02:00 Paul Carter-Brown <paul.carter-brown@smilecoms.c
> om
> >:
>
> > Will see what I can do to reproduce for you. Maven and I do not get one
> > well :-(
> >
> >
> >
> > On 27 April 2017 at 09:30, Romain Manni-Bucau <rmannibu...@gmail.com>
> > wrote:
> >
> > > Ok, at that point maybe try to reproduce it on a small sample on
> github -
> > > goal is to share with us your setup more or less but not confidential
> > data.
> > >
> > > You can use:
> > >
> > > <dependency>
> > > <groupId>com.wix</groupId>
> > > <artifactId>wix-embedded-mysql</artifactId>
> > > <version>2.1.4</version>
> > > </dependency>
> > >
> > > And in java:
> > >
> > >
> > > EmbeddedMysql.anEmbeddedMysql(MysqldConfig
> > > .aMysqldConfig(Version.v5_7_17)
> > > .withPort(Integer.parseInt(port))
> > > .withUser("user", "pass")
> > > .build());
> > > final EmbeddedMysql mysql = builder.start()
> > > .addSchema(SchemaConfig.aSchemaConfig("test").build());
> > >
> > >
> > > To write a test with a running MySQL (first time you launch it
> downloads
> > > mysql so it can be a bit long but then it is cached.
> > >
> > > This way we could grab it locally and investigate a bit more.
> > >
> > > Romain Manni-Bucau
> > > @rmannibucau <https://twitter.com/rmannibucau> | Blog
> > > <https://blog-rmannibucau.rhcloud.com> | Old Blog
> > > <http://rmannibucau.wordpress.com> | Github <
> > https://github.com/rmannibuca
> > > u> |
> > > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory
> > > <https://javaeefactory-rmannibucau.rhcloud.com>
> > >
> > > 2017-04-27 6:06 GMT+02:00 Paul Carter-Brown
> > <paul.carter-brown@smilecoms.c
> > > om
> > > >:
> > >
> > > > No. Autocommit is off
> > > >
> > > > Paul
> > > >
> > > > Sent from my phone. Message may be brief and contain typos.
> > > >
> > > >
> > > > On 27 Apr 2017 12:47 a.m., "Romain Manni-Bucau" <
> rmannibu...@gmail.com
> > >
> > > > wrote:
> > > >
> > > > > Are you in autocommit mode?
> > > > >
> > > > > Le 26 avr. 2017 22:37, "Paul Carter-Brown"
> > > <paul.carter-brown@smilecoms.
> > > > > com>
> > > > > a écrit :
> > > > >
> > > > > > Hi,
> > > > > >
> > > > > > Unfortunately, the same result with dbcp2. I also turned on mysql
> > > > general
> > > > > > query log and can see the commit come through after the select
> > comes
> > > in
> > > > > on
> > > > > > another connection:
> > > > > >
> > > > > >
> > > > > > 2017-04-26T19:46:22.243742Z 20038 Query INSERT INTO
> > > > > > SmileDB.customer_profile ... <removed>
> > > > > > 2017-04-26T19:46:22.245984Z 20038 Query SELECT LAST_INSERT_ID()
> > > > > > 2017-04-26T19:46:22.291193Z 20038 Query select
> > @@session.tx_read_only
> > > > > > 2017-04-26T19:46:22.317914Z 20031 Query SET autocommit=0
> > > > > > 2017-04-26T19:46:22.318088Z 20031 Query SELECT * FROM
> > > > > > SmileDB.customer_profile WHERE CUSTOMER_PROFILE_ID=1267253 AND
> > > > > STATUS='AC'
> > > > > > 2017-04-26T19:46:22.372481Z 20038 Query commit
> > > > > >
> > > > > >
> > > > > > And here is the log of the lifecycle listener getting commit
> > called:
> > > > > >
> > > > > > 2017/04/26 21:46:22.293 FINE [TomEE-Exec-31][301][com.
> > > > > > smilecoms.commons.base.lifecycle.SmileConnectionLifecycleInterc
> > > > > > eptor.commit]
> > > > > > |Commit called
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > > On 26 April 2017 at 17:12, Romain Manni-Bucau <
> > rmannibu...@gmail.com
> > > >
> > > > > > wrote:
> > > > > >
> > > > > > > maybe switch to dbcp pool to see if it behaves the same, if not
> > can
> > > > be
> > > > > an
> > > > > > > equals/hashcode issue
> > > > > > >
> > > > > > >
> > > > > > > Romain Manni-Bucau
> > > > > > > @rmannibucau <https://twitter.com/rmannibucau> | Blog
> > > > > > > <https://blog-rmannibucau.rhcloud.com> | Old Blog
> > > > > > > <http://rmannibucau.wordpress.com> | Github <
> > > > > > https://github.com/rmannibuca
> > > > > > > u> |
> > > > > > > LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE
> > > Factory
> > > > > > > <https://javaeefactory-rmannibucau.rhcloud.com>
> > > > > > >
> > > > > > > 2017-04-26 16:45 GMT+02:00 Paul Carter-Brown <
> > > > > > > paul.carter-br...@smilecoms.com>:
> > > > > > >
> > > > > > > > Hi Romain,
> > > > > > > >
> > > > > > > > In order to better understand the commit timing, I have put
> > some
> > > > > > logging
> > > > > > > in
> > > > > > > > a custom MySQL ConnectionLifecycleInterceptor so that I can
> do
> > a
> > > > > stack
> > > > > > > > trace when commit is called and see where it's called
> relative
> > to
> > > > the
> > > > > > > SOAP
> > > > > > > > service invocation. I also put a Thread.sleep(1000) in the
> > commit
> > > > > > method
> > > > > > > of
> > > > > > > > my ConnectionLifecycleInterceptor to see how it influenced
> the
> > > > > response
> > > > > > > > going back to the client. Whats very strange is that the
> 1000ms
> > > > sleep
> > > > > > > does
> > > > > > > > result in the response taking almost 1000ms longer. I say
> > almost,
> > > > > > because
> > > > > > > > again when running with multiple threads, I can get a
> situation
> > > > where
> > > > > > the
> > > > > > > > response beats the completion of the commit. I cannot create
> > this
> > > > > when
> > > > > > > the
> > > > > > > > client has only one thread. Here is a log snippet showing the
> > > > > scenario:
> > > > > > > >
> > > > > > > > 1) Here is our ConnectionLifecycleInterceptor getting the
> > commit
> > > > call
> > > > > > and
> > > > > > > > logging the stack before sleeping for 1000ms. Its committing
> a
> > > new
> > > > > row
> > > > > > > with
> > > > > > > > ID 615867
> > > > > > > > 2017/04/26 16:22:50.592 FINE
> > > > > > > > [TomEE-Exec-15][207][com.smilecoms.commons.base.lifecycle.
> > > > > > > > SmileConnectionLifecycleInterceptor.commit]
> > > > > > > > |Commit called
> > > > > > > > 2017/04/26 16:22:50.593 FINE
> > > > > > > > [TomEE-Exec-15][207][com.smilecoms.commons.base.lifecycle.
> > > > > > > > SmileConnectionLifecycleInterceptor.commit]
> > > > > > > > |Stack in commit. Sleeping now:
> > > > > > > > java.lang.Exception
> > > > > > > > at
> > > > > > > > com.smilecoms.commons.base.lifecycle.
> > > > SmileConnectionLifecycleInterc
> > > > > > > > eptor.commit(SmileConnectionLifecycleInterceptor.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.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.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.transaction.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.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(WsSe
> > > > > > > rvlet.java:98)
> > > > > > > > at
> > > > > > > > org.apache.catalina.core.ApplicationFilterChain.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.OpenEJBSecurityListener$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.Http11Processor.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.smilecoms.commons.base.lifecycle.
> > > > > > > > SmileConnectionLifecycleInterceptor.commit]
> > > > > > > > |Commit sleep finished
> > > > > > > >
> > > > > > > > I would expect that only after 2017/04/26 16:22:51.594 would
> > the
> > > > > client
> > > > > > > > receive the SOAP response to the insert but clearly that is
> not
> > > the
> > > > > > case.
> > > > > > > > It is slowed down by the sleep but there still seems to be
> some
> > > > race
> > > > > > > > condition where it somehow can still beat the commit
> returning.
> > > If
> > > > > the
> > > > > > > > commit were called after sending the response or in parallel
> to
> > > > doing
> > > > > > so
> > > > > > > > then I would have expected the 1000ms sleep to not impact the
> > > > > response
> > > > > > > time
> > > > > > > > of the service. Very very strange....
> > > > > > > >
> > > > > > > > Here is the code snippet of my SmileConnectionLifecycleInterc
> > > > eptor:
> > > > > > > >
> > > > > > > > public class SmileConnectionLifecycleInterceptor implements
> > > > > > > > ConnectionLifecycleInterceptor {
> > > > > > > >
> > > > > > > > private static final Logger log =
> > > > > > > > LoggerFactory.getLogger(SmileConnectionLifecycleInterc
> > > > eptor.class);
> > > > > > > >
> > > > > > > >
> > > > > > > > @Override
> > > > > > > > public boolean commit() throws SQLException {
> > > > > > > > log.debug("Commit called");
> > > > > > > > log.debug("Stack in commit. Sleeping now: ", new
> > > > > Exception());
> > > > > > > > try {
> > > > > > > > Thread.sleep(1000);
> > > > > > > > } catch (Exception e) {
> > > > > > > >
> > > > > > > > }
> > > > > > > > log.debug("Commit sleep finished");
> > > > > > > > return true;
> > > > > > > > }
> > > > > > > > ...
> > > > > > > >
> > > > > > > >
> > > > > > > > Any thoughts?
> > > > > > > >
> > > > > > > > Paul
> > > > > > > >
> > > > > > > > On 26 April 2017 at 13:50, Paul Carter-Brown <
> > > > > > > > paul.carter-br...@smilecoms.com> wrote:
> > > > > > > >
> > > > > > > > > Thought so. Let me try and create a reproducable test case
> > and
> > > > let
> > > > > > you
> > > > > > > > > know what i find
> > > > > > > > >
> > > > > > > > > Paul
> > > > > > > > >
> > > > > > > > > Sent from my phone. Message may be brief and contain typos.
> > > > > > > > >
> > > > > > > > >
> > > > > > > > > On 26 Apr 2017 13:35, "Romain Manni-Bucau" <
> > > > rmannibu...@gmail.com>
> > > > > > > > wrote:
> > > > > > > > >
> > > > > > > > >> Hi
> > > > > > > > >>
> > > > > > > > >> Shouldn't be possible since it would assume this flow:
> > > > > > > > >>
> > > > > > > > >> thread1. start tx | thread2. -
> > > > > > > > >> thread1. create the entry | thread2. -
> > > > > > > > >> thread1. serialize the entry | thread2. -
> > > > > > > > >> thread1. commit tx | thread2. - find the
> entry
> > > > > > > > >> thread1. | thread2. - fails
> > > > > > > > >>
> > > > > > > > >> The commit will happen
> > > > > > > > >> in org.apache.openejb.server.cxf.
> > ejb.EjbMethodInvoker#invoke
> > > > > where
> > > > > > > the
> > > > > > > > >> serialization happens after
> > > > > > > > >> in org.apache.cxf.jaxb.io.DataWriterImpl#write(java.
> > > > lang.Object,
> > > > > > > > >> org.apache.cxf.service.model.MessagePartInfo, T)
> > > > > > > > >>
> > > > > > > > >> Only case it should be possible to happen is if you
> wrapped
> > > > jaxws
> > > > > > > > >> servlet/layer with a custom transaction management
> (through
> > a
> > > > > filter
> > > > > > > for
> > > > > > > > >> instance) which would start/commit outside default JAXWS
> > > > handling.
> > > > > > > > >>
> > > > > > > > >>
> > > > > > > > >> Romain Manni-Bucau
> > > > > > > > >> @rmannibucau <https://twitter.com/rmannibucau> | Blog
> > > > > > > > >> <https://blog-rmannibucau.rhcloud.com> | Old Blog
> > > > > > > > >> <http://rmannibucau.wordpress.com> | Github <
> > > > > > > > >> https://github.com/rmannibucau> |
> > > > > > > > >> LinkedIn <https://www.linkedin.com/in/rmannibucau> |
> JavaEE
> > > > > Factory
> > > > > > > > >> <https://javaeefactory-rmannibucau.rhcloud.com>
> > > > > > > > >>
> > > > > > > > >> 2017-04-26 12:59 GMT+02:00 Paul Carter-Brown <
> > > > > > > > >> paul.carter-br...@smilecoms.com>:
> > > > > > > > >>
> > > > > > > > >> > Hi
> > > > > > > > >> >
> > > > > > > > >> > I have a call flow as follows in tomee:
> > > > > > > > >> >
> > > > > > > > >> > 1. Client calls jaxws service that adds a row into mysql
> > > > table.
> > > > > > EJB
> > > > > > > is
> > > > > > > > >> > using JTA with eclipselink JPA entity bean. Seevice
> > returns
> > > > the
> > > > > > > > primary
> > > > > > > > >> key
> > > > > > > > >> > of the row just added.
> > > > > > > > >> > 2. Client uses returned soap message that contains the
> > > primary
> > > > > key
> > > > > > > and
> > > > > > > > >> > calls a second service that does a select for the row in
> > > > > question.
> > > > > > > > >> >
> > > > > > > > >> > The service in 1 and 2 is in the same tomee instance and
> > > > caching
> > > > > > in
> > > > > > > > jpa
> > > > > > > > >> is
> > > > > > > > >> > disabled. Tx isolation isread committed.
> > > > > > > > >> >
> > > > > > > > >> > Under high load and concurrency doing about 1000 tps i
> get
> > > > > about a
> > > > > > > 20%
> > > > > > > > >> > failure rate where the service at stage 2 cannot find
> the
> > > row
> > > > > > > inserted
> > > > > > > > >> at
> > > > > > > > >> > stage 1. The row is inserted at some stage as i do see
> it
> > in
> > > > the
> > > > > > db.
> > > > > > > > >> Its as
> > > > > > > > >> > though service 1 is returning prior to the database
> having
> > > > > > committed
> > > > > > > > the
> > > > > > > > >> > data. My understanding is that this should not be
> possible
> > > as
> > > > it
> > > > > > > would
> > > > > > > > >> > create all sorts of inconsistencies. Is what i am
> > observing
> > > > > > expected
> > > > > > > > >> > behaviour?
> > > > > > > > >> >
> > > > > > > > >> > Paul
> > > > > > > > >> >
> > > > > > > > >> > Sent from my phone. Message may be brief and contain
> > typos.
> > > > > > > > >> >
> > > > > > > > >> > --
> > > > > > > > >> >
> > > > > > > > >> >
> > > > > > > > >> > This email is subject to the disclaimer of Smile
> > > > Communications
> > > > > at
> > > > > > > > >> > http://www.smilecoms.com/home/email-disclaimer/ <
> > > > > > > > >> http://www.smilecoms.com/
> > > > > > > > >> > disclaimer>
> > > > > > > > >> >
> > > > > > > > >> >
> > > > > > > > >>
> > > > > > > > >
> > > > > > > >
> > > > > > > >
> > > > > > > > --
> > > > > > > >
> > > > > > > > *Paul Carter-Brown*
> > > > > > > >
> > > > > > > > *Group Chief Information Officer*
> > > > > > > >
> > > > > > > > *Smile Communications Pty (Ltd) *
> > > > > > > > Smile +234 (0) 702 000 1234
> > > > > > > > Mobile +27 (0) 83 4427 179
> > > > > > > > Skype PaulC-B
> > > > > > > > paul.carter-br...@smilecoms.com
> > > > > > > > www.smilecoms.com
> > > > > > > >
> > > > > > > > --
> > > > > > > >
> > > > > > > >
> > > > > > > > This email is subject to the disclaimer of Smile
> Communications
> > > at
> > > > > > > > http://www.smilecoms.com/home/email-disclaimer/ <
> > > > > > > http://www.smilecoms.com/
> > > > > > > > disclaimer>
> > > > > > > >
> > > > > > > >
> > > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > > --
> > > > > >
> > > > > > *Paul Carter-Brown*
> > > > > >
> > > > > > *Group Chief Information Officer*
> > > > > >
> > > > > > *Smile Communications Pty (Ltd) *
> > > > > > Smile +234 (0) 702 000 1234 <+234%20702%20000%201234>
> > > > > > Mobile +27 (0) 83 4427 179
> > > > > > Skype PaulC-B
> > > > > > paul.carter-br...@smilecoms.com
> > > > > > www.smilecoms.com
> > > > > >
> > > > > > --
> > > > > >
> > > > > >
> > > > > > This email is subject to the disclaimer of Smile Communications
> at
> > > > > > http://www.smilecoms.com/home/email-disclaimer/ <
> > > > > http://www.smilecoms.com/
> > > > > > disclaimer>
> > > > > >
> > > > > >
> > > > >
> > > >
> > > > --
> > > >
> > > >
> > > > This email is subject to the disclaimer of Smile Communications at
> > > > http://www.smilecoms.com/home/email-disclaimer/ <
> > > http://www.smilecoms.com/
> > > > disclaimer>
> > > >
> > > >
> > >
> >
> >
> >
> > --
> >
> > *Paul Carter-Brown*
> >
> > *Group Chief Information Officer*
> >
> > *Smile Communications Pty (Ltd) *
> > Smile +234 (0) 702 000 1234 <+234%20702%20000%201234>
> > Mobile +27 (0) 83 4427 179
> > Skype PaulC-B
> > paul.carter-br...@smilecoms.com
> > www.smilecoms.com
> >
> > --
> >
> >
> > This email is subject to the disclaimer of Smile Communications at
> > http://www.smilecoms.com/home/email-disclaimer/ <
> http://www.smilecoms.com/
> > disclaimer>
> >
> >
>
>
>
--
*Paul Carter-Brown*
*Group Chief Information Officer*
*Smile Communications Pty (Ltd) *
Smile +234 (0) 702 000 1234
Mobile +27 (0) 83 4427 179
Skype PaulC-B
paul.carter-br...@smilecoms.com
www.smilecoms.com
--
This email is subject to the disclaimer of Smile Communications at
http://www.smilecoms.com/home/email-disclaimer/
<http://www.smilecoms.com/disclaimer>
