Exception in JDBCImple.write_state: primary key constraint violation (JDBC ObjectStore in use)
mauromol Jan 12, 2012 6:29 AMHi,
I'm using JBossTS JTA 4.15.0 embedded into our web application with Spring.
Recently the following errors started to appear in the logs of our web application:
[INFO ] 2012/01/10 22:26:33 - Transaction Expired Entry Monitor - com.arjuna.ats.arjuna - ARJUNA12303: ExpiredTransactionScanner - log 0:ffffc0a8221f:e079:4f0abd09:582 is assumed complete and will be moved.
2012-01-10 22:29:16,256 [Transaction Expired Entry Monitor] WARN com.arjuna.ats.arjuna - ARJUNA12258: JDBCImple:write_state caught exception
org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_E ON PUBLIC.JBOSSTSTXTABLE(UIDSTRING, STATETYPE)"; SQL statement:
INSERT INTO JBossTSTxTable (StateType,TypeName,UidString,ObjectState) VALUES (?,?,?,?) [23001-139]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:327)
at org.h2.message.DbException.get(DbException.java:167)
at org.h2.message.DbException.get(DbException.java:144)
at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:157)
at org.h2.index.PageBtree.find(PageBtree.java:115)
at org.h2.index.PageBtreeLeaf.addRow(PageBtreeLeaf.java:137)
at org.h2.index.PageBtreeLeaf.addRowTry(PageBtreeLeaf.java:92)
at org.h2.index.PageBtreeIndex.addRow(PageBtreeIndex.java:87)
at org.h2.index.PageBtreeIndex.add(PageBtreeIndex.java:78)
at org.h2.table.RegularTable.addRow(RegularTable.java:116)
at org.h2.command.dml.Insert.insertRows(Insert.java:120)
at org.h2.command.dml.Insert.update(Insert.java:82)
at org.h2.command.CommandContainer.update(CommandContainer.java:70)
at org.h2.command.Command.executeUpdate(Command.java:199)
at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:141)
at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:127)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple.write_state(JDBCImple.java:852)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple.write_state(JDBCImple.java:860)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple.write_state(JDBCImple.java:860)
at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple.write_state(JDBCImple.java:860)
< this stack trace line repeats thousand of times and I can't see the rest of the stack trace >
Then, the following line repeats thousand of times:
2012-01-10 22:29:16,287 [Transaction Expired Entry Monitor] WARN com.arjuna.ats.arjuna - ARJUNA12248: freePool - freeing a connection which is already free!
and, in the end, the following line appear:
[INFO ] 2012/01/10 22:29:16 - Transaction Expired Entry Monitor - com.arjuna.ats.arjuna - ARJUNA12304: Removing old transaction status manager item 0:ffffc0a8221f:e079:4f0abd09:582
The problem manifested again, for other times.
Today I checked the contents of the JBOSSTSTXTABLE of the ObjectStore database (we're using an H2 database for the object store) and here is its contents:
STATETYPE | TYPENAME | UIDSTRING | OBJECTSTATE |
---|---|---|---|
1 | /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction | 0:ffffc0a8221f:eb5a:4f02d4c3:582 | 2342450110204000000000092341524a554e4123000000000000001c00000000000000000000ffffc0a8221f0000eb5a4f02d4c3000005820000001c00000000000000000000ffffc0a8221f0000eb5a4f02d4c30000058700000134a312a213000001cf00000001000000ab000000070000000000000001000200040000001d0000001c0000008000000000000000000000ffffc0a8221f0000eb5a4f02d4c3000005823100000000000000000000ffffc0a8221f0000eb5a4f02d4c300000583000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000001c00000000000000000000ffffc0a8221f0000eb5a4f02d4c30000058400000000000001cf0000000e0000000000000006 |
1 | /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction | 0:ffffc0a8221f:ce57:4f046535:582 | 2342450110204000000000092341524a554e4123000000000000001c00000000000000000000ffffc0a8221f0000ce574f046535000005820000001c00000000000000000000ffffc0a8221f0000ce574f0465350000058700000134a92ef534000001cf00000001000000ab000000070000000000000001000200040000001d0000001c0000008000000000000000000000ffffc0a8221f0000ce574f046535000005823100000000000000000000ffffc0a8221f0000ce574f04653500000583000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000001c00000000000000000000ffffc0a8221f0000ce574f0465350000058400000000000001cf0000000e0000000000000006 |
1 | /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction | 0:ffffc0a8221f:db11:4f046f1f:582 | 2342450110204000000000092341524a554e4123000000000000001c00000000000000000000ffffc0a8221f0000db114f046f1f000005820000001c00000000000000000000ffffc0a8221f0000db114f046f1f0000058700000134a955865c000001cf00000001000000ab000000070000000000000001000200040000001d0000001c0000008000000000000000000000ffffc0a8221f0000db114f046f1f000005823100000000000000000000ffffc0a8221f0000db114f046f1f00000583000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000001c00000000000000000000ffffc0a8221f0000db114f046f1f0000058400000000000001cf0000000e0000000000000006 |
1 | /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction | 0:ffffc0a8221f:e079:4f0abd09:582 | 2342450110204000000000092341524a554e4123000000000000001c00000000000000000000ffffc0a8221f0000e0794f0abd09000005820000001c00000000000000000000ffffc0a8221f0000e0794f0abd090000058700000134c1f6073a000001cf00000001000000ab000000070000000000000001000200040000001d0000001c0000008000000000000000000000ffffc0a8221f0000e0794f0abd09000005823100000000000000000000ffffc0a8221f0000e0794f0abd0900000583000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000001c00000000000000000000ffffc0a8221f0000e0794f0abd090000058400000000000001cf0000000e0000000000000006 |
1 | /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction | 0:ffffc0a8221f:da53:4f0bff5d:582 | 2342450110204000000000092341524a554e4123000000000000001c00000000000000000000ffffc0a8221f0000da534f0bff5d000005820000001c00000000000000000000ffffc0a8221f0000da534f0bff5d0000058700000134c6e103e6000001cf00000001000000ab000000070000000000000001000200040000001d0000001c0000008000000000000000000000ffffc0a8221f0000da534f0bff5d000005823100000000000000000000ffffc0a8221f0000da534f0bff5d00000583000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000001c00000000000000000000ffffc0a8221f0000da534f0bff5d0000058400000000000001cf0000000e0000000000000006 |
1 | /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction | 0:ffffc0a8221f:da59:4f0c015b:582 | 2342450110204000000000092341524a554e4123000000000000001c00000000000000000000ffffc0a8221f0000da594f0c015b000005820000001c00000000000000000000ffffc0a8221f0000da594f0c015b0000058700000134c6e8bb6d000001cf00000001000000ab000000070000000000000001000200040000001d0000001c0000008000000000000000000000ffffc0a8221f0000da594f0c015b000005823100000000000000000000ffffc0a8221f0000da594f0c015b00000583000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000001c00000000000000000000ffffc0a8221f0000da594f0c015b0000058400000000000001cf0000000e0000000000000006 |
Do you have any idea on what is going on here? Were there dead/incomplete transactions? Why does a primary constraint exception occur?
Looking at the code in JDBCImple, it looks like the flow between write_state, retryConnection and freePool isn't very clear. In particular, I'm not surprised to see so much recursive calls to write_state and so much "freeing a connection which is already free!" lines in the log... Instead, I'm surprised a stack overflow exception didn't occur...
The DBMS in use is SQL Server.
Thanks in advance for any help.
Mauro.