cxf-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Sergey Beryozkin <sberyoz...@gmail.com>
Subject Re: Aw: Re: Re: Re: Re: CXF JAX-RS client proxy and duplicate requests under load
Date Tue, 28 Apr 2015 11:45:12 GMT
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" <sberyozkin@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" <sberyozkin@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" <sberyozkin@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" <sberyozkin@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]]
>>>
>>>
>>
>>
>


-- 
Sergey Beryozkin

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

Blog: http://sberyozkin.blogspot.com

Mime
View raw message