geronimo-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stella Lok <oinvertedwo...@gmail.com>
Subject DB2 Connection::rollback sometimes called for unknown reason within a committed XA transaction
Date Mon, 02 Sep 2013 12:07:02 GMT
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.

Mime
View raw message