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

• Key: AMQ-1063
• Type: Bug
• Status: Open
• Priority: Major
• Assignee: Unassigned
• Reporter: [e-mail]
• Component/s: Broker
• Affects Version/s: 5.0.0
• Fix Version/s: 5.2.0

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.

Comments

[Ken Gallo]

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.

[Artem]

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.

[Artem]

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

[Frank Russo]

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...

[James Strachan]

updated affected version

[Vadim Pesochinskiy]

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

[Vadim Pesochinskiy]

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.

[Tim Walters]

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.