Qpid
  1. Qpid
  2. QPID-2507

C++ broker can deadlock when processing a bind.

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.7
    • Component/s: C++ Broker
    • Labels:
      None
    • Environment:

      c++ broker on linux.

      Description

      Rarely happens, but I was lucky enough to catch this on the debugger.

      Broker locks due to lock inversion. Here's the flow:

      thread 1 (broker):
      1) gets bind request for the management topic exchange
      2) binds to the management topic exchange [takes topic->lock]
      3) attempts to call management agent allocId() [takes mgmt agent->userLock]

      At the same time:

      thread 4 (mgmt agent periodic timer)
      1) periodic processing [takes mgmt agent->userLock]
      2) call topicexchange::route() [takes topic->lock]

      thread one holds the topic->lock, tries to take mgmt agent->userLock
      thread four holds mgmt agent->userLock, tries to take topic->lock

      deadlock.

        Activity

        Hide
        Ken Giusti added a comment -

        Here are the stack traces for the stuck threads:

        (gdb) info thread
        4 Thread 0x7fb395dec910 (LWP 22467) pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85
        3 Thread 0x7fb3953ba910 (LWP 22469) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
        2 Thread 0x7fb38ffff910 (LWP 22470) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136

        • 1 Thread 0x7fb395ded790 (LWP 22466) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
          (gdb) bt
          warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.)

        warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.)

        warning: (Internal error: pc 0x40d590 in read in psymtab, but not in symtab.)

        #0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
        #1 0x000000355e408ff0 in _L_lock_1017 () from /lib64/libpthread.so.0
        #2 0x000000355e408e51 in __pthread_mutex_lock (mutex=0x7fb3953bb120) at pthread_mutex_lock.c:82
        #3 0x00007fb396b5344d in qpid::sys::Mutex::lock (this=<value optimized out>) at ../include/qpid/sys/posix/Mutex.h:116
        #4 ScopedLock (this=<value optimized out>) at ../include/qpid/sys/Mutex.h:33
        #5 qpid::management::ManagementAgent::allocateId (this=<value optimized out>) at qpid/management/ManagementAgent.cpp:2118
        #6 0x00007fb396ac57e1 in qpid::broker::Exchange::Binding::startManagement (this=0x254cd50) at qpid/broker/Exchange.cpp:343
        #7 0x00007fb396b4717d in qpid::broker::TopicExchange::bind (this=0x203f578, queue={px = 0x25171c0, pn = {pi_ = 0x23e1a00}}, routingKey=<value optimized out>, args=<value optimized out>) at qpid/broker/TopicExchange.cpp:214
        #8 0x00007fb396b75df2 in qpid::broker::ManagementTopicExchange::bind (this=0x203f560, queue={px = 0x25171c0, pn = {pi_ = 0x23e1a00}}, routingKey=Traceback (most recent call last):
        File "/usr/lib/python2.6/site-packages/gdb/libstdcxx/v6/printers.py", line 453, in to_string
        return self.val['_M_dataplus']['_M_p'].string(encoding)
        RuntimeError: Cannot access memory at address 0x30
        , args=0xffffffffffffffff) at qpid/management/ManagementTopicExchange.cpp:62
        #9 0x00007fb396b334cf in qpid::broker::SessionAdapter::ExchangeHandlerImpl::bind (this=0x2515408, queueName="mgmt-test-session", exchangeName=<value optimized out>, routingKey="console.#", arguments=<value optimized out>) at qpid/broker/SessionAdapter.cpp:189
        #10 0x00007fb39660f553 in qpid::framing::ExchangeBindBody::invoke<qpid::framing::AMQP_ServerOperations::ExchangeHandler> (invocable=<value optimized out>, this=<value optimized out>) at ./qpid/framing/ExchangeBindBody.h:88
        #11 qpid::framing::AMQP_ServerOperations::ExchangeHandler::Invoker::visit (invocable=<value optimized out>, this=<value optimized out>) at qpid/framing/ServerInvoker.cpp:642
        #12 0x00007fb396611651 in qpid::framing::AMQP_ServerOperations::Invoker::visit (this=0x7fffb3696a90, body=@0x23e0260) at qpid/framing/ServerInvoker.cpp:353
        #13 0x00007fb396b4295f in qpid::framing::invoke<qpid::broker::SessionAdapter> (target=<value optimized out>, body=@0x30) at ./qpid/framing/Invoker.h:67
        #14 0x00007fb396b40433 in qpid::broker::SessionState::handleCommand (this=0x25150b0, method=0x23e0260, id=@0x7fffb3696cc0) at qpid/broker/SessionState.cpp:197
        #15 0x00007fb396b40878 in qpid::broker::SessionState::handleIn (this=0x25150b0, frame=@0x7fffb3697a00) at qpid/broker/SessionState.cpp:329
        #16 0x00007fb396677c7e in qpid::amqp_0_10::SessionHandler::handleIn (this=0x23dcdf0, f=@0x7fffb3697a00) at qpid/amqp_0_10/SessionHandler.cpp:93
        #17 0x00007fb396aa0d93 in qpid::framing::Handler<qpid::framing::AMQFrame&>::operator() (t=<value optimized out>, this=<value optimized out>) at ./qpid/framing/Handler.h:42
        #18 qpid::broker::Connection::received (t=<value optimized out>, this=<value optimized out>) at qpid/broker/Connection.cpp:143
        #19 0x00007fb396a83808 in qpid::amqp_0_10::Connection::decode (this=0x20e3d00, buffer=<value optimized out>, size=<value optimized out>) at qpid/amqp_0_10/Connection.cpp:58
        #20 0x00007fb3966b9a10 in qpid::sys::AsynchIOHandler::readbuff (this=0x7fb3904b09d0, buff=0x7fb39059ab20) at qpid/sys/AsynchIOHandler.cpp:135
        #21 0x00007fb3965e894b in boost::function2<void, qpid::sys::AsynchIO&, qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fb3904b31e8, a0=@0x7fb3904b3090, a1=0x7fb39059ab20) at /usr/include/boost/function/function_template.hpp:989
        #22 0x00007fb3965e7229 in qpid::sys::posix::AsynchIO::readable (this=0x7fb3904b3090, h=<value optimized out>) at qpid/sys/posix/AsynchIO.cpp:418
        #23 0x00007fb3966c09c4 in boost::function1<void, qpid::sys::DispatchHandle&>::operator() (this=<value optimized out>, a0=@0x80) at /usr/include/boost/function/function_template.hpp:989
        #24 0x00007fb3966bd7bc in qpid::sys::DispatchHandle::processEvent (this=0x7fb3904b3098, type=qpid::sys::Poller::READABLE) at qpid/sys/DispatchHandle.cpp:278
        #25 0x00007fb3965f475a in qpid::sys::Poller::Event::process (this=<value optimized out>) at ./qpid/sys/Poller.h:123
        #26 qpid::sys::Poller::run (this=<value optimized out>) at qpid/sys/epoll/EpollPoller.cpp:483
        #27 0x00007fb396a957aa in qpid::broker::Broker::run (this=<value optimized out>) at qpid/broker/Broker.cpp:338
        warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.)

        warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.)

        #28 0x000000000040d617 in QpiddDaemon::child (warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.)

        this=0x7fffb3698de0) at posix/QpiddBroker.cpp:130
        #29 0x00007fb396aaca43 in qpid::broker::Daemon::fork (this=0x7fffb3698de0) at qpid/broker/Daemon.cpp:91
        #30 0x000000000040c83d in QpiddBroker::execute (this=<value optimized out>, options=<value optimized out>) at posix/QpiddBroker.cpp:168
        #31 0x0000000000408dc2 in main (argc=6, argv=0x7fffb36993a8) at qpidd.cpp:80

        (gdb) thread 4
        [Switching to thread 4 (Thread 0x7fb395dec910 (LWP 22467))]#0 pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85
        Current language: auto; currently asm
        (gdb) bt
        #0 pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85
        #1 0x00007fb396b4647b in qpid::sys::RWlock::rlock (this=<value optimized out>) at ../include/qpid/sys/posix/Mutex.h:141
        #2 ScopedRlock (this=<value optimized out>) at ../include/qpid/sys/Mutex.h:53
        #3 qpid::broker::TopicExchange::route (this=<value optimized out>) at qpid/broker/TopicExchange.cpp:308
        #4 0x00007fb396b59480 in qpid::management::ManagementAgent::sendBuffer (this=<value optimized out>, buf=<value optimized out>, length=<value optimized out>, exchange={px = 0x203f5e8, pn = {pi_ = 0x203f710}}, routingKey="console.obj.1.0.org.apache.qpid.broker.binding") at qpid/management/ManagementAgent.cpp:482
        #5 0x00007fb396b6ba52 in qpid::management::ManagementAgent::periodicProcessing (this=<value optimized out>) at qpid/management/ManagementAgent.cpp:735
        #6 0x00007fb396b6f297 in qpid::management::ManagementAgent::Periodic::fire (this=0x7fb380c8e500) at qpid/management/ManagementAgent.cpp:391
        #7 0x00007fb3966c3330 in qpid::sys::Timer::run (this=0x203b5f0) at qpid/sys/Timer.cpp:118
        #8 0x00007fb3965eac5a in qpid::sys::(anonymous namespace)::runRunnable (p=0x203f5b8) at qpid/sys/posix/Thread.cpp:35
        #9 0x000000355e40685a in start_thread (arg=<value optimized out>) at pthread_create.c:297
        #10 0x000000355d8de22d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
        #11 0x0000000000000000 in ?? ()
        (gdb)

        Show
        Ken Giusti added a comment - Here are the stack traces for the stuck threads: (gdb) info thread 4 Thread 0x7fb395dec910 (LWP 22467) pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85 3 Thread 0x7fb3953ba910 (LWP 22469) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136 2 Thread 0x7fb38ffff910 (LWP 22470) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136 1 Thread 0x7fb395ded790 (LWP 22466) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136 (gdb) bt warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.) warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.) warning: (Internal error: pc 0x40d590 in read in psymtab, but not in symtab.) #0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136 #1 0x000000355e408ff0 in _L_lock_1017 () from /lib64/libpthread.so.0 #2 0x000000355e408e51 in __pthread_mutex_lock (mutex=0x7fb3953bb120) at pthread_mutex_lock.c:82 #3 0x00007fb396b5344d in qpid::sys::Mutex::lock (this=<value optimized out>) at ../include/qpid/sys/posix/Mutex.h:116 #4 ScopedLock (this=<value optimized out>) at ../include/qpid/sys/Mutex.h:33 #5 qpid::management::ManagementAgent::allocateId (this=<value optimized out>) at qpid/management/ManagementAgent.cpp:2118 #6 0x00007fb396ac57e1 in qpid::broker::Exchange::Binding::startManagement (this=0x254cd50) at qpid/broker/Exchange.cpp:343 #7 0x00007fb396b4717d in qpid::broker::TopicExchange::bind (this=0x203f578, queue={px = 0x25171c0, pn = {pi_ = 0x23e1a00}}, routingKey=<value optimized out>, args=<value optimized out>) at qpid/broker/TopicExchange.cpp:214 #8 0x00007fb396b75df2 in qpid::broker::ManagementTopicExchange::bind (this=0x203f560, queue={px = 0x25171c0, pn = {pi_ = 0x23e1a00}}, routingKey=Traceback (most recent call last): File "/usr/lib/python2.6/site-packages/gdb/libstdcxx/v6/printers.py", line 453, in to_string return self.val ['_M_dataplus'] ['_M_p'] .string(encoding) RuntimeError: Cannot access memory at address 0x30 , args=0xffffffffffffffff) at qpid/management/ManagementTopicExchange.cpp:62 #9 0x00007fb396b334cf in qpid::broker::SessionAdapter::ExchangeHandlerImpl::bind (this=0x2515408, queueName="mgmt-test-session", exchangeName=<value optimized out>, routingKey="console.#", arguments=<value optimized out>) at qpid/broker/SessionAdapter.cpp:189 #10 0x00007fb39660f553 in qpid::framing::ExchangeBindBody::invoke<qpid::framing::AMQP_ServerOperations::ExchangeHandler> (invocable=<value optimized out>, this=<value optimized out>) at ./qpid/framing/ExchangeBindBody.h:88 #11 qpid::framing::AMQP_ServerOperations::ExchangeHandler::Invoker::visit (invocable=<value optimized out>, this=<value optimized out>) at qpid/framing/ServerInvoker.cpp:642 #12 0x00007fb396611651 in qpid::framing::AMQP_ServerOperations::Invoker::visit (this=0x7fffb3696a90, body=@0x23e0260) at qpid/framing/ServerInvoker.cpp:353 #13 0x00007fb396b4295f in qpid::framing::invoke<qpid::broker::SessionAdapter> (target=<value optimized out>, body=@0x30) at ./qpid/framing/Invoker.h:67 #14 0x00007fb396b40433 in qpid::broker::SessionState::handleCommand (this=0x25150b0, method=0x23e0260, id=@0x7fffb3696cc0) at qpid/broker/SessionState.cpp:197 #15 0x00007fb396b40878 in qpid::broker::SessionState::handleIn (this=0x25150b0, frame=@0x7fffb3697a00) at qpid/broker/SessionState.cpp:329 #16 0x00007fb396677c7e in qpid::amqp_0_10::SessionHandler::handleIn (this=0x23dcdf0, f=@0x7fffb3697a00) at qpid/amqp_0_10/SessionHandler.cpp:93 #17 0x00007fb396aa0d93 in qpid::framing::Handler<qpid::framing::AMQFrame&>::operator() (t=<value optimized out>, this=<value optimized out>) at ./qpid/framing/Handler.h:42 #18 qpid::broker::Connection::received (t=<value optimized out>, this=<value optimized out>) at qpid/broker/Connection.cpp:143 #19 0x00007fb396a83808 in qpid::amqp_0_10::Connection::decode (this=0x20e3d00, buffer=<value optimized out>, size=<value optimized out>) at qpid/amqp_0_10/Connection.cpp:58 #20 0x00007fb3966b9a10 in qpid::sys::AsynchIOHandler::readbuff (this=0x7fb3904b09d0, buff=0x7fb39059ab20) at qpid/sys/AsynchIOHandler.cpp:135 #21 0x00007fb3965e894b in boost::function2<void, qpid::sys::AsynchIO&, qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7fb3904b31e8, a0=@0x7fb3904b3090, a1=0x7fb39059ab20) at /usr/include/boost/function/function_template.hpp:989 #22 0x00007fb3965e7229 in qpid::sys::posix::AsynchIO::readable (this=0x7fb3904b3090, h=<value optimized out>) at qpid/sys/posix/AsynchIO.cpp:418 #23 0x00007fb3966c09c4 in boost::function1<void, qpid::sys::DispatchHandle&>::operator() (this=<value optimized out>, a0=@0x80) at /usr/include/boost/function/function_template.hpp:989 #24 0x00007fb3966bd7bc in qpid::sys::DispatchHandle::processEvent (this=0x7fb3904b3098, type=qpid::sys::Poller::READABLE) at qpid/sys/DispatchHandle.cpp:278 #25 0x00007fb3965f475a in qpid::sys::Poller::Event::process (this=<value optimized out>) at ./qpid/sys/Poller.h:123 #26 qpid::sys::Poller::run (this=<value optimized out>) at qpid/sys/epoll/EpollPoller.cpp:483 #27 0x00007fb396a957aa in qpid::broker::Broker::run (this=<value optimized out>) at qpid/broker/Broker.cpp:338 warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.) warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.) #28 0x000000000040d617 in QpiddDaemon::child (warning: (Internal error: pc 0x40d616 in read in psymtab, but not in symtab.) this=0x7fffb3698de0) at posix/QpiddBroker.cpp:130 #29 0x00007fb396aaca43 in qpid::broker::Daemon::fork (this=0x7fffb3698de0) at qpid/broker/Daemon.cpp:91 #30 0x000000000040c83d in QpiddBroker::execute (this=<value optimized out>, options=<value optimized out>) at posix/QpiddBroker.cpp:168 #31 0x0000000000408dc2 in main (argc=6, argv=0x7fffb36993a8) at qpidd.cpp:80 (gdb) thread 4 [Switching to thread 4 (Thread 0x7fb395dec910 (LWP 22467))] #0 pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85 Current language: auto; currently asm (gdb) bt #0 pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85 #1 0x00007fb396b4647b in qpid::sys::RWlock::rlock (this=<value optimized out>) at ../include/qpid/sys/posix/Mutex.h:141 #2 ScopedRlock (this=<value optimized out>) at ../include/qpid/sys/Mutex.h:53 #3 qpid::broker::TopicExchange::route (this=<value optimized out>) at qpid/broker/TopicExchange.cpp:308 #4 0x00007fb396b59480 in qpid::management::ManagementAgent::sendBuffer (this=<value optimized out>, buf=<value optimized out>, length=<value optimized out>, exchange={px = 0x203f5e8, pn = {pi_ = 0x203f710}}, routingKey="console.obj.1.0.org.apache.qpid.broker.binding") at qpid/management/ManagementAgent.cpp:482 #5 0x00007fb396b6ba52 in qpid::management::ManagementAgent::periodicProcessing (this=<value optimized out>) at qpid/management/ManagementAgent.cpp:735 #6 0x00007fb396b6f297 in qpid::management::ManagementAgent::Periodic::fire (this=0x7fb380c8e500) at qpid/management/ManagementAgent.cpp:391 #7 0x00007fb3966c3330 in qpid::sys::Timer::run (this=0x203b5f0) at qpid/sys/Timer.cpp:118 #8 0x00007fb3965eac5a in qpid::sys::(anonymous namespace)::runRunnable (p=0x203f5b8) at qpid/sys/posix/Thread.cpp:35 #9 0x000000355e40685a in start_thread (arg=<value optimized out>) at pthread_create.c:297 #10 0x000000355d8de22d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #11 0x0000000000000000 in ?? () (gdb)

          People

          • Assignee:
            Ken Giusti
            Reporter:
            Ken Giusti
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development