Lorenz Quack created QPID-6921:
----------------------------------
Summary: When trying to create a duplicate model object confusing
DELETE messages get logged at DEBUG
Key: QPID-6921
URL: https://issues.apache.org/jira/browse/QPID-6921
Project: Qpid
Issue Type: Bug
Components: Java Broker
Reporter: Lorenz Quack
Analysing the logs from
{{org.apache.qpid.test.client.CloseOnNoRouteForMandatoryMessageTest#testNoRouteMessageReurnedWhenExceptionMessageLengthIsGreater255}}
(but this issue is not specific to that test) I encountered this surprising
log entry:
{noformat}
2015-11-30 15:26:57,922 DEBUG [IO-/127.0.0.1:58531]
o.a.q.s.p.v.AMQChannel RECV[2] ExchangeDeclare[ exchange:
abcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabc
deabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde
type: direct passive: false durable: false autoDelete: false internal: false
nowait: true arguments: null ]
2015-11-30 15:26:57,922 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.c.u.TaskExecutorImpl Performing Task['create child' on
'ProvidedStoreVirtualHostImpl [id=ba53ae6a-f6d1-4aea-af94-3c104415c421,
name=test]' with arguments 'childClass=Exchange, name=abcdeabcdeabcd
eabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde,
type=direct']
2015-11-30 15:26:57,923 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.c.u.TaskExecutorImpl Performing Task['create' on
'DirectExchange[abcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde
abcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde]']
2015-11-30 15:26:57,923 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.c.u.TaskExecutorImpl Performing Task['set desired state' on
'DirectExchange[abcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde]'
with arguments 'DELETED']
2015-11-30 15:26:57,923 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.c.u.TaskExecutorImpl Task['set desired state' on
'DirectExchange[abcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde]'
with arguments 'DELETED'] performed successfully with result: null
2015-11-30 15:26:57,923 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.c.u.TaskExecutorImpl Task['create' on
'DirectExchange[abcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcdeabcde]']
performed successfully with result: null
2015-11-30 15:26:57,924 DEBUG [IO-/127.0.0.1:58531]
o.a.q.s.p.v.BrokerDecoder Frame handled in 2 ms.
{noformat}
The problem is that an Exchange with that name already exists and upon
receiving the new ExchangeDeclare we only detect the duplicate after the object
has been created and then mark it for deletion. This is confusing especially
since there is nothing in the logs to distinguish the two exchanges.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
