ActiveMQ
  1. ActiveMQ
  2. AMQ-1063

Journaled JDBC checkpoint fails with java.io.IOException: Already started.

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 5.0.0
    • Fix Version/s: 5.9.1, 5.10.0
    • Component/s: Broker
    • Labels:
      None
    • Environment:

      Windows XP Professional, JVM 1.5.0_09, MySQL 5.0.27

      Description

      I am running trunk using JDBC against MySQL 5.0.27. I am seeing the above mentioned IOException. Do not have specific instructions on how to reproduce at the current time, but I was using durable subscriptions with the store durable cursor if that helps. (I'll post if I find out more information.)

      <persistenceAdapter>

      <journaledJDBC journalLogFiles="5" dataDirectory="../activemq-data" dataSource="#mysql-ds"/>

      </persistenceAdapter>

      <bean id="mysql-ds" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close">
      <property name="driverClassName" value="com.mysql.jdbc.Driver"/>
      <property name="url" value="jdbc:mysql://localhost/activemq?relaxAutoCommit=true"/>
      <property name="username" value="*** OMITTED ***"/>
      <property name="password" value="*** OMITTED *** "/>
      <property name="poolPreparedStatements" value="true"/>
      </bean>

      Log trace:

      2006-11-19 19:19:48,078 [/127.0.0.1:4898] DEBUG JournalPersistenceAdapter - Waking for checkpoint to complete.
      2006-11-19 19:19:48,078 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Checkpoint started.
      2006-11-19 19:19:48,078 [eckpoint Worker] ERROR JournalPersistenceAdapter - Failed to checkpoint a message store: java.util.concurrent.ExecutionException: java.io.IOException: Already started.
      java.util.concurrent.ExecutionException: java.io.IOException: Already started.
      at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:205)
      at java.util.concurrent.FutureTask.get(FutureTask.java:80)
      at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:386)
      at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129)
      at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:88)
      at org.apache.activemq.thread.DedicatedTaskRunner.access$0(DedicatedTaskRunner.java:76)
      at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39)
      Caused by: java.io.IOException: Already started.
      at org.apache.activemq.store.jdbc.TransactionContext.begin(TransactionContext.java:145)
      at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.beginTransaction(JDBCPersistenceAdapter.java:358)
      at org.apache.activemq.store.journal.JournalPersistenceAdapter.beginTransaction(JournalPersistenceAdapter.java:189)
      at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:41)
      at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:247)
      at org.apache.activemq.store.journal.JournalTopicMessageStore.checkpoint(JournalTopicMessageStore.java:162)
      at org.apache.activemq.store.journal.JournalPersistenceAdapter$5.call(JournalPersistenceAdapter.java:373)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
      at java.util.concurrent.FutureTask.run(FutureTask.java:123)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)
      2006-11-19 19:19:48,109 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Checkpoint done.

        Activity

        Hide
        Ken Gallo added a comment -

        Do you have the mysql-connector-java.jar in the lib folder?
        Do you have an activemq schema in your db?

        It works in my Windows XP, Java 1.5.0_06, MySQL 5.0.24 environment.

        Show
        Ken Gallo added a comment - Do you have the mysql-connector-java.jar in the lib folder? Do you have an activemq schema in your db? It works in my Windows XP, Java 1.5.0_06, MySQL 5.0.24 environment.
        Hide
        Artem added a comment -

        I have the same problem with MS SQL 2005.
        Symptomis the same as was described - plus
        many durable queue produsers and consumers, large queue size.
        Exception occurs suddenly, after 6-7-24 hours of fine work.

        Show
        Artem added a comment - I have the same problem with MS SQL 2005. Symptomis the same as was described - plus many durable queue produsers and consumers, large queue size. Exception occurs suddenly, after 6-7-24 hours of fine work.
        Hide
        Artem added a comment -

        Can I use JDBC Persistence without Journaling as walkaround?
        Thank you for replay, It's very critical for me. Thank you.

        Show
        Artem added a comment - Can I use JDBC Persistence without Journaling as walkaround? Thank you for replay, It's very critical for me. Thank you.
        Hide
        Frank Russo added a comment -

        We are having the same issue using Oracle. Here is our config:

        <persistenceAdapter>
        <journaledJDBC journalLogFiles="5" dataDirectory="$

        {activemq.home}

        /activemq-data" dataSource="#oracle-ds"/>
        </persistenceAdapter>

        <bean id="oracle-ds" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close">
        <property name="driverClassName" value="oracle.jdbc.driver.OracleDriver"/>
        <property name="url" value="***"/>
        <property name="username" value="***"/>
        <property name="password" value="***"/>
        <property name="poolPreparedStatements" value="true"/>
        </bean>

        Any ideas what could cause this?

        Thanks...

        Show
        Frank Russo added a comment - We are having the same issue using Oracle. Here is our config: <persistenceAdapter> <journaledJDBC journalLogFiles="5" dataDirectory="$ {activemq.home} /activemq-data" dataSource="#oracle-ds"/> </persistenceAdapter> <bean id="oracle-ds" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close"> <property name="driverClassName" value="oracle.jdbc.driver.OracleDriver"/> <property name="url" value="***"/> <property name="username" value="***"/> <property name="password" value="***"/> <property name="poolPreparedStatements" value="true"/> </bean> Any ideas what could cause this? Thanks...
        Hide
        james strachan added a comment -

        updated affected version

        Show
        james strachan added a comment - updated affected version
        Hide
        Vadim Pesochinskiy added a comment -

        And we also have been having "this" issue since Feb 2007 in 4.1.0 on Derby

        Other people, also having this issue:

        http://www.nabble.com/failed-to-checkpoint-a-message-store--tf3156345s2354.html#a8752776
        http://www.nabble.com/Failed-to-checkpoint-a-messaeg-store-tf1758021s2354.html#a4781889

        Config:

        <persistenceAdapter>
        <journaledJDBC journalLogFiles="5" dataDirectory="$

        {messageStoreDir}

        " dataSource="#derby-ds"/>
        </persistenceAdapter>
        <bean id="derby-ds" class="org.apache.derby.jdbc.EmbeddedDataSource">
        <property name="databaseName" value="derbydb"/>
        <property name="createDatabase" value="create"/>
        </bean>

        SEVERE: Failed to checkpoint a message store: edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Not started.
        edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Not started.
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.getResult(FutureTask.java:299)
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.get(FutureTask.java:118)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:386)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:88)
        at org.apache.activemq.thread.DedicatedTaskRunner.access$000(DedicatedTaskRunner.java:25)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39)
        Caused by: java.io.IOException: Not started.
        at org.apache.activemq.store.jdbc.TransactionContext.rollback(TransactionContext.java:168)
        at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.rollbackTransaction(JDBCPersistenceAdapter.java:368)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.rollbackTransaction(JournalPersistenceAdapter.java:197)
        at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:62)
        at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:247)
        at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:221)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:356)
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.run(FutureTask.java:176)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:595)
        org.apache.activemq.store.journal.JournalPersistenceAdapter doCheckpoint

        Show
        Vadim Pesochinskiy added a comment - And we also have been having "this" issue since Feb 2007 in 4.1.0 on Derby Other people, also having this issue: http://www.nabble.com/failed-to-checkpoint-a-message-store--tf3156345s2354.html#a8752776 http://www.nabble.com/Failed-to-checkpoint-a-messaeg-store-tf1758021s2354.html#a4781889 Config: <persistenceAdapter> <journaledJDBC journalLogFiles="5" dataDirectory="$ {messageStoreDir} " dataSource="#derby-ds"/> </persistenceAdapter> <bean id="derby-ds" class="org.apache.derby.jdbc.EmbeddedDataSource"> <property name="databaseName" value="derbydb"/> <property name="createDatabase" value="create"/> </bean> SEVERE: Failed to checkpoint a message store: edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Not started. edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Not started. at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.getResult(FutureTask.java:299) at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.get(FutureTask.java:118) at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:386) at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129) at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:88) at org.apache.activemq.thread.DedicatedTaskRunner.access$000(DedicatedTaskRunner.java:25) at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39) Caused by: java.io.IOException: Not started. at org.apache.activemq.store.jdbc.TransactionContext.rollback(TransactionContext.java:168) at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.rollbackTransaction(JDBCPersistenceAdapter.java:368) at org.apache.activemq.store.journal.JournalPersistenceAdapter.rollbackTransaction(JournalPersistenceAdapter.java:197) at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:62) at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:247) at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:221) at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:356) at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.run(FutureTask.java:176) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675) at java.lang.Thread.run(Thread.java:595) org.apache.activemq.store.journal.JournalPersistenceAdapter doCheckpoint
        Hide
        Vadim Pesochinskiy added a comment -

        After that happens the first time I keep seeing this every second or so about 30 times and after that AMQ is dead. No messages are delivered anymore. Once in this state I cannot pull up messages via jconsole / operations / Browse As Table.

        Show
        Vadim Pesochinskiy added a comment - After that happens the first time I keep seeing this every second or so about 30 times and after that AMQ is dead. No messages are delivered anymore. Once in this state I cannot pull up messages via jconsole / operations / Browse As Table.
        Hide
        Tim Walters added a comment -

        I've been looking at the 4.1.1 code for checkpointing and think I've found a problem.

        JDBC statements for copying messages to the longterm storage are handled by a TransactionContext object. If a SQLException is raised during execution of TransactionContext.commit(), the finally clause will close the JDBC connection and clear the 'inTx' flag showing a current transaction. However the exception will cause a TransactionContext.rollback() to be called, which will see the cleared 'inTx' flag and throw an exception with the 'Not started' message in the logs above. Also, the JDBC rollback() and statement close() methods won't be called correctly which could cause leaks or partial data commits.

        JDBCPersistenceAdapter.log only logs SQL errors at the debug level, so the root cause of this problem is likely to be missing from the logs. My guess is that the different reports above might each reflect a different SQL error.

        It looks like the minimal changes which should be made here are:

        • Log SQL errors during commit() at a error level
        • Make sure rollback() can be called after the commit() error.
        Show
        Tim Walters added a comment - I've been looking at the 4.1.1 code for checkpointing and think I've found a problem. JDBC statements for copying messages to the longterm storage are handled by a TransactionContext object. If a SQLException is raised during execution of TransactionContext.commit(), the finally clause will close the JDBC connection and clear the 'inTx' flag showing a current transaction. However the exception will cause a TransactionContext.rollback() to be called, which will see the cleared 'inTx' flag and throw an exception with the 'Not started' message in the logs above. Also, the JDBC rollback() and statement close() methods won't be called correctly which could cause leaks or partial data commits. JDBCPersistenceAdapter.log only logs SQL errors at the debug level, so the root cause of this problem is likely to be missing from the logs. My guess is that the different reports above might each reflect a different SQL error. It looks like the minimal changes which should be made here are: Log SQL errors during commit() at a error level Make sure rollback() can be called after the commit() error.
        Hide
        Benoit Guillon added a comment -

        Is there any known workaround to this issue ?

        I currently use this configuration for persistence:

        <persistenceAdapter>
        <journaledJDBC journalLogFiles="5" dataDirectory="/data/activemq-data" dataSource="#datasource" createTablesOnStartup="false" useDatabaseLock="false"/>
        </persistenceAdapter>

        Thanks.

        Show
        Benoit Guillon added a comment - Is there any known workaround to this issue ? I currently use this configuration for persistence: <persistenceAdapter> <journaledJDBC journalLogFiles="5" dataDirectory="/data/activemq-data" dataSource="#datasource" createTablesOnStartup="false" useDatabaseLock="false"/> </persistenceAdapter> Thanks.
        Hide
        Vipul Kothiyal added a comment -

        I am getting same error messages with mysql as message store with AMQ 5.2.0. any workaround for this issue?

        Show
        Vipul Kothiyal added a comment - I am getting same error messages with mysql as message store with AMQ 5.2.0. any workaround for this issue?
        Hide
        Vipul Kothiyal added a comment -

        Using Jdbc persistence without jornaling seems to ahve done the trick, I know it's BAD for performace but better then the whole meesage queue getting frozen.
        Any better suggestions?

        Cheers
        V

        Show
        Vipul Kothiyal added a comment - Using Jdbc persistence without jornaling seems to ahve done the trick, I know it's BAD for performace but better then the whole meesage queue getting frozen. Any better suggestions? Cheers V
        Hide
        Subendu Dasgupta added a comment -

        I am facing the same issue with MySql 5.1 and activemq 5.3 (on Fuse 3.4.04) lib folder. Here is my configuration.

        <amq:persistenceAdapter>
        <amq:journaledJDBC journalLogFiles="5" dataDirectory="./data/activemq-data" dataSource="#ors-activemq-ds" createTablesOnStartup="true" useDatabaseLock="false"/>
        </amq:persistenceAdapter>

        <bean id="ors-activemq-ds" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close">
        <property name="driverClassName" value="$

        {activemq.jdbc.driver}

        " />
        <property name="url" value="$

        {activemq.jdbc.url}

        " />
        <property name="username" value="$

        {activemq.jdbc.username}

        " />
        <property name="password" value="$

        {activemq.jdbc.password}

        " />
        <property name="poolPreparedStatements" value="true" />
        </bean>

        java.util.concurrent.ExecutionException: java.io.IOException: Already started.
        at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222)
        at java.util.concurrent.FutureTask.get(FutureTask.java:83)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:421)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$1.iterate(JournalPersistenceAdapter.java:124)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        Caused by: java.io.IOException: Already started.
        at org.apache.activemq.store.jdbc.TransactionContext.begin(TransactionContext.java:148)
        at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.beginTransaction(JDBCPersistenceAdapter.java:399)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.beginTransaction(JournalPersistenceAdapter.java:216)
        at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:41)
        at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:258)
        at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:233)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:391)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:390)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)

        Show
        Subendu Dasgupta added a comment - I am facing the same issue with MySql 5.1 and activemq 5.3 (on Fuse 3.4.04) lib folder. Here is my configuration. <amq:persistenceAdapter> <amq:journaledJDBC journalLogFiles="5" dataDirectory="./data/activemq-data" dataSource="#ors-activemq-ds" createTablesOnStartup="true" useDatabaseLock="false"/> </amq:persistenceAdapter> <bean id="ors-activemq-ds" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close"> <property name="driverClassName" value="$ {activemq.jdbc.driver} " /> <property name="url" value="$ {activemq.jdbc.url} " /> <property name="username" value="$ {activemq.jdbc.username} " /> <property name="password" value="$ {activemq.jdbc.password} " /> <property name="poolPreparedStatements" value="true" /> </bean> java.util.concurrent.ExecutionException: java.io.IOException: Already started. at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222) at java.util.concurrent.FutureTask.get(FutureTask.java:83) at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:421) at org.apache.activemq.store.journal.JournalPersistenceAdapter$1.iterate(JournalPersistenceAdapter.java:124) at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122) at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) Caused by: java.io.IOException: Already started. at org.apache.activemq.store.jdbc.TransactionContext.begin(TransactionContext.java:148) at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.beginTransaction(JDBCPersistenceAdapter.java:399) at org.apache.activemq.store.journal.JournalPersistenceAdapter.beginTransaction(JournalPersistenceAdapter.java:216) at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:41) at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:258) at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:233) at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:391) at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:390) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        Hide
        Edgar Vonk added a comment -

        Here I read that a workaround is to just not pool prepared statements. So I have now put:

        <property name="poolPreparedStatements" value="false"/>
        

        in our (Oracle) datasource definition in activemq.xml.

        Has anyone else tried this? And does it really solve the issue?

        Show
        Edgar Vonk added a comment - Here I read that a workaround is to just not pool prepared statements. So I have now put: <property name= "poolPreparedStatements" value= " false " /> in our (Oracle) datasource definition in activemq.xml. Has anyone else tried this? And does it really solve the issue?
        Hide
        Edgar Vonk added a comment -

        I am confused. Is this the same issue as AMQ-1611 or not?

        And if so, will upgrading to ActiveMQ to 5.3.0 (we are now at 5.2.0) simply fix this issue?

        Show
        Edgar Vonk added a comment - I am confused. Is this the same issue as AMQ-1611 or not? And if so, will upgrading to ActiveMQ to 5.3.0 (we are now at 5.2.0) simply fix this issue?
        Hide
        Vipul Kothiyal added a comment -

        ^^no upgrade to 5.3.0 doesn't fix it. also <property name="poolPreparedStatements" value="false"/> doesn't fix it.

        Show
        Vipul Kothiyal added a comment - ^^no upgrade to 5.3.0 doesn't fix it. also <property name="poolPreparedStatements" value="false"/> doesn't fix it.
        Hide
        Gary Tully added a comment -

        Vipul, is it reproducible? Can you upload the output of the broker with debug logging enabled, that may help

        Show
        Gary Tully added a comment - Vipul, is it reproducible? Can you upload the output of the broker with debug logging enabled, that may help
        Hide
        Vipul Kothiyal added a comment -

        Hi Gary,
        It's an intermittent issue for us, happens every now and then, a restart of the broker fixes till next occurrence. We don't have debugging enabled in our logs, but I'll do and post the output when it happens next time around.
        Cheers
        V

        Show
        Vipul Kothiyal added a comment - Hi Gary, It's an intermittent issue for us, happens every now and then, a restart of the broker fixes till next occurrence. We don't have debugging enabled in our logs, but I'll do and post the output when it happens next time around. Cheers V
        Hide
        Hondong added a comment -

        We even have the same Issue under ActiveMQ 4.1.2 and Oracle DS
        It seems, that it appear under heavy Load?

        I´ll try to reproduce it with debugging enabled...

        Show
        Hondong added a comment - We even have the same Issue under ActiveMQ 4.1.2 and Oracle DS It seems, that it appear under heavy Load? I´ll try to reproduce it with debugging enabled...
        Hide
        Hondong added a comment -

        Hi,

        here is the Log with this error in Debug Mode.
        I´ll Attach it to this issue, but I think this is the interesting part for you:

        2010-05-06 19:20:49,275 [5fda:6db0:61938] DEBUG AbstractRegion - Removing consumer: aa82a0e0-dc97-47ef-b34a-6d89a9826915:399:45359
        2010-05-06 19:20:50,289 [5fda:6db0:61938] DEBUG AbstractRegion - Adding consumer: aa82a0e0-dc97-47ef-b34a-6d89a9826915:399:45360
        2010-05-06 19:20:50,382 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Checkpoint started.
        2010-05-06 19:20:50,398 [5fda:6db0:61938] DEBUG AbstractRegion - Removing consumer: aa82a0e0-dc97-47ef-b34a-6d89a9826915:399:45360
        2010-05-06 19:20:50,585 [eckpoint Worker] ERROR JournalPersistenceAdapter - Failed to checkpoint a message store: edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Already started.
        edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Already started.
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.getResult(FutureTask.java:299)
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.get(FutureTask.java:118)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:386)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:101)
        at org.apache.activemq.thread.DedicatedTaskRunner.access$000(DedicatedTaskRunner.java:25)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39)
        Caused by: java.io.IOException: Already started.
        at org.apache.activemq.store.jdbc.TransactionContext.begin(TransactionContext.java:145)
        at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.beginTransaction(JDBCPersistenceAdapter.java:358)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.beginTransaction(JournalPersistenceAdapter.java:189)
        at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:41)
        at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:247)
        at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:221)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:356)
        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.run(FutureTask.java:176)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
        at java.lang.Thread.run(Thread.java:619)
        2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Marking journal at: 190:18104176
        2010-05-06 19:20:50,585 [eckpoint Worker] ERROR JournalPersistenceAdapter - Failed to mark the Journal: org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark.
        org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark.
        at org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:340)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:403)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129)
        at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:101)
        at org.apache.activemq.thread.DedicatedTaskRunner.access$000(DedicatedTaskRunner.java:25)
        at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39)
        2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JDBCPersistenceAdapter - Cleaning up old messages.
        2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG DefaultJDBCAdapter - Executing SQL: DELETE FROM ACTIVEMQ_MSGS WHERE ( EXPIRATION<>0 AND EXPIRATION<?) OR ID <= ( SELECT min(ACTIVEMQ_ACKS.LAST_ACKED_ID) FROM ACTIVEMQ_ACKS WHERE ACTIVEMQ_ACKS.CONTAINER=ACTIVEMQ_MSGS.CONTAINER)
        2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG DefaultJDBCAdapter - Deleted 0 old message(s).
        2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JDBCPersistenceAdapter - Cleanup done.
        2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Checkpoint done.

        Show
        Hondong added a comment - Hi, here is the Log with this error in Debug Mode. I´ll Attach it to this issue, but I think this is the interesting part for you: 2010-05-06 19:20:49,275 [5fda:6db0:61938] DEBUG AbstractRegion - Removing consumer: aa82a0e0-dc97-47ef-b34a-6d89a9826915:399:45359 2010-05-06 19:20:50,289 [5fda:6db0:61938] DEBUG AbstractRegion - Adding consumer: aa82a0e0-dc97-47ef-b34a-6d89a9826915:399:45360 2010-05-06 19:20:50,382 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Checkpoint started. 2010-05-06 19:20:50,398 [5fda:6db0:61938] DEBUG AbstractRegion - Removing consumer: aa82a0e0-dc97-47ef-b34a-6d89a9826915:399:45360 2010-05-06 19:20:50,585 [eckpoint Worker] ERROR JournalPersistenceAdapter - Failed to checkpoint a message store: edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Already started. edu.emory.mathcs.backport.java.util.concurrent.ExecutionException: java.io.IOException: Already started. at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.getResult(FutureTask.java:299) at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.get(FutureTask.java:118) at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:386) at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129) at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:101) at org.apache.activemq.thread.DedicatedTaskRunner.access$000(DedicatedTaskRunner.java:25) at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39) Caused by: java.io.IOException: Already started. at org.apache.activemq.store.jdbc.TransactionContext.begin(TransactionContext.java:145) at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.beginTransaction(JDBCPersistenceAdapter.java:358) at org.apache.activemq.store.journal.JournalPersistenceAdapter.beginTransaction(JournalPersistenceAdapter.java:189) at org.apache.activemq.util.TransactionTemplate.run(TransactionTemplate.java:41) at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:247) at org.apache.activemq.store.journal.JournalMessageStore.checkpoint(JournalMessageStore.java:221) at org.apache.activemq.store.journal.JournalPersistenceAdapter$4.call(JournalPersistenceAdapter.java:356) at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.run(FutureTask.java:176) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675) at java.lang.Thread.run(Thread.java:619) 2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Marking journal at: 190:18104176 2010-05-06 19:20:50,585 [eckpoint Worker] ERROR JournalPersistenceAdapter - Failed to mark the Journal: org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. at org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:340) at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:403) at org.apache.activemq.store.journal.JournalPersistenceAdapter$2.iterate(JournalPersistenceAdapter.java:129) at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:101) at org.apache.activemq.thread.DedicatedTaskRunner.access$000(DedicatedTaskRunner.java:25) at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:39) 2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JDBCPersistenceAdapter - Cleaning up old messages. 2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG DefaultJDBCAdapter - Executing SQL: DELETE FROM ACTIVEMQ_MSGS WHERE ( EXPIRATION<>0 AND EXPIRATION<?) OR ID <= ( SELECT min(ACTIVEMQ_ACKS.LAST_ACKED_ID) FROM ACTIVEMQ_ACKS WHERE ACTIVEMQ_ACKS.CONTAINER=ACTIVEMQ_MSGS.CONTAINER) 2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG DefaultJDBCAdapter - Deleted 0 old message(s). 2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JDBCPersistenceAdapter - Cleanup done. 2010-05-06 19:20:50,585 [eckpoint Worker] DEBUG JournalPersistenceAdapter - Checkpoint done.
        Hide
        Hondong added a comment -

        Here are the Debug Log Files...

        Show
        Hondong added a comment - Here are the Debug Log Files...
        Hide
        Petr Nídl added a comment - - edited

        I've analyzed the problem for 5.6.0 release. It happens when org.apache.activemq.store.journal.JournalPersistenceAdapter starts new transaction during checkpoint and fails to retrieve the database connection for this task. The main cause is in org.apache.activemq.store.jdbc.TransactionContext.begin() method (lines 153-159):

        public void begin() throws IOException {
        if (inTx)

        { throw new IOException("Already started."); }

        inTx = true;
        connection = getConnection();
        }

        Lines 157 and 158 should be switched because currently the TransactionContext instance is marked as "inTx" even though the getConnection() method throws an exception. From that moment the TransactionContext instance is marked as "inTx" forever and will never start new transaction again.

        Show
        Petr Nídl added a comment - - edited I've analyzed the problem for 5.6.0 release. It happens when org.apache.activemq.store.journal.JournalPersistenceAdapter starts new transaction during checkpoint and fails to retrieve the database connection for this task. The main cause is in org.apache.activemq.store.jdbc.TransactionContext.begin() method (lines 153-159): public void begin() throws IOException { if (inTx) { throw new IOException("Already started."); } inTx = true; connection = getConnection(); } Lines 157 and 158 should be switched because currently the TransactionContext instance is marked as "inTx" even though the getConnection() method throws an exception. From that moment the TransactionContext instance is marked as "inTx" forever and will never start new transaction again.
        Hide
        Claus Ibsen added a comment -

        Thanks for reporting.

        And Petr Nídl for the suggested fix.

        Show
        Claus Ibsen added a comment - Thanks for reporting. And Petr Nídl for the suggested fix.
        Hide
        Radek Kraus added a comment -

        I'm sorry for comment to fixed issue. But IMHO the fix suggested by Petr Nidl isn't 100% correct. We already tried to use this fix. It seams, that really solved the java.io.IOException: Already started. problem. But after this fix we faced to new problems:

        1. invoke a commit on Firebird connection, which is set as autocommit = true (already reported in AMQ-4836 by Jiri Patera)
        2. (most important) possibility to set the connection as autocommit = true, even if the connection is configured as autocommit = false on datasource level, when transaction is started (TransactionContext.begin() method is invoked), see the getConnection() method. The reason for this behavior is "line switching" in suggested fix. I don't know all places and ways, where transactions are used, but IMHO it seams as problem, when the transaction is started and connection is configured as autocommit = true

        Maybe I miss something, but thought that this comment can be useful.

        Show
        Radek Kraus added a comment - I'm sorry for comment to fixed issue. But IMHO the fix suggested by Petr Nidl isn't 100% correct. We already tried to use this fix. It seams, that really solved the java.io.IOException: Already started. problem. But after this fix we faced to new problems: invoke a commit on Firebird connection, which is set as autocommit = true (already reported in AMQ-4836 by Jiri Patera) ( most important ) possibility to set the connection as autocommit = true , even if the connection is configured as autocommit = false on datasource level, when transaction is started ( TransactionContext.begin() method is invoked), see the getConnection() method. The reason for this behavior is "line switching" in suggested fix. I don't know all places and ways, where transactions are used, but IMHO it seams as problem, when the transaction is started and connection is configured as autocommit = true Maybe I miss something, but thought that this comment can be useful.
        Hide
        Gary Tully added a comment -

        there is indeed a problem with this fix as pointed out above.

        getConnection depends on the inTx flag.

        maybe the correct fix is to clear the inTx flag in TransactionContext.getConnection() before we throw the ioe.

        Show
        Gary Tully added a comment - there is indeed a problem with this fix as pointed out above. getConnection depends on the inTx flag. maybe the correct fix is to clear the inTx flag in TransactionContext.getConnection() before we throw the ioe.
        Hide
        Gary Tully added a comment -
        Show
        Gary Tully added a comment - the change to the inTx flag is sorted in https://git-wip-us.apache.org/repos/asf?p=activemq.git;a=commit;h=b7c430d0

          People

          • Assignee:
            Claus Ibsen
            Reporter:
            jk@penguinsfan.com
          • Votes:
            19 Vote for this issue
            Watchers:
            20 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development