You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Hiram Chirino (JIRA)" <ji...@apache.org> on 2008/05/12 20:04:43 UTC
[jira] Commented: (AMQ-1720) Default Broker config does not
shutdown when an internal persistence error occurs.
[ https://issues.apache.org/activemq/browse/AMQ-1720?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=42751#action_42751 ]
Hiram Chirino commented on AMQ-1720:
------------------------------------
Pasting in a log showing a broker who's DB connection has died and the broker tired to shutdown the but the process has not exited.
{code}
ACTIVEMQ_HOME: C:\iona\apache-activemq-5.0.0.11-fuse\bin\..
ACTIVEMQ_BASE: C:\iona\apache-activemq-5.0.0.11-fuse\bin\..
Loading message broker from: xbean:activemq.xml
INFO BrokerService - Using Persistence Adapter: JDBCPersistenceAdaptor(org.apache.commons.dbcp.BasicDataSource@c272bc)
INFO BrokerService - ActiveMQ 5.0.0.11-fuse JMS Message Broker (localhost) is starting
INFO BrokerService - For help or more information please see: http://activemq.apache.org/
INFO ManagementContext - JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi
INFO JDBCPersistenceAdapter - Database driver recognized: [mysql-ab_jdbc_driver]
INFO DefaultDatabaseLocker - Attempting to acquire the exclusive lock to become the Master broker
INFO DefaultDatabaseLocker - Becoming the master on dataSource: org.apache.commons.dbcp.BasicDataSource@c272bc
INFO TransportServerThreadSupport - Listening for connections at: tcp://jluod810:61616
INFO TransportConnector - Connector openwire Started
INFO TransportServerThreadSupport - Listening for connections at: ssl://jluod810:61617
INFO TransportConnector - Connector ssl Started
INFO TransportServerThreadSupport - Listening for connections at: stomp://jluod810:61613
INFO TransportConnector - Connector stomp Started
INFO TransportServerThreadSupport - Listening for connections at: xmpp://jluod810:61222
INFO TransportConnector - Connector xmpp Started
INFO NetworkConnector - Network Connector org.apache.activemq.transport.discovery.multicast.MulticastDiscoveryAgent@25491d Started
INFO BrokerService - ActiveMQ JMS Message Broker (localhost, ID:jluod810-2851-1210614072672-0:0) started
INFO DiscoveryNetworkConnector - Establishing network connection between from vm://localhost to tcp://martinmd800:61616
INFO TransportConnector - Connector vm://localhost Started
INFO DemandForwardingBridge - Network connection between vm://localhost#2 and tcp://martinmd800/10.5.1.158:61616(localhost) has been established.
INFO log - Logging to org.slf4j.impl.JCLLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
INFO log - jetty-6.1.0.1-fuse
INFO WebConsoleStarter - ActiveMQ WebConsole initialized.
INFO /admin - Initializing Spring FrameworkServlet 'dispatcher'
INFO log - ActiveMQ Console at http://0.0.0.0:8161/admin
INFO log - ActiveMQ Web Demos at http://0.0.0.0:8161/demo
INFO log - Started SelectChannelConnector@0.0.0.0:8161
ERROR DefaultDatabaseLocker - Failed to update database lock: com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:
** BEGIN NESTED EXCEPTION **
java.net.SocketException
MESSAGE: Connection reset by peer: socket write error
STACKTRACE:
java.net.SocketException: Connection reset by peer: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2744)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1612)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1332)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1604)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1519)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1504)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:94)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:94)
at org.apache.activemq.store.jdbc.DefaultDatabaseLocker.keepAlive(DefaultDatabaseLocker.java:103)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.databaseLockKeepAlive(JDBCPersistenceAdapter.java:458)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter$3.run(JDBCPersistenceAdapter.java:260)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:280)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:135)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:65)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:142)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:166)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
** END NESTED EXCEPTION **
Last packet sent to the server was 0 ms ago.
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:
** BEGIN NESTED EXCEPTION **
java.net.SocketException
MESSAGE: Connection reset by peer: socket write error
STACKTRACE:
java.net.SocketException: Connection reset by peer: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2744)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1612)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1332)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1604)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1519)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1504)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:94)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:94)
at org.apache.activemq.store.jdbc.DefaultDatabaseLocker.keepAlive(DefaultDatabaseLocker.java:103)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.databaseLockKeepAlive(JDBCPersistenceAdapter.java:458)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter$3.run(JDBCPersistenceAdapter.java:260)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:280)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:135)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:65)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:142)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:166)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
** END NESTED EXCEPTION **
Last packet sent to the server was 0 ms ago.
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2759)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1612)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1332)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1604)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1519)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1504)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:94)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:94)
at org.apache.activemq.store.jdbc.DefaultDatabaseLocker.keepAlive(DefaultDatabaseLocker.java:103)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.databaseLockKeepAlive(JDBCPersistenceAdapter.java:458)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter$3.run(JDBCPersistenceAdapter.java:260)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:280)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:135)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:65)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:142)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:166)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
INFO JDBCPersistenceAdapter - No longer able to keep the exclusive lock so giving up being a master
INFO BrokerService - ActiveMQ Message Broker (localhost, ID:jluod810-2851-1210614072672-0:0) is shutting down
INFO DemandForwardingBridge - localhost bridge to localhost stopped
INFO NetworkConnector - Network Connector org.apache.activemq.transport.discovery.multicast.MulticastDiscoveryAgent@25491d Stopped
INFO TransportConnector - Connector openwire Stopped
INFO TransportConnector - Connector ssl Stopped
WARN ActiveMQConnection - Async exception with no exception listener: org.apache.activemq.transport.InactivityIOException: Channel was inactive for too long: localhost/127.0.0.1:61616
org.apache.activemq.transport.InactivityIOException: Channel was inactive for too long: localhost/127.0.0.1:61616
at org.apache.activemq.transport.InactivityMonitor.oneway(InactivityMonitor.java:225)
at org.apache.activemq.transport.InactivityMonitor$3.run(InactivityMonitor.java:135)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
INFO TransportConnector - Connector stomp Stopped
INFO TransportConnector - Connector xmpp Stopped
ERROR JDBCPersistenceAdapter - Could not stop service: JDBCPersistenceAdaptor(org.apache.commons.dbcp.BasicDataSource@c272bc). Reason: com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Connection.close() has already been called. Invalid operation in this state.
com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Connection.close() has already been called. Invalid operation in this state.
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:888)
at com.mysql.jdbc.Connection.getMutex(Connection.java:3755)
at com.mysql.jdbc.Connection.rollback(Connection.java:5251)
at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:220)
at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:220)
at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.rollback(PoolingDataSource.java:288)
at org.apache.activemq.store.jdbc.DefaultDatabaseLocker.stop(DefaultDatabaseLocker.java:94)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.stop(JDBCPersistenceAdapter.java:204)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:475)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.stopBroker(JDBCPersistenceAdapter.java:474)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.databaseLockKeepAlive(JDBCPersistenceAdapter.java:466)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter$3.run(JDBCPersistenceAdapter.java:260)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:280)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:135)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:65)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:142)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:166)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
ERROR ManagedTopicRegion - Could not stop service: TopicRegion: destinations=9, subscriptions=2, memory=0%. Reason: java.lang.InterruptedException
java.lang.InterruptedException
at java.lang.Object.wait(Native Method)
at org.apache.activemq.thread.DedicatedTaskRunner.shutdown(DedicatedTaskRunner.java:72)
at org.apache.activemq.thread.DedicatedTaskRunner.shutdown(DedicatedTaskRunner.java:83)
at org.apache.activemq.broker.region.Topic.stop(Topic.java:469)
at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:629)
at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:109)
at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:187)
at org.apache.activemq.broker.TransactionBroker.stop(TransactionBroker.java:117)
at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:157)
at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:157)
at org.apache.activemq.broker.BrokerService$2.stop(BrokerService.java:1513)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:477)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.stopBroker(JDBCPersistenceAdapter.java:474)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.databaseLockKeepAlive(JDBCPersistenceAdapter.java:466)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter$3.run(JDBCPersistenceAdapter.java:260)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:280)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:135)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:65)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:142)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:166)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
ERROR BrokerService$2 - Could not stop service: org.apache.activemq.broker.BrokerService$2@12b9f14. Reason: java.lang.InterruptedException
java.lang.InterruptedException
at java.lang.Object.wait(Native Method)
at org.apache.activemq.thread.DedicatedTaskRunner.shutdown(DedicatedTaskRunner.java:72)
at org.apache.activemq.thread.DedicatedTaskRunner.shutdown(DedicatedTaskRunner.java:83)
at org.apache.activemq.broker.region.Topic.stop(Topic.java:469)
at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:629)
at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:109)
at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:187)
at org.apache.activemq.broker.TransactionBroker.stop(TransactionBroker.java:117)
at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:157)
at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:157)
at org.apache.activemq.broker.BrokerService$2.stop(BrokerService.java:1513)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:477)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.stopBroker(JDBCPersistenceAdapter.java:474)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.databaseLockKeepAlive(JDBCPersistenceAdapter.java:466)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter$3.run(JDBCPersistenceAdapter.java:260)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:280)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:135)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:65)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:142)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:166)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
WARN ActiveMQConnection - Async exception with no exception listener: org.apache.activemq.transport.TransportDisposedIOException: Peer (vm://localhost#1) disposed.
org.apache.activemq.transport.TransportDisposedIOException: Peer (vm://localhost#1) disposed.
at org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:198)
at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
INFO TransportConnector - Connector vm://localhost Stopped
INFO BrokerService - ActiveMQ JMS Message Broker (localhost, ID:jluod810-2851-1210614072672-0:0) stopped
WARN JDBCPersistenceAdapter - Failed to stop brokercom.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Connection.close() has already been called. Invalid operation in this state.
{code}
> Default Broker config does not shutdown when an internal persistence error occurs.
> ----------------------------------------------------------------------------------
>
> Key: AMQ-1720
> URL: https://issues.apache.org/activemq/browse/AMQ-1720
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.1.0
> Reporter: Hiram Chirino
> Assignee: Hiram Chirino
>
> This is due to all the other non-deamon threads running that are not part of the broker but in the default config. For example jetty threads and camel stuff.
> We should allow the broker server to callback to a listener to that the Main that starts it all can System.exit properly when the broker is shutdown.. that should cause the non-daemon stuff to exit too.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.