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

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: JBoss A-MQ 6.3
    • Fix Version/s: JBoss A-MQ 6.3.x
    • Component/s: kahadb
    • Labels:
      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]
      

        Gliffy Diagrams

          Attachments

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

            Issue Links

              Activity

                People

                • Assignee:
                  garytully Gary Tully
                  Reporter:
                  pfox Patrick Fox
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  4 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: