[AMQ-5786] ActiveMQ failed to start with KahaDB reporting corrupt journal records and throwing NegativeArraySizeException

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Incomplete
• Affects Version/s: 5.11.1
• Component/s: KahaDB

Environment

Karaf 3.0.3

• Assignee: Unassigned
• Reporter: Martin Lichtin
• Created: 20/May/15 14:46
• Updated: 21/Jan/16 11:07
• Resolved: 20/Jan/16 22:45

Description

ActiveMQ failed to start up, with the following information:

2015-05-20 14:23:21,709 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 5504795..5505130
2015-05-20 14:23:21,725 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 5611475..5612818
2015-05-20 14:23:21,749 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 6139835..6140254
2015-05-20 14:23:21,756 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 6246179..6247270
2015-05-20 14:23:21,765 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 6512519..6520426
2015-05-20 14:23:21,789 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 7606018..7627848
2015-05-20 14:23:21,794 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 7630473..7650409
2015-05-20 14:23:21,796 | INFO  | apache.activemq.server]) | Journal                          | tore.kahadb.disk.journal.Journal  219 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Corrupt journal records found in 'activemq/kahadb/db-1.log' between offsets: 7650488..7703243
2015-05-20 14:23:22,065 | INFO  | apache.activemq.server]) | MessageDatabase                  | .kahadb.MessageDatabase$Metadata  168 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | KahaDB is version 5
2015-05-20 14:23:22,188 | INFO  | apache.activemq.server]) | MessageDatabase                  | emq.store.kahadb.MessageDatabase  603 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Recovering from the journal ...
2015-05-20 14:23:22,188 | ERROR | apache.activemq.server]) | BrokerService                    | he.activemq.broker.BrokerService  609 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Failed to start Apache ActiveMQ ([broker-amq, null], java.io.IOException: Invalid location: 1:6516763, : java.lang.NegativeArraySizeException)
2015-05-20 14:23:22,189 | INFO  | apache.activemq.server]) | BrokerService                    | he.activemq.broker.BrokerService  758 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Apache ActiveMQ 5.11.1 (broker-amq, null) is shutting down
2015-05-20 14:23:22,194 | INFO  | apache.activemq.server]) | TransportConnector               | tivemq.broker.TransportConnector  291 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Connector openwire stopped
2015-05-20 14:23:22,372 | INFO  | apache.activemq.server]) | JobSchedulerStoreImpl            | .scheduler.JobSchedulerStoreImpl  259 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | JobSchedulerStore: activemq/broker-amq/scheduler stopped.
2015-05-20 14:23:22,372 | INFO  | apache.activemq.server]) | PListStoreImpl                   | tore.kahadb.plist.PListStoreImpl  356 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | PListStore:[/integrator/int1/proc/broker-amq/karaf-std-0.2-440/activemq/broker-amq/tmp_storage] stopped
2015-05-20 14:23:22,372 | INFO  | apache.activemq.server]) | KahaDBStore                      | ctivemq.store.kahadb.KahaDBStore  245 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Stopping async queue tasks
2015-05-20 14:23:22,372 | INFO  | apache.activemq.server]) | KahaDBStore                      | ctivemq.store.kahadb.KahaDBStore  259 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Stopping async topic tasks
2015-05-20 14:23:22,373 | INFO  | apache.activemq.server]) | KahaDBStore                      | ctivemq.store.kahadb.KahaDBStore  287 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Stopped KahaDB
2015-05-20 14:23:22,664 | INFO  | apache.activemq.server]) | BrokerService                    | he.activemq.broker.BrokerService  819 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Apache ActiveMQ 5.11.1 (broker-amq, null) uptime 1.245 seconds
2015-05-20 14:23:22,664 | INFO  | apache.activemq.server]) | BrokerService                    | he.activemq.broker.BrokerService  821 | 105 - org.apache.activemq.activemq-osgi - 5.11.1 | Apache ActiveMQ 5.11.1 (broker-amq, null) is shutdown
2015-05-20 14:23:22,676 | ERROR | apache.activemq.server]) | configadmin                      | ?                                   ? | 6 - org.apache.felix.configadmin - 1.8.0 | [org.osgi.service.cm.ManagedServiceFactory, id=673, bundle=105/mvn:org.apache.activemq/activemq-osgi/5.11.1]: Updating configuration org.apache.activemq.server.02ee5a2d-fb5b-48ce-b4e1-93ed72adba19 caused a problem: Cannot start the broker
org.osgi.service.cm.ConfigurationException: null : Cannot start the broker
        at org.apache.activemq.osgi.ActiveMQServiceFactory.updated(ActiveMQServiceFactory.java:120)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at Proxyfc1340e4_63f4_474d_995e_cdb9ac0c71b9.updated(Unknown Source)[:]
        at org.apache.felix.cm.impl.helper.ManagedServiceFactoryTracker.provideConfiguration(ManagedServiceFactoryTracker.java:88)[6:org.apache.felix.configadmin:1.8.0]
        at org.apache.felix.cm.impl.ConfigurationManager$ManagedServiceFactoryUpdate.provide(ConfigurationManager.java:1605)[6:org.apache.felix.configadmin:1.8.0]
        at org.apache.felix.cm.impl.ConfigurationManager$ManagedServiceFactoryUpdate.run(ConfigurationManager.java:1548)[6:org.apache.felix.configadmin:1.8.0]
        at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:103)[6:org.apache.felix.configadmin:1.8.0]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_45]
Caused by: java.io.IOException: Invalid location: 1:6516763, : java.lang.NegativeArraySizeException
        at org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readRecord(DataFileAccessor.java:92)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.disk.journal.Journal.read(Journal.java:619)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:1013)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.MessageDatabase.recover(MessageDatabase.java:605)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:399)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:417)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:261)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:206)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:223)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:651)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:640)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.broker.BrokerService.start(BrokerService.java:605)[105:org.apache.activemq.activemq-osgi:5.11.1]
        at org.apache.activemq.osgi.ActiveMQServiceFactory.updated(ActiveMQServiceFactory.java:116)[105:org.apache.activemq.activemq-osgi:5.11.1]
        ... 6 more
Caused by: java.lang.NegativeArraySizeException
        at org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readRecord(DataFileAccessor.java:87)[105:org.apache.activemq.activemq-osgi:5.11.1]
        ... 20 more

<kahaDB> is configured with checkForCorruptJournalFiles="true".

Issue Links

• duplicates: AMQ-3098 Failed to page in more queue messages - Cannot consume messages
• relates to: AMQ-6134 ActiveMQ corrupted state when local disk fills up and Queues begin to buffer to KahaDB