Description of problem: Per [1], qpid trace-logs statistics about object deletion. However some of these data are wrong. In particular msgDepth for a queue is everytime zero (and msgTotalDequeues equals to msgTotalEnqueues despite no consumer was subscribed to the queue). [1] https://access.redhat.com/site/documentation/en-US/Red_Hat_Enterprise_MRG/2/html-single/Messaging_Installation_and_Configuration_Guide/index.html#Tracking_Object_Lifecycles Version-Release number of selected component (if applicable): qpid-cpp-*-0.18-17 (MRG 2.3.3) How reproducible: 100% Steps to Reproduce: echo "trace=yes" >> /etc/qpidd.conf echo "log-to-file=/tmp/qpidd.log" >> /etc/qpidd.conf rm -rf /var/lib/qpidd/* /tmp/qpidd.log service qpidd restart qpid-send -m 123 -a "testQueue; {create:always, delete:always}" grep "Mgmt delete queue" /tmp/qpidd.log Actual results: 2013-08-29 14:05:38 [Model] trace Mgmt delete queue. id:testQueue Statistics: {acquires:123, bindingCount:0, bindingCountHigh:0, bindingCountLow:0, byteDepth:0, byteFtdDepth:0, byteFtdDequeues:0, byteFtdEnqueues:0, bytePersistDequeues:0, bytePersistEnqueues:0, byteTotalDequeues:0, byteTotalEnqueues:0, byteTxnDequeues:0, byteTxnEnqueues:0, consumerCount:0, consumerCountHigh:0, consumerCountLow:0, discardsLvq:0, discardsOverflow:0, discardsPurge:0, discardsRing:0, discardsSubscriber:0, discardsTtl:0, flowStopped:False, flowStoppedCount:0, messageLatencyAvg:0, messageLatencyCount:0, messageLatencyMax:0, messageLatencyMin:0, msgDepth:0, msgFtdDepth:0, msgFtdDequeues:0, msgFtdEnqueues:0, msgPersistDequeues:0, msgPersistEnqueues:0, msgTotalDequeues:123, msgTotalEnqueues:123, msgTxnDequeues:0, msgTxnEnqueues:0, releases:0, reroutes:0, unackedMessages:0, unackedMessagesHigh:0, unackedMessagesLow:0} Expected results: acquires:0 msgTotalDequeues:0 (several other counters are supposed to be wrong as well like byteFtdDequeues, but not in this trivial reproducer) Additional info: The trace log is logged when calling destructor of QMF object for the queue. While at that time, the queue's content is apparently gone (either to alternate exchange or automatically purged).
Created attachment 791879 [details] Patch proposal Tricky patch: It temporarily resets mgmtObject for the deleted queue to zero (while keeping the shared_ptr to the object in auxiliary variable), just to suppress updating statistics when cleaning the queue content. The same can / should be done for other objects (binding, session,..) whose statistics might get wrong during some cleanup work.
One correction to reproducer: as the "Mgmt delete queue" log appears during periodic processing that runs every 10 seconds by default, let add: sleep 10 before the grep command.
Created attachment 792201 [details] Updated patch proposal This patch also corrects the identical bug but for sessions and clientCredit / unackedMessages statistics. Reproducer for the session test case: qpid-send -m 11 -a "myQueue; {create:always}" qpid-receive -m 100 -a "myQueue; {create:always}" -f (in another terminal) qpid-tool list connection call <ID_of_qpid-receive-connection> close and now check result: grep Tx /tmp/qpidd.log | grep session should return "unackedMessages:11" No other management object than queue and session seems to update its statistics during its closure. The patch is based on qpid 0.22-4 as I don't suppose a backport to 0.18.
The patch in Comment 1 produces the desired effect but has several issues of confusing the statistics by disconnecting a management object from it's actual object. As long as there's no exceptions it will produce the desired effect and succeed. I'd like to suggest a more direct method. Please refer to generated code in qpid/cpp/managementgen/qmfgen/templates/Class.cpp. In the destructor of the management object is where the trace log is emitted. We could add another method, debugStats(), that would be the exact same code as the Mgmt delete Statistics except that it would take a string and emit a debug log. Then in Queue::destroyed() you could have the addition of two lines if (mgmtObject != 0) mgmtObject->debugStats("Queue destroyed"); to get the stats you want without messing with the mgmtObject pointer. The debug stats code would be autogenerated for every qmf object present and future. The debugStats() function would be available to be called randomly throughout the code base for convenient debugging.
Created attachment 793071 [details] patch with debugStats (In reply to Chuck Rolke from comment #4) > The patch in Comment 1 produces the desired effect but has several issues of > confusing the statistics by disconnecting a management object from it's > actual object. As long as there's no exceptions it will produce the desired > effect and succeed. > > I'd like to suggest a more direct method. Please refer to generated code in > qpid/cpp/managementgen/qmfgen/templates/Class.cpp. In the destructor of the > management object is where the trace log is emitted. We could add another > method, debugStats(), that would be the exact same code as the Mgmt delete > Statistics except that it would take a string and emit a debug log. > > Then in Queue::destroyed() you could have the addition of two lines > > if (mgmtObject != 0) > mgmtObject->debugStats("Queue destroyed"); > > to get the stats you want without messing with the mgmtObject pointer. > > The debug stats code would be autogenerated for every qmf object present and > future. The debugStats() function would be available to be called randomly > throughout the code base for convenient debugging. This enhancement makes sense, though having the drawback in explicitly calling debugStats at the beginning of destructor/closing method of every manageable object. As generic Class.cpp destructor can't call debugStats method since queue and session stats are already wrong ("over-updated"). Also, as different exchange types might "over-update" statistics in future, I decided to call the debugStats() method from individual destructors of all exchange types and not from QPID_BROKER_INLINE_EXTERN virtual qpid::broker::Exchange::~Exchange(); Attached is a patch for that. It lacks calling debugStats for memory, as the class qpid::sys::posix::MemStat does not have management object declared, just provided in method argument. Anyway, there is imho no need to fix this as memory statistics are empty now (check current trace "Mgmt delete memory. id:amqp-broker Statistics: {}").
Committed to upstream as r1520579.
Tested on qpid-cpp-server-0.30-7 @ rhel6 32/64 and rhel7. Looked mainly on following items: acquires, msgDepth, msgTotal{En,De}queues, msgPersist{En,De}queues, bytePersist{En,De}queues, byteTotal{En,De}queues Marking as verified, as expected values are shown in trace log, when Mgmt queue delete occurs.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHEA-2015-0805.html
Reopenning as it does _not_ work: reproducer fairly simple: echo "trace=yes" >> /etc/qpid/qpidd.conf echo "log-to-file=/tmp/qpidd.log" >> /etc/qpid/qpidd.conf service qpidd restart qpid-config add queue testQueue1 qpid-send --address "testQueue1; {node: { type: queue }, assert: never, create: never}" -m 13 --content-size=1024 qpid-config del queue testQueue1 --force grep testQueue1 /tmp/qpidd.log | grep "destroying queue" Output: 2015-04-30 10:43:25 [Model] trace Mgmt destroying queue. id:testQueue1 Statistics: {acquires:0, bindingCount:0, bindingCountHigh:1, bindingCountLow:0, byteDepth:0, byteFtdDepth:0, byteFtdDequeues:0, byteFtdEnqueues:0, bytePersistDequeues:0, bytePersistEnqueues:0, byteTotalDequeues:14183, byteTotalEnqueues:14183, byteTxnDequeues:0, byteTxnEnqueues:0, consumerCount:0, consumerCountHigh:0, consumerCountLow:0, creator:anonymous, discardsLvq:0, discardsOverflow:0, discardsPurge:0, discardsRing:0, discardsSubscriber:0, discardsTtl:0, flowStopped:False, flowStoppedCount:0, messageLatencyAvg:0, messageLatencyCount:0, messageLatencyMax:0, messageLatencyMin:0, msgDepth:0, msgFtdDepth:0, msgFtdDequeues:0, msgFtdEnqueues:0, msgPersistDequeues:0, msgPersistEnqueues:0, msgTotalDequeues:13, msgTotalEnqueues:13, msgTxnDequeues:0, msgTxnEnqueues:0, redirectPeer:, redirectSource:False, releases:0, reroutes:0, unackedMessages:0, unackedMessagesHigh:0, unackedMessagesLow:0} See byteDepth:0, msgDepth:0. Also msgTotalDequeues should be zero as no dequeue had been made prior deleting the queue. It still sounds the queue first purges its messages and then calls debugSnapshot - something had to changed since the time of my upstream commit. Reproducible on qpid-cpp-server-0.30-8.el6.x86_64 and today's upstream trunk.
Fixed by commit https://svn.apache.org/r1676982 . Resetting release flags.
How to test: (let print the queue deletion trace twice: first for queue deleted by user, second by shutting-down broker; both results should be the same wrt. the printed log) qpid-config add queue testQueue1 qpid-send --address testQueue1 -m 13 --content-size=1024 qpid-config del queue testQueue1 --force qpid-config add queue testQueue1 qpid-send --address testQueue1 -m 13 --content-size=1024 service qpidd stop grep "destroying queue. id:testQueue1 Statistics:" should return twice the same stats with counters: bindingCount:1, byteDepth:14183, byteTotalDequeues:0, byteTotalEnqueues:14183, msgDepth:13, msgTotalDequeues:0, msgTotalEnqueues:13,
Verified on both rhel 6 archs and rhel 7. qpid-cpp-server-0.34-1 msg*Dequeues are correctly showing 0 after queue deletion and not purged number of messages as previously. Thank you Pavel for checking and reopening this BZ.