Hello Alex,
I did some debugging and activated logging on Qpid Broker Side and Jersey
Client Side. Analyzing the logs, I don't see any wrong behavior client-side
because I don't see double request.
On the contrary, I see a delete request and then a create request which is
failing.
However, on the broker side, I see 2 requests being received in parallel. I
think this is where the problem lies.
I stopped logging at the moment a query failed.
========
Broker Logs
========
[HttpManagement-HTTP-378] (o.e.j.s.Server) - REQUEST
/api/latest/queue/default/default on
AsyncHttpConnection@7b1b3aa2,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=2,c=58},r=5
[HttpManagement-HTTP-373] (o.e.j.s.Server) - REQUEST
/api/latest/queue/default/default on
AsyncHttpConnection@66381a52,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=2,c=58},r=1
[HttpManagement-HTTP-378] (o.e.j.s.Server) - RESPONSE
/api/latest/queue/default/default 201 handled=true
[HttpManagement-HTTP-373] (o.e.j.s.Server) - RESPONSE
/api/latest/queue/default/default 409 handled=true
==========
Jersey Client logs
==========
<record>
<date>2016-09-09T15:13:26</date>
<millis>1473426806227</millis>
<sequence>4390</sequence>
<logger>org.glassfish.jersey.logging.LoggingFeature</logger>
<level>INFO</level>
<class>org.glassfish.jersey.logging.LoggingInterceptor</class>
<method>log</method>
<thread>1</thread>
<message>2196 * Sending client request on thread main
2196 > DELETE
http://localhost:8080/api/latest/queue/default/default/restQueueFail
2196 > Accept: application/json
2196 > Authorization: Basic Z3Vlc3Q6Z3Vlc3Q=
</message>
</record>
<record>
<date>2016-09-09T15:13:26</date>
<millis>1473426806227</millis>
<sequence>4391</sequence>
<logger>org.glassfish.jersey.logging.LoggingFeature</logger>
<level>INFO</level>
<class>org.glassfish.jersey.logging.LoggingInterceptor</class>
<method>log</method>
<thread>1</thread>
<message>2196 * Client response received on thread main
2196 < 200
2196 < Cache-Control: no-cache
2196 < Content-Length: 0
2196 < Expires: Thu, 01 Jan 1970 00:00:00 GMT
2196 < Pragma: no-cache
2196 < Set-Cookie: JSESSIONID_8080=1xc1j94fhqpz8dznsnugibzka;Path=/
</message>
</record>
<record>
<date>2016-09-09T15:13:26</date>
<millis>1473426806227</millis>
<sequence>4392</sequence>
<logger>org.glassfish.jersey.logging.LoggingFeature</logger>
<level>INFO</level>
<class>org.glassfish.jersey.logging.LoggingInterceptor</class>
<method>log</method>
<thread>1</thread>
<message>2197 * Sending client request on thread main
2197 > PUT http://localhost:8080/api/latest/queue/default/default
2197 > Accept: application/json
2197 > Authorization: Basic Z3Vlc3Q6Z3Vlc3Q=
2197 > Content-Type: application/json
</message>
</record>
<record>
<date>2016-09-09T15:13:26</date>
<millis>1473426806243</millis>
<sequence>4393</sequence>
<logger>org.glassfish.jersey.logging.LoggingFeature</logger>
<level>INFO</level>
<class>org.glassfish.jersey.logging.LoggingInterceptor</class>
<method>log</method>
<thread>1</thread>
<message>2197 * Client response received on thread main
2197 < 409
2197 < Content-Length: 73
2197 < Content-Type: application/json;charset=UTF-8
2197 < Expires: Thu, 01 Jan 1970 00:00:00 GMT
2197 < Set-Cookie: JSESSIONID_8080=1ccjr3yiqac6l1slkizfbasepa;Path=/
</message>
</record>
> From: [email protected]
> Date: Fri, 9 Sep 2016 14:01:23 +0100
> Subject: Re: [Qpid Java Broker 6.0.x] Random failure in queue
> creation/deletion using REST calls
> To: [email protected]
>
> Adel,
> I simply changed the log level to ALL for logging rule Qpid
> (org.apache.qpid.*) in logfile logger. That enables all possible Qpid
> logging.
> Alternately, you can just add new logging rule to enable debug logging
> for logger "org.apache.qpid.server.management.plugin.filter.LoggingFilter".
>
> Potentially http request/response logging can be filtered from broker
> logs (with ALL logging enabled) using egrep utility, for example:
> tail -f ~/.qpid/log/qpid.log | egrep "REQUEST|RESPONSE"
>
> Kind Regards,
> Alex
>
>
>
> On 9 September 2016 at 13:01, Adel Boutros <[email protected]> wrote:
> > Hello Alex,
> > I am glad you were able to reproduce.
> > Can you please share what you activate in the logging to see the duplicate
> > request?
> > Regards,Adel
> >
> >> From: [email protected]
> >> Date: Fri, 9 Sep 2016 12:22:09 +0100
> >> Subject: Re: [Qpid Java Broker 6.0.x] Random failure in queue
> >> creation/deletion using REST calls
> >> To: [email protected]
> >>
> >> Hi Adel,
> >> I looked into an issue you had reported. I ran your sample application
> >> attached to the JIRA QPID-7420 and found that every time when
> >> application fails it sends 2 similar requests: first one is handled by
> >> the broker successfully and the other one fails because the work is
> >> already performed as part of first request. For example, if first
> >> request deletes the queue, the second one receives 404, as queue does
> >> not exist anymore.
> >>
> >> Unfortunately it was tricky to discover that two same requests are
> >> made from the application, as Broker operational logging does not log
> >> failed management operation attempts. It seems we need to improve
> >> logging in this area. I had to switch to DEBUG logging in order to
> >> find the cause of the problem.
> >>
> >> I am not familiar with jersey and not sure why 2 requests are sent. It
> >> could be an issue with jersey itself or some settings...
> >>
> >> I am going to resolve QPID-7420 as not an issue.
> >>
> >> Kind Regards,
> >> Alex
> >>
> >> On 8 September 2016 at 09:24, Adel Boutros <[email protected]> wrote:
> >> > Hello guys,
> >> >
> >> > As I mentioned in my previous post, I am having some random REST call
> >> > failures when deleting and creating a queue. I was able to have a
> >> > smaller test code but still the error is very random. I launch my test
> >> > code 10 000 times to get the exception: The failure occurs sometimes at
> >> > run 600 or run 2000, etc...
> >> >
> >> > I don't know if someone has faced a similar issue before.
> >> >
> >> > I have also created a Jira issue for this with the minimalist test code
> >> > I could find so far:
> >> > https://issues.apache.org/jira/browse/QPID-7420
> >> >
> >> > Do not hesitate to let me know if there are missing information.
> >> >
> >> > I have tested with Java Broker 6.0.0, 6.0.1 and 6.0.4 and they all have
> >> > the issue.
> >> >
> >> > I would like to keep debugging the issue from my side. So I was
> >> > wondering if you could provide me some hints where to look in the code
> >> > or what to activate to see in the logs if possible?
> >> >
> >> > Regards,
> >> > Adel
> >> >
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: [email protected]
> >> For additional commands, e-mail: [email protected]
> >>
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [email protected]
> For additional commands, e-mail: [email protected]
>
