Hi Sergey. Thanks for the quick reply! I haven't explicitly looked for other methods yet. I just stumbled across DELETE because of the exception. Right now, I looked in the log for duplicate GETs. But they were all unique. Maybe some more information: During the deletion of the 10 resources in a loop, the following is done: for - get sub resource by id from proxy - perform DELETE - perform GET on same resource (proxy) and expect a 404. loop If I remove the GET from the loop, it seems to work. Maybe somehow the state of the proxy gets "dirty" by NotFoundException (404) and somehow affects the next DELETE? Just a wild guess :). The whole testmethod is executed sequentially. This includes creating a new proxy via JAXRSClientFactory.create() as local method variable. So I think this should be safe. The test method itself is of course invoked by 50 threads concurrently. create() is invoked _without_ the threadSafe boolean since the proxy itself is not accessed by different threads concurrently. 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 >
