Return-Path: X-Original-To: apmail-activemq-users-archive@www.apache.org Delivered-To: apmail-activemq-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 13A3511978 for ; Wed, 16 Jul 2014 14:23:41 +0000 (UTC) Received: (qmail 71281 invoked by uid 500); 16 Jul 2014 14:23:40 -0000 Delivered-To: apmail-activemq-users-archive@activemq.apache.org Received: (qmail 71241 invoked by uid 500); 16 Jul 2014 14:23:40 -0000 Mailing-List: contact users-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@activemq.apache.org Delivered-To: mailing list users@activemq.apache.org Received: (qmail 71224 invoked by uid 99); 16 Jul 2014 14:23:40 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 16 Jul 2014 14:23:40 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of christian.posta@gmail.com designates 209.85.215.50 as permitted sender) Received: from [209.85.215.50] (HELO mail-la0-f50.google.com) (209.85.215.50) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 16 Jul 2014 14:23:36 +0000 Received: by mail-la0-f50.google.com with SMTP id gf5so595726lab.9 for ; Wed, 16 Jul 2014 07:23:14 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; bh=CJXV04q2UsCw5b4QmRKWEpUq9QQMtgJQ6U01Wb+cty0=; b=xa9yEBzUf6Lsxwg9o3m4sza6n/Uvn2YZ236og8j1hWkEDU1c2Lnq4vJebU5rof9ka1 SdxJJZ/ZcAMGq36EQkocztCvRRiMDZuTl9+m7X+bCHC7HXcB/rgR1uMVgrHZymnwsuRo SCyDyQytdJNMZEupVM5kDKIuUADYJ0dlRiiefV1KTQVFBDmbpSmadFPNWT1KLK+AnyOS LpQAiFQbJLRP9+H0DMvNlOLFmUdqpSJD6hL8/u9IMrDi/95oa6mIoYb5SHW5iHZchiwU Q3azh+5S3KvapSUfowbVRa184fZ6cCHriAI9RS4+PaKj7haBEorGyE0cGbG5t+QcUvZg MUeA== MIME-Version: 1.0 X-Received: by 10.112.19.133 with SMTP id f5mr23779309lbe.48.1405520594294; Wed, 16 Jul 2014 07:23:14 -0700 (PDT) Received: by 10.114.77.193 with HTTP; Wed, 16 Jul 2014 07:23:14 -0700 (PDT) In-Reply-To: References: Date: Wed, 16 Jul 2014 07:23:14 -0700 Message-ID: Subject: Re: Master not correctly shuting down From: Christian Posta To: "users@activemq.apache.org" Content-Type: multipart/alternative; boundary=14dae93d8c86bf5e3904fe504334 X-Virus-Checked: Checked by ClamAV on apache.org --14dae93d8c86bf5e3904fe504334 Content-Type: text/plain; charset=UTF-8 If there is a blocked thread somehow, your stack trace didn't indicate any Jetty thread issues. It did indicate some problems with the mysql connection, however. On Wed, Jul 16, 2014 at 1:07 AM, Manu wrote: > Any clue ? > > > > On Fri, Jul 4, 2014 at 9:52 AM, Manu wrote: > > > No that large : 360 messages of average size of less than 1Ko. > > I did not check the heap at the time of the event. I'll take a look at > > those next time ... > > > > But do you think Jetty can have keep ActiveMq from shutting down ? > > > > > > > > On Thu, Jul 3, 2014 at 5:58 PM, Christian Posta < > christian.posta@gmail.com > > > wrote: > > > >> How large were these messages you were trying to browse, and how much > >> broker memory and JVM heap was available? > >> > >> > >> On Thu, Jul 3, 2014 at 3:07 AM, Manu wrote: > >> > >> > Hi there, > >> > > >> > We're facing a strange problem with our master slave configuration. > >> > We are using ActiveMQ 5.8.0 with a master/slave configuration with a > >> mysql > >> > persistent storage. > >> > > >> > This morning we were browsing the activemq admin console > >> > (http://:8161/admin/queues.jsp) > >> > and wanted to browse 360 messages that was in the queue. > >> > The request seemed to make mysql a bit overloaded :) and ActiveMq > >> failed to > >> > update the lease (is this the lock ?) and decided to shutdown. > >> > But, it seems jetty was blocking the shutdown with one of its threads. > >> > So both instance remained active (the admin console was still > >> available). > >> > We had to shut down both instances and restart them. Everything > >> restarted > >> > well, > >> > master was available and slave was waiting. > >> > > >> > How can we avoid this behavior ? > >> > > >> > Thanks in advance ! > >> > Manuel > >> > > >> > Here is the log extract : > >> > 2014-07-03 08:18:14,049 | WARN | locker keepalive resulted in: > >> > java.io.IOException: The last packet successfully received from the > >> server > >> > was 46 618 422 milliseconds ago. The last packet sent successfully to > >> the > >> > server was 46 618 424 milliseconds ago. is longer than the server > >> > configured value of 'wait_timeout'. You should consider either > expiring > >> > and/or testing connection validity before use in your application, > >> > increasing the server configured values for client timeouts, or using > >> the > >> > Connector/J connection property 'autoReconnect=true' to avoid this > >> problem. > >> > | org.apache.activemq.broker.LockableServiceSupport | ActiveMQ Cleanup > >> > Timer > >> > java.io.IOException: The last packet successfully received from the > >> server > >> > was 46 618 422 milliseconds ago. The last packet sent successfully to > >> the > >> > server was 46 618 424 milliseconds ago. is longer than the server > >> > configured value of 'wait_timeout'. You should consider either > expiring > >> > and/or testing connection validity before use in your application, > >> > increasing the server configured values for client timeouts, or using > >> the > >> > Connector/J connection property 'autoReconnect=true' to avoid this > >> problem. > >> > at > >> > > >> > > >> > org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport.java:45) > >> > at > >> > > >> > > >> > org.apache.activemq.store.jdbc.LeaseDatabaseLocker.keepAlive(LeaseDatabaseLocker.java:231) > >> > at > >> > > >> > > >> > org.apache.activemq.broker.LockableServiceSupport.keepLockAlive(LockableServiceSupport.java:115) > >> > at > >> > > >> > > >> > org.apache.activemq.broker.LockableServiceSupport$1.run(LockableServiceSupport.java:88) > >> > at java.util.concurrent.Executors$RunnableAdapter.call(Unknown > >> > Source) > >> > at > java.util.concurrent.FutureTask$Sync.innerRunAndReset(Unknown > >> > Source) > >> > at java.util.concurrent.FutureTask.runAndReset(Unknown Source) > >> > at > >> > > >> > > >> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(Unknown > >> > Source) > >> > at > >> > > >> > > >> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(Unknown > >> > Source) > >> > at > >> > > >> > > >> > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown > >> > Source) > >> > at > >> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown > >> > Source) > >> > at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown > >> > Source) > >> > at java.lang.Thread.run(Unknown Source) > >> > Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: > The > >> > last packet successfully received from the server was 46 618 422 > >> > milliseconds ago. The last packet sent successfully to the server was > >> 46 > >> > 618 424 milliseconds ago. is longer than the server configured value > of > >> > 'wait_timeout'. You should consider either expiring and/or testing > >> > connection validity before use in your application, increasing the > >> server > >> > configured values for client timeouts, or using the Connector/J > >> connection > >> > property 'autoReconnect=true' to avoid this problem. > >> > at > sun.reflect.GeneratedConstructorAccessor8.newInstance(Unknown > >> > Source) > >> > at > >> > sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown > >> Source) > >> > at java.lang.reflect.Constructor.newInstance(Unknown Source) > >> > at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) > >> > at > >> > > >> > com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1121) > >> > at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3938) > >> > at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2551) > >> > at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731) > >> > at > >> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2809) > >> > at > >> > > >> > com.mysql.jdbc.StatementImpl.executeSimpleNonQuery(StatementImpl.java:1703) > >> > at > >> > > >> > com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2447) > >> > at > >> > > >> > com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2375) > >> > at > >> > > >> > com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2359) > >> > at > >> > > >> > > >> > org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) > >> > at > >> > > >> > > >> > org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) > >> > at > >> > > >> > > >> > org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) > >> > at > >> > > >> > > >> > org.apache.activemq.store.jdbc.LeaseDatabaseLocker.keepAlive(LeaseDatabaseLocker.java:228) > >> > ... 11 more > >> > Caused by: java.net.SocketException: Broken pipe > >> > at java.net.SocketOutputStream.socketWrite0(Native Method) > >> > at java.net.SocketOutputStream.socketWrite(Unknown Source) > >> > at java.net.SocketOutputStream.write(Unknown Source) > >> > at java.io.BufferedOutputStream.flushBuffer(Unknown Source) > >> > at java.io.BufferedOutputStream.flush(Unknown Source) > >> > at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3919) > >> > ... 22 more > >> > 2014-07-03 08:18:19,050 | INFO | amq01, no longer able to keep the > >> > exclusive lock so giving up being a master | > >> > org.apache.activemq.broker.LockableServiceSupport | ActiveMQ Cleanup > >> Timer > >> > 2014-07-03 08:18:19,051 | INFO | Apache ActiveMQ 5.8.0 (amq01, > >> > ID:esb01-46942-1403704389061-0:1) is shutting down | > >> > org.apache.activemq.broker.BrokerService | ActiveMQ Cleanup Timer > >> > 2014-07-03 08:18:21,144 | INFO | Connector openwire Stopped | > >> > org.apache.activemq.broker.TransportConnector | ActiveMQ Cleanup Timer > >> > 2014-07-03 08:18:29,998 | INFO | > >> > PListStore:[/opt/activemq/data/amq01/tmp_storage] stopped | > >> > org.apache.activemq.store.kahadb.plist.PListStoreImpl | ActiveMQ > Cleanup > >> > Timer > >> > 2014-07-03 08:18:30,005 | INFO | Apache ActiveMQ 5.8.0 (amq01, > >> > ID:esb01-46942-1403704389061-0:1) uptime 7 days 16 hours | > >> > org.apache.activemq.broker.BrokerService | ActiveMQ Cleanup Timer > >> > 2014-07-03 08:18:30,005 | INFO | Apache ActiveMQ 5.8.0 (amq01, > >> > ID:esb01-46942-1403704389061-0:1) is shutdown | > >> > org.apache.activemq.broker.BrokerService | ActiveMQ Cleanup Timer > >> > 2014-07-03 08:18:30,005 | INFO | Closing > >> > org.apache.activemq.xbean.XBeanBrokerFactory$1@6f878144: startup date > >> [Wed > >> > Jun 25 15:53:05 CEST 2014]; root of context hierarchy | > >> > org.apache.activemq.xbean.XBeanBrokerFactory$1 | ActiveMQ Cleanup > Timer > >> > 2014-07-03 08:18:30,021 | INFO | Destroying Spring FrameworkServlet > >> > 'dispatcher' | /admin | ActiveMQ Cleanup Timer > >> > 2014-07-03 08:18:30,124 | WARN | 1 threads could not be stopped | > >> > org.eclipse.jetty.util.thread.QueuedThreadPool | ActiveMQ Cleanup > Timer > >> > > >> > >> > >> > >> -- > >> *Christian Posta* > >> http://www.christianposta.com/blog > >> http://fabric8.io > >> twitter: @christianposta > >> > > > > > -- *Christian Posta* http://www.christianposta.com/blog http://fabric8.io twitter: @christianposta --14dae93d8c86bf5e3904fe504334--