You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by Manu <me...@gmail.com> on 2014/07/03 12:07:53 UTC
Master not correctly shuting down
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://<host>: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
Re: Master not correctly shuting down
Posted by Christian Posta <ch...@gmail.com>.
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 <me...@gmail.com> wrote:
> Any clue ?
>
>
>
> On Fri, Jul 4, 2014 at 9:52 AM, Manu <me...@gmail.com> 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 <me...@gmail.com> 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://<host>: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
Re: Master not correctly shuting down
Posted by Manu <me...@gmail.com>.
Any clue ?
On Fri, Jul 4, 2014 at 9:52 AM, Manu <me...@gmail.com> 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 <me...@gmail.com> 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://<host>: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
>>
>
>
Re: Master not correctly shuting down
Posted by Manu <me...@gmail.com>.
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 <ch...@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 <me...@gmail.com> 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://<host>: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
>
Re: Master not correctly shuting down
Posted by Christian Posta <ch...@gmail.com>.
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 <me...@gmail.com> 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://<host>: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