COM+ VB6 Application on 64 bit system: IBM CLI Driver transaction error when connecting to DB2

Question

We are trying to migrate an Intranet Web Application, developed in VB6, from Windows Server 2003 to Windows Server 2008 R2 and we are facing a problem with two phase commit transactions between Microsoft SQL Server 2008 and DB2 on Z/OS Mainframe.

On Windows Server 2008 R2 with DB2 v9.7.500.702 Fixpack 8 (64 bit) installed, the VB6 component registered in a COM+ application, when trying to update in transaction one table on SQL Server and another table on DB2, returns this error:

[IBM][CLI Driver] SQL0998N Error occurred during transaction or heuristic processing. Reason Code = "16". Subcode = "2-80004005". SQLSTATE=58005

Running the VB6 application in Debug, the exception is raised when the Open() method is called on the ADODB.Connection object (Db2 connection).

Db2Diag shows this:

2013-06-26-09.14.15.822000+120 I41317H405 LEVEL: Severe
PID : 5972 TID : 5588 PROC : dllhost.exe
INSTANCE: DB2 NODE : 000
APPID : *LOCAL.DB2.1306260714140626071414
EDUID : 5588
FUNCTION: DB2 UDB, XA DTP Support, MicrosoftXARMCreate, probe:364
DATA #1 : String, 69 bytes
HRESULT: 80004005
HRESULT Message: Unspecified error

System event viewer reports this:

The XA Transaction Manager attempted to load the XA resource manager DLL. The call to LOADLIBRARY for the XA resource manager DLL failed: DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL, HR=0x800700c1, File=d:\w7rtm\com\complus\dtc\dtc\xatm\src\xarmconn.cpp Line=2446.

Firewall is TURNED OFF.
I've already tried to reinstall MSDTC.
DTCPing.exe worked correctly.
This is my DTC configuration:

I found this blog that suggests to change the HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\MSDTC\XADLL\C:\Program Files\IBM\SQLLIB\BIN\DB2APP.DLL registry key referencing the db2app64.dll instead of the db2app.dll that the DB2 client installer normally set.

After changing the registry Key as suggested, the event viewer error report does not show anymore but the application still gives this error:

[IBM][CLI Driver][DB2] SQL0998N Error occurred during transaction or heuristic processing. Reason Code = "16". Subcode = "3-8004D00E". SQLSTATE=58005

Db2Diag shows this:

2013-06-25-12.22.37.192000+120 I39609H572 LEVEL: Severe
PID : 4364 TID : 1804 PROC : dllhost.exe
INSTANCE: DB2 NODE : 000
APPID : *LOCAL.DB2.1306251022380625102238
EDUID : 1804
FUNCTION: DB2 UDB, XA DTP Support, MicrosoftEnlistWithRM, probe:422
DATA #1 : String, 130 bytes
HRESULT: 8004D00E
HRESULT Message: The transaction has already been implicitly or explicitly committed or aborted

and inspecting the Db2 trace log reports this error:

pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.605   ;seq=94468      ;eventid=TRACING_STARTED                          ;;"TM Identifier='(null)                                            '" ;"MSDTC is resuming the tracing of long - lived transactions"
pid=2664       ;tid=1764       ;time=06/25/2013-10:46:11.725   ;seq=94469      ;eventid=CHECKPOINTING_STARTED                    ;;"TM Identifier='(null)                                            '" ;"MSDTC is resuming the checkpointing of transactions "
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.624   ;seq=94470      ;eventid=TRANSACTION_BEGUN                        ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"transaction has begun, description :'Foo.bstx'"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.624   ;seq=94471      ;eventid=TRANSACTION_PROPOGATED_TO_CHILD_NODE     ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"transaction propagated to 'DVD1SSQ4' as transaction child node #1"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.764   ;seq=94472      ;eventid=RM_ENLISTED_IN_TRANSACTION               ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"resource manager #1002 enlisted as transaction enlistment #1. RM guid = '185bcf6e-85b5-402c-8d43-0368d4c5ee46'"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.858   ;seq=94473      ;eventid=ABORT_DUE_TO_CONNECTION_DOWN_FROM_RM     ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"connection to the resource manager #1002 for transaction enlistment #1 went down"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.858   ;seq=94474      ;eventid=TRANSACTION_ABORTING                     ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"transaction is aborting"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.858   ;seq=94475      ;eventid=CHILD_NODE_ISSUED_ABORT                  ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"abort request issued to transaction child node #1 'DVD1SSQ4'"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.858   ;seq=94476      ;eventid=CHILD_NODE_ACKNOWLEDGED_ABORT            ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"received acknowledgement of abort request from transaction child node #1 'DVD1SSQ4'"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.858   ;seq=94477      ;eventid=TRANSACTION_ABORTED                      ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"transaction has been aborted"
pid=2664       ;tid=2020       ;time=06/25/2013-10:46:11.837   ;seq=94478      ;eventid=RM_ENLIST_FAILED_TRANSACTION_NOT_FOUND   ;tx_guid=4d2b1dc0-8679-44f2-a649-e440057f2423     ;"TM Identifier='(null)                                            '" ;"attempt to enlist the resource manager failed cause the transaction could not be found. Some possible reasons include, client might have already called commit or transaction might have got aborted due to timeout. RM guid = 'aa265ceb-27b0-4de0-999b-80b58dee4af8'"

Enabling Diagnostic tracing on MS DTC, we only get this entry:

06-25-2013 12:43:17:746 : [ a68.132c] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] LookUpXaDllPath (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xatmdll.cpp@175): Looking up XA DLL 'C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL'
06-25-2013 12:43:17:746 : [ a68.132c] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] LookUpXaDllPath (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xatmdll.cpp@294): Xa DLL Lookup completed, HR=00000000, Path='C:\Program Files\IBM\SQLLIB\BIN\DB2APP64.DLL'
06-25-2013 12:43:17:746 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1915): CValidateTask::TaskRoutine - calling xa_open - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL, OpenString="DB=FOO,UID=FOO,PWD=FOO,TPM=MSDTC"
06-25-2013 12:43:17:777 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1919): CValidateTask::TaskRoutine - returned from xa_open with error=0 - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL, OpenString="DB=FOO,UID=FOO,PWD=FOO,TPM=MSDTC"
06-25-2013 12:43:17:777 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1934): CValidateTask::TaskRoutine - calling xa_close - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL
06-25-2013 12:43:17:777 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1943): CValidateTask::TaskRoutine - returned from xa_close with error=0 - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL
06-25-2013 12:43:17:855 : [ a68.156c] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] LookUpXaDllPath (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xatmdll.cpp@175): Looking up XA DLL 'C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL'
06-25-2013 12:43:17:855 : [ a68.156c] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] LookUpXaDllPath (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xatmdll.cpp@294): Xa DLL Lookup completed, HR=00000000, Path='C:\Program Files\IBM\SQLLIB\BIN\DB2APP64.DLL'
06-25-2013 12:43:17:855 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1915): CValidateTask::TaskRoutine - calling xa_open - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL, OpenString="DB=FOO,UID=FOO,PWD=FOO,TPM=MSDTC"
06-25-2013 12:43:17:886 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1919): CValidateTask::TaskRoutine - returned from xa_open with error=0 - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL, OpenString="DB=FOO,UID=FOO,PWD=FOO,TPM=MSDTC"
06-25-2013 12:43:17:886 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1934): CValidateTask::TaskRoutine - calling xa_close - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL
06-25-2013 12:43:17:886 : [ a68. 6e4] 0x00000000 [    TRACE_XA] [TRACE_VERBOSE] CValidateTask::TaskRoutine (d:\w7rtm\com\complus\dtc\dtc\xatm\src\xataskmgr.cpp@1943): CValidateTask::TaskRoutine - returned from xa_close with error=0 - DLL=C:\PROGRAM FILES\IBM\SQLLIB\BIN\DB2APP.DLL

Running testconn20.exe or testconn32.exe using the -dtc flag, the XA connection test passes without errors.

...
Step 4: Selecting rows from SYSIBM.systables to validate existence of packages
SELECT * FROM SYSIBM.systables FETCH FIRST 5 rows only
Elapsed: 0.0468015

Step 5: Calling GetSchema for tables to validate existence of schema functions
Elapsed: 1.5132485

Step 6: Creating XA connection
DB2TransactionScope: Connection Closed.
Elapsed: 2.152869
Test passed.

On the old server with Windows Server 2003 and Db2 9.5.800.186 FixPack8 (32 bit) installed, everything works smoothly without any problem; the db2 trace log, running the same application, shows this:

pid=5188       ;tid=4516       ;time=06/25/2013-11:52:12.382   ;seq=5          ;eventid=TRACING_STARTED                          ;;"TM Identifier='(null)                                            '" ;"MSDTC is resuming the tracing of long - lived transactions"
pid=5188       ;tid=1536       ;time=06/25/2013-11:52:12.616   ;seq=6          ;eventid=CHECKPOINTING_STARTED                    ;;"TM Identifier='(null)                                            '" ;"MSDTC is resuming the checkpointing of transactions "
pid=5188       ;tid=4516       ;time=06/25/2013-11:52:12.382   ;seq=7          ;eventid=TRANSACTION_BEGUN                        ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"transaction has begun, description :'Foo.bstx'"
pid=5188       ;tid=4352       ;time=06/25/2013-11:52:12.382   ;seq=8          ;eventid=TRANSACTION_PROPOGATED_TO_CHILD_NODE     ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"transaction propagated to 'DVD1SSQ4' as transaction child node #1"
pid=5188       ;tid=4516       ;time=06/25/2013-11:52:12.647   ;seq=9          ;eventid=RM_ENLISTED_IN_TRANSACTION               ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"resource manager #1001 enlisted as transaction enlistment #1. RM guid = '3a1e3c78-a7ac-40f4-9101-d0506d78c405'"
pid=5188       ;tid=5360       ;time=06/25/2013-11:52:12.913   ;seq=10         ;eventid=RECEIVED_COMMIT_REQUEST_FROM_BEGINNER    ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"received request to commit the transaction from beginner"
pid=5188       ;tid=5360       ;time=06/25/2013-11:52:12.913   ;seq=11         ;eventid=CHILD_NODE_ISSUED_PREPARE                ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"prepare request issued to transaction child node #1 'DVD1SSQ4'"
pid=5188       ;tid=5360       ;time=06/25/2013-11:52:12.913   ;seq=12         ;eventid=RM_ISSUED_PREPARE                        ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"prepare request issued to resource manager #1001 for transaction enlistment #1"
pid=5188       ;tid=4352       ;time=06/25/2013-11:52:12.928   ;seq=13         ;eventid=CHILD_NODE_VOTED_COMMIT                  ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"transaction child node #1 'DVD1SSQ4' voted commit"
pid=5188       ;tid=4516       ;time=06/25/2013-11:52:12.928   ;seq=14         ;eventid=RM_VOTED_COMMIT                          ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"resource manager #1001 voted commit for transaction enlistment #1"
pid=5188       ;tid=1932       ;time=06/25/2013-11:52:12.944   ;seq=15         ;eventid=TRANSACTION_COMMITTED                    ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"transaction has got committed"
pid=5188       ;tid=1932       ;time=06/25/2013-11:52:12.944   ;seq=16         ;eventid=CHILD_NODE_ISSUED_COMMIT                 ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"commit request issued to transaction child node #1 'DVD1SSQ4'"
pid=5188       ;tid=1932       ;time=06/25/2013-11:52:12.944   ;seq=17         ;eventid=RM_ISSUED_COMMIT                         ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"commit request issued to resource manager #1001 for transaction enlistment #1"
pid=5188       ;tid=4352       ;time=06/25/2013-11:52:12.944   ;seq=18         ;eventid=CHILD_NODE_ACKNOWLEDGED_COMMIT           ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"received acknowledgement of commit request from transaction child node #1 'DVD1SSQ4'"
pid=5188       ;tid=4736       ;time=06/25/2013-11:52:12.944   ;seq=19         ;eventid=RM_ACKNOWLEDGED_COMMIT                   ;tx_guid=16bfbb83-9b31-4c59-a06f-c5b59978f0ca     ;"TM Identifier='(null)                                            '" ;"received acknowledgement of commit request from the resource manager #1001 for transaction enlistment #1"
pid=5188       ;tid=4056       ;time=06/25/2013-11:53:07.118   ;seq=20         ;eventid=TRACING_STOPPED                          ;;"TM Identifier='(null)                                            '" ;"MSDTC is suspending the tracing of long - lived transactions due to lack of activity"

Do you know if MSDTC (64 bit) supports a 2phase commit Transaction called from a 32 bit application (Dllhost.exe 32 bit or Vb6.exe 32 bit)?
TestConn32.exe works and passes dtc test without problem (after the Db2app64.dll fix described above), so it does not seem a 32 bit compatibility problem.
I've already tried to change the DB2 driver from 32 to 64 bits but the problem remains.

Any hints?

Answer 1

I've finally found the problem and, in retrospect, the following fix might seem obvious!

As documented here, if the MTS or COM+ objects use ADO to access the database, the OLE DB resource pooling must be turned off so that the Microsoft OLE DB provider for ODBC does not interfere with ODBC connection pooling.

The OLEDB_SERVICES DWORD value of the HKEY_CLASSES_ROOT\CLSID\{c8b522cb-5cf3-11ce-ade5-00aa0044773d} key must be set to:

0xfffffffc - All services enabled except pooling and auto-enlistment

Was this the fix? Nope, this key was already correctly set!
Watching with ProcMon all the registry activity, I've found that the Dllhost.exe 32 bit reads the OLEDB_SERVICES of this other key (WoW6432Node):

HKEY_LOCAL_MACHINE\SOFTWARE\Classes\Wow6432Node\CLSID{c8b522cb-5cf3-11ce-de5-00aa0044773d}

The OS uses this key to present a separate view of HKEY_LOCAL_MACHINE\SOFTWARE for 32-bit applications that run on a 64-bit version of Windows.

Setting OLEDB_SERVICES to 0xfffffffc finally nailed it.

Answer 2

This similar to a known bug in DB2 - see http://www-01.ibm.com/support/docview.wss?uid=swg21572529.

However, it would appear that the bug was fixed in DB2 9.7 Fixpack 2, and you're on Fixpack 5, so maybe you're running in to a different issue. I would advise opening a PMR with IBM if the referenced document doesn't provide any assistance.