Bug 1269071 - [AMQP1.0] 3.1 C++ client with DIGEST-MD5 stuck forever when attempting to consume messages from 3.2 broker
Summary: [AMQP1.0] 3.1 C++ client with DIGEST-MD5 stuck forever when attempting to con...
Keywords:
Status: NEW
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp
Version: 3.1
Hardware: All
OS: Linux
medium
medium
Target Milestone: ---
: ---
Assignee: messaging-bugs
QA Contact: Messaging QE
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-10-06 08:39 UTC by Pavel Moravec
Modified: 2020-11-04 22:33 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Pavel Moravec 2015-10-06 08:39:46 UTC
Description of problem:
Having a 3.1 (or also 3.0) C++ client using DIGEST-MD5 SASL mechanism over AMQP 1.0, it fails to consume messages from 3.2 broker.


Version-Release number of selected component (if applicable):
client: qpid-cpp-client-0.30-8.el6.x86_64
broker: qpid-cpp-server-0.34-5.el6.x86_64


How reproducible:
100%


Steps to Reproduce:
1. On one machine, run 3.2 broker with DIGEST-MD5 and PLAIN and ANONYMOUS mechs enabled, and with admin/admin credentials set
2. On another machine, create a queue, send there 1000 messages and try to consume them over AMQP1.0 with DIGEST-MD5:
qpid-config add queue test2 -b mrg32broker
qpid-send -b admin/admin@mrg32broker -a "test2; { node: { type: queue} }" -m 1000
export QPID_LOG_ENABLE="trace+"
qpid-receive -b admin/admin@mrg32broker --connection-options "{ protocol: amqp1.0, sasl-mechanism:'DIGEST-MD5' }" -a "test2; { node: { type: queue } , assert: never}"


Actual results:
qpid-receive stucks with trace log:

2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]: 0 <- @attach(18) [name="test2_150f23c5-f629-4b2d-9bef-09c8f0fd7689", handle=0, role=false, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="test2", durable=0, timeout=0, dynamic=false, distribution-mode=:move, capabilities=:queue], target=@target(41) [durable=0, timeout=0, dynamic=false], initial-delivery-count=0]
2015-10-06 09:56:35 [Network] debug tcp:train1:5672 decoded 138 bytes from 138
2015-10-06 09:56:35 [Messaging] debug Attach succeeded from test2
2015-10-06 09:56:35 [Messaging] debug wakeupDriver()
2015-10-06 09:56:35 [Security] trace tcp:train1:5672 Sasl::canEncode(): 0 || 0
2015-10-06 09:56:35 [Security] trace tcp:train1:5672 Sasl::canEncode(): 0 || 0
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 encode(65535)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]: 0 -> @flow(19) [next-incoming-id=0, incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0, link-credit=1000, drain=false]
2015-10-06 09:56:35 [Network] debug tcp:train1:5672 encoded 42 bytes from 65535
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 encode(65535)
2015-10-06 09:56:35 [Messaging] debug In ConnectionContext::get(), current=0
2015-10-06 09:56:35 [Messaging] debug wakeupDriver()
2015-10-06 09:56:35 [Messaging] debug Waiting for message or for credit to be drained: credit=1000, queued=0
2015-10-06 09:56:35 [Security] trace tcp:train1:5672 Sasl::canEncode(): 0 || 0
2015-10-06 09:56:35 [Security] trace tcp:train1:5672 Sasl::canEncode(): 0 || 0
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 encode(65535)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]: 0 -> @flow(19) [next-incoming-id=0, incoming-window=2147483647, next-outgoing-id=0, outgoing-window=0, handle=0, delivery-count=0, link-credit=1000, drain=true]
2015-10-06 09:56:35 [Network] debug tcp:train1:5672 encoded 42 bytes from 65535
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 encode(65535)
2015-10-06 09:56:35 [Security] trace tcp:train1:5672 Sasl::canEncode(): 0 || 0
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(0)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]: 0 -> @close(24) [error=@error(29) [condition=:"amqp:connection:framing-error", description="connection aborted"]]
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]:   <- EOS
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(0)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]:   <- EOS
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(0)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]:   <- EOS
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(65506)
2015-10-06 09:56:35 [Network] debug tcp:train1:5672 decoded 65506 bytes from 65506
2015-10-06 09:56:35 [Messaging] debug Waiting for message or for credit to be drained: credit=1000, queued=0
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(29)
2015-10-06 09:56:35 [Network] debug tcp:train1:5672 decoded 29 bytes from 29
2015-10-06 09:56:35 [Messaging] debug Waiting for message or for credit to be drained: credit=1000, queued=0
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(0)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]:   <- EOS
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(0)
2015-10-06 09:56:35 [Protocol] trace [3eb23c9a-d498-4f7d-98c3-6eec80ebae2e]:   <- EOS
2015-10-06 09:56:35 [Messaging] trace tcp:train1:5672 decode(31932)
2015-10-06 09:56:35 [Network] debug tcp:train1:5672 decoded 31932 bytes from 31932
2015-10-06 09:56:35 [Messaging] debug Waiting for message or for credit to be drained: credit=1000, queued=0


Expected results:
qpid-receive to successfully consume messages


Additional info:
1) Test variants:
- using 3.1 client against 3.2 broker: fails, using 3.2 client: succeeds
- using PLAIN, ANONYMOUS or even CRAM-MD5 authentication: succeeds
- if queue has <100 messages (and never had 1000 or more), test succeeds


2) Key observation: log records
2015-10-06 09:56:35 [Messaging] debug In ConnectionContext::get(), current=0
2015-10-06 09:56:35 [Messaging] debug wakeupDriver()
2015-10-06 09:56:35 [Messaging] debug Waiting for message or for credit to be drained: credit=1000, queued=0

should appear before sending AMQP flow performative with drain=false and this flow is not expected to be sent by the client (just flow with drain=true should be there). At least any successful test had that.

I.e. it sounds like a concurrency bug where DIGEST-MD5 mechanism causes proton(?) driver to wake up too late.


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