Uploaded image for project: 'ActiveMQ Classic'
  1. ActiveMQ Classic
  2. AMQ-2500

Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 5.2.0
    • 5.3.0
    • None
    • None

    • JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations

    • Regression

    Description

      The following test-programm reads and writes messages into the same queue (testQueue). After Reading several messages the class starts two threads that are writing messages in the same queue. After writing several messages the producer hangs on:

      producer.send()

      and doesn't recover even if the reader continues reading messages from the queue. Even stopping the clients (via kill) doesn't change the broker's behaviour. In this state further connections opened from other clients hang on the same method call (producer.send()). The client's connections will remain open as you can see in the jconsole-screenshot, that has been taken after the producer in the example hung. Althogh the consumer may continue reading new producer can only continue writing messages into the queue after activeMQ has been restarted.

      The following two snippets show the difference between the first (127.0.0.1:49372) and the second (127.0.0.1:49385) message producer: The first producer works as expected and adds it's messages to the queue. The second producer stops with the following log-entry: 2009-11-13 09:41:45,639 [127.0.0.1:49385] DEBUG AbstractRegion - Adding consumer: ID:JoergsPC-49370-1258101701975-0:14:-1:1

      ...
      2009-11-13 09:41:42,376 [eue://testQueue] DEBUG Queue - queue://testQueue - Recovery - Message pushed '21290107 - Message ID:JoergsPC-50687-1258047095293-0:2810:1:1:1 dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:0:1:1, destinations=1, dispatched=197, delivered=0, pending=0'
      2009-11-13 09:41:42,376 [eue://testQueue] DEBUG Queue - queue://testQueue - Recovery - Message pushed '31931917 - Message ID:JoergsPC-50687-1258047095293-0:2811:1:1:1 dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:0:1:1, destinations=1, dispatched=198, delivered=0, pending=0'
      2009-11-13 09:41:42,376 [eue://testQueue] DEBUG Queue - queue://testQueue - Recovery - Message pushed '10144386 - Message ID:JoergsPC-50687-1258047095293-0:2812:1:1:1 dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:0:1:1, destinations=1, dispatched=199, delivered=0, pending=0'
      2009-11-13 09:41:42,381 [127.0.0.1:49372] DEBUG WireFormatNegotiator - Received WireFormat: WireFormatInfo { version=3, properties=

      {CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
      2009-11-13 09:41:42,381 [127.0.0.1:49372] DEBUG WireFormatNegotiator - Sending: WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}

      , magic=[A,c,t,i,v,e,M,Q]}
      2009-11-13 09:41:42,382 [127.0.0.1:49372] DEBUG WireFormatNegotiator - tcp:///127.0.0.1:49372 before negotiation: OpenWireFormat

      {version=3, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false}
      2009-11-13 09:41:42,394 [127.0.0.1:49372] DEBUG WireFormatNegotiator - tcp:///127.0.0.1:49372 after negotiation: OpenWireFormat{version=3, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false}
      2009-11-13 09:41:42,395 [127.0.0.1:49372] DEBUG TransportConnection - Setting up new connection: /127.0.0.1:49372
      2009-11-13 09:41:42,409 [127.0.0.1:49372] DEBUG AbstractRegion - Adding consumer: ID:JoergsPC-49370-1258101701975-0:1:-1:1
      2009-11-13 09:41:42,414 [127.0.0.1:49372] DEBUG AbstractRegion - Adding destination: topic://ActiveMQ.Advisory.Producer.Queue.testQueue
      2009-11-13 09:41:42,416 [127.0.0.1:49372] DEBUG AMQMessageStore - Journalled message add for: ID:JoergsPC-49370-1258101701975-0:1:1:1:1, at: offset = 10684963, file = 4, size = 270, type = 1
      2009-11-13 09:41:42,416 [eue://testQueue] DEBUG AMQMessageStore - Doing batch update... adding: 1 removing: 0
      2009-11-13 09:41:42,417 [eue://testQueue] DEBUG AMQMessageStore - Batch update done.
      2009-11-13 09:41:42,418 [eue://testQueue] DEBUG Usage - Memory usage change. from: 7, to: 8
      2009-11-13 09:41:42,418 [eue://testQueue] DEBUG Usage - Memory usage change. from: 1, to: 2
      2009-11-13 09:41:42,425 [eue://testQueue] DEBUG Usage - Memory usage change. from: 8, to: 9
      2009-11-13 09:41:42,433 [eue://testQueue] DEBUG Usage - Memory usage change. from: 9, to: 10
      2009-11-13 09:41:42,440 [eue://testQueue] DEBUG Usage - Memory usage change. from: 10, to: 11
      2009-11-13 09:41:42,470 [127.0.0.1:49371] DEBUG AbstractRegion - Removing consumer: ID:JoergsPC-49370-1258101701975-0:0:1:1
      2009-11-13 09:41:42,474 [127.0.0.1:49371] DEBUG AMQMessageStore - flush starting ...
      2009-11-13 09:41:42,474 [127.0.0.1:49371] DEBUG AbstractRegion - Removing consumer: ID:JoergsPC-49370-1258101701975-0:0:-1:1
      2009-11-13 09:41:42,477 [127.0.0.1:49371] DEBUG TransportConnection - Stopping connection: /127.0.0.1:49371
      ...


      ...
      2009-11-13 09:41:45,319 [eue://testQueue] DEBUG Queue - queue://testQueue - Recovery - Message pushed '21569784 - Message ID:JoergsPC-50687-1258047095293-0:3422:1:1:1 dropped=false locked=false' to subscription: 'QueueSubscription: consumer=ID:JoergsPC-49370-1258101701975-0:13:1:1, destinations=1, dispatched=797, delivered=0, pending=0'
      2009-11-13 09:41:45,320 [eue://testQueue] DEBUG Usage - Memory usage change. from: 181, to: 182
      2009-11-13 09:41:45,327 [eue://testQueue] DEBUG Usage - Memory usage change. from: 182, to: 183
      2009-11-13 09:41:45,331 [eue://testQueue] DEBUG Usage - Memory usage change. from: 183, to: 184
      2009-11-13 09:41:45,332 [eue://testQueue] DEBUG Usage - Memory usage change. from: 45, to: 46
      2009-11-13 09:41:45,338 [eue://testQueue] DEBUG Usage - Memory usage change. from: 184, to: 185
      2009-11-13 09:41:45,344 [eue://testQueue] DEBUG Usage - Memory usage change. from: 185, to: 186
      2009-11-13 09:41:45,349 [eue://testQueue] DEBUG Usage - Memory usage change. from: 186, to: 187
      2009-11-13 09:41:45,356 [eue://testQueue] DEBUG Usage - Memory usage change. from: 187, to: 188
      2009-11-13 09:41:45,356 [eue://testQueue] DEBUG Usage - Memory usage change. from: 46, to: 47
      2009-11-13 09:41:45,442 [127.0.0.1:49384] DEBUG AbstractRegion - Removing consumer: ID:JoergsPC-49370-1258101701975-0:13:1:1
      2009-11-13 09:41:45,445 [eue://testQueue] DEBUG Usage - Memory usage change. from: 188, to: 189
      2009-11-13 09:41:45,443 [127.0.0.1:49372] DEBUG AbstractRegion - Removing consumer: ID:JoergsPC-49370-1258101701975-0:1:-1:1
      2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TransportConnection - Stopping connection: /127.0.0.1:49372
      2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TcpTransport - Stopping transport tcp:///127.0.0.1:49372
      2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TransportConnection - Stopped transport: /127.0.0.1:49372
      2009-11-13 09:41:45,632 [127.0.0.1:49372] DEBUG TransportConnection - Connection Stopped: /127.0.0.1:49372
      2009-11-13 09:41:45,636 [127.0.0.1:49385] DEBUG WireFormatNegotiator - Sending: WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
      2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG WireFormatNegotiator - Received WireFormat: WireFormatInfo { version=3, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
      2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG WireFormatNegotiator - tcp:///127.0.0.1:49385 before negotiation: OpenWireFormat{version=3, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false}

      2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG WireFormatNegotiator - tcp:///127.0.0.1:49385 after negotiation: OpenWireFormat

      {version=3, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false}

      2009-11-13 09:41:45,638 [127.0.0.1:49385] DEBUG TransportConnection - Setting up new connection: /127.0.0.1:49385
      2009-11-13 09:41:45,639 [127.0.0.1:49385] DEBUG AbstractRegion - Adding consumer: ID:JoergsPC-49370-1258101701975-0:14:-1:1
      2009-11-13 09:41:45,641 [eue://testQueue] DEBUG Usage - Memory usage change. from: 189, to: 190
      2009-11-13 09:41:45,647 [eue://testQueue] DEBUG Usage - Memory usage change. from: 190, to: 191
      2009-11-13 09:41:45,653 [eue://testQueue] DEBUG Usage - Memory usage change. from: 191, to: 192
      2009-11-13 09:41:45,653 [eue://testQueue] DEBUG Usage - Memory usage change. from: 47, to: 48
      2009-11-13 09:41:45,658 [eue://testQueue] DEBUG Usage - Memory usage change. from: 192, to: 193
      2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage - Memory usage change. from: 193, to: 192
      2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage - Memory usage change. from: 192, to: 191
      2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage - Memory usage change. from: 48, to: 47
      2009-11-13 09:41:45,663 [127.0.0.1:49384] DEBUG Usage - Memory usage change. from: 191, to: 190
      2009-11-13 09:41:45,664 [127.0.0.1:49384] DEBUG Usage - Memory usage change. from: 190, to: 189
      2009-11-13 09:41:45,664 [127.0.0.1:49384] DEBUG AMQMessageStore - flush starting ...
      2009-11-13 09:41:45,664 [127.0.0.1:49384] DEBUG AbstractRegion - Removing consumer: ID:JoergsPC-49370-1258101701975-0:13:-1:1
      2009-11-13 09:41:45,665 [127.0.0.1:49384] DEBUG TransportConnection - Stopping connection: /127.0.0.1:49384
      ...

      Attachments

        1. JMX-Screenshot.PNG
          79 kB
          Matthias Strolz
        2. DummyMessageConsumer.java
          8 kB
          Matthias Strolz

        Activity

          People

            Unassigned Unassigned
            matthias.strolz@movilitas.com Matthias Strolz
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: