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}
>
>
>
