You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Matthias Strolz (JIRA)" <ji...@apache.org> on 2009/11/18 14:26:52 UTC
[jira] Created: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
------------------------------------------------------------------------------------------------------------
Key: AMQ-2500
URL: https://issues.apache.org/activemq/browse/AMQ-2500
Project: ActiveMQ
Issue Type: Bug
Affects Versions: 5.2.0
Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
Reporter: Matthias Strolz
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
...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Matthias Strolz (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matthias Strolz updated AMQ-2500:
---------------------------------
Attachment: DummyMessageConsumer.java
This dummy implementation produces the problem described in the bug report.
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Matthias Strolz (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=56068#action_56068 ]
Matthias Strolz commented on AMQ-2500:
--------------------------------------
I tested the behaviour on 5.3 and the 5.4 Snapshot. With both versions the broker recovers after several messages have been read from the queue. So the error obviously doesn't occur anymore.
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Matthias Strolz (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matthias Strolz updated AMQ-2500:
---------------------------------
Attachment: DummyMessageConsumer.java
I appended a version without internal dependency to AbstractConsumer
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Resolved: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Gary Tully resolved AMQ-2500.
-----------------------------
Resolution: Fixed
Fix Version/s: 5.3.0
resolving based on comment from Matthias.
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Fix For: 5.3.0
>
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Matthias Strolz (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matthias Strolz updated AMQ-2500:
---------------------------------
Attachment: (was: DummyMessageConsumer.java)
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Matthias Strolz (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matthias Strolz updated AMQ-2500:
---------------------------------
Attachment: JMX-Screenshot.PNG
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Fredrik Jonson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=55550#action_55550 ]
Fredrik Jonson commented on AMQ-2500:
-------------------------------------
I failed to compile the attached test, there is a missing dependency on class AbstractConsumer.
Matthias can you reproduce it against the 5.3.0 release? I haven't seen any public discussion of plans to make a 5.2 bugfix release at this stage, so it is likely that you'll be urged to upgrade anyway, either to 5.3.0 or to 5.3.1 when it is released.
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (AMQ-2500) Active MQ Blocks when sending and
receiving messages and doesn't release resources even after queue is empty
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/activemq/browse/AMQ-2500?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=55547#action_55547 ]
Gary Tully commented on AMQ-2500:
---------------------------------
can you verify if this problem exists with a current snapshot[1], If it does, a thread dump of the broker and the hung client would be helpful.
[1] https://repository.apache.org/content/repositories/snapshots/org/apache/activemq/apache-activemq/5.4-SNAPSHOT/
> Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty
> ------------------------------------------------------------------------------------------------------------
>
> Key: AMQ-2500
> URL: https://issues.apache.org/activemq/browse/AMQ-2500
> Project: ActiveMQ
> Issue Type: Bug
> Affects Versions: 5.2.0
> Environment: JDK 1.6.0.x, Windows XP and Vista, ActiveMQ Default-configurations
> Reporter: Matthias Strolz
> Attachments: DummyMessageConsumer.java, JMX-Screenshot.PNG
>
>
> 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
> ...
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.