You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cxf.apache.org by Veit Guna <Ve...@gmx.de> on 2015/04/27 12:28:36 UTC
CXF JAX-RS client proxy and duplicate requests under load
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
Re: CXF JAX-RS client proxy and duplicate requests under load
Posted by Sergey Beryozkin <sb...@gmail.com>.
And do you create a proxy with a thread safe flag enabled ?
Cheers, Sergey
On 27/04/15 12:25, Sergey Beryozkin wrote:
> 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
>>
>
Re: CXF JAX-RS client proxy and duplicate requests under load
Posted by Sergey Beryozkin <sb...@gmail.com>.
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
>