Petals BC SOAP

With the current 4.4.1-SNAPSHOT version (svn#38660), I get the following stack trace that should be the same problem symptom:

container-node_1 2015/10/29 15:32:48,156 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap.edpt-4bb2b850-7e52-11e5-aecc-0242ac11003a] : Can't return the service client to the pool javax.jbi.messaging.MessagingException: Can't find the Axis service client's pool: this should never happen! Key: http://172.17.0.39:80/samples-SOAP-services/services/notifyVacationService,{http://petals.ow2.org/samples/se-bpmn/notifyVacationService}newVacationRequest,http://www.w3.org/ns/wsdl/in-out
        at org.ow2.petals.binding.soap.SoapComponentContext.returnServiceClient(SoapComponentContext.java:588)
        at org.ow2.petals.binding.soap.listener.outgoing.SOAPCaller.call(SOAPCaller.java:228)
        at org.ow2.petals.binding.soap.listener.outgoing.JBIListener.onJBIMessage(JBIListener.java:59)
        at org.ow2.petals.component.framework.process.MessageExchangeProcessor.invokeJBIListener(MessageExchangeProcessor.java:475)
        at org.ow2.petals.component.framework.process.MessageExchangeProcessor.processAsProvider(MessageExchangeProcessor.java:414)
        at org.ow2.petals.component.framework.process.MessageExchangeProcessor.process(MessageExchangeProcessor.java:276)
        at org.ow2.petals.component.framework.process.MessageExchangeProcessor.run(MessageExchangeProcessor.java:200)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)

This problem occurs also on a container completely started before to launch the load test, that is not instantiated by Roboconf autonomic.

So, this problem should be a simple request processing concurrency problem, not linked to the startup of SU.

There hasn't been any property holder reload or something like that that would explain a change of the one of the elements of the ServiceClientKey used to identify the pool?? Or that would explain that the pool was removed (which also happen on property holder reload).

The question is: is it happening around the time onPlaceHolderValuesReloaded is called?

If yes, it is easy to fix: if the pool is not there, then we can just discard the object and it will be garbage collected instead of being returned to the pool.

I'm not able to say if a placeholder reloading occurs around the time of this error. I will run again the load test and check that.

With a new run of the load test, we can see into logs of a replicated container:

• in MONIT traces:

  container-node 2015/10/30 13:45:53,476 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap.edpt-57e0bef0-7f0c-11e5-aae9-0242ac11004e] : Can't return the service client to the pool
  javax.jbi.messaging.MessagingException: Can't find the Axis service client's pool: this should never happen! Key: http://172.17.0.63:80/samples-SOAP-services/services/notifyVacationService,{http://petals.ow2.org/samples/se-bpmn/notifyVacationService}newVacationRequest,http://www.w3.org/ns/wsdl/in-out
          at org.ow2.petals.binding.soap.SoapComponentContext.returnServiceClient(SoapComponentContext.java:588)
          at org.ow2.petals.binding.soap.listener.outgoing.SOAPCaller.call(SOAPCaller.java:228)
          at org.ow2.petals.binding.soap.listener.outgoing.JBIListener.onJBIMessage(JBIListener.java:59)
          at org.ow2.petals.component.framework.process.MessageExchangeProcessor.invokeJBIListener(MessageExchangeProcessor.java:475)
          at org.ow2.petals.component.framework.process.MessageExchangeProcessor.processAsProvider(MessageExchangeProcessor.java:414)
          at org.ow2.petals.component.framework.process.MessageExchangeProcessor.process(MessageExchangeProcessor.java:276)
          at org.ow2.petals.component.framework.process.MessageExchangeProcessor.run(MessageExchangeProcessor.java:200)
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
          at java.lang.Thread.run(Thread.java:745)

• in general Petals traces, place holders of BC SOAP was reloaded 4 times in 0.5s :

  container-node 2015/10/30 13:45:53,065 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53113,localport=7800]
  container-node 2015/10/30 13:45:53,067 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53114,localport=7800]
  container-node 2015/10/30 13:45:53,136 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloading.
  container-node 2015/10/30 13:45:53,136 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
  container-node 2015/10/30 13:45:53,215 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53130,localport=7800]
  container-node 2015/10/30 13:45:53,254 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53146,localport=7800]
  container-node 2015/10/30 13:45:53,255 GMT+0000 SEVERE [Petals.Transporter.NioTransportProtocol.NioSelectorAgent] : Socket Socket[addr=/172.17.0.76,port=7800,localport=48265] : null
  java.nio.channels.ClosedChannelException
          at java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:194)
          at org.ow2.petals.microkernel.transport.platform.nio.selector.NioSelectorAgent.run(NioSelectorAgent.java:109)
          at java.lang.Thread.run(Thread.java:745)
  container-node 2015/10/30 13:45:53,266 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53147,localport=7800]
  container-node 2015/10/30 13:45:53,269 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloading.
  container-node 2015/10/30 13:45:53,270 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
  container-node 2015/10/30 13:45:53,399 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53171,localport=7800]
  container-node 2015/10/30 13:45:53,433 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloading.
  container-node 2015/10/30 13:45:53,433 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
  container-node 2015/10/30 13:45:53,434 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53188,localport=7800]
  container-node 2015/10/30 13:45:53,446 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53189,localport=7800]
  container-node 2015/10/30 13:45:53,505 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53205,localport=7800]
  container-node 2015/10/30 13:45:53,511 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53206,localport=7800]
  container-node 2015/10/30 13:45:53,546 GMT+0000 INFO [Petals.Transporter.NioTransportProtocol.NioServerAgent] : A connection is accepted: Socket[addr=/172.17.0.76,port=53215,localport=7800]
  container-node 2015/10/30 13:45:53,560 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloading.
  container-node 2015/10/30 13:45:53,561 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.

So the error seems to be concomitant to the place holders reloading.

The fix you proposed seems to be valid, but don't you think that the synchronization of place holders reloading and pools usage should be reviewed ? For example, when a place holders reloading occurs, the place holders reloading waits the end of current request processing and new incoming requests should wait the end of the place holders reloading ?

I was thinking about that, and:
1) new requests are actually already blocked, due to the synchronisation on the pools (borrowServiceClient blocks until the reload has finished.

2) delaying the reload could be done, but this would introduce many complexity and blocking behaviour in the code for nothing very important: if we just skip the return in case the pool has disappeared or a new one has taken over, then the returned object will be garbage collected and the pool will have no problems: so the current request will end as it should without any problem.

I'm implementing this fix now

Ok, so the implementation will be as follows:

• There is the map containing the pool for each ServiceClientKey (aka the URL, which is potentially changed by placeholder reload)
• There will be a map containing the closed pools for each ServiceClientKey
• On reload of the placeholders, the pools are closed and moved to the closed pools map if there is still some active object not yet returned

Two cases can arise on returning an object:

• The URL actually changed because of the placeholders reload, so the object can only be returned to the closed pool (that matches the returned object ServiceClientKey)
• The URL didn't change, so the object returned can actually either be returned to the new current pool for this ServiceClientKey, or the closed one, it is exactly equivalent since objects created from a pool are only dependent on the ServiceClientKey.

So what should happen on returning an object is:

• If there is an closed pool for the returned object ServiceClientKey, then return the object to this pool, and remove it from the map if there is no more active objects not yet returned
• Else, simply return the object to the current pool for its ServiceClientKey.

It should cover both cases: what can happen is that sometimes an object borrowed from the current pool is returned to the closed one, but it's ok as explained above.

Caused by PETALSBCSOAP-173.

IMO, we can fix the synchronization problem using

• a simple Semaphore(max size of ws client pool)
• the semaphore is unitary acquired into SoapComponentContext.borrowServiceClient when borrowing the ws-client from its pool,
• the semaphore is unitary released when returning the ws-client to its pool,
• deleting ws-client pools, the semaphore is acquired with a number of permits equals to the max size of ws-client pools before deleting pool, and released just after.

This should be sufficient to synchronize place holders reloading with ws-client pool usages.

I already responded to that in PETALSBCSOAP-173, let's keep discussion there

A fix has been committed, could you test again and tell me if it's good?

It seems ok now