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?
* Can't the log messages be clearer? (Example: Queue creation failed: Queue
testQueue already exist)
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}
