Hello Alex, Actually, I launched Wireshark and it seems you are right, 2 delete requests are sent consecutively. The problem seems to be in fact coming from Jersey Client
Wireshark (filter: http) 47992 30.115608 src.ip 33273 dest.ip 8080 112 HTTP PUT /api/latest/queue/default/default HTTP/1.1 (application/json) 48386 30.127898 dest.ip 8080 src.ip 33273 317 HTTP HTTP/1.1 201 Created 48430 30.128921 src.ip 33142 dest.ip 8080 291 HTTP GET /api/latest/queue/default/default/restQueueFail HTTP/1.1 48904 30.142792 src.ip 33106 dest.ip 8080 294 HTTP DELETE /api/latest/queue/default/default/restQueueFail HTTP/1.1 48908 30.142955 dest.ip 8080 src.ip 33142 323 HTTP HTTP/1.1 200 OK (application/json) 49592 30.161594 src.ip 33274 dest.ip 8080 294 HTTP DELETE /api/latest/queue/default/default/restQueueFail HTTP/1.1 49700 30.171616 dest.ip 8080 src.ip 33106 237 HTTP HTTP/1.1 200 OK 49718 30.193521 dest.ip 8080 src.ip 33274 283 HTTP HTTP/1.1 404 Not Found (application/json) Regards, Adel From: [email protected] To: [email protected] Subject: RE: [Qpid Java Broker 6.0.x] Random failure in queue creation/deletion using REST calls Date: Fri, 9 Sep 2016 15:19:09 +0200 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] >
