Qpid
  1. Qpid
  2. QPID-4012

[Java Broker] PriorityQueue entries may attempt to access message metadata in the store after it is no longer available

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.16
    • Fix Version/s: 0.17
    • Component/s: Java Broker
    • Labels:
      None
    • Environment:

      Running a test with multiple producers and consumers for a while using just priority queues exposes this issue.

      Description

      The Exception thrown is,

      The exception is,

      qpidbrkr`20120518072800.628`Uncaught exception in thread "IoReceiver - /10.224.75.24:34340"
      java.lang.RuntimeException: org.apache.qpid.AMQStoreException: Metadata not found for message with id 1330312 [error code 541: internal error]
      at org.apache.qpid.server.store.berkeleydb.BDBMessageStore$StoredBDBMessage.getMetaData(BDBMessageStore.java:2327)
      at org.apache.qpid.server.message.MessageTransferMessage.getMetaData(MessageTransferMessage.java:43)
      at org.apache.qpid.server.message.MessageTransferMessage.getMessageHeader(MessageTransferMessage.java:58)
      at org.apache.qpid.server.queue.QueueEntryImpl.getMessageHeader(QueueEntryImpl.java:303)
      at org.apache.qpid.server.queue.PriorityQueueList$PriorityQueueEntryImpl.compareTo(PriorityQueueList.java:189)
      at org.apache.qpid.server.queue.PriorityQueueList$PriorityQueueEntryImpl.compareTo(PriorityQueueList.java:179)
      at org.apache.qpid.server.queue.SimpleAMQQueue.updateSubRequeueEntry(SimpleAMQQueue.java:853)
      at org.apache.qpid.server.queue.SimpleAMQQueue.requeue(SimpleAMQQueue.java:875)
      at org.apache.qpid.server.queue.QueueEntryImpl.release(QueueEntryImpl.java:245)
      at org.apache.qpid.server.subscription.Subscription_0_10.release(Subscription_0_10.java:715)
      at org.apache.qpid.server.subscription.ExplicitAcceptDispositionChangeListener.onRelease(ExplicitAcceptDispositionChangeListener.java:62)
      at org.apache.qpid.server.transport.ServerSession.onClose(ServerSession.java:373)
      at org.apache.qpid.server.transport.ServerSessionDelegate.closed(ServerSessionDelegate.java:1579)
      at org.apache.qpid.transport.Session.closed(Session.java:1097)
      at org.apache.qpid.transport.Connection.closed(Connection.java:541)
      at org.apache.qpid.server.transport.ServerConnection.closed(ServerConnection.java:420)
      at org.apache.qpid.transport.network.Assembler.closed(Assembler.java:112)
      at org.apache.qpid.transport.network.InputHandler.closed(InputHandler.java:204)
      at org.apache.qpid.server.protocol.ProtocolEngine_0_10.closed(ProtocolEngine_0_10.java:206)
      at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.closed(MultiVersionProtocolEngine.java:102)
      at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:174)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: org.apache.qpid.AMQStoreException: Metadata not found for message with id 1330312 [error code 541: internal error]
      at org.apache.qpid.server.store.berkeleydb.BDBMessageStore.getMessageMetaData(BDBMessageStore.java:1842)
      at org.apache.qpid.server.store.berkeleydb.BDBMessageStore$StoredBDBMessage.getMetaData(BDBMessageStore.java:2323)
      ... 21 more

        Activity

        Hide
        Keith Wall added a comment -

        Change look good, no comments.

        Show
        Keith Wall added a comment - Change look good, no comments.
        Hide
        Praveen Murugesan added a comment -

        Hi Robbie,

        I tested the change. It works well. Thanks a lot.

        Praveen

        Show
        Praveen Murugesan added a comment - Hi Robbie, I tested the change. It works well. Thanks a lot. Praveen
        Hide
        Robbie Gemmell added a comment -

        Keith, can you review please?

        Thanks,
        Robbie

        Show
        Robbie Gemmell added a comment - Keith, can you review please? Thanks, Robbie
        Hide
        Praveen Murugesan added a comment -

        Hi Robbie,

        Thanks for the quick update. I'm going to attach the patch to my 0.16 build. I'll keep you updated on how this holds up.

        Thanks a lot for looking at this in short notice.

        Praveen.

        Show
        Praveen Murugesan added a comment - Hi Robbie, Thanks for the quick update. I'm going to attach the patch to my 0.16 build. I'll keep you updated on how this holds up. Thanks a lot for looking at this in short notice. Praveen.
        Hide
        Robbie Gemmell added a comment -

        I have made an update to change how the priorities are compared on queue entries in order to avoid retrieving the message metadata, and thus avoid trying to access it after it may have been removed from the store.

        I have attached the patch, I expect it should apply to the 0.16 source as well if you want to do that.

        Show
        Robbie Gemmell added a comment - I have made an update to change how the priorities are compared on queue entries in order to avoid retrieving the message metadata, and thus avoid trying to access it after it may have been removed from the store. I have attached the patch, I expect it should apply to the 0.16 source as well if you want to do that.
        Hide
        Praveen Murugesan added a comment -

        On earlier correspondence with Robbie,

        Hi Praveen,

        Based on a quick look this does appear directly related to the change
        for the other issue yes, and I think I can guess what probably
        happened (a previously released entry was compared to a newly released
        entry after the original entry was consumed, its data removed from the
        store, and its soft referenced in-memory metadata was garbage
        collected, so that when inspecting the priority as done for the
        previous fix we ended up accessing the store again to retrieve
        metadata later than we can/should). If so its potentially not going to
        be that consistently reproducable, but has a couple of simple fixes
        available.

        I'm busy and/or away until later in the week but if you raise a JIRA
        then I will pick it up.

        Probably time to go to sleep before the alarm goes off to wake me up

        Robbie

        On 19 May 2012 02:17, Praveen M <lefthandmagic@gmail.com> wrote:
        > Hi,
        >
        > We encountered this exception when running some long tests on Qpid using
        > the Java Broker.
        >
        > The test uses priority queues with 10 levels.
        >
        > I'm curious is this was due to some gaps in the change to fix the bug that
        > I filed earlier.
        > https://issues.apache.org/jira/browse/QPID-3927
        >
        > Robbie, Can you please let us know if you can think the cause of the
        > exception below was due to some obvious bug?
        > I am going to try and reproduce this and provide a test which could
        > reproduce this soon. Just posting it as a heads up in case you know if
        > something is amiss atop your head.
        >
        >
        > The exception is,
        >
        > qpidbrkr`20120518072800.628`Uncaught exception in thread "IoReceiver - /
        > 10.224.75.24:34340"
        >
        > java.lang.RuntimeException: org.apache.qpid.AMQStoreException: Metadata not
        > found for message with id 1330312 [error code 541: internal error]
        >
        > at
        > org.apache.qpid.server.store.berkeleydb.BDBMessageStore$StoredBDBMessage.getMetaData(BDBMessageStore.java:2327)
        >
        > at
        > org.apache.qpid.server.message.MessageTransferMessage.getMetaData(MessageTransferMessage.java:43)
        >
        > at
        > org.apache.qpid.server.message.MessageTransferMessage.getMessageHeader(MessageTransferMessage.java:58)
        >
        > at
        > org.apache.qpid.server.queue.QueueEntryImpl.getMessageHeader(QueueEntryImpl.java:303)
        >
        > at
        > org.apache.qpid.server.queue.PriorityQueueList$PriorityQueueEntryImpl.compareTo(PriorityQueueList.java:189)
        >
        > at
        > org.apache.qpid.server.queue.PriorityQueueList$PriorityQueueEntryImpl.compareTo(PriorityQueueList.java:179)
        >
        > at
        > org.apache.qpid.server.queue.SimpleAMQQueue.updateSubRequeueEntry(SimpleAMQQueue.java:853)
        >
        > at
        > org.apache.qpid.server.queue.SimpleAMQQueue.requeue(SimpleAMQQueue.java:875)
        >
        > at
        > org.apache.qpid.server.queue.QueueEntryImpl.release(QueueEntryImpl.java:245)
        >
        > at
        > org.apache.qpid.server.subscription.Subscription_0_10.release(Subscription_0_10.java:715)
        >
        > at
        > org.apache.qpid.server.subscription.ExplicitAcceptDispositionChangeListener.onRelease(ExplicitAcceptDispositionChangeListener.java:62)
        >
        > at
        > org.apache.qpid.server.transport.ServerSession.onClose(ServerSession.java:373)
        >
        > at
        > org.apache.qpid.server.transport.ServerSessionDelegate.closed(ServerSessionDelegate.java:1579)
        >
        > at
        > org.apache.qpid.transport.Session.closed(Session.java:1097)
        >
        > at
        > org.apache.qpid.transport.Connection.closed(Connection.java:541)
        >
        > at
        > org.apache.qpid.server.transport.ServerConnection.closed(ServerConnection.java:420)
        >
        > at
        > org.apache.qpid.transport.network.Assembler.closed(Assembler.java:112)
        >
        > at
        > org.apache.qpid.transport.network.InputHandler.closed(InputHandler.java:204)
        >
        > at
        > org.apache.qpid.server.protocol.ProtocolEngine_0_10.closed(ProtocolEngine_0_10.java:206)
        >
        > at
        > org.apache.qpid.server.protocol.MultiVersionProtocolEngine.closed(MultiVersionProtocolEngine.java:102)
        >
        > at
        > org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:174)
        >
        > at java.lang.Thread.run(Thread.java:619)
        >
        > Caused by: org.apache.qpid.AMQStoreException: Metadata not found for
        > message with id 1330312 [error code 541: internal error]
        >
        > at
        > org.apache.qpid.server.store.berkeleydb.BDBMessageStore.getMessageMetaData(BDBMessageStore.java:1842)
        >
        > at
        > org.apache.qpid.server.store.berkeleydb.BDBMessageStore$StoredBDBMessage.getMetaData(BDBMessageStore.java:2323)
        >
        > ... 21 more
        >
        >
        > Thank you,
        >
        > –
        > -Praveen

        Show
        Praveen Murugesan added a comment - On earlier correspondence with Robbie, Hi Praveen, Based on a quick look this does appear directly related to the change for the other issue yes, and I think I can guess what probably happened (a previously released entry was compared to a newly released entry after the original entry was consumed, its data removed from the store, and its soft referenced in-memory metadata was garbage collected, so that when inspecting the priority as done for the previous fix we ended up accessing the store again to retrieve metadata later than we can/should). If so its potentially not going to be that consistently reproducable, but has a couple of simple fixes available. I'm busy and/or away until later in the week but if you raise a JIRA then I will pick it up. Probably time to go to sleep before the alarm goes off to wake me up Robbie On 19 May 2012 02:17, Praveen M <lefthandmagic@gmail.com> wrote: > Hi, > > We encountered this exception when running some long tests on Qpid using > the Java Broker. > > The test uses priority queues with 10 levels. > > I'm curious is this was due to some gaps in the change to fix the bug that > I filed earlier. > https://issues.apache.org/jira/browse/QPID-3927 > > Robbie, Can you please let us know if you can think the cause of the > exception below was due to some obvious bug? > I am going to try and reproduce this and provide a test which could > reproduce this soon. Just posting it as a heads up in case you know if > something is amiss atop your head. > > > The exception is, > > qpidbrkr`20120518072800.628`Uncaught exception in thread "IoReceiver - / > 10.224.75.24:34340" > > java.lang.RuntimeException: org.apache.qpid.AMQStoreException: Metadata not > found for message with id 1330312 [error code 541: internal error] > > at > org.apache.qpid.server.store.berkeleydb.BDBMessageStore$StoredBDBMessage.getMetaData(BDBMessageStore.java:2327) > > at > org.apache.qpid.server.message.MessageTransferMessage.getMetaData(MessageTransferMessage.java:43) > > at > org.apache.qpid.server.message.MessageTransferMessage.getMessageHeader(MessageTransferMessage.java:58) > > at > org.apache.qpid.server.queue.QueueEntryImpl.getMessageHeader(QueueEntryImpl.java:303) > > at > org.apache.qpid.server.queue.PriorityQueueList$PriorityQueueEntryImpl.compareTo(PriorityQueueList.java:189) > > at > org.apache.qpid.server.queue.PriorityQueueList$PriorityQueueEntryImpl.compareTo(PriorityQueueList.java:179) > > at > org.apache.qpid.server.queue.SimpleAMQQueue.updateSubRequeueEntry(SimpleAMQQueue.java:853) > > at > org.apache.qpid.server.queue.SimpleAMQQueue.requeue(SimpleAMQQueue.java:875) > > at > org.apache.qpid.server.queue.QueueEntryImpl.release(QueueEntryImpl.java:245) > > at > org.apache.qpid.server.subscription.Subscription_0_10.release(Subscription_0_10.java:715) > > at > org.apache.qpid.server.subscription.ExplicitAcceptDispositionChangeListener.onRelease(ExplicitAcceptDispositionChangeListener.java:62) > > at > org.apache.qpid.server.transport.ServerSession.onClose(ServerSession.java:373) > > at > org.apache.qpid.server.transport.ServerSessionDelegate.closed(ServerSessionDelegate.java:1579) > > at > org.apache.qpid.transport.Session.closed(Session.java:1097) > > at > org.apache.qpid.transport.Connection.closed(Connection.java:541) > > at > org.apache.qpid.server.transport.ServerConnection.closed(ServerConnection.java:420) > > at > org.apache.qpid.transport.network.Assembler.closed(Assembler.java:112) > > at > org.apache.qpid.transport.network.InputHandler.closed(InputHandler.java:204) > > at > org.apache.qpid.server.protocol.ProtocolEngine_0_10.closed(ProtocolEngine_0_10.java:206) > > at > org.apache.qpid.server.protocol.MultiVersionProtocolEngine.closed(MultiVersionProtocolEngine.java:102) > > at > org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:174) > > at java.lang.Thread.run(Thread.java:619) > > Caused by: org.apache.qpid.AMQStoreException: Metadata not found for > message with id 1330312 [error code 541: internal error] > > at > org.apache.qpid.server.store.berkeleydb.BDBMessageStore.getMessageMetaData(BDBMessageStore.java:1842) > > at > org.apache.qpid.server.store.berkeleydb.BDBMessageStore$StoredBDBMessage.getMetaData(BDBMessageStore.java:2323) > > ... 21 more > > > Thank you, > > – > -Praveen

          People

          • Assignee:
            Keith Wall
            Reporter:
            Praveen Murugesan
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development