Petals BC SOAP

Concurrency problems with the WS client pools and the placeholders reloading

Details

  • Type: Bug Bug
  • Status: Resolved Resolved
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 4.4.0
  • Fix Version/s: 4.4.2
  • Component/s: None
  • Security Level: Public
  • Description:
    Hide

    The problem is that when the placeholders are reloaded, the pools are destroyed, but problems can arise:

    • Some objects were not returned yet: they risk being returned to a newly created pool instead of the old one, or worst, an exception is thrown if there is not yet a new pool created (see PETALSBCSOAP-168).
    • The pool can be removed/closed after the pool is retrieved during a borrow, but before an object is actually borrowed from it and thus an exception is thrown by the pool because it is closed (see PETALSBCSOAP-171).
    • Maybe other problems... ?
    Show
    The problem is that when the placeholders are reloaded, the pools are destroyed, but problems can arise:
    • Some objects were not returned yet: they risk being returned to a newly created pool instead of the old one, or worst, an exception is thrown if there is not yet a new pool created (see PETALSBCSOAP-168).
    • The pool can be removed/closed after the pool is retrieved during a borrow, but before an object is actually borrowed from it and thus an exception is thrown by the pool because it is closed (see PETALSBCSOAP-171).
    • Maybe other problems... ?
  • Environment:
    -

Issue Links

Depends
 

Activity

Descending order - Click to sort in ascending order
Hide
Permalink
Christophe DENEUX added a comment - Mon, 19 Sep 2016 - 14:52:09 +0200

According to the performance test executed 2016/09/19, no more errors occurs about this issue.

Show
Christophe DENEUX added a comment - Mon, 19 Sep 2016 - 14:52:09 +0200 According to the performance test executed 2016/09/19, no more errors occurs about this issue.
Hide
Permalink
Victor NOËL added a comment - Fri, 6 Nov 2015 - 17:51:32 +0100

Ok, I committed another fix, much simpler: we store the pool from which a service client has been taken inside the service client, and use it to return the client: so now there is much less synchronization needed.

As for the probes, I think we shouldn't use a pool probes, but make a custom one that we can increment and decrement per key in our borrow/return, if that's possible…?

Show
Victor NOËL added a comment - Fri, 6 Nov 2015 - 17:51:32 +0100 Ok, I committed another fix, much simpler: we store the pool from which a service client has been taken inside the service client, and use it to return the client: so now there is much less synchronization needed. As for the probes, I think we shouldn't use a pool probes, but make a custom one that we can increment and decrement per key in our borrow/return, if that's possible…?
Hide
Permalink
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:48:10 +0100 - edited

Yes, when there is no more service clients available AND none became available before the end of the timeout (the pool first blocks for timeout and then throw an exception).

So, normally, with these settings, it's really strange that the BC SOAP can't get enough service clients yes…

Show
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:48:10 +0100 - edited Yes, when there is no more service clients available AND none became available before the end of the timeout (the pool first blocks for timeout and then throw an exception). So, normally, with these settings, it's really strange that the BC SOAP can't get enough service clients yes…
Hide
Permalink
Christophe DENEUX added a comment - Thu, 5 Nov 2015 - 16:28:41 +0100

The same operation is always invoked. The default value of processorMaxPoolSize is used: 50. The timeout configured on the provides section is 30000ms (30s).

IMO, an exhaustion occurs when there is no more service clients available.

Show
Christophe DENEUX added a comment - Thu, 5 Nov 2015 - 16:28:41 +0100 The same operation is always invoked. The default value of processorMaxPoolSize is used: 50. The timeout configured on the provides section is 30000ms (30s). IMO, an exhaustion occurs when there is no more service clients available.
Hide
Permalink
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:17:16 +0100

Also, what is the configured timeout on the provides sections corresponding to these service clients?
This is this timeout that determines if a pool is exhausted or not when there is no more service clients available.

Show
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:17:16 +0100 Also, what is the configured timeout on the provides sections corresponding to these service clients? This is this timeout that determines if a pool is exhausted or not when there is no more service clients available.
Hide
Permalink
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:05:26 +0100

Ah, and it is highly possible that WsClientPoolClientsInUseMax is not giving us the right value (so no, probes doesn't give us the right value...) because when the switch of pools happen on reload, nothing is done w.r.t. the probes to handle this inbetween situation...

Show
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:05:26 +0100 Ah, and it is highly possible that WsClientPoolClientsInUseMax is not giving us the right value (so no, probes doesn't give us the right value...) because when the switch of pools happen on reload, nothing is done w.r.t. the probes to handle this inbetween situation...
Hide
Permalink
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:03:57 +0100

There is 25 injectors but are you using multiple operations? there is one service client per url/operation…

What is the value used for ProcessorMaxPoolSize?

At least the monitoring probes seem to give us correct values

Show
Victor NOËL added a comment - Thu, 5 Nov 2015 - 16:03:57 +0100 There is 25 injectors but are you using multiple operations? there is one service client per url/operation… What is the value used for ProcessorMaxPoolSize? At least the monitoring probes seem to give us correct values
Hide
Permalink
Christophe DENEUX added a comment - Thu, 5 Nov 2015 - 15:46:22 +0100

The fix seems insufficient. With BC SOAP 4.4.1-SNAPSHOT (svn#38674), I get the following error 13 times in flow monit logs:

container-prov-node-1_-4 2015/11/05 14:03:09,698 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap] : Service client pool is exhausted (Key: 'http://172.17.0.2:80/samples-SOAP-services/services/notifyVacationService,{http://petals.ow2.org/samples/se-bpmn/notifyVacationService}newVacationRequest,http://www.w3.org/ns/wsdl/in-out')
container-prov-node-1_-4 2015/11/05 14:03:09,701 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap.edpt-cc0984c0-83c5-11e5-851f-0242ac110008] : Cannot get a service client 'http://172.17.0.2:80/samples-SOAP-services/services/notifyVacationService, {http://petals.ow2.org/samples/se-bpmn/notifyVacationService}newVacationRequest, http://www.w3.org/ns/wsdl/in-out' from the pool because none is available. Retry later !

and with in the same time in general log of the container:

container-prov-node-1_-4 2015/11/05 14:01:23,338 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:01:35,597 GMT+0000 INFO [Petals.Container.Components.petals-se-activiti] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:03,646 GMT+0000 INFO [Petals.Container.Components.petals-se-activiti] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:06,905 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:07,664 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,438 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,510 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,693 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,846 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:09,017 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:09,108 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:25,964 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:10,949 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,152 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,309 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,438 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,487 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,558 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,581 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:33,629 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:33,753 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:33,967 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:34,287 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.

Metrics of this BC SOAP indicate:

  • WsClientPoolClientsInUseCurrent = 0, that is OK,
  • WsClientPoolClientsInUseMax = 50, that is strange because the load test has only 25 injectors,
  • WsClientPoolExhaustions = 13, the number of error 'Service client pool is exhausted ...'.

I get also the following error 7 times:

container-prov-node-1_-4 2015/11/05 14:03:11,194 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap.edpt-cc0984c0-83c5-11e5-851f-0242ac110008] : 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.2:80/samples-SOAP-services/services/notifyVacationService,{http://petals.ow
2.org/samples/se-bpmn/notifyVacationService}newVacationRequest,http://www.w3.org/ns/wsdl/in-out
        at org.ow2.petals.binding.soap.SoapComponentContext.returnServiceClient(SoapComponentContext.java:530)
        at org.ow2.petals.binding.soap.listener.outgoing.SOAPCaller.call(SOAPCaller.java:234)
        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)
Show
Christophe DENEUX added a comment - Thu, 5 Nov 2015 - 15:46:22 +0100 The fix seems insufficient. With BC SOAP 4.4.1-SNAPSHOT (svn#38674), I get the following error 13 times in flow monit logs: 
container-prov-node-1_-4 2015/11/05 14:03:09,698 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap] : Service client pool is exhausted (Key: 'http://172.17.0.2:80/samples-SOAP-services/services/notifyVacationService,{http://petals.ow2.org/samples/se-bpmn/notifyVacationService}newVacationRequest,http://www.w3.org/ns/wsdl/in-out')
container-prov-node-1_-4 2015/11/05 14:03:09,701 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap.edpt-cc0984c0-83c5-11e5-851f-0242ac110008] : Cannot get a service client 'http://172.17.0.2:80/samples-SOAP-services/services/notifyVacationService, {http://petals.ow2.org/samples/se-bpmn/notifyVacationService}newVacationRequest, http://www.w3.org/ns/wsdl/in-out' from the pool because none is available. Retry later !
and with in the same time in general log of the container: 
container-prov-node-1_-4 2015/11/05 14:01:23,338 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:01:35,597 GMT+0000 INFO [Petals.Container.Components.petals-se-activiti] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:03,646 GMT+0000 INFO [Petals.Container.Components.petals-se-activiti] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:06,905 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:07,664 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,438 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,510 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,693 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:08,846 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:09,017 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:09,108 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:02:25,964 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:10,949 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,152 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,309 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,438 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,487 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,558 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:11,581 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:33,629 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:33,753 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:33,967 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
container-prov-node-1_-4 2015/11/05 14:03:34,287 GMT+0000 INFO [Petals.Container.Components.petals-bc-soap] : Placeholders reloaded.
Metrics of this BC SOAP indicate:
  • WsClientPoolClientsInUseCurrent = 0, that is OK,
  • WsClientPoolClientsInUseMax = 50, that is strange because the load test has only 25 injectors,
  • WsClientPoolExhaustions = 13, the number of error 'Service client pool is exhausted ...'.
I get also the following error 7 times: 
container-prov-node-1_-4 2015/11/05 14:03:11,194 GMT+0000 WARNING [Petals.Container.Components.petals-bc-soap.edpt-cc0984c0-83c5-11e5-851f-0242ac110008] : 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.2:80/samples-SOAP-services/services/notifyVacationService,{http://petals.ow
2.org/samples/se-bpmn/notifyVacationService}newVacationRequest,http://www.w3.org/ns/wsdl/in-out
        at org.ow2.petals.binding.soap.SoapComponentContext.returnServiceClient(SoapComponentContext.java:530)
        at org.ow2.petals.binding.soap.listener.outgoing.SOAPCaller.call(SOAPCaller.java:234)
        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)
Hide
Permalink
Victor NOËL added a comment - Mon, 2 Nov 2015 - 14:22:08 +0100

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

Show
Victor NOËL added a comment - Mon, 2 Nov 2015 - 14:22:08 +0100 A fix has been committed, could you test again and tell me if it's good?
Hide
Permalink
Victor NOËL added a comment - Mon, 2 Nov 2015 - 09:20:31 +0100

I don't really like adding more complex mechanisms relying on a specific value if this number is also managed by the pool and stuffs like this: the problem is to be sure everything stays consistent between all the mechanism that relies on this value. And it also means we have to maintain one more collection of stuffs (the semaphore) mapped to the keys that can change during reloads… !

It's a lot of maintenance work while there exists simpler mechanisms to handle this kind of situation I think. Anyway, I already came up with a solution, I'm testing it and will commit it soon.

Show
Victor NOËL added a comment - Mon, 2 Nov 2015 - 09:20:31 +0100 I don't really like adding more complex mechanisms relying on a specific value if this number is also managed by the pool and stuffs like this: the problem is to be sure everything stays consistent between all the mechanism that relies on this value. And it also means we have to maintain one more collection of stuffs (the semaphore) mapped to the keys that can change during reloads… ! It's a lot of maintenance work while there exists simpler mechanisms to handle this kind of situation I think. Anyway, I already came up with a solution, I'm testing it and will commit it soon.
Hide
Permalink
Christophe DENEUX added a comment - Fri, 30 Oct 2015 - 22:00:25 +0100

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.

Show
Christophe DENEUX added a comment - Fri, 30 Oct 2015 - 22:00:25 +0100 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.

People

Dates

  • Created:
    Fri, 30 Oct 2015 - 17:40:05 +0100
    Updated:
    Mon, 19 Sep 2016 - 14:52:49 +0200
    Resolved:
    Mon, 19 Sep 2016 - 14:52:49 +0200
Atlassian JIRA (v4.1.2#531) | Report a problem | Request a feature | Contact administrators
Powered by a free Atlassian JIRA open source license for Petals ESB. Try JIRA - bug tracking software for your team.