Exception in JDBCImple.write_state: primary key constraint violation (JDBC ObjectStore in use)

[mauromol]

Hi,

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.

[mauromol]

Going back in the logs, I find that the first time "freeing a connection which is already free!" was produced was the following:

[INFO ] 2012/01/02 22:09:11 - Transaction Expired Entry Monitor - com.arjuna.ats.arjuna - ARJUNA12296: ExpiredEntryMonitor running at Mon, 2 Jan 2012 22:09:11

[INFO ] 2012/01/02 22:09:11 - Transaction Expired Entry Monitor - com.arjuna.ats.arjuna - ARJUNA12303: ExpiredTransactionScanner - log 0:ffffc0a8221f:e17b:4f01b670:583 is assumed complete and will be moved.

2012-01-02 22:12:35,459 [Transaction Expired Entry Monitor] WARN  com.arjuna.ats.arjuna - ARJUNA12248: freePool - freeing a connection which is already free!

2012-01-02 22:12:35,459 [Transaction Expired Entry Monitor] WARN  com.arjuna.ats.arjuna - ARJUNA12248: freePool - freeing a connection which is already free!

<repeating many times>

After that:

[WARN ] 2012/01/02 22:12:35 - Transaction Expired Entry Monitor - com.arjuna.ats.arjuna - ARJUNA12248: freePool - freeing a connection which is already free!

Exception in thread "Transaction Expired Entry Monitor" java.lang.StackOverflowError

at java.security.AccessController.doPrivileged(Native Method)

at java.net.URLClassLoader.findClass(Unknown Source)

at sun.misc.Launcher$ExtClassLoader.findClass(Unknown Source)

at java.lang.ClassLoader.loadClass(Unknown Source)

at java.lang.ClassLoader.loadClass(Unknown Source)

at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source)

at java.lang.ClassLoader.loadClass(Unknown Source)

at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1560)

at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1491)

at org.apache.log4j.spi.LoggingEvent.<init>(LoggingEvent.java:159)

at org.apache.log4j.Category.forcedLog(Category.java:391)

at org.apache.log4j.Category.log(Category.java:856)

at org.jboss.logging.Log4jLogger.doLog(Log4jLogger.java:44)

at org.jboss.logging.Logger.logv(Logger.java:1925)

at com.arjuna.ats.arjuna.logging.arjunaI18NLogger_$logger.warn_objectstore_JDBCImple_writefailed(arjunaI18NLogger_$logger.java:2782)

at com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple.write_state(JDBCImple.java:862)

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)

<repeating many times>

Can this have caused a corrupted JBOSSTSTXTABLE?

Anyway, from that day on, the web application (and so JBossTS...) has been restarted many times, so the state of JBossTS should have been cleared, apart from the contents of the ObjectStore table JBOSSTSTXTABLE wich was never cleared.

Mauro.

[mmusgrov]

It is odd. All the symptoms you report stem directly from the duplicate key constraint violation. Your logs indicate that it happened after the transaction manager (TM) moved the transaction into the expired transaction table. If after a configurable period (default is about 10 hours) the TM is still unable to commit an outstanding transaction branch it assumes that it was already committed and ignores it but keeps a record of it by moving it into this "expired" table.

Maybe the  table for expired transactions and the table "JBossTSTxTable" are, due to misconfiguration the same table - that would explain the problem (but it is just an hypothesis).

The reason you get so many log entries is because when the transaction is logged by doing an SQL insert there is a catch block which "guesses" the error is due to transient transport failure (rather than the constraint violation) and tries to obtain another connection and redo the write operation (by a recursive call to write_state). Because the duplicate condition will never go away eventually there is a stack overflow. (you will also see thousands of log entries like "[Transaction Expired Entry Monitor] WARN  com.arjuna.ats.arjuna - ARJUNA12248: freePool - freeing a connection which is already free!" since there is a finally block which, as the stack unwinds, frees the connection used for the write operation but the connection was already marked as free as part of the retry operation. That is probably a bug but not the cause of your issue.

FYI the offending entry is xid 0:ffffc0a8221f:e079:4f0abd09:582. If you are happy that the original transaction branch was completed OK then it is safe to delete that row.

[mauromol]

Hi Michael,

thanks for your help.

First of all, one question: in my objectstore database I only have one table, JBOSSTSTXTABLE... should I have more?

I'm using an H2 file-based database for the objectstore. The database is built by JBossTS automatically, schema included. So, if there should be another table in there, it seems like it's JBossTS's fault for not having created it. What should I look for in order to understand if it's a misconfiguration issue?

Do you suggest to open a new JIRA issue for the code flow that leads to the stack overflow exception in my case?

Mauro.

[mmusgrov]

Did you create the table JBOSSTSTXTABLE yourself. The primary key is wrong (and that is why there is a primary key constaint violation). The create table statement should include the type name, something like (depending on what H2 is expecting):

CREATE TABLE JBOSSTSTXTABLE (StateType INTEGER, TypeName VARCHAR(255), UidString VARCHAR(255), ObjectState BLOB, PRIMARY KEY(UidString, StateType, TypeName))

You could either recreate the table or alter the primary key: alter table JBOSSTSTXTABLE add constraint xyz primary key (UidString, StateType, TypeName)

[mauromol]

No, I did not create JBOSSTSTXTABLE myself. As I said, it must be JBossTS that creates it by itself. When JBossTS starts and it finds no ObjectStore database (i.e.: there is no file for the ObjectStore H2 database), the database is created by H2 and the schema is created by JBossTS.

The JBOSSTSTXTABLE that I have is the following:

- column STATETYPE INTEGER(10) NOT NULL

- column TYPENAME VARCHAR(1024) NOT NULL

- column UIDSTRING VARCHAR(255) NOT NULL,

- column OBJECTSTATE VARBINARY(2147483647)

- an only index, of type PRIMARY KEY, on UIDSTRING, STATETYPE, TYPENAME

So, the schema seems to be correct.

Anyway, as I said, this is the only table I have in my database.

[mauromol]

More precisely, we created a h2_driver class that extends com.arjuna.ats.internal.arjuna.objectstore.jdbc.postgresql_driver, since we initialize our H2 connections in PostgreSQL compatibility mode, so the client code (JBossTS in this case) can use the PostgreSQL syntax for DDL and DML statements. Therefore, we're relying on com.arjuna.ats.internal.arjuna.objectstore.jdbc.postgresql_driver.createTable(Statement, String) for the creation of the tables in the ObjectStore database. As far as I can see, only one table is created in the ObjectStore database and it's JBOSSTSTXTABLE, with the schema above. So, no tables for the expired transactions...

[mmusgrov]

OK, the reason I asked was because the log is saying:

"org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY_KEY_E ON PUBLIC.JBOSSTSTXTABLE(UIDSTRING, STATETYPE)"; SQL statement:"

whereas I would have expected "PRIMARY_KEY_E ON PUBLIC.JBOSSTSTXTABLE(UIDSTRING, STATETYPE, TYPENAME)" if typename really was part of the primary key.

What does "show columns from PUBLIC.JBOSSTSTXTABLE" report?

Anyway, as I said, this is the only table I have in my database.

We are using JBOSSTSTXTABLE for both active and expired log entries so this if fine, we disciminate between active and expired log entries by using different TYPENAMEs (that's why it's part of the key).

[mauromol]

What information do you actually need about the columns? SHOW COLUMNS is not supported by PostgreSQL/H2, however if I use the following:

SELECT * FROM
   information_schema.COLUMNS
WHERE
  table_name = 'JBOSSTSTXTABLE'

I get the following result:

TABLE_CATALOG	TABLE_SCHEMA	TABLE_NAME	COLUMN_NAME	ORDINAL_POSITION	COLUMN_DEFAULT	IS_NULLABLE	DATA_TYPE	CHARACTER_MAXIMUM_LENGTH	CHARACTER_OCTET_LENGTH	NUMERIC_PRECISION	NUMERIC_PRECISION_RADIX	NUMERIC_SCALE	CHARACTER_SET_NAME	COLLATION_NAME	TYPE_NAME	NULLABLE	IS_COMPUTED	SELECTIVITY	CHECK_CONSTRAINT	SEQUENCE_NAME	REMARKS	SOURCE_DATA_TYPE
OBJECTSTORE	PUBLIC	JBOSSTSTXTABLE	STATETYPE	1	null	NO	4	10	10	10	10	0	Unicode	OFF	INTEGER	0	FALSE	50		null		null
OBJECTSTORE	PUBLIC	JBOSSTSTXTABLE	TYPENAME	2	null	NO	12	1024	1024	1024	10	0	Unicode	OFF	VARCHAR	0	FALSE	50		null		null
OBJECTSTORE	PUBLIC	JBOSSTSTXTABLE	UIDSTRING	3	null	NO	12	255	255	255	10	0	Unicode	OFF	VARCHAR	0	FALSE	50		null		null
OBJECTSTORE	PUBLIC	JBOSSTSTXTABLE	OBJECTSTATE	4	null	YES	-3	2147483647	2147483647	2147483647	10	0	Unicode	OFF	VARBINARY	1	FALSE	50		null		null

Mauro.

[mmusgrov]

I thought you were using H2 for the transaction manager object store database (your last post implies you are using postgres):

- your first post says "org.h2.jdbc.JdbcSQLException: Unique index or primary key violation" (which, incidently, is  reporting the wrong primary key and appears to be the root cause of the errors);

- your fourth post says "I'm using an H2 file-based database for the objectstore"

The reason I asked if you had created the table yourself is because we don't have automatic table creation for H2.

The reason I asked you to run "show columns from PUBLIC.JBOSSTSTXTABLE"  was to verify that the primary key for the object store table is correct. This is the syntax that H2 uses to describe its tables.

[mauromol]

As I said previously:

- we are using H2 to store the ObjectStore information in a file-based database

- we are using H2 in PostgreSQL compatibility mode; this means that H2 is accepting SQL statements in a form accepted by PosgreSQL

- this allows us to provide an extension of com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple based on com.arjuna.ats.internal.arjuna.objectstore.jdbc.postgresql_driver; so, our implementation (named h2_driver) is simply extending your postgresql_driver and redefining the method com.arjuna.ats.internal.arjuna.objectstore.jdbc.postgresql_driver.name() in order to return "h2" instead of "postgresql"; in particular, the method createTable of our h2_driver, which is responsible of the creation of the JBOSSTSTXTABLE, is actually com.arjuna.ats.internal.arjuna.objectstore.jdbc.postgresql_driver.createTable(Statement, String), because we don't override it

- if I open the H2 console of our embedded H2 instance, if I try to write "show columns from PUBLIC.JBOSSTSTXTABLE" I get a syntax error; this must be because H2 in PostgreSQL compatibility mode only accepts SQL statements in PostgreSQL form, I guess...

-  in any case, as I wrote before, this is the structure of the table:

- column STATETYPE INTEGER(10) NOT NULL

- column TYPENAME VARCHAR(1024) NOT NULL

- column UIDSTRING VARCHAR(255) NOT NULL,

- column OBJECTSTATE VARBINARY(2147483647)

- an only index, of type PRIMARY KEY, on UIDSTRING, STATETYPE, TYPENAME

This information is clearly visible in the H2 console.

Mauro.

[mmusgrov]

It sounds like H2 in PostgreSQL compatibility mode is not doing what you expect (maybe there are config options that you could investigate, maybe it isn't 100% compatible): the log you quoted in the first post says Unique index or primary key violation:"PRIMARY_KEY_E ON PUBLIC.JBOSSTSTXTABLE(UIDSTRING, STATETYPE)"; but the JDBC object store implementation needs TYPENAME to be part of the primary key.

[mauromol]

I wrote a message in the H2 mailing list to investigate whether it's a bug of the version of H2 we're using.

I will report back as soon as I have more information.

Thank you very much for your help!

Mauro.

[tomjenkinson]

Michael Musgrove wrote:

It sounds like H2 in PostgreSQL compatibility mode is not doing what you expect (maybe there are config options that you could investigate, maybe it isn't 100% compatible): the log you quoted in the first post says Unique index or primary key violation:"PRIMARY_KEY_E ON PUBLIC.JBOSSTSTXTABLE(UIDSTRING, STATETYPE)"; but the JDBC object store implementation needs TYPENAME to be part of the primary key.

+1

Mauro, did you get an answer from the mailing list? It definitely appears that the error message you are getting from H2 implies when insert is called via DML it thinks the PK is just UIDSTRING,STATETYPE wheras when a query on the schema is executed it knows the PK is "an only index, of type PRIMARY KEY, on UIDSTRING, STATETYPE, TYPENAME"

[mauromol]

Tom Jenkinson ha scritto:

Mauro, did you get an answer from the mailing list? It definitely appears that the error message you are getting from H2 implies when insert is called via DML it thinks the PK is just UIDSTRING,STATETYPE wheras when a query on the schema is executed it knows the PK is "an only index, of type PRIMARY KEY, on UIDSTRING, STATETYPE, TYPENAME"

I tried to contact the H2 team... but they have a Google Group where new users can write, but their message must be approved. I'm waiting for approval since 17 Jan 2012. I even tried to write again on 24 Jan 2012, but my messages don't appear in the group yet...

I'm going to wait for some more days, then I'll try to contact them in other ways... Suggestions are welcome.

Mauro.