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(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.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> >> >>
