Hi Gary,
I set the logging level to DEBUG and after restarting, the log shows that
the select and update query for the ACTIVEMQ_LOCK times out. Here is the
exception:
----------------------------------------
2011-07-05 09:12:01,217 | INFO | Database lock driver override not found
for : [mysql-ab_jdbc_driver]. Will use default implementation. |
org.apache.activemq.store.jdbc.JDBCPersistenceAdapter | main
2011-07-05 09:12:01,218 | DEBUG | Using default JDBC Locker:
org.apache.activemq.store.jdbc.DefaultDatabaseLocker@40363068 |
org.apache.activemq.store.jdbc.JDBCPersistenceAdapter | main
2011-07-05 09:12:01,218 | INFO | Attempting to acquire the exclusive lock
to become the Master broker |
org.apache.activemq.store.jdbc.DefaultDatabaseLocker | main
2011-07-05 09:12:01,218 | DEBUG | Locking Query is SELECT * FROM
ACTIVEMQ_LOCK FOR UPDATE |
org.apache.activemq.store.jdbc.DefaultDatabaseLocker | main
2011-07-05 09:12:52,019 | DEBUG | Lock failure: java.sql.SQLException: Lock
wait timeout exceeded; try restarting transaction |
org.apache.activemq.store.jdbc.DefaultDatabaseLocker | main
java.sql.SQLException: Lock wait timeout exceeded; try restarting
transaction
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1075)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3566)
at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:1553)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1409)
at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2875)
at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:476)
at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2581)
at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1757)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2171)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1364)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
at
org.apache.activemq.store.jdbc.DefaultDatabaseLocker.start(DefaultDatabaseLocker.java:73)
at
org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.start(JDBCPersistenceAdapter.java:287)
at
org.apache.activemq.broker.BrokerService.start(BrokerService.java:493)
at
org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1536)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1477)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1409)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at
org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
at
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
at
org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:574)
at
org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:895)
at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:425)
at
org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:64)
at
org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
at
org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:114)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:114)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:70)
at
org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
at
org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
at
org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
at
org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at
org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:143)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at
org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:85)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.activemq.console.Main.runTaskClass(Main.java:251)
at org.apache.activemq.console.Main.main(Main.java:107)
2011-07-05 09:12:52,021 | DEBUG | Caught while closing statement:
java.sql.SQLException: Already closed |
org.apache.activemq.store.jdbc.DefaultDatabaseLocker | main
java.sql.SQLException: Already closed
at
org.apache.commons.dbcp.PoolablePreparedStatement.close(PoolablePreparedStatement.java:76)
at
org.apache.commons.dbcp.DelegatingStatement.close(DelegatingStatement.java:168)
at
org.apache.activemq.store.jdbc.DefaultDatabaseLocker.start(DefaultDatabaseLocker.java:115)
at
org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.start(JDBCPersistenceAdapter.java:287)
at
org.apache.activemq.broker.BrokerService.start(BrokerService.java:493)
at
org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
.....
2011-07-05 09:20:40,506 | INFO | Failed to acquire lock. Sleeping for 1000
milli(s) before trying again... |
org.apache.activemq.store.jdbc.DefaultDatabaseLocker | main
-------------------------------------------
The jconsole tells the broker is in slave state, though i'm not sure that
the information given by jconsole is accurate, since when i try to check the
attributes of the broker in jconsole, the following exceptions are thrown in
the broker's log:
-------------------------------------------
2011-07-05 09:21:59,246 | DEBUG | Failed to read URI to build
transportURIsAsMap | org.apache.activemq.broker.BrokerService | RMI TCP
Connection(8)-192.168.11.192
java.lang.NullPointerException
at
org.apache.activemq.broker.BrokerService.getTransportConnectorURIsAsMap(BrokerService.java:1109)
at
org.apache.activemq.broker.jmx.BrokerView.getOpenWireURL(BrokerView.java:318)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:93)
at
com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:27)
at
com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208)
at
com.sun.jmx.mbeanserver.PerInterface.getAttribute(PerInterface.java:65)
at
com.sun.jmx.mbeanserver.MBeanSupport.getAttribute(MBeanSupport.java:216)
at
com.sun.jmx.mbeanserver.MBeanSupport.getAttributes(MBeanSupport.java:223)
at javax.management.StandardMBean.getAttributes(StandardMBean.java:376)
at
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getAttributes(DefaultMBeanServerInterceptor.java:726)
at
com.sun.jmx.mbeanserver.JmxMBeanServer.getAttributes(JmxMBeanServer.java:665)
at
javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1407)
at
javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:72)
at
javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1264)
at
javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1359)
at
javax.management.remote.rmi.RMIConnectionImpl.getAttributes(RMIConnectionImpl.java:636)
at sun.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
at sun.rmi.transport.Transport$1.run(Transport.java:159)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
2011-07-05 09:21:59,247 | DEBUG | Failed to read URI to build
transportURIsAsMap | org.apache.activemq.broker.BrokerService | RMI TCP
Connection(8)-192.168.11.192
java.lang.NullPointerException
at
org.apache.activemq.broker.BrokerService.getTransportConnectorURIsAsMap(BrokerService.java:1109)
at
org.apache.activemq.broker.jmx.BrokerView.getSslURL(BrokerView.java:328)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
......
--------------------------------------------------------------------
Here is a snapshot of the broker's attributes in jconsole.
http://activemq.2283324.n4.nabble.com/file/n3645301/activemq.png
----------
Then i tried to fire against the broker and here is the output:
> mvn exec:java -Pproducer -Dtransacted=true -Dp.sleep.time=500
> -Dmessage.count=100 -Dbroker.url=tcp://192.168.11.107:61616
.....
[05/Jul/2011 09:13:39] DEBUG WireFormatNegotiator -
tcp:///192.168.11.107:61616 before negotiation: OpenWireFormat{version=7,
cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false,
sizePrefixDisabled=false}
[05/Jul/2011 09:13:39] DEBUG WireFormatNegotiator -
tcp:///192.168.11.107:61616 after negotiation: OpenWireFormat{version=6,
cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true,
sizePrefixDisabled=false}
[05/Jul/2011 09:13:39] DEBUG JmsTemplate - Executing callback on JMS
Session: PooledSession { ActiveMQSession
{id=ID:fade-cpu-57842-1309850019654-0:1:1,started=false} }
[05/Jul/2011 09:13:39] DEBUG JmsTemplate - Sending created message:
ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
null, originalDestination = null, originalTransactionId = null, producerId =
null, destination = null, transactionId = null, expiration = 0, timestamp =
0, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = null,
replyTo = null, persistent = false, type = null, priority = 0, groupID =
null, groupSequence = 0, targetConsumerId = null, compressed = false, userID
= null, content = null, marshalledProperties = null, dataStructure = null,
redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties =
false, readOnlyBody = false, droppable = false, text = Message: 0 sent at:
Tue Jul 05 09:13:39 CEST ... ...}
[05/Jul/2011 09:13:39] DEBUG TransactionContext -
Begin:TX:ID:fade-cpu-57842-1309850019654-0:1:1
[05/Jul/2011 09:13:39] DEBUG ActiveMQSession -
ID:fade-cpu-57842-1309850019654-0:1:1 Transaction Commit
:TX:ID:fade-cpu-57842-1309850019654-0:1:1
[05/Jul/2011 09:13:39] DEBUG TransactionContext - Commit:
TX:ID:fade-cpu-57842-1309850019654-0:1:1 syncCount: 0
[05/Jul/2011 09:13:39] DEBUG ActiveMQSession -
ID:fade-cpu-57842-1309850019654-0:1:1 Transaction Rollback
[05/Jul/2011 09:13:40] INFO AmqProducer - [Thread-2] Sending message:
'Message: 1 sent at: Tue Jul 05 09:13:40 CEST 2011
...'
[05/Jul/2011 09:13:40] DEBUG JmsTemplate - Executing callback on JMS
Session: PooledSession { ActiveMQSession
{id=ID:fade-cpu-57842-1309850019654-0:1:1,started=false} }
[05/Jul/2011 09:13:40] DEBUG JmsTemplate - Sending created message:
ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
null, originalDestination = null, originalTransactionId = null, producerId =
null, destination = null, transactionId = null, expiration = 0, timestamp =
0, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = null,
replyTo = null, persistent = false, type = null, priority = 0, groupID =
null, groupSequence = 0, targetConsumerId = null, compressed = false, userID
= null, content = null, marshalledProperties = null, dataStructure = null,
redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties =
false, readOnlyBody = false, droppable = false, text = Message: 1 sent at:
Tue Jul 05 09:13:40 CEST ... ...}
[05/Jul/2011 09:13:40] DEBUG TransactionContext -
Begin:TX:ID:fade-cpu-57842-1309850019654-0:1:2
[05/Jul/2011 09:13:40] DEBUG ActiveMQSession -
ID:fade-cpu-57842-1309850019654-0:1:1 Transaction Commit
:TX:ID:fade-cpu-57842-1309850019654-0:1:2
[05/Jul/2011 09:13:40] DEBUG TransactionContext - Commit:
TX:ID:fade-cpu-57842-1309850019654-0:1:2 syncCount: 0
[05/Jul/2011 09:13:40] DEBUG ActiveMQSession -
ID:fade-cpu-57842-1309850019654-0:1:1 Transaction Rollback
[05/Jul/2011 09:13:40] INFO AmqProducer - [Thread-2] Sending message:
'Message: 2 sent at: Tue Jul 05 09:13:40 CEST 2011
...'
[05/Jul/2011 09:13:40] DEBUG JmsTemplate - Executing callback on JMS
Session: PooledSession { ActiveMQSession
{id=ID:fade-cpu-57842-1309850019654-0:1:1,started=false} }
....
---------------------------------------------------------------
I'm not quite sure how to understand the following three lines coming up
after sending each message:
[05/Jul/2011 09:13:40] DEBUG ActiveMQSession -
ID:fade-cpu-57842-1309850019654-0:1:1 Transaction Commit
:TX:ID:fade-cpu-57842-1309850019654-0:1:2
[05/Jul/2011 09:13:40] DEBUG TransactionContext - Commit:
TX:ID:fade-cpu-57842-1309850019654-0:1:2 syncCount: 0
[05/Jul/2011 09:13:40] DEBUG ActiveMQSession -
ID:fade-cpu-57842-1309850019654-0:1:1 Transaction Rollback
Do we have a commit or rollback here ?!! Not very clear what activemq mean.
The messages get persisted in the brokers database anyway.
Regards,
-Farhad
--
View this message in context:
http://activemq.2283324.n4.nabble.com/Fail-to-acquire-lock-Stays-as-slave-tp3643888p3645301.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
