Hi, I am using Websphere Application Server Community Edition 2.0.0.2-20080401 on Windows Server 2003. I am experiencing intermittent problems with an EJB that inserts a row each into 3 tables. The datasource used by the EJB is of the TranQL XA Resource Adapter (tranql-connector-1.4.jar and tranql-connector-db2-common-1.1.jar) for DB2 pool type, and the driver type is 4. The underlying database is DB2 v9.5.0.808.
The EJB is using Bean Managed Transactions. It is coded to: 1. Get a UserTransaction from SessionContext 2. Call UserTransaction::begin 3. Insert a row into Table 1. 4. Insert a row into Table 2 which has an identity column (i.e. autonumber) primary key. 5. Insert a row into Table 3 using the autogenerated number from the row inserted into table 2. Table 3 has no foreign key constraints. 6. Publish a JMS message 7. Call UserTransaction::commit Intermittently, a problem happens where the EJB has successfully committed the UserTransaction, but when I inspect the tables, only Table 3 has a new row. Interestingly, the next row successfully inserted into Table 2 will be greater than the last row in Table 2 by 2 instead of 1, indicating that the sequence for the identity column had been incremented during the transaction during which the problem occurred. Hence, I suspected that although the UserTransaction had been committed, the insertions into Tables 1 and 2 had been rolled back. To verify if that was true, I configured the Database Pool to set the TraceFile property. Then, I was able to see from the DB2 trace file that after the insertion into Table 2, Connection::rollback was called. Here is an excerpt of the DB2 trace, that is taken from between the insert into Table 2 and before the insert into Table 3. The first bolded line shows that an insert was done into Table 2, as PreparedStatement::getGeneratedKeys() returned the autonumber primary key of 145012. The third bolded line shows that rollback was called on the Connection. > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][PreparedStatement@318a318a] >> getGeneratedKeys () returned ResultSet@78da78da > > [ibm][db2][jcc][SystemMonitor:start] > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] next () >> called > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] next () >> returned true > > [ibm][db2][jcc][SystemMonitor:stop] core: 0.129933ms | network: 0.0ms | >> server: 0.0ms > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] getInt (1) >> called > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] getInt () >> returned 145012 > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] wasNull () >> called > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] wasNull () >> returned false > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] getInt (1) >> called > > *[ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] getInt () >> returned 145012* > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] wasNull () >> called > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] wasNull () >> returned false > > [ibm][db2][jcc][SystemMonitor:start] > > [ibm][db2][jcc][Time:2013-09-02-15 >> :10:00.469][Thread:http-0.0.0.0-8080-3][ResultSet@78da78da] close () >> called > > [ibm][db2][jcc][SystemMonitor:stop] core: 0.062957ms | network: 0.0ms | >> server: 0.0ms > > [ibm][db2][jcc][SystemMonitor:start] > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:00.469][Thread:http-0.0.0.0-8080-3][PreparedStatement@318a318a] >> close () called > > [ibm][db2][jcc][SystemMonitor:stop] core: 0.075763ms | network: 0.0ms | >> server: 0.0ms > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.829][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getMetaData () returned DatabaseMetaData@312e312e > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getTransactionIsolation () returned 2 > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getMetaData () returned DatabaseMetaData@312e312e > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getCatalog () returned null > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getAutoCommit () returned false > > [ibm][db2][jcc][SystemMonitor:start] > > * >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> rollback () called* > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][T4XAResource@7b847b84] >> makeEntryCurrent(new,old) (0, 0) called > > [ibm][db2][jcc] >> [t4][time:2013-09-02-15:10:06.844][thread:http-0.0.0.0-8080-3][tracepoint:1][Request.flush] > > [ibm][db2][jcc][t4] SEND BUFFER: SYNCCTL (ASCII) >> (EBCDIC) > > [ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F >> 0123456789ABCDEF 0123456789ABCDEF > > [ibm][db2][jcc][t4] 0000 001FD00100010019 1055000511870400 >> .........U...... ..}..........g.. > > [ibm][db2][jcc][t4] 0010 081801FFFFFFFF00 08190310000000 >> ............... ............... > > [ibm][db2][jcc][t4] > > [ibm][db2][jcc][t4] >> [time:2013-09-02-15:10:06.844][thread:http-0.0.0.0-8080-3][tracepoint:101]Request >> flushed. > > [ibm][db2][jcc][t4] >> [time:2013-09-02-15:10:06.844][thread:http-0.0.0.0-8080-3][tracepoint:102]Reply >> to be filled. > > [ibm][db2][jcc] >> [t4][time:2013-09-02-15:10:06.844][thread:http-0.0.0.0-8080-3][tracepoint:2][Reply.fill] > > [ibm][db2][jcc][t4] RECEIVE BUFFER: SYNCCRD (ASCII) >> (EBCDIC) > > [ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F >> 0123456789ABCDEF 0123456789ABCDEF > > [ibm][db2][jcc][t4] 0000 0012D0030001000C 1248000819040000 >> .........H...... ..}............. > > [ibm][db2][jcc][t4] 0010 0000 .. >> .. > > [ibm][db2][jcc][t4] > > [ibm][db2][jcc][Connection@5fc25fc2] DB2 LUWID: >> 127.0.0.1.23050.130902071010.0013 > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> rollback () returned null > > [ibm][db2][jcc][SystemMonitor:stop] core: 2.7474659999999997ms | network: >> 1.664142ms | server: 0.0ms > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> setAutoCommit (true) called > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> setAutoCommit (false) called > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getAutoCommit () returned false > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> getAutoCommit () returned false > > >> [ibm][db2][jcc][Time:2013-09-02-15:10:06.844][Thread:http-0.0.0.0-8080-3][Connection@5fc25fc2] >> setAutoCommit (true) called > > [ibm][db2][jcc][SystemMonitor:start] > > The configuration for the datasource in var/config/config.xml looks like this: > <module name="console.dbpool/myDS/1.0/rar"> >> >> - <gbean >>> name="console.dbpool/myDS/1.0/rar?J2EEApplication=null,JCAConnectionFactory=myDS,JCAResource=console.dbpool/myDS/1.0/rar,ResourceAdapter=console.dbpool/myDS/1.0/rar,ResourceAdapterModule=console.dbpool/myDS/1.0/rar,j2eeType=JCAManagedConnectionFactory,name=myDS"> >> >> <attribute name="TraceFile">c:\logs\db2trace.log</attribute> >> >> <attribute name="PreparedStatementCacheSize">0</attribute> >> >> <attribute name="DatabaseName">MyDB</attribute> >> >> <attribute name="Password">...</attribute> >> >> <attribute name="ServerName">localhost</attribute> >> >> <attribute name="UserName">Admin</attribute> >> >> <attribute name="DriverType">4</attribute> >> >> <attribute name="TraceFileAppend">true</attribute> >> >> <attribute name="PortNumber">50000</attribute> >> >> </gbean> >> >> - <gbean >>> name="console.dbpool/myDS/1.0/rar?J2EEApplication=null,JCAConnectionFactory=myDS,JCAManagedConnectionFactory=myDS,JCAResource=console.dbpool/myDS/1.0/rar,ResourceAdapter=console.dbpool/myDS/1.0/rar,ResourceAdapterModule=console.dbpool/myDS/1.0/rar,j2eeType=JCAConnectionManager,name=myDS"> >> >> <attribute name="partitionMinSize">20</attribute> >> >> <attribute name="partitionMaxSize">100</attribute> >> >> <attribute name="blockingTimeoutMilliseconds">5000</attribute> >> >> <attribute name="idleTimeoutMinutes">15</attribute> >> >> </gbean> >> >> </module> >> >> > If anyone could advise why Connection::rollback is sometimes getting called during the transaction, the help would be greatly appreciated. Do let me know if I should furnish anymore details as well. Thanks a lot.
