Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1590760

Summary: qpidd segfault with huge backtrace when deleting autoDel queue just being auto-deleted
Product: Red Hat Enterprise MRG Reporter: Pavel Moravec <pmoravec>
Component: qpid-cppAssignee: Cliff Jansen <cjansen>
Status: CLOSED ERRATA QA Contact: Zdenek Kraus <zkraus>
Severity: high Docs Contact:
Priority: medium    
Version: 3.2CC: cjansen, jfrancin, jross, mcressma, sjay, zkraus
Target Milestone: 3.2.12   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: qpid-cpp-1.36.0-21 Doc Type: Bug Fix
Doc Text:
Cause: An autodelete queue will be deleted when the last consumer detaches from it. If, concurrently, the queue is attempted to be deleted via another mechanism (management/QMF), there is a window where one thread deletes the queue while the other thinks it still exists, Consequence: possibly causing qpidd to segfault. Fix: Result: The locking scheme was enhanced to close the window, thus avoiding the race condition that caused the problem.
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-02-21 13:35:28 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Pavel Moravec 2018-06-13 11:13:02 UTC
Description of problem:
When below two actions happen concurrently on an auto-delete queue (without auto-del timeout), qpidd segfaults.

Two actions:
- detaching (latest) consumer of the auto-del queue
- deleting the queue in either way (i.e. via QMF or by sending proper AMQP performative)

cause that:

- segfaulting thread from the detach event has backtrace like:
#0  0x00007f9af745f40d in ScopedLock (this=0x7f9adc6c5a88, expectedVersion=1) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/sys/Mutex.h:33
#1  qpid::broker::Queue::tryAutoDelete (this=0x7f9adc6c5a88, expectedVersion=1) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1348
#2  0x00007f9af745eed4 in qpid::broker::Queue::scheduleAutoDelete (this=0x7f9adc6c5a88, immediate=false) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1339
#3  0x00007f9af745f524 in qpid::broker::Queue::tryAutoDelete (this=0x7f9adc6c5a88, expectedVersion=<value optimized out>) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1367
#4  0x00007f9af745eed4 in qpid::broker::Queue::scheduleAutoDelete (this=0x7f9adc6c5a88, immediate=false) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1339
..
#12012 0x00007f9af745eed4 in qpid::broker::Queue::scheduleAutoDelete (this=0x7f9adc6c5a88, immediate=false) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1339
#12013 0x00007f9af74601c6 in qpid::broker::Queue::cancel (this=0x7f9adc6c5a88, c=..., connectionId="qpid.127.0.0.1:5672-127.0.0.1:56736", userId="anonymous")
    at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:637
..

- other thread trying to delete the queue has bt like:

#0  0x000000343ee11016 in qpid::broker::Exchange::propagateFedOp (this=0x260ee30, routingKey="autoDel_93", tags="", op="U", origin="", extra_args=0x0)
    at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Exchange.cpp:344
#1  0x000000343ee66baf in qpid::broker::DirectExchange::unbind (this=0x260edd0, queue=..., routingKey="autoDel_93", args=<value optimized out>)
    at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/DirectExchange.cpp:159
#2  0x000000343eeac7c9 in qpid::broker::QueueBindings::unbind (this=<value optimized out>, exchanges=..., queue=...) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/QueueBindings.cpp:47
#3  0x000000343ee39b1d in qpid::broker::Queue::unbind (this=<value optimized out>, exchanges=<value optimized out>) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1208
#4  0x000000343ee39ca6 in qpid::broker::Queue::destroyed (this=0x7ff820308810) at /usr/src/debug/qpid-cpp-1.36.0/src/qpid/broker/Queue.cpp:1162
#5  0x000000343eeb1027 in qpid::broker::QueueRegistry::destroy (this=0x2606278, name="autoDel_93", connectionId="qpid.127.0.0.1:5672-127.0.0.1:39240", userId="anonymous")
..


The segfault happens since depth of the backtrace exceeds some limit.


Version-Release number of selected component (if applicable):
qpid-cpp-server-1.36.0-11.el6.x86_64
(but imho applicable to any newer qpid-cpp-server version since the bug should be in Queue.cpp that is identical to upstream)


How reproducible:
randomly, but 100% in 1 hour


Steps to Reproduce:
run below script with optionally updated parameters, such that numbers of "resource-deleted" (from qpid-receive) and "Delete failed. No such queue" (from delete_queue) errors are similar (i.e. the events to trigger the race condition happen usually at very similar time)


queues=125
slept=0.9922
for i in $(seq 1 $queues); do
        while true; do
                qpid-receive -a "autoDel_${i}; {create:always, node:{ x-declare:{auto-delete:True}}}" --timeout=1 &
                sleep $slept
                delete_queue autoDel_${i}
                sleep 1
        done &
        sleep 0.1
done


Actual results:
within a hour, segfault with above backtraces


Expected results:
no segfault


Additional info:

Comment 1 Pavel Moravec 2018-06-14 08:44:39 UTC
forgot to add the delete_queue source code (simply C++ client deleting the queue via QMF):

# cat delete_queue.cpp
#include <cstdlib>
#include <iostream>

#include <sstream>

#include <qpid/messaging/Address.h>
#include <qpid/messaging/Connection.h>
#include <qpid/messaging/Message.h>
#include <qpid/messaging/Sender.h>
#include <qpid/messaging/Receiver.h>
#include <qpid/messaging/Session.h>


using namespace qpid::messaging;
using namespace qpid::types;

using std::stringstream;
using std::string;

int main(int argc, char** argv) {
    const char* queue_name = argc>1 ? argv[1] : "queue_name";
    const char* url = argc>2 ? argv[2] : "amqp:tcp:127.0.0.1:5672";

    Connection connection(url/*, connectionOptions*/);
    try {
        connection.open();
        Session session = connection.createSession();
        Sender sender = session.createSender("qmf.default.direct/broker");
        Address responseQueue("#reply-queue; {create:always, node:{x-declare:{auto-delete:true}}}");
        Receiver receiver = session.createReceiver(responseQueue);

        Message message;
        Variant::Map content;
	Variant::Map OID;
	Variant::Map arguments;
	OID["_object_name"] = "org.apache.qpid.broker:broker:amqp-broker";
	arguments["type"] = "queue";
	arguments["name"] = queue_name;
	
        content["_object_id"] = OID;
        content["_method_name"] = "delete";
        content["_arguments"] = arguments;
	
        encode(content, message);
	message.setReplyTo(responseQueue);
	message.setProperty("x-amqp-0-10.app-id", "qmf2");
	message.setProperty("qmf.opcode", "_method_request");

        sender.send(message, true);
	
	Message response;
	if (receiver.fetch(response,qpid::messaging::Duration(30000)) == true)
	{
		qpid::types::Variant::Map recv_props = response.getProperties();
		if (recv_props["x-amqp-0-10.app-id"] == "qmf2")
			if (recv_props["qmf.opcode"] == "_method_response")
				std::cout << "Response: OK" << std::endl;
			else if (recv_props["qmf.opcode"] == "_exception")
				std::cerr << "Error: " << response.getContent() << std::endl;
			else
				std::cerr << "Invalid response received!" << std::endl;
		else
			std::cerr << "Invalid response not of qmf2 type received!" << std::endl;
	}
	else
		std::cout << "Timeout: No response received within 30 seconds!" << std::endl;

        connection.close();
        return 0;
    } catch(const std::exception& error) {
        std::cout << error.what() << std::endl;
        connection.close();
    }
    return 1;
}

Comment 2 Pavel Moravec 2018-06-14 08:48:37 UTC
.. and confirmed it is reproducible in upstream

Comment 3 Cliff Jansen 2018-07-20 16:06:56 UTC
There is a time gap between de-registering a queue from the QueueRegistry (with its QueueRegistry lock) and marking the queue as deleted (later with the Queue::messageLock via Queue::destroyed()).  

During this gap, QueueRegistry methods (QueueRegistry::destroyIfUntouched, QueueRegistry::destroy) consider the queue deleted, Queue methods assume it is still alive.

The gap is usually small and matters not.  But it can be arbitrarily large depending on circumstances and the test case shows that.  On beefier hardware, increasing the number of queues in the script (queues=125) increases thread competition so that the gap may be large enough to see the failure sooner.

The existing use of multiple locks is obviously important for performance when destruction is expensive and requires disengaging multiple observers, rationalizing exchanges, emitting management events, and unwinding durable storage.  The commit log shows a history of MP issues around deletion including deadlocks, so a conservative fix is probably in order.  See also QPID-7306.

Query whether a separate Queue::deletionPending lock/mutex would provide better MP logic with minimal performance impact (i.e. only causing contention on corner cases) when processing code affected by Queue::deleted.

Comment 5 Zdenek Kraus 2019-02-06 14:02:07 UTC
This issue was tested with RHEL 6 and 7, with following packages:

qpid-cpp-server-1.36.0-21

Fix works as expected.
->VERIFIED

Comment 7 errata-xmlrpc 2019-02-21 13:35:28 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.

https://access.redhat.com/errata/RHBA-2019:0390