Return-Path: X-Original-To: apmail-activemq-dev-archive@www.apache.org Delivered-To: apmail-activemq-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id D9024102A8 for ; Mon, 17 Nov 2014 17:25:40 +0000 (UTC) Received: (qmail 93697 invoked by uid 500); 17 Nov 2014 17:25:34 -0000 Delivered-To: apmail-activemq-dev-archive@activemq.apache.org Received: (qmail 93611 invoked by uid 500); 17 Nov 2014 17:25:34 -0000 Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list dev@activemq.apache.org Received: (qmail 93390 invoked by uid 99); 17 Nov 2014 17:25:33 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 17 Nov 2014 17:25:33 +0000 Date: Mon, 17 Nov 2014 17:25:33 +0000 (UTC) From: "Jesse Fugitt (JIRA)" To: dev@activemq.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (AMQ-5440) KahaDB error at startup "Looking for key N but not found in fileMap" MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/AMQ-5440?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Jesse Fugitt updated AMQ-5440: ------------------------------ Attachment: KahaDB.zip kahadbtest.log Broker KahaDB folder that causes startup error and TRACE level log showing the GC records that caused it. > KahaDB error at startup "Looking for key N but not found in fileMap" > -------------------------------------------------------------------- > > Key: AMQ-5440 > URL: https://issues.apache.org/jira/browse/AMQ-5440 > Project: ActiveMQ > Issue Type: Bug > Components: Message Store > Affects Versions: 5.10.0 > Reporter: Jesse Fugitt > Priority: Critical > Attachments: KahaDB.zip, kahadbtest.log > > > After being shutdown uncleanly, KahaDB can hit a startup error at times that causes the broker to fail to start up and potentially causes messages to be re-assigned that are not marked as redelivered. > The log message at startup is: > 2014-11-17 11:10:36,826 | ERROR | Looking for key 275 but not found in fileMap: {305=db-305.log number = 305 , length = 8217, 304=db-304.log number = 304 , length = 8217, 307=db-307.log number = 307 , length = 8217, 306=db-306.log number = 306 , length = 8217, 309=db-309.log number = 309 , length = 8217, 308=db-308.log number = 308 , length = 8217, 311=db-311.log number = 311 , length = 8217, 310=db-310.log number = 310 , length = 8217, 313=db-313.log number = 313 , length = 8217, 312=db-312.log number = 312 , length = 8217, 314=db-314.log number = 314 , length = 317, 303=db-303.log number = 303 , length = 8433} | org.apache.activemq.store.kahadb.disk.journal.Journal | main > and the stack trace is: > Starting TestApp... > INFO | KahaDB is version 5 > ERROR | Looking for key 275 but not found in fileMap: {305=db-305.log number = 305 , length = 8217, 304=db-304.log number = 304 , length = 8217, 307=db-307.log number = 307 , length = 8217, 306=db-306.log number = 306 , length = 8217, 309=db-309.log number = 309 , length = 8217, 308=db-308.log number = 308 , length = 8217, 311=db-311.log number = 311 , length = 8217, 310=db-310.log number = 310 , length = 8217, 313=db-313.log number = 313 , length = 8217, 312=db-312.log number = 312 , length = 8217, 314=db-314.log number = 314 , length = 317, 303=db-303.log number = 303 , length = 8433} > Exception in thread "main" java.io.IOException: Could not locate data file KahaDB\db-275.log > at org.apache.activemq.store.kahadb.disk.journal.Journal.getDataFile(Journal.java:353) > at org.apache.activemq.store.kahadb.disk.journal.Journal.read(Journal.java:600) > at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:1014) > at org.apache.activemq.store.kahadb.MessageDatabase.recoverProducerAudit(MessageDatabase.java:687) > at org.apache.activemq.store.kahadb.MessageDatabase.recover(MessageDatabase.java:595) > at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:400) > at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:418) > at org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:262) > at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:194) > at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) > at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:215) > at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) > at kahadbtest.TestApp.run(TestApp.java:29) > at kahadbtest.TestApp.main(TestApp.java:21) > This was fairly hard to reproduce without unclean shutdown but the attached log and "broken" KahaDB folder should help debug the problem. Also, I will attach the small test app that exercises the KahaDB APIs that I was using to cause the invalid state (I normally start and stop the app a few times until the problem appears at startup at which point it will no longer start). > Some initial debugging looks like it might be related to the way that message acks are stored via the metadata serialization and how that interacts with the GC timer but I didn't see anything obvious. -- This message was sent by Atlassian JIRA (v6.3.4#6332)