activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stevo Slavić <ssla...@gmail.com>
Subject Database locked wait delay longer than databaseLockedWaitDelay
Date Wed, 04 Jan 2012 13:44:08 GMT
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.

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message