Bug 1002605 - Trace queue deletion statistics show msgDepth:0 every time
Trace queue deletion statistics show msgDepth:0 every time
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp (Show other bugs)
2.3
All All
medium Severity medium
: 3.2
: ---
Assigned To: Pavel Moravec
Michal Toth
: Patch, Reopened, TestCaseProvided
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-08-29 10:10 EDT by Pavel Moravec
Modified: 2015-10-13 09:00 EDT (History)
9 users (show)

See Also:
Fixed In Version: qpid-cpp-0.32-3
Doc Type: Bug Fix
Doc Text:
It was discovered that the event and log about deleting some provisionable objects (for example, the queue) have zero counters in many statistics, regardless of the truth values. This caused the information in the event and the log to be incorrect. An update in deletion procedures of the objects now ensures the statistic counters provide proper values both in the event and the log.
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-10-13 09:00:55 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Patch proposal (832 bytes, patch)
2013-08-29 12:00 EDT, Pavel Moravec
no flags Details | Diff
Updated patch proposal (1.61 KB, patch)
2013-08-30 10:17 EDT, Pavel Moravec
no flags Details | Diff
patch with debugStats (12.32 KB, patch)
2013-09-03 04:59 EDT, Pavel Moravec
no flags Details | Diff


External Trackers
Tracker ID Priority Status Summary Last Updated
Apache JIRA QPID-5107 None None None Never
Apache JIRA QPID-6524 None None None Never

  None (edit)
Description Pavel Moravec 2013-08-29 10:10:47 EDT
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).
Comment 1 Pavel Moravec 2013-08-29 12:00:18 EDT
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.
Comment 2 Pavel Moravec 2013-08-29 12:01:47 EDT
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.
Comment 3 Pavel Moravec 2013-08-30 10:17:37 EDT
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.
Comment 4 Chuck Rolke 2013-08-30 10:37:17 EDT
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.
Comment 5 Pavel Moravec 2013-09-03 04:59:26 EDT
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: {}").
Comment 6 Pavel Moravec 2013-09-06 10:37:07 EDT
Committed to upstream as r1520579.
Comment 11 Michal Toth 2015-03-25 08:01:30 EDT
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.
Comment 14 errata-xmlrpc 2015-04-14 09:46:55 EDT
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
Comment 15 Pavel Moravec 2015-04-30 06:00:26 EDT
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.
Comment 16 Pavel Moravec 2015-04-30 09:30:54 EDT
Fixed by commit https://svn.apache.org/r1676982 .

Resetting release flags.
Comment 17 Pavel Moravec 2015-04-30 09:37:10 EDT
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,
Comment 18 Michal Toth 2015-07-20 07:07:42 EDT
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.

Note You need to log in before you can comment on or make changes to this bug.