Hello Rob,
Indeed, this is helpful.
Just to share some context, I have some code which checks existence of a queue,
deletes it and creates it via REST API in Java (javax.ws.rs-api). However, I
have some random failures when I run the code repeatedly for a certain time.
So, I wanted to see how I can check it from the logs of the broker
The logic is (each line involves a REST call):
If queue exits
delete queue
create queue
Sometimes deletion fails and sometimes creation fails. I am still debugging it
(I expect it to be a clumsy mistake in the code) but for example in the case of
the creation failure, I have error 409 which could mean queue already exists
but I don't think the error message is actually clear enough to confirm my
assumption.
Regards,
Adel
> From: [email protected]
> Date: Wed, 7 Sep 2016 14:49:46 +0100
> Subject: Re: [Java Broker - 6.0.4] Rest API logs are a bit tricky
> To: [email protected]
>
> Hi Adel,
>
> On 7 September 2016 at 09:12, Adel Boutros <[email protected]> wrote:
>
> > Hello,
> >
> > I was playing around with the Rest API and noticed the logs generated are
> > not always easy to understand.
> > In my example, I tried to create twice the same queue expecting the second
> > one to fail and it did. However when I tried to understand the logs
> > generated, I found a lot of "successful tasks" and only one number
> > indicating an error which is the response code 409.
> >
> > My questions
> > * Is it expected for all the tasks to be successful especially the queue
> > creation?
> > * Why is the queue being marked deleted and then created on the 2nd create
> > request?
> >
>
> So most of the logs you have turned on here are DEBUG logs which are really
> aimed at Qpid developers (or at least people who understand the underlying
> code) ... the fact that tasks are "successful" is just indicating that the
> task thread pool successfully completed a job without throwing an
> exception. The fact that you see the state of the Queue being set to
> deleted in the second example is an artefact of how the underlying code
> works (the object is instantiated, then the duplication error is detected,
> then this new duplicate child needs to be deleted). Logging at levels INFO
> and above should be understandable by end users.
>
>
> > * Can't the log messages be clearer? (Example: Queue creation failed:
> > Queue testQueue already exist)
> >
>
> I agree that what we need is a clearer set of (INFO-level) log messages
> which can be used to audit actions taken through the REST API that are
> (potentially) mutating the broker state. We'll raise a JIRA for this and
> try to include something in the 6.2 release (I think we're a little late
> for 6.1 now which we are trying to close down at the moment... 6.2 is
> targeted to be released by the end of the year).
>
> Hope this helps,
> Rob
>
>
> >
> > I have set all of the below loggers to DEBUG on file logger:
> > org.eclipse.jetty.server.*
> > org.apache.qpid.server.management.plugin.session.*
> > org.apache.qpid.server.configuration.updater.*
> > org.apache.qpid.server.virtualhost.*
> > org.apache.qpid.server.queue.*
> > org.glassfish.jersey.filter.*
> >
> > *****************
> > Successful queue creation log
> > *****************
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.Server) - REQUEST /api/latest/queue/default/default on
> > AsyncHttpConnection@1bae008,g=HttpGenerator{s=0,h=-1,b=-1,c=
> > -1},p=HttpParser{s=2,l=2,c=65},r=1
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.h.ContextHandler) - scope null||/api/latest/queue/default/default
> > @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.h.ContextHandler) - context=||/api/latest/queue/default/default
> > @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.session) - Got Session ID ih390ue4aoki1nat59gm3p9jq from cookie
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.session) - sessionManager=org.eclipse.jetty.server.session.
> > HashSessionManager@174c2d7
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.session) - session=org.eclipse.jetty.
> > server.session.HashedSession:ih390ue4aoki1nat59gm3p9jq@30029392
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Performing Task['create child' on
> > 'VirtualHost[id=36df8647-0bd1-494e-814b-4268803c5d77,
> > name=default, type=DERBY]' with arguments 'childClass=Queue,
> > name=testQueue2, type=null']
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Performing Task['create' on 'testQueue2']
> > 2016-09-07 09:53:17,566 INFO [VirtualHostNode-default-Config]
> > (q.m.q.created) - [mng:ANONYMOUS(/client_ip:40826)]
> > [vh(/default)/qu(testQueue2)] QUE-1001 : Create : ID:
> > ec7d14c2-0f5d-4993-9e04-c18bad9e9daf Durable
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Task['create' on 'testQueue2'] performed successfully with result: null
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Task['create child' on 'VirtualHost[id=36df8647-0bd1-494e-814b-4268803c5d77,
> > name=default, type=DERBY]' with arguments 'childClass=Queue,
> > name=testQueue2, type=null'] performed successfully with result: null
> > HttpManagement-HTTP-141 - /api/latest/queue/default/default]
> > (o.e.j.s.Server) - RESPONSE /api/latest/queue/default/default 201
> > handled=true
> > HttpManagement-HTTP-141] (o.e.j.s.AsyncHttpConnection) - Enabled read
> > interest SCEP@7088e8{l(/client_ip:40831)<->r(/10.25.49.28:8080),
> > s=1,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{
> > AsyncHttpConnection@1bae008,g=HttpGenerator{s=4,h=0,b=-1,c=-
> > 1},p=HttpParser{s=0,l=2,c=65},r=1}
> > HttpManagement-HTTP-136] (o.e.j.s.AsyncHttpConnection) - Disabled read
> > interest while writing response SCEP@7088e8{l(/client_ip:40831)<->r(/
> > 10.25.49.28:8080),s=1,open=true,ishut=true,oshut=false,rb=false,wb=false,
> > w=true,i=1r}-{AsyncHttpConnection@1bae008,g=HttpGenerator{s=0,h=-1,b=-1,c=
> > -1},p=HttpParser{s=0,l=0,c=-3},r=1}
> > HttpManagement-HTTP-118 Selector2] (o.e.j.s.AbstractHttpConnection) -
> > closed AsyncHttpConnection@1bae008,g=HttpGenerator{s=0,h=-1,b=-1,c=
> > -1},p=HttpParser{s=0,l=0,c=-3},r=1
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.Server) - REQUEST
> > /service/structure on AsyncHttpConnection@8f0e18,g=
> > HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=42,c=0},r=7
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.h.ContextHandler) -
> > scope null||/service/structure @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.Server) - REQUEST /api/latest/broker on AsyncHttpConnection@1e668b7
> > ,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=42,c=0},r=7
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.h.ContextHandler) -
> > context=||/service/structure @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.h.ContextHandler) - scope null||/api/latest/broker @
> > o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.session) - Got
> > Session ID 1plelsp7va5x1137kd16hhau2b from cookie
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.h.ContextHandler) - context=||/api/latest/broker @
> > o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.session) -
> > sessionManager=org.eclipse.jetty.server.session.HashSessionManager@174c2d7
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.session) - Got Session ID 1plelsp7va5x1137kd16hhau2b from cookie
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.session) -
> > session=org.eclipse.jetty.server.session.HashedSession:
> > 1plelsp7va5x1137kd16hhau2b@24899107
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.session) - sessionManager=org.eclipse.jetty.server.session.
> > HashSessionManager@174c2d7
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.session) - session=org.eclipse.jetty.
> > server.session.HashedSession:1plelsp7va5x1137kd16hhau2b@24899107
> > HttpManagement-HTTP-141 - /service/structure] (o.e.j.s.Server) - RESPONSE
> > /service/structure 200 handled=true
> > HttpManagement-HTTP-141] (o.e.j.s.AsyncHttpConnection) - Enabled read
> > interest SCEP@2a0faf{l(/client_ip:40824)<->r(/10.25.49.28:8080),
> > s=1,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{
> > AsyncHttpConnection@8f0e18,g=HttpGenerator{s=4,h=0,b=0,c=-
> > 1},p=HttpParser{s=0,l=42,c=0},r=7}
> > HttpManagement-HTTP-137 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.Server) - RESPONSE /api/latest/broker 200 handled=true
> > HttpManagement-HTTP-137] (o.e.j.s.AsyncHttpConnection) - Enabled read
> > interest SCEP@176e827{l(/client_ip:40825)<->r(/server_ip:8080),s=
> > 1,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{
> > AsyncHttpConnection@1e668b7,g=HttpGenerator{s=4,h=0,b=0,c=-
> > 1},p=HttpParser{s=0,l=42,c=0},r=7}
> >
> > *****************
> > Failed queue creation log
> > *****************
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.Server) - REQUEST /api/latest/queue/default/default on
> > AsyncHttpConnection@172d263,g=HttpGenerator{s=0,h=-1,b=-1,c=
> > -1},p=HttpParser{s=2,l=2,c=65},r=1
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.h.ContextHandler) - scope null||/api/latest/queue/default/default
> > @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.h.ContextHandler) - context=||/api/latest/queue/default/default
> > @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.session) - Got Session ID ih390ue4aoki1nat59gm3p9jq from cookie
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.session) - sessionManager=org.eclipse.jetty.server.session.
> > HashSessionManager@174c2d7
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.session) - session=org.eclipse.jetty.
> > server.session.HashedSession:ih390ue4aoki1nat59gm3p9jq@30029392
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Performing Task['create child' on
> > 'VirtualHost[id=36df8647-0bd1-494e-814b-4268803c5d77,
> > name=default, type=DERBY]' with arguments 'childClass=Queue,
> > name=testQueue2, type=null']
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Performing Task['create' on 'testQueue2']
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Performing Task['set desired state' on 'testQueue2' with arguments
> > 'DELETED']
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Task['set desired state' on 'testQueue2' with arguments 'DELETED']
> > performed successfully with result: null
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Task['create' on 'testQueue2'] performed successfully with result: null
> > VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) -
> > Task['create child' on 'VirtualHost[id=36df8647-0bd1-494e-814b-4268803c5d77,
> > name=default, type=DERBY]' with arguments 'childClass=Queue,
> > name=testQueue2, type=null'] performed successfully with result: null
> > HttpManagement-HTTP-136 - /api/latest/queue/default/default]
> > (o.e.j.s.Server) - RESPONSE /api/latest/queue/default/default 409
> > handled=true
> > HttpManagement-HTTP-136] (o.e.j.s.AsyncHttpConnection) - Enabled read
> > interest SCEP@1c9aa0b{l(/client_ip:40833)<->r(/server_ip:8080),s=
> > 1,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{
> > AsyncHttpConnection@172d263,g=HttpGenerator{s=4,h=0,b=0,c=-
> > 1},p=HttpParser{s=0,l=2,c=65},r=1}
> > HttpManagement-HTTP-139] (o.e.j.s.AsyncHttpConnection) - Disabled read
> > interest while writing response SCEP@1c9aa0b{l(/client_ip:
> > 40833)<->r(/server_ip:8080),s=1,open=true,ishut=true,oshut=
> > false,rb=false,wb=false,w=true,i=1r}-{AsyncHttpConnection@172d263,g=
> > HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=-3},r=1}
> > HttpManagement-HTTP-119 Selector3] (o.e.j.s.AbstractHttpConnection) -
> > closed AsyncHttpConnection@172d263,g=HttpGenerator{s=0,h=-1,b=-1,c=
> > -1},p=HttpParser{s=0,l=0,c=-3},r=1
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.Server) - REQUEST
> > /service/structure on AsyncHttpConnection@8f0e18,g=
> > HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=42,c=0},r=11
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.h.ContextHandler) -
> > scope null||/service/structure @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.Server) - REQUEST /api/latest/broker on AsyncHttpConnection@1e668b7
> > ,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=42,c=0},r=11
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.h.ContextHandler) -
> > context=||/service/structure @ o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.h.ContextHandler) - scope null||/api/latest/broker @
> > o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.session) - Got
> > Session ID 1plelsp7va5x1137kd16hhau2b from cookie
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.h.ContextHandler) - context=||/api/latest/broker @
> > o.e.j.s.ServletContextHandler{/,null}
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.session) -
> > sessionManager=org.eclipse.jetty.server.session.HashSessionManager@174c2d7
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.session) - Got Session ID 1plelsp7va5x1137kd16hhau2b from cookie
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.session) -
> > session=org.eclipse.jetty.server.session.HashedSession:
> > 1plelsp7va5x1137kd16hhau2b@24899107
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.session) - sessionManager=org.eclipse.jetty.server.session.
> > HashSessionManager@174c2d7
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.session) - session=org.eclipse.jetty.
> > server.session.HashedSession:1plelsp7va5x1137kd16hhau2b@24899107
> > HttpManagement-HTTP-140 - /service/structure] (o.e.j.s.Server) - RESPONSE
> > /service/structure 200 handled=true
> > HttpManagement-HTTP-140] (o.e.j.s.AsyncHttpConnection) - Enabled read
> > interest SCEP@2a0faf{l(/client_ip:40824)<->r(/server_ip:8080),s=
> > 1,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{
> > AsyncHttpConnection@8f0e18,g=HttpGenerator{s=4,h=0,b=0,c=-
> > 1},p=HttpParser{s=0,l=42,c=0},r=11}
> > HttpManagement-HTTP-136 -
> > /api/latest/broker?depth=2&excludeInheritedContext=true]
> > (o.e.j.s.Server) - RESPONSE /api/latest/broker 200 handled=true
> > HttpManagement-HTTP-136] (o.e.j.s.AsyncHttpConnection) - Enabled read
> > interest SCEP@176e827{l(/client_ip:40825)<->r(/server_ip:8080),s=
> > 1,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{
> > AsyncHttpConnection@1e668b7,g=HttpGenerator{s=4,h=0,b=0,c=-
> > 1},p=HttpParser{s=0,l=42,c=0},r=11}
> >
> >
> >
