Hello ActiveMQ community, While testing shared fileystem storage master/slave setup behavior when master node loses access to shared filesystem storage and gets fenced, on slave node databaseLockedWaitDelay unexpectedly did not get respected, actual delay was much longer at a single last check. Log (INFO level only) from that incident follows:
2012-01-04 13:58:38,654 | INFO | Database /data/activemq_data/kahadb/lock is locked... waiting 10 seconds for the database to be unlocked. Reason: java.io.IOException: File '/data/activemq_data/kahadb/lock' could not be locked. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 13:58:48,658 | INFO | Database /data/activemq_data/kahadb/lock is locked... waiting 10 seconds for the database to be unlocked. Reason: java.io.IOException: File '/data/activemq_data/kahadb/lock' could not be locked. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 13:58:58,662 | INFO | Database /data/activemq_data/kahadb/lock is locked... waiting 10 seconds for the database to be unlocked. Reason: java.io.IOException: File '/data/activemq_data/kahadb/lock' could not be locked. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 13:59:08,665 | INFO | Database /data/activemq_data/kahadb/lock is locked... waiting 10 seconds for the database to be unlocked. Reason: java.io.IOException: File '/data/activemq_data/kahadb/lock' could not be locked. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 13:59:18,669 | INFO | Database /data/activemq_data/kahadb/lock is locked... waiting 10 seconds for the database to be unlocked. Reason: java.io.IOException: File '/data/activemq_data/kahadb/lock' could not be locked. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 14:04:40,710 | INFO | Database /data/activemq_data/kahadb/lock is locked... waiting 10 seconds for the database to be unlocked. Reason: java.io.IOException: File '/data/activemq_data/kahadb/lock' could not be locked. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 14:04:50,749 | INFO | Corrupt journal records found in '/data/activemq_data/kahadb/db-1.log' between offsets: 114003-114353 | org.apache.kahadb.journal.Journal | WrapperSimpleAppMain 2012-01-04 14:04:51,521 | INFO | KahaDB is version 3 | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 14:04:51,607 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 14:04:51,758 | INFO | Recovery replayed 6 operations from the journal in 0.218 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | WrapperSimpleAppMain 2012-01-04 14:04:51,783 | INFO | ActiveMQ 5.5.0 JMS Message Broker (localhost) is starting | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain 2012-01-04 14:04:51,783 | INFO | For help or more information please see: http://activemq.apache.org/ | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain 2012-01-04 14:04:52,076 | INFO | Listening for connections at: tcp://foo02:61616 | org.apache.activemq.transport.TransportServerThreadSupport | WrapperSimpleAppMain 2012-01-04 14:04:52,077 | INFO | Connector openwire Started | org.apache.activemq.broker.TransportConnector | WrapperSimpleAppMain 2012-01-04 14:04:52,087 | INFO | ActiveMQ JMS Message Broker (localhost, ID:foo02-4323-1325682291636-0:1) started | org.apache.activemq.broker.BrokerService | WrapperSimpleAppMain 2012-01-04 14:04:52,203 | INFO | jetty-7.1.6.v20100715 | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:52,271 | WARN | Can't reuse /tmp/Jetty_0_0_0_0_8161_admin__admin__9l5s6p, using /tmp/Jetty_0_0_0_0_8161_admin__admin__9l5s6p_2844807028438572996 | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:52,685 | INFO | ActiveMQ WebConsole initialized. | org.apache.activemq.web.WebConsoleStarter | WrapperSimpleAppMain 2012-01-04 14:04:52,804 | INFO | Initializing Spring FrameworkServlet 'dispatcher' | /admin | WrapperSimpleAppMain 2012-01-04 14:04:53,062 | INFO | ActiveMQ Console at http://0.0.0.0:8161/admin | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:53,063 | WARN | Can't reuse /tmp/Jetty_0_0_0_0_8161_camel__camel__.3v7y27, using /tmp/Jetty_0_0_0_0_8161_camel__camel__.3v7y27_8693365593673680321 | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:53,297 | INFO | Initializing Spring root WebApplicationContext | /camel | WrapperSimpleAppMain 2012-01-04 14:04:53,374 | INFO | OSGi environment not detected. | org.apache.camel.spring.handler.CamelNamespaceHandler | WrapperSimpleAppMain 2012-01-04 14:04:54,174 | INFO | Apache Camel 2.7.0 (CamelContext: camel) is starting | org.apache.camel.spring.SpringCamelContext | WrapperSimpleAppMain 2012-01-04 14:04:54,181 | INFO | JMX enabled. Using ManagedManagementStrategy. | org.apache.camel.spring.SpringCamelContext | WrapperSimpleAppMain 2012-01-04 14:04:54,619 | INFO | Found 5 packages with 16 @Converter classes to load | org.apache.camel.impl.converter.AnnotationTypeConverterLoader | WrapperSimpleAppMain 2012-01-04 14:04:54,640 | INFO | Loaded 152 type converters in 0.345 seconds | org.apache.camel.impl.converter.DefaultTypeConverter | WrapperSimpleAppMain 2012-01-04 14:04:54,959 | INFO | Connector vm://localhost Started | org.apache.activemq.broker.TransportConnector | WrapperSimpleAppMain 2012-01-04 14:04:55,047 | INFO | Route: route1 started and consuming from: Endpoint[activemq://example.A] | org.apache.camel.spring.SpringCamelContext | WrapperSimpleAppMain 2012-01-04 14:04:55,059 | INFO | Total 1 routes, of which 1 is started. | org.apache.camel.spring.SpringCamelContext | WrapperSimpleAppMain 2012-01-04 14:04:55,059 | INFO | Apache Camel 2.7.0 (CamelContext: camel) started in 0.886 seconds | org.apache.camel.spring.SpringCamelContext | WrapperSimpleAppMain 2012-01-04 14:04:55,987 | INFO | Camel Console at http://0.0.0.0:8161/camel| org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:55,987 | WARN | Can't reuse /tmp/Jetty_0_0_0_0_8161_demo__demo__uj3swb, using /tmp/Jetty_0_0_0_0_8161_demo__demo__uj3swb_286090998992124536 | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:56,006 | INFO | ActiveMQ Web Demos at http://0.0.0.0:8161/demo | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:56,006 | WARN | Can't reuse /tmp/Jetty_0_0_0_0_8161_fileserver__fileserver__rlvn9v, using /tmp/Jetty_0_0_0_0_8161_fileserver__fileserver__rlvn9v_7990089765695821370 | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:56,015 | INFO | RESTful file access application at http://0.0.0.0:8161/fileserver | org.eclipse.jetty.util.log | WrapperSimpleAppMain 2012-01-04 14:04:56,074 | INFO | Started SelectChannelConnector@0.0.0.0:8161 | org.eclipse.jetty.util.log | WrapperSimpleAppMain All but last check took 10sec as expected, but last one took 4min and 22sec! I'm not sure what was the cause. Does anyone have any ideas? Regards, Stevo.
