Re: CXF JAX-RS client proxy and duplicate requests under load

Wed, 29 Apr 2015 07:19:49 -0700 

Hi Viet,
We've chatted with Dan, and it appears we can not safely close AsyncHttpConduit's client thread pool as that pool may be shared with other HttpClient. 


This pool should get cleared if the CXF bus that is ultimately keeping 
this conduit is shutdown.



If you have the same CXF default bus shared between the server and 
clients then I guess it will only happen when CXF gets unloaded.



CXF client uses a thread default bus but I'm not sure it is safe to 
assume that such a bus would be different from the one used by the server.



I think what you can try to do is to create a unique bus for this shared 
client, if you get it injected on the server then you'd have a bus 
attribute set on jaxrs:client:


<core:bus name="cxf1" id="cxf1"/>
and then set refer to it from jaxrs:client.

From the code:
Bus bus = BusFactory.newInstance().createBus();
JAXRSClientfactoryBean bean = ...
bean.setBus()

and then before calling Client.close(), safe a reference to this bus

with WebClient.getConfig(proxy).getBus();

and then after close(), do bus.shutdown().


Can you please experiment ? If that works then I can add a property the 
client to optionally shutdown the bus on close() to simplify the code.


Thanks, Sergey


On 29/04/15 12:25, Sergey Beryozkin wrote:

Hi Veit

I've checked AsyncHttpConduit, it creates CloseableHttpClient.
I do not see it being cached, CXF does not call on CloseableHttpClient,
I wonder if it should, even though it is auto-closeable, I'll have to
ask Dan about it... Will get back to you...

Thanks, Sergey

On 29/04/15 08:05, Veit Guna wrote:

Hi Sergey.

Ok, I've tried that with:

WebClient.client(myProxy).close();

but the underlying thread pool does not seem to be closed. The JVM is
still waiting for
the threads to be shutdown (I guess).

Any ideas?

Thanks
Veit


Gesendet: Dienstag, 28. April 2015 um 17:32 Uhr
Von: "Sergey Beryozkin" <sberyoz...@gmail.com>
An: users@cxf.apache.org
Betreff: Re: Aw: Re: Re: Re: Re: Re: CXF JAX-RS client proxy and
duplicate requests under load
Just a quick note that to close a proxy you need to cast to Client first
with a WebClient helper, and then close it...

Cheers, Sergey
On 28/04/15 16:30, Sergey Beryozkin wrote:

Hi Veit
On 28/04/15 16:21, Veit Guna wrote:

Hi Sergery.

On first sight, it seems to work with the HttpClient conduit.
But now I'm wondering, when the created thread-pool of the HttpClient
conduit will be closed.
As I can see, 8 threads are created (=cpu core count) and won't be
terminated on normal
test case exit. So when the client is used somewhere in a war
(server-to-server communication), this
will lead to hanging threads on e.g. re-deploy or shutdown.

Do you have any insights into that?


WebClient API and JAX-RS 2.0 Client API has close() method so it should
help


I haven't had time yet to look into the Jersey CXF client yet, but I'm
not very keen on switching
from CXF to plain Jersey client ;). I will do some googling regarding
HttpUrlConnection though.


OK...

Just in case,

MyService myService =
JAXRSClientFactory.create("http://localhost:8080/test";,
MyService.class);
myService.getSomething(uuid1.toString());

can be replaced with this 2.0 API:

Client client = ClientBuilder.newClient();
client.target("http://localhost:8080/test";).request("application/json").get(String.class);



that would run with CXF and then you can try Jersey client...

Cheers, Sergey


Thanks
Veit


Gesendet: Dienstag, 28. April 2015 um 13:45 Uhr
Von: "Sergey Beryozkin" <sberyoz...@gmail.com>
An: users@cxf.apache.org
Betreff: Re: Aw: Re: Re: Re: Re: CXF JAX-RS client proxy and duplicate
requests under load
If it works with Jersey Client (HttpUrlConnection) and is also known to
work with CXF HttpClient based conduit, then I guess it would narrow it
down to CXF UrlConnectionHttpConduit that might set some of the
properties on HttpUrlConnection which might affect it somehow...

Sergey

On 28/04/15 12:07, Sergey Beryozkin wrote:

Hi

Thanks for preparing this test, appears to be that using HttpClient
resolves it. So I've updated pom.xml:

<dependency>
<groupId>org.apache.cxf</groupId>
<artifactId>cxf-rt-transports-http-hc</artifactId>
<version>3.0.4</version>
<scope>test</scope>
</dependency>

and added this line to LoadTest(), immediately after creating a proxy,

WebClient.getConfig(myService).getRequestContext().put("use.async.http.conduit",


true);

Run the test 3 times, works fine.

I'm not sure what conclusions should be drawn here. I think it is
probably Java HttpURLConnection sending some duplicate requests ?

Can you please investigate if HttpURLConnection is known to do it in
some cases ? I've no other ideas right now. May be also run a Jersey
client in the same setup ?

Sergey




On 27/04/15 21:46, Veit Guna wrote:

Hi Sergey.

I've created a separate standalone maven project, that demonstrates
the problem.
It's no beauty - but it gets to the point :).

It contains a war that offers the endpoints and a cxf client, that
sends requests to it.

If you run "mvn clean install" it will automatically deploy the
war to
a tomcat
container via cargo and executes the TestNG testcase. And will
hopefully fail ;).

As you requested a non-testng Test as well, try the "SimpleExecutor".
It has a
main() you can execute. It should print Exceptions on the console
that
indicates
the problem. You will see, that duplicate requests (UUIDs) will come
to the server.
Just search the logs on both sides for the duplicates and you'll see
what I mean.

Funny thing: if I enable CXF logging, the tests are green :). Maybe
has something
TODO with timing.

The war does not perform any authentication. It would be nice, If you
could
try the "async transport" by yourself ;).

Thanks
Veit



Gesendet: Montag, 27. April 2015 um 18:43 Uhr
Von: "Sergey Beryozkin" <sberyoz...@gmail.com>
An: users@cxf.apache.org
Betreff: Re: Aw: Re: Re: Re: CXF JAX-RS client proxy and duplicate
requests under load
On 27/04/15 17:17, Veit Guna wrote:

Thanks :).

Sadly this doesn't make any difference :(. Still two requests...

This is sad indeed :-).

Is there any chance for you to prepare a test (without TestNG, just a
java client with multiple threads) ? CXF proxy does not send the same
request twice for a given thread invocation. I honestly can not
think of
why it might be the case. Hmm..., a couple of thoughts:

- you use Basic Authentication, and CXF HttpConduit (wrapper above
the
low-level HTTP transport) can retransmit if a server has replied with
401. This is perhaps unlikely to cause a problem in your case but can
you please double check if the problem persists without using Basic
Auth
(may be you need to temp disable the server-based authentication...)

- Can you please include cxf-rt-transports-http-hc module which
HttpClient async transport. Then set a property with a bean,
"use.async.http.conduit" - true. And rerun the test.

If you create a test that fails consistently then I can do the above
check with the async transport myself

Thanks, Sergey




Regards,
Veit



Gesendet: Montag, 27. April 2015 um 17:55 Uhr
Von: "Sergey Beryozkin" <sberyoz...@gmail.com>
An: users@cxf.apache.org
Betreff: Re: Aw: Re: Re: CXF JAX-RS client proxy and duplicate
requests under load
Sure, use JAXRSClientFactoryBean instead,

JAXRSClientFactoryBean bean = new JAXRSClientFactoryBean();
bean.setAddress(...);
bean.setServiceClass(...);
bean.setThreadSafe(true);
bean.setUserName(...);
bean.setPassword(...);
SomeClass proxy = bean.create(SomeClass.class);

Cheers, Sergey

On 27/04/15 16:52, Veit Guna wrote:

Sure, but I can't find a suitable ctor on JAXRSClientFactory for
specifiying threadSafety AND username/password.
Could you give me a hint :)?

Thanks.



Gesendet: Montag, 27. April 2015 um 17:34 Uhr
Von: "Sergey Beryozkin" <sberyoz...@gmail.com>
An: users@cxf.apache.org
Betreff: Re: Aw: Re: CXF JAX-RS client proxy and duplicate requests
under load
Hi
Can you actually set a threadSafe flag on the factory before
creating a
proxy ?
If you have a proxy reused by multiple threads and invoking
multiple
methods on it there are likely to be some side-effects.
I'm not 100% yet that is the cause of the problem but I;d like
you to
confirm that you are seeing the same problem even of you set a flag

Thanks, Sergey

On 27/04/15 16:31, Veit Guna wrote:

Hi Sergey.

I've tested some more. It seems that it is not only related to
DELETE requests.
I've isolated the problem into the following:

- created an endpoint that simply takes an ID and stores it in a
HashSet
- if an entry already exists, it fails with an Exception (to
demonstrate duplicate requests)
- the endpoint always returns 404
- the test method (50 parallel threads, 50 invocations)
- loops 10 times over:
- performs a GET request to the endpoint using a newly generated
uuid, within a try catch NotFoundException block.
- performs a 2nd GET request using a new uuid, within a try catch
NotFoundException block

If all goes well, the test should be ok.
But in my case, the same request (same UUID) came in 5 times and
returned HTTP 500 (Exception due to duplicate UUIDs).

That means, that if you have 2 invocations on a proxy, and the 2nd
returns an Exception (e.g. NotFound) , it seems to send one of the
requests again to the server.

Can you confirm that behavior?

Thanks
Veit





Gesendet: Montag, 27. April 2015 um 13:25 Uhr
Von: "Sergey Beryozkin" <sberyoz...@gmail.com>
An: users@cxf.apache.org
Betreff: Re: CXF JAX-RS client proxy and duplicate requests under
load
Hi

So even though the client proxy calls delete() only once you still
see a
DELETE request coming twice to the server.
The initial question: Do you observe it for delete() only ?

Thanks, Sergey



On 27/04/15 11:28, Veit Guna wrote:

Hi.

I'm using Apache CXF 3.0.4 in client JAX-RS proxy mode to access
my services on the server via annotated server interfaces.
Under normal operation, this works so far.

Now, I've created a testcase that:

- create a proxy with JAXRSClientFactory.create()
- creates 10 resources
- gets the 10 resources
- updates the 10 resources
- deletes the 10 resources.

All above sequentially executed. Works when simply executed.

Now I've configured TestNG to execute this test method with 50
threads and 50 invocations concurrently.
Every now and then, it happens that the testcase fails with an
HTTP 500 error.

I've checked the server logs and I can see, that a DELETE request
for the same resource comes in twice in
a distance of approx. 20 msecs. Of course, only one request
succeeds, the other fails.

I've created logging on the testcase client side and I can
confirm, that delete() is only called once on
the CXF client proxy. So I'm wondering, why the client generates
two requests. Any idea what is happening there?

I also enabled the CXF logging on client side via cxf.xml and I
can see:

- DELETE request is send (ID: 1779)
- Response HTTP 500 is returned (ID: 1779)
- DELETE request is send? (ID: 1779 - SAME id?! Logged as
"Inbound
Message")
- No response. No further ID 1779.

The server side logging looks like this

- DELETE comes in (thread 437)
20ms later
- DELETE comes in (thread 521)
2secs later
- thread 521 completes successfully with HTTP 204.
- thread 437 throws HTTP 500.

What I'm wondering is, how the order gets mixed up. Any idea how
that can happen?

Here are detailed extractions from the logs:

--cut here--
############
Client side:
############

11:31:16,662 INFO [] [LoggingOutInterceptor:250] - Outbound
Message
---------------------------
ID: 1779
Address:
http://localhost:8080/someservice/api/1/tenants/6a4322df-ad20-41b7-a5c9-908cadc509f5/repositories/f7c21bad-6743-4bed-916c-0b58d876204e/entries/46f069fa-c6a2-41cc-9dbc-ac5a2faffcfb



Http-Method: DELETE
Content-Type: application/xml
Headers: {Content-Type=[application/xml], Accept=[text/plain],
Authorization=[Basic ZmlsZW5zaGFyZTpzZWNyZXQ=]}
...
...
--------------------------------------
11:31:18,776 INFO [] [LoggingInInterceptor:250] - Inbound Message
----------------------------
ID: 1779
Response-Code: 500
Encoding: ISO-8859-1
Content-Type: application/json
Headers: {connection=[close], Content-Length=[308],
content-type=[application/json], Date=[Mon, 27 Apr 2015 09:31:18
GMT], Server=[Apache-Coyote/1.1]}
Payload: {
--------------------------------------
11:31:18,776 INFO [] [LoggingInInterceptor:250] - Inbound Message
----------------------------
ID: 1779
Address:
http://localhost:8080/someservice/api/1/tenants/6a4322df-ad20-41b7-a5c9-908cadc509f5/repositories/f7c21bad-6743-4bed-916c-0b58d876204e/entries/46f069fa-c6a2-41cc-9dbc-ac5a2faffcfb



Http-Method: DELETE
Content-Type: application/xml
Headers: {Content-Type=[application/xml], Accept=[text/plain],
Authorization=[Basic ZmlsZW5zaGFyZTpzZWNyZXQ=]}


############
Server side:
############

Apr 27, 2015 11:31:16 AM
org.glassfish.jersey.filter.LoggingFilter
log
INFO: 33572 * Server has received a request on thread
http-bio-8080-exec-437
33572 > DELETE
http://localhost:8080/someservice/api/1/tenants/6a4322df-ad20-41b7-a5c9-908cadc509f5/repositories/f7c21bad-6743-4bed-916c-0b58d876204e/entries/46f069fa-c6a2-41cc-9dbc-ac5a2faffcfb



33572 > accept: text/plain
33572 > authorization: Basic something=
33572 > cache-control: no-cache
33572 > connection: keep-alive
33572 > content-type: */*
33572 > host: localhost:8080
33572 > pragma: no-cache
33572 > user-agent: Apache CXF 3.0.4

20ms between them

Apr 27, 2015 11:31:16 AM
org.glassfish.jersey.filter.LoggingFilter
log
INFO: 33573 * Server has received a request on thread
http-bio-8080-exec-521
33573 > DELETE
http://localhost:8080/someservice/api/1/tenants/6a4322df-ad20-41b7-a5c9-908cadc509f5/repositories/f7c21bad-6743-4bed-916c-0b58d876204e/entries/46f069fa-c6a2-41cc-9dbc-ac5a2faffcfb



33573 > accept: text/plain
33573 > authorization: Basic something=
33573 > cache-control: no-cache
33573 > connection: keep-alive
33573 > content-type: */*
33573 > host: localhost:8080
33573 > pragma: no-cache
33573 > user-agent: Apache CXF 3.0.4


Apr 27, 2015 11:31:18 AM
org.glassfish.jersey.filter.LoggingFilter
log
INFO: 33654 * Server responded with a response on thread
http-bio-8080-exec-521
33654 < 204


Apr 27, 2015 11:31:18 AM
org.glassfish.jersey.filter.LoggingFilter
log
INFO: 33669 * Server responded with a response on thread
http-bio-8080-exec-437
33669 < 500
33669 < Content-Type: application/json
{
someerror json
}
--cut here--

Thanks.
Veit










--
Sergey Beryozkin

Talend Community Coders
http://coders.talend.com/

Blog:
http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com]][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com]]][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com]][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com]]]]












--
Sergey Beryozkin

Talend Community Coders
http://coders.talend.com/[http://coders.talend.com/][http://coders.talend.com/[http://coders.talend.com/]]


Blog:
http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com][http://sberyozkin.blogspot.com[http://sberyozkin.blogspot.com]]





































					Reply via email to