Fix for BTM-33 leads to another problem

I accidentally attached the wrong log file (it still shows the error, but also has some test logs that I added to BTM in it)

Use the attached file to get a correct representation of what it output when using the SVN trunk.

It seems like the description was cut off, here's the rest:

[- When the main thread ] executes the query in a global transaction instead of a local one.

I think this build should fix this race condition: http://snapshots.repository.codehaus.org/org/codehaus/btm/btm/1.3.3-20090317/btm-1.3.3-20090317.jar

Please try it out and report the outcome.

Thanks. I will try tomorrow.

Could you commit the potential fix into SVN (possibly in a branch)? I'm reluctant to put binary-only changes live.

Committed in trunk.

I'm sorry, but the fix doesn't work! I get the same error still after a few seconds.

I've attached two new logs running the new version. One is the jar you provided, one is my build from the SVN trunk (I had to stub some JDBC 4 functions as I couldn't figure out how to compile it using the older JDK; i have 1.6)

Some info on my machine: Intel Dual Core T2400 @1.83GHz, Linux 2.6.26-1 SMP

Don't be sorry, that's my mistake. I've identified the problem and stopped halfway while fixing it. I guess I was too tired.

Here's another snapshot build with the latest fix candidate: http://snapshots.repository.codehaus.org/org/codehaus/btm/btm/1.3.3-20090318/btm-1.3.3-20090318.jar and the source changes are also in the trunk.

I just hope I'm not exhausting your patience...

Well...

I couldn't reproduce the bug in my test case, and we deployed the new version on 2 live servers.

It seemed to work well, but after a few hours, one server went haywire! I might just be an unlucky coincidence, but I want to report it:

It started with the following exception:

Caused by: bitronix.tm.internal.BitronixSystemException: error logging status
at bitronix.tm.BitronixTransaction.setStatus(BitronixTransaction.java:283)
at bitronix.tm.BitronixTransaction.setStatus(BitronixTransaction.java:261)
at bitronix.tm.twopc.Preparer.prepare(Preparer.java:74)
at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:176)
at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:96)
at com.freiheit.parship.transactionsupport.DelegatingTransactionManagerInterceptor.commit(DelegatingTransactionManagerInterceptor.java:144)
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)
... 174 more
Caused by: bitronix.tm.journal.CorruptedTransactionLogException: corrupted log found at position 21 (no record terminator found)
at bitronix.tm.journal.TransactionLogCursor.readLog(TransactionLogCursor.java:81)
at bitronix.tm.journal.TransactionLogCursor.readLog(TransactionLogCursor.java:46)
at bitronix.tm.journal.DiskJournal.collectDanglingRecords(DiskJournal.java:336)
at bitronix.tm.journal.DiskJournal.copyDanglingRecords(DiskJournal.java:308)
at bitronix.tm.journal.DiskJournal.swapJournalFiles(DiskJournal.java:271)
at bitronix.tm.journal.DiskJournal.log(DiskJournal.java:80)
at bitronix.tm.BitronixTransaction.setStatus(BitronixTransaction.java:272)
... 180 more

This exception occured a few times, after that, things really got messed up:
Caused by: java.sql.SQLException: error enlisting a JdbcConnectionHandle of a JdbcPooledConnection from datasource contacts2 in state ACCESSIBLE wrapping org.postgresql.xa.PGXAConnection@1a3b47f7 on Pooled connection wrapping physical connection org.postgresql.jdbc4.Jdbc4Connection@29f1b695
at bitronix.tm.resource.jdbc.JdbcConnectionHandle.enlistResource(JdbcConnectionHandle.java:63)
at bitronix.tm.resource.jdbc.JdbcConnectionHandle.prepareStatement(JdbcConnectionHandle.java:200)
at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:225)
at $Proxy4.prepareStatement(Unknown Source)
at com.ibatis.sqlmap.engine.execution.SqlExecutor.prepareStatement(SqlExecutor.java:494)
at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecutor.java:176)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecuteQuery(GeneralStatement.java:205)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:173)
... 100 more
Caused by: bitronix.tm.internal.BitronixRollbackException: transaction has been marked as rollback only
at bitronix.tm.BitronixTransaction.enlistResource(BitronixTransaction.java:64)
at bitronix.tm.resource.common.TransactionContextHelper.enlist(TransactionContextHelper.java:255)
at bitronix.tm.resource.common.TransactionContextHelper.enlistInCurrentTransaction(TransactionContextHelper.java:48)
at bitronix.tm.resource.jdbc.JdbcConnectionHandle.enlistResource(JdbcConnectionHandle.java:59)
... 110 more

after a few of these, the server was completely done for. Every DB request failed with:

Caused by: java.sql.SQLException: error enlisting a JdbcConnectionHandle of a Jd
bcPooledConnection from datasource user2 in state ACCESSIBLE wrapping org.postgr
esql.xa.PGXAConnection@7988df1b on Pooled connection wrapping physical connectio
n org.postgresql.jdbc4.Jdbc4Connection@8efa3f3
at bitronix.tm.resource.jdbc.JdbcConnectionHandle.enlistResource(JdbcCon
nectionHandle.java:61)
at bitronix.tm.resource.jdbc.JdbcConnectionHandle.prepareStatement(JdbcC
onnectionHandle.java:200)
at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$T
ransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:225
)
at $Proxy4.prepareStatement(Unknown Source)
at com.ibatis.sqlmap.engine.execution.SqlExecutor.prepareStatement(SqlEx
ecutor.java:494)
at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecut
or.java:176)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecut
eQuery(GeneralStatement.java:205)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQu
eryWithCallback(GeneralStatement.java:173)
... 60 more
Caused by: bitronix.tm.internal.BitronixSystemException: transaction timed out
at bitronix.tm.resource.common.TransactionContextHelper.enlistInCurrentT
ransaction(TransactionContextHelper.java:44)
at bitronix.tm.resource.jdbc.JdbcConnectionHandle.enlistResource(JdbcCon
nectionHandle.java:59)
... 70 more

As already mentioned, this didn't happen on the other server, however, that server did run the new version of BTM for a shorter period of time. After restarting, the new server refused to boot because the transaction log was corrupt (which didn't surprise me)

What is your impression? Is it likely that the new fix caused that?

The fix has no impact at all on the journal so this surprises me. I managed to get the new build running with your test for hours without a single problem while multiple journal swaps happened.

The disk journal is built to store data in a very safe way and I've never experienced nor got any report of a journal problem that wasn't due to a mis-use or a hardware failure...

Please continue testing this build if you can and comment back in a few days to report if the problem got reproduced or not.

Thanks.

Bad news.

We retried today on 2 different machines, and we got exactly the same problems.

It started with a corrupted log exception, intestingly again at position 21.
We then shut the server down, moved the logs and started it up again.
After a while, the log was again corrupted, at position 21.

Some more facts:

In both tests (yesterday and today), the corruption only occured on a 64 bit server, the 32 bit didn't show it. However, the 32-bit servers both have less memory available and therefore spend more time GCing as well as not having much memory free for file system caches etc, and secondly, they don't serve as many domains as the 64 bit ones do, so they don't have as much traffic and database connections.

Some more random facts:

• during the tests, the average number of postgresql locks increased, but this could also be a result of the bug and the accompianing transaction leak
• BTM didn't log any exceptions and seems to work until the corruption; the other servers running 1.3.2 regulary log exceptions like "cannot switch state from IN_POOL to IN_POOL" and the exception this bug report was originally about

Any thoughts about this? If not, I will try to rewrite the application to always use global transactions in the hope it will work well with 1.3.2

I could provide the corrupted btm.tlog files if they would help (and if they don't store any sensitive information).

I looked at the transaction log files myself, and they are indeed corrupted. What I have gathered so far is this:
The corrupt entry is the first entry in btm1.log, the record type is 08h and the record size is given as 4Eh bytes, while in fact it is 7 bytes smaller. Interestingly, the broken entry contains only one "unique name", there are other entries which are of type 08h and 4Eh bytes long, these contain 2 unique names, the second one being 5 bytes long.

(I have only looked at one of the corrupted logs, but as the other two also seem to be corrupt at pos 21, I assume that they have the same problem)

After further analysis, the crc32 in the corrupted entry is also only correct if you assume that there were originally 2 unique names. That is, it is incorrect for the actual record that was written.

It seems like somehow, one entry in uniqueNames in TransactionRecord gets lost... Weird.

Created a follow up bug report http://jira.codehaus.org/browse/BTM-44

Since you identified the root cause of the disk corruption and we can safely conclude that it is not related to this issue I'm now marking it as resolved.