Return-Path: Delivered-To: apmail-activemq-dev-archive@www.apache.org Received: (qmail 42039 invoked from network); 18 Nov 2009 13:27:17 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 18 Nov 2009 13:27:17 -0000 Received: (qmail 43762 invoked by uid 500); 18 Nov 2009 13:27:17 -0000 Delivered-To: apmail-activemq-dev-archive@activemq.apache.org Received: (qmail 43732 invoked by uid 500); 18 Nov 2009 13:27:17 -0000 Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list dev@activemq.apache.org Received: (qmail 43691 invoked by uid 99); 18 Nov 2009 13:27:17 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 18 Nov 2009 13:27:17 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=10.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.140] (HELO brutus.apache.org) (140.211.11.140) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 18 Nov 2009 13:27:13 +0000 Received: from brutus (localhost [127.0.0.1]) by brutus.apache.org (Postfix) with ESMTP id AD225234C1EF for ; Wed, 18 Nov 2009 05:26:52 -0800 (PST) Message-ID: <1283158486.1258550812701.JavaMail.jira@brutus> Date: Wed, 18 Nov 2009 05:26:52 -0800 (PST) From: "Matthias Strolz (JIRA)" To: dev@activemq.apache.org Subject: [jira] Created: (AMQ-2500) Active MQ Blocks when sending and receiving messages and doesn't release resources even after queue is empty MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: ae95407df07c98740808b2ef9da0087c X-Virus-Checked: Checked by ClamAV on apache.org 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.