Bug 1090368 - [Selectors] does not recognize redelivered message with amqp.redelivered
Summary: [Selectors] does not recognize redelivered message with amqp.redelivered
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp
Version: 3.0
Hardware: Unspecified
OS: Unspecified
medium
high
Target Milestone: 3.0
: ---
Assignee: Andrew Stitcher
QA Contact: Zdenek Kraus
URL:
Whiteboard:
Depends On:
Blocks: 453539
TreeView+ depends on / blocked
 
Reported: 2014-04-23 07:52 UTC by Zdenek Kraus
Modified: 2014-09-24 15:11 UTC (History)
5 users (show)

Fixed In Version: qpid-cpp-0.22-40
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-09-24 15:11:14 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Apache JIRA QPID-5735 0 None None None Never
Red Hat Product Errata RHEA-2014:1296 0 normal SHIPPED_LIVE Red Hat Enterprise MRG Messaging 3.0 Release 2014-09-24 19:00:06 UTC

Description Zdenek Kraus 2014-04-23 07:52:53 UTC
[Selectors] does not recognize redelivered message with amqp.redelivered

Description of problem:
selector amqp.redelivered treating all messages as not redelivered.

Version-Release number of selected component (if applicable):
qpid-cpp-server-0.22-37

How reproducible:
100%

Steps to Reproduce:
# create redelivered message
1. ./qc2_spout --log-msgs dict "q;{create:always}"
2. ./qc2_drain -a noack "q"

# create not redelivered message
3. ./qc2_spout --log-msgs dict "q;{create:always}"

# read redelivered messages
4. ./qc2_drain --log-msgs dict "q;{link:{selector:\"amqp.redelivered = TRUE\"}}"

# read not redelivered messages
5. ./qc2_drain --log-msgs dict "q;{link:{selector:\"amqp.redelivered = FALSE\"}}"

Actual results:
[4]

[5]
{'redelivered': True, 'reply_to': None, 'subject': None, 'content_type': None, 'id': None, 'user_id': None, 'correlation_id': None, 'priority': 0, 'durable': False, 'ttl': 0.000000e+00, 'size': None, 'properties': {'spout-id': '8db488f5-1b91-43f6-a5f8-5c6ae994d072:0', 'x-amqp-0-10.routing-key': 'q'}, 'content': None}
{'redelivered': False, 'reply_to': None, 'subject': None, 'content_type': None, 'id': None, 'user_id': None, 'correlation_id': None, 'priority': 0, 'durable': False, 'ttl': 0.000000e+00, 'size': None, 'properties': {'spout-id': '479cb9c7-2e9b-45ad-a122-78409c9b236d:0', 'x-amqp-0-10.routing-key': 'q'}, 'content': None}

Expected results:
[4]
{'redelivered': True, 'reply_to': None, 'subject': None, 'content_type': None, 'id': None, 'user_id': None, 'correlation_id': None, 'priority': 0, 'durable': False, 'ttl': 0.000000e+00, 'size': None, 'properties': {'spout-id': '8db488f5-1b91-43f6-a5f8-5c6ae994d072:0', 'x-amqp-0-10.routing-key': 'q'}, 'content': None}

[5]
{'redelivered': False, 'reply_to': None, 'subject': None, 'content_type': None, 'id': None, 'user_id': None, 'correlation_id': None, 'priority': 0, 'durable': False, 'ttl': 0.000000e+00, 'size': None, 'properties': {'spout-id': '479cb9c7-2e9b-45ad-a122-78409c9b236d:0', 'x-amqp-0-10.routing-key': 'q'}, 'content': None}

Additional info:

# qpid log
2014-04-23 09:47:02 [Model] debug Create connection. user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47217
2014-04-23 09:47:02 [Broker] debug anonymous.2ca67218-6613-426f-bbb1-d7b75b005f7d: attached on broker.
2014-04-23 09:47:02 [Broker] debug anonymous.2ca67218-6613-426f-bbb1-d7b75b005f7d: ready to send, activating output.
2014-04-23 09:47:02 [Broker] debug Selector parsed[amqp.redelivered = TRUE] into: (I:amqp.redelivered=BOOL:true)
2014-04-23 09:47:02 [Model] debug Create subscription. queue:q destination:q user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47217 exclusive:F
2014-04-23 09:47:02 [Broker] debug next() called for invalid cursor, index started at 0 (of 2)
2014-04-23 09:47:02 [Broker] debug in next(), cursor set to 1
2014-04-23 09:47:02 [Broker] debug in next(), returning message at 1
2014-04-23 09:47:02 [Broker] debug Selector identifier: amqp.redelivered->BOOL:false
2014-04-23 09:47:02 [Broker] debug Consumer doesn't want message from 'q'
2014-04-23 09:47:02 [Broker] debug next() called for cursor at 1, index set to 1 (of 2)
2014-04-23 09:47:02 [Broker] debug in next(), cursor set to 2
2014-04-23 09:47:02 [Broker] debug in next(), returning message at 2
2014-04-23 09:47:02 [Broker] debug Selector identifier: amqp.redelivered->BOOL:false
2014-04-23 09:47:02 [Broker] debug Consumer doesn't want message from 'q'
2014-04-23 09:47:02 [Broker] debug next() called for cursor at 2, index set to 2 (of 2)
2014-04-23 09:47:02 [Broker] debug no message to return from next
2014-04-23 09:47:02 [Broker] debug No messages to dispatch on queue 'q'
2014-04-23 09:47:02 [Model] debug Delete subscription. destination:q user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47217
2014-04-23 09:47:02 [Broker] debug anonymous.2ca67218-6613-426f-bbb1-d7b75b005f7d: detached on broker.
2014-04-23 09:47:02 [Model] debug Delete connection. user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47217
2014-04-23 09:47:06 [Security] debug SASL: No Authentication Performed
2014-04-23 09:47:06 [Broker] debug LinkRegistry::notifyConnection(); key=qpid.127.0.0.1:5672-127.0.0.1:47218
2014-04-23 09:47:06 [Model] debug Create connection. user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47218
2014-04-23 09:47:06 [Broker] debug anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c: attached on broker.
2014-04-23 09:47:06 [Broker] debug anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c: ready to send, activating output.
2014-04-23 09:47:06 [Broker] debug Selector parsed[amqp.redelivered = FALSE] into: (I:amqp.redelivered=BOOL:false)
2014-04-23 09:47:06 [Model] debug Create subscription. queue:q destination:q user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47218 exclusive:F
2014-04-23 09:47:06 [Broker] debug next() called for invalid cursor, index started at 0 (of 2)
2014-04-23 09:47:06 [Broker] debug in next(), cursor set to 1
2014-04-23 09:47:06 [Broker] debug in next(), returning message at 1
2014-04-23 09:47:06 [Broker] debug Selector identifier: amqp.redelivered->BOOL:false
2014-04-23 09:47:06 [Broker] debug Subscription q on anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c has sufficient  credit for message of 90 bytes: messages: 1 bytes: unlimited
2014-04-23 09:47:06 [Broker] debug Attempting to acquire message 1 from 'q' with state 1
2014-04-23 09:47:06 [Broker] debug Message 1 retrieved from 'q'
2014-04-23 09:47:06 [Broker] debug Credit allocated for q on anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c, was messages: 1 bytes: unlimited now messages: 0 bytes: unlimited
2014-04-23 09:47:06 [Broker] debug clean(): 1 messages remain; head is now 0
2014-04-23 09:47:06 [Broker] debug DeliveryRecord::setEnded() id=1
2014-04-23 09:47:06 [Broker] debug Accepted 1
2014-04-23 09:47:06 [Broker] debug next() called for cursor at 1, index set to 0 (of 1)
2014-04-23 09:47:06 [Broker] debug in next(), cursor set to 2
2014-04-23 09:47:06 [Broker] debug in next(), returning message at 2
2014-04-23 09:47:06 [Broker] debug Selector identifier: amqp.redelivered->BOOL:false
2014-04-23 09:47:06 [Broker] debug Subscription q on anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c has sufficient  credit for message of 90 bytes: messages: 1 bytes: unlimited
2014-04-23 09:47:06 [Broker] debug Attempting to acquire message 2 from 'q' with state 1
2014-04-23 09:47:06 [Broker] debug Message 2 retrieved from 'q'
2014-04-23 09:47:06 [Broker] debug Credit allocated for q on anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c, was messages: 1 bytes: unlimited now messages: 0 bytes: unlimited
2014-04-23 09:47:06 [Broker] debug clean(): 0 messages remain; head is now 0
2014-04-23 09:47:06 [Broker] debug DeliveryRecord::setEnded() id=2
2014-04-23 09:47:06 [Broker] debug Accepted 2
2014-04-23 09:47:06 [Broker] debug next() called for cursor at 2, index set to 0 (of 0)
2014-04-23 09:47:06 [Broker] debug no message to return from next
2014-04-23 09:47:06 [Broker] debug No messages to dispatch on queue 'q'
2014-04-23 09:47:06 [Model] debug Delete subscription. destination:q user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47218
2014-04-23 09:47:06 [Broker] debug anonymous.c68b8752-224b-4d7a-b6d2-45646cc12e5c: detached on broker.
2014-04-23 09:47:06 [Model] debug Delete connection. user:anonymous rhost:qpid.127.0.0.1:5672-127.0.0.1:47218

Comment 2 Andrew Stitcher 2014-04-29 19:35:32 UTC
The 3.0 selector functionality should include the redelivered flag

In my quick tests I am seeing a strange behaviour:

The first time the message is redelivered it still matches the selector "amqp.redelivered=false" (although it has the Redelivered header) but subsequently it matches "amqp.redelivered=true"

It may be that the header is set *after* the selector is run so that the selector test happens before the msg field is updated to take account of the redelivery.

Comment 3 Andrew Stitcher 2014-04-30 03:50:10 UTC
This is now fixed on the trunk branch of qpid in r1591183
[ https://svn.apache.org/r1591183 ]

Comment 6 Irina Boverman 2014-05-14 20:28:33 UTC
Merging 0.22-mrg-astitcher-bz1090368 branch.

Comment 8 Zdenek Kraus 2014-05-21 10:42:55 UTC
tested on RHEL 6.5 i686 && x86_64 with following packages:

python-qpid-0.22-14.el6
qpid-proton-c-0.7-1.el6
qpid-cpp-server-devel-0.22-40.el6
qpid-cpp-server-ha-0.22-40.el6
qpid-jca-0.22-2.el6
qpid-cpp-server-0.22-40.el6
qpid-tools-0.22-12.el6
qpid-java-client-0.22-6.el6
qpid-qmf-debuginfo-0.22-31.el6
qpid-snmpd-debuginfo-1.0.0-16.el6
qpid-cpp-client-devel-docs-0.22-40.el6
qpid-cpp-client-0.22-40.el6
qpid-cpp-client-devel-0.22-40.el6
qpid-tests-0.22-15.el6
qpid-snmpd-1.0.0-16.el6
qpid-cpp-server-linearstore-0.22-40.el6
qpid-java-common-0.22-6.el6
qpid-java-example-0.22-6.el6
qpid-proton-debuginfo-0.7-1.el6
qpid-proton-c-devel-0.7-1.el6
python-qpid-qmf-0.22-31.el6
qpid-qmf-devel-0.22-31.el6
qpid-cpp-server-rdma-0.22-40.el6
qpid-cpp-server-xml-0.22-40.el6
qpid-jca-xarecovery-0.22-2.el6
perl-qpid-debuginfo-0.22-12.el6
qpid-qmf-0.22-31.el6
perl-qpid-0.22-12.el6
qpid-cpp-debuginfo-0.22-40.el6
qpid-cpp-client-rdma-0.22-40.el6
ruby-qpid-qmf-0.22-31.el6


works as expected.

Comment 9 errata-xmlrpc 2014-09-24 15:11:14 UTC
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.

http://rhn.redhat.com/errata/RHEA-2014-1296.html


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