Uploaded image for project: 'JBoss A-MQ'
  1. JBoss A-MQ
  2. ENTMQ-2065

[A-MQ 6, kahadb, recovery] partial last write in journal is blocking broker restart

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • JBoss A-MQ 6.3.x
    • JBoss A-MQ 6.3
    • kahadb
    • None

    Description

      From the logs a broker write appears to fail (due to disk space issues). The broker is configured to shutdown when it hits a "no space on disk error" 

      2017-02-06 15:27:56,962 | WARN  | Data File Writer | DataFileAppender                 | db.disk.journal.DataFileAppender  349 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Journal failed while writing at: 58:35654773
java.io.IOException: No space left on device
	at java.io.RandomAccessFile.writeBytes(Native Method)[:1.8.0_45]
	at java.io.RandomAccessFile.write(RandomAccessFile.java:525)[:1.8.0_45]
	at org.apache.activemq.util.RecoverableRandomAccessFile.write(RecoverableRandomAccessFile.java:245)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender.processQueue(DataFileAppender.java:332)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender$1.run(DataFileAppender.java:169)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
2017-02-06 15:27:56,963 | ERROR | .0.1:54XXX@XXXX | MessageDatabase                  | emq.store.kahadb.MessageDatabase 1088 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | KahaDB failed to store to Journal
java.io.IOException: No space left on device
	at java.io.RandomAccessFile.writeBytes(Native Method)[:1.8.0_45]
	at java.io.RandomAccessFile.write(RandomAccessFile.java:525)[:1.8.0_45]
	at org.apache.activemq.util.RecoverableRandomAccessFile.write(RecoverableRandomAccessFile.java:245)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender.processQueue(DataFileAppender.java:332)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender$1.run(DataFileAppender.java:169)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
2017-02-06 15:27:56,964 | INFO  | .0.1:54XXX@XXXX | DefaultIOExceptionHandler        | q.util.DefaultIOExceptionHandler  166 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Stopping BrokerService[amq] due to exception, java.io.IOException: No space left on device
java.io.IOException: No space left on device
	at java.io.RandomAccessFile.writeBytes(Native Method)[:1.8.0_45]
	at java.io.RandomAccessFile.write(RandomAccessFile.java:525)[:1.8.0_45]
	at org.apache.activemq.util.RecoverableRandomAccessFile.write(RecoverableRandomAccessFile.java:245)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender.processQueue(DataFileAppender.java:332)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender$1.run(DataFileAppender.java:169)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
2017-02-06 15:27:56,965 | WARN  | .0.1:54XXX@XXXX | LocalTransaction                 | emq.transaction.LocalTransaction   73 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Store COMMIT FAILED: 
org.apache.activemq.broker.SuppressReplyException: ShutdownBrokerInitiated
	at org.apache.activemq.util.DefaultIOExceptionHandler.handle(DefaultIOExceptionHandler.java:162)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.BrokerService.handleIOException(BrokerService.java:2661)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:1089)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:1047)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.KahaDBTransactionStore.commit(KahaDBTransactionStore.java:301)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transaction.LocalTransaction.commit(LocalTransaction.java:70)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:252)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.BrokerFilter.commitTransaction(BrokerFilter.java:112)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.BrokerFilter.commitTransaction(BrokerFilter.java:112)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:117)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.TransportConnection.processCommitTransactionOnePhase(TransportConnection.java:528)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:100)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:326)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:190)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:300)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_45]
Caused by: java.io.IOException: No space left on device
	at java.io.RandomAccessFile.writeBytes(Native Method)[:1.8.0_45]
	at java.io.RandomAccessFile.write(RandomAccessFile.java:525)[:1.8.0_45]
	at org.apache.activemq.util.RecoverableRandomAccessFile.write(RecoverableRandomAccessFile.java:245)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender.processQueue(DataFileAppender.java:332)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.journal.DataFileAppender$1.run(DataFileAppender.java:169)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
2017-02-06 15:27:56,966 | INFO  | okerService[amq] | BrokerService                    | he.activemq.broker.BrokerService  789 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Apache ActiveMQ 5.11.0.redhat-630224 (amq, ID:XXXX1) is shutting down

      But when the broker is restart the checkForCorruptJournalFiles="true" appears to detect the partial last write and block the startup.

      2017-02-06 15:28:44,900 | WARN  | AMQ-1-thread-1   | Journal                          | tore.kahadb.disk.journal.Journal  467 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Corrupt journal records found in '/XXX/db-58.log' between offsets: 35654773..35912055
2017-02-06 15:28:44,920 | INFO  | AMQ-1-thread-1   | MessageDatabase                  | .kahadb.MessageDatabase$Metadata  181 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | KahaDB is version 5
2017-02-06 15:28:44,956 | INFO  | AMQ-1-thread-1   | MessageDatabase                  | emq.store.kahadb.MessageDatabase  640 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Recovering from the journal @58:35559434
2017-02-06 15:28:45,297 | INFO  | AMQ-1-thread-1   | MessageDatabase                  | emq.store.kahadb.MessageDatabase  668 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Recovery replayed 58 operations from the journal in 0.362 seconds.
2017-02-06 15:28:45,328 | ERROR | AMQ-1-thread-1   | MessageDatabase                  | emq.store.kahadb.MessageDatabase  929 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Detected corrupt journal files. [58:35654773 >= key < 58:35912056]
2017-02-06 15:28:45,328 | ERROR | AMQ-1-thread-1   | BrokerService                    | he.activemq.broker.BrokerService  611 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Failed to start Apache ActiveMQ ([amq, null], java.io.IOException: Detected corrupt journal files. [58:35654773 >= key < 58:35912056])
2017-02-06 15:28:45,329 | INFO  | AMQ-1-thread-1   | BrokerService                    | he.activemq.broker.BrokerService  789 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Apache ActiveMQ 5.11.0.redhat-630224 (amq, null) is shutting down
2017-02-06 15:28:45,330 | INFO  | AMQ-1-thread-1   | TransportConnector               | tivemq.broker.TransportConnector  291 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Connector openwire stopped
2017-02-06 15:28:45,330 | INFO  | AMQ-1-thread-1   | TransportConnector               | tivemq.broker.TransportConnector  291 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Connector amqp stopped
2017-02-06 15:28:45,330 | INFO  | AMQ-1-thread-1   | TransportConnector               | tivemq.broker.TransportConnector  291 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Connector mqtt stopped
2017-02-06 15:28:45,330 | INFO  | AMQ-1-thread-1   | TransportConnector               | tivemq.broker.TransportConnector  291 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Connector ws stopped
2017-02-06 15:28:45,331 | INFO  | AMQ-1-thread-1   | PListStoreImpl                   | tore.kahadb.plist.PListStoreImpl  370 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | PListStore:[/XXX/tmp_storage] stopped
2017-02-06 15:28:45,332 | INFO  | AMQ-1-thread-1   | KahaDBStore                      | ctivemq.store.kahadb.KahaDBStore  244 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Stopping async queue tasks
2017-02-06 15:28:45,332 | INFO  | AMQ-1-thread-1   | KahaDBStore                      | ctivemq.store.kahadb.KahaDBStore  258 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Stopping async topic tasks
2017-02-06 15:28:45,332 | INFO  | AMQ-1-thread-1   | KahaDBStore                      | ctivemq.store.kahadb.KahaDBStore  286 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Stopped KahaDB
2017-02-06 15:28:45,364 | INFO  | AMQ-1-thread-1   | BrokerService                    | he.activemq.broker.BrokerService  850 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Apache ActiveMQ 5.11.0.redhat-630224 (amq, null) uptime 6.644 seconds
2017-02-06 15:28:45,364 | INFO  | AMQ-1-thread-1   | BrokerService                    | he.activemq.broker.BrokerService  852 | 162 - org.apache.activemq.activemq-osgi - 5.11.0.redhat-630224 | Apache ActiveMQ 5.11.0.redhat-630224 (amq, null) is shutdown
2017-02-06 15:28:45,364 | INFO  | AMQ-1-thread-1   | ActiveMQServiceFactory           | Factory$ClusteredConfiguration$1  502 | 176 - io.fabric8.mq.mq-fabric - 1.2.0.redhat-630224 | Broker amq failed to start.  Will try again in 10 seconds
2017-02-06 15:28:45,365 | ERROR | AMQ-1-thread-1   | ActiveMQServiceFactory           | Factory$ClusteredConfiguration$1  503 | 176 - io.fabric8.mq.mq-fabric - 1.2.0.redhat-630224 | Exception on start: java.io.IOException: Detected corrupt journal files. [58:35654773 >= key < 58:35912056]
java.io.IOException: Detected corrupt journal files. [58:35654773 >= key < 58:35912056]
	at org.apache.activemq.store.kahadb.MessageDatabase.recoverIndex(MessageDatabase.java:930)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase$5.execute(MessageDatabase.java:676)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.disk.page.Transaction.execute(Transaction.java:779)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase.recover(MessageDatabase.java:673)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:429)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:447)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:283)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:205)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:223)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:658)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:642)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at org.apache.activemq.broker.BrokerService.start(BrokerService.java:607)[162:org.apache.activemq.activemq-osgi:5.11.0.redhat-630224]
	at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration.doStart(ActiveMQServiceFactory.java:549)[176:io.fabric8.mq.mq-fabric:1.2.0.redhat-630224]
	at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration.access$400(ActiveMQServiceFactory.java:359)[176:io.fabric8.mq.mq-fabric:1.2.0.redhat-630224]
	at io.fabric8.mq.fabric.ActiveMQServiceFactory$ClusteredConfiguration$1.run(ActiveMQServiceFactory.java:490)[176:io.fabric8.mq.mq-fabric:1.2.0.redhat-630224]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_45]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_45]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_45]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_45]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_45]

      Attachments

        1. amq.log.gz
          1.10 MB
        2. exception_log.txt
          25 kB
        3. R1.logs.tar.gz
          3.34 MB

        Issue Links

          is related to

          Bug - A problem that impairs or prevents the functions of the product. ENTMQ-2073 [A-MQ, kahadb] NullPointerException raised at org.apache.activemq.store.kahadb.disk.index.BTreeNode$BTreeIterator.findNextPage()

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Activity

            People

              gtully@redhat.com Gary Tully
              rhn-support-pfox Patrick Fox (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: