Blacktie : problem with transaction and xa datasource

[gleysour]

Hello,

I currently conducting a proof of concept to replace a part of our information system based on Oracle/Tuxedo with Narayana/Blacktie.

First of all, thanks to Tom Jenkinson for it's great work to offer an open source replacement of the product tuxedo.

Actually I am facing a strange case (maybe a bug) when using a transaction against an xa datasource

Here the context :

one server process with services and connect to an xa datasource (server works with the context datasource to issue direct sql via oci)

one client process with call service, begin/commit transaction

1) When the transaction is begin/commit by the server (same process) everyhing is OK

2) When the transaction is begin/commit since the client it failed.

When i debug the problem seems to be in  "HttpTxManager::enlist" method

The httpTx->enlistUrl() return NULL then the variable recUrl is not properly initialized.

And as this variable char *recUrl is not initialize to NULL it try to "Enlisted branch" which a dirty default value.

The log :

case 1)

TxHttpTxManager          :127 ) - GWL : enlist methode  begin

TxHttpTxManager          :130 ) - GWL : enlist methode  guard isOpen TX_OK

TxHttpTxManager          :136 ) - GWL : enlist methode  recup pointer enlisturl avant

TxHttpTxManager          :138 ) - GWL : enlist methode  recup pointer enlisturl apres

TxHttpTxManager          :141 ) - GWL : enlist methode  enlisturl NOT NULL

TxHttpTxManager          :179 ) - GWL : enlist methode  recUrl

TxHttpTxManager          :183 ) - Enlisted branch 131077%3a120%3a1%3a1%3a24%3a534136 rec url: http://172.20.20.122:8080/rest-at-coordinator/tx/recovery-coordinator/0_ffffac14147a_77a9c193_53330072_1a/0_ffffac14147a_77a9c193_53330072_1b

and everything goes ok

case 2)

TxHttpTxManager          :127 ) - GWL : enlist methode  begin

TxHttpTxManager          :130 ) - GWL : enlist methode  guard isOpen TX_OK

TxHttpTxManager          :136 ) - GWL : enlist methode  recup pointer enlisturl avant

TxHttpTxManager          :138 ) - GWL : enlist methode  recup pointer enlisturl apres

TxHttpTxManager          :176 ) - GWL : enlist methode  enlisturl NULL donc recUrl = NULL (or default value on stack ?)

TxHttpTxManager          :179 ) - GWL : enlist methode  recUrl

TxHttpTxManager          :183 ) - Enlisted branch 131077%3a120%3a1%3a2%3a49%3a419249 rec url: XAWrapper::XAWrapper(XABranchNotification*, XID&, long int, xa_switch_t*, XARecoveryLog&, const char*)

and the transaction failed.

My conclusion, it seems that fully information transaction is not transmitted between distinct process ...

i don't know if it is a real bug, so i begin with the forum

Any help would be appreciated to focus arround this problem

Best regards,

    Gwenael Leysour

Environnement :

CentOS 6.5

Wildfly-8.0.0.CR1 / Narayana-5.0.0.Final

Blacktie compile in 32 bits (with third-parties include in distrib CentOS : log4cxx-0.10.0-13, xerces-c-3.0.1-20, apr-1.3.9-5)

Oracle 11.2.0

Applications in 32 bits

PS : sorry for my broken English

[mmusgrov]

Hi, thanks for a clear statement of the issue. I do have 2 questions though:

1. Are all the database accesses done through the service;
2. Would it be possible for you to attach the trace logs for the bit of code that does the resource enlistment.

The transaction control and resource enlistment is done via a service running in the wildfly application server. It may be useful to see what the service does when asked to enlist the oracle resource. If at all possible could you also enable trace logging for that subsystem: find the logging subsystem entry in standalone-rts.xml and at the following:

    <logger category="org.jboss.jbossts.star">

        <level name="TRACE"/>

    </logger>

and change the level in the root-logger to TRACE.

Mike

[zhfeng]

Hi, can you also provide the btconfig.xml used by the server and the client ?

Thanks,

Amos

[gleysour]

Hi, Michael and Amos

Thanks for your quick answers

I have tried to extract the usefull informations from the whole logs

trace_jbosssts.star     (logs from jboss server)

server_trace.txt     (logs of the process serveur, attach with xa datasource)

xa_NULL.trc      (logs from oracle xa library)

btconfig.xml_client

btconfig.xml_server     (in this case we only use <SERVER name ='Trc' xa='true' >)

We can see, one service transaction fully success (the one initiate inside the server), and the 4 others failed issue from client.

Exactly, the transaction become in state "suspend" and the xacommit never done. (because of lack of enlistement of xa datasource)

Best regards,

     Gwenael

[gleysour]

Hello,

Here are some additional information

In case 1 (we stay in same process) )

The transaction is start (via method start) and recUrl is initialize properly

In case 2 (2 processes) )

We use the method HttpControl 'reassociate' in this case recUrl is not initialize

and the enlistement will failed.

I am back to my office tuesday, i will continue investigation around this

Gwenael,

[gleysour]

Hi,

Here the news,

I made this little (ugly)  patch into HttpTXManager::enlist

==>

	char *recUrl = NULL;          // Safer to intialize to NULL
	HttpControl *httpTx = dynamic_cast<HttpControl*>(tx);

    const char *enlistUrl = httpTx->enlistUrl();   

    const char *txnUrl = httpTx->txnUrl();          // retrieve txnUrl too

    LOG4CXX_INFO(httptxlogger, "GWL : enlistUrl " << enlistUrl << "  txnUrl " << txnUrl );

    if (enlistUrl == NULL ) {

// do the trick ...... enlistUrl=txnUrl;

    }

==>

(The sequence diagram is the one page 76 of JTS Programmers Guide)

Well now it seems to works.The xa is correctly enlisted, And all xa_commit are done when the tx is committed.

Can you check this potential fix and his reliability, please

In the meantime I continue my evaluation of blacktie

Gwenael

[tomjenkinson]

Thanks for the patch suggestion, hopefully mmusgrov or zhfeng can verify this for us shortly.

If it is the correct approach, you may like to raise a pull request with your fix in it so your authorship will be shown in the commit logs? If you are interested in this please can you sign the CLA (project is "JBoss Transactions") over here: https://cla.jboss.org/ then raise a pull request over here: jbosstm/narayana · GitHub (It will be CI'd for you automatically)

Thanks for your interest in BlackTie!

[mmusgrov]

The trace_jbosssts.star log shows that the enlist request is invalid. I don't see the error response in the blacktie server log so this must be an enlist request coming from the client (I cannot check that because I don't see any client logs) - can you verify that that is the case.

My guess is that the enlist request is failing because you are enlisting the participant (ie the oracle database resource manager) from the client but the participant has already been enlisted by the blacktie server (and I do see a successful enlist request in the blacktie server log to indicate that this is what is happening). The final commit request should still succeed however since the transaction coordinator knows about the participant (via the server enlistment of the oracle resource manager).

The fix would be to not enlist the database in both the client and the server.

[zhfeng]

Can you provide us the code of the client you used ? I think it will be much useful for us to understand the problem and verify the patch.

Thanks,

Amos

[gleysour]

Hello,

I respond in order:

First to Tom,

Thanks for your proposition, after that the fix was verified, i could raise a pull request.

We are really interested by this alternative to Tuxedo. We will try to test his reliability with our POC

(by the way, do you know if some others firms have already investigate this opportunity ? have you some feedback ?)

Second to Michael,

Well, the logs that i have send may be incomplete for the whole understanding of the problem. I will try to send you more complete and clean logs.

Basically, our clients and servers operate since several years with tuxedo, so the manner of exchanges, transactions, database operations are not in doubt

So we expect that blacktie operates as Tuxedo.

Third to Amos

Unfortunatly, i can not provide the code because of

- the fact we use a 'home' framework to provide an abstraction layer with midlleware and database. (quite complexe, and huge) (code involve is 2 millions lines of code c++  ). So all call to tpcall, transactions orders, sql, are manage by this framework. Ours clients and servers never deals directly with Tuxedo , Oracle ...

- and our code is not open ..

But i think i could describe more precisely the process and the chaine of call (client and server). To reproduce simply the problem.

I have other fix to report (i will soon open others threads in the forum)

best regards,

Gwenael

[mmusgrov]

The patch is not valid. The reason the enlist fails is because the service has already enlisted the same resource. Your attempt to register the resource a second time from the client is ignored (actually your client code will have received an error response from the transaction coordinator and if you supply the client blacktie log then we can verify that that is the case). But do note that, even though the enlist has failed, I would expect your transaction to still successfully commit all work on the resource (since it has already been enlisted into the transaction by the service). So:

1) Can you check you blacktie client log for the failing enlist request;

2) Tell us the manner in which the transaction fails to commit (again the blacktie client should give us this information).

Gwenael Leysour de Rohello wrote:

Basically, our clients and servers operate since several years with tuxedo, so the manner of exchanges, transactions, database operations are not in doubt

So we expect that blacktie operates as Tuxedo.

BlackTie is an implementation of the XATMI specification (so Tuxedo and BlackTie are similar only in so far as they are both implementations of XATMI). XATMI defines how clients access services. It is the service that performs the accesses to resource managers (RMs) (not the clients). So if you are doing database calls from the client then strictly speaking that would be an invalid use of BlackTie. However, we do have an example that shows an RM being accessed from both the client and service within the same transaction, Amos, have we ran the txfooapp example recently to see if it still working.

[gleysour]

sorry, for this misunderstood

Q1) The failing enlist request is not on client side

Q2) The transaction doesn't failed but the sql order is never committed (because the lack of enlistement)

i confirm

- There is no database calls from the clients.

- It is always the service that performs the accesses to RM

Here the sequencial actions from the case i have exposed

(process a)                                      (process b)

Client                                               Server

                                                        (init)

                                                        Init connexion xa

                                                        Retrieve xa context

                                                        tx_set_transaction_time_out

                                                        tx_begin

                                                            server can call his own local services 'serviceX'

                                                        tx-commit

tx_set_transaction_time_out       

tx_begin

tpcall 'service1'                                  service1 : do sql with xa context

tx_commit

tx_set_transaction_time_out

tx_begin

tpcall 'service2'                                   service2 : do sql with xa context

tx_commit

=>>>> The exchange with the logs

[ CLIENT SIDE INITIATE TRANSACTION ]

tx_set_transaction_time_out

tx_begin

2014-04-01 18:22:26,699 [0xf7731710] DEBUG (TxHttpControl            :227 ) - URLS: Loc: http://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40

Enlist: http://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40

END: http://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40/terminator

[ CLIENT SIDE TPCALL ]

tpcall 'ItrClt'                    

2014-04-01 18:22:26,699 [0xf7731710] DEBUG (TxManager                :136 ) - begin: ok

2014-04-01 18:22:26,699 [0xf7731710] TRACE (XATMIc                   :477 ) - tpalloc type: X_OCTET size: 236

.....

2014-04-01 18:22:26,701 [0xf7731710] TRACE (XATMIc                   :531 ) - tpcall: ItrClt ilen: 236 flags: 32

...

[ SERVER SIDE REASSOCIATE TRANSACTION ]

manage service 'ItrClt'

2014-04-01 18:22:26,803 [0x6237b70] TRACE (TxManagerc               :39  ) - txx_associate_serialized:39:ENTERhttp://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40

2014-04-01 18:22:26,803 [0x6237b70] TRACE (TxHttpTxManager          :93  ) - associate_transaction:93:ENTERhttp://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40

2014-04-01 18:22:26,804 [0x6237b70] TRACE (TxControl                :36  ) - TxControl:36:ENTER new TXCONTROL: 0xf02029c8

2014-04-01 18:22:26,804 [0x6237b70] TRACE (TxHttpControl            :162 ) - HttpControl:162:ENTER reassociate HTTPTXCONTROL: 0xf02029a8 txn=http://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40

2014-04-01 18:22:26,804 [0x6237b70] TRACE (XAResourceManager        :348 ) - xa_start:348:ENTER 120: flags=200000 lookup XID: 20005:24:0:0_ffffac14147a_-308dc3dd_533ae6c2_40

2014-04-01 18:22:26,804 [0x6237b70] DEBUG (XAResourceManager        :397 ) -  branch not found

2014-04-01 18:22:26,804 [0x6237b70] TRACE (XAResourceManager        :353 ) - xa_start:353:creating branch 131077:36:0:0_ffffac14147a_-308dc3dd_533ae6c2_40

2014-04-01 18:22:26,804 [0x6237b70] TRACE (XAResourceManager        :455 ) - gen_xid:455:Leaving with XID: 131077:36:18:0_ffffac14147a_-308dc3dd_533ae6c2_40120:1:11:26:804488

2014-04-01 18:22:26,804 [0x6237b70] TRACE (TxXAWrapper              :50  ) - XAWrapper:50:ENTER address=0xf0205458 new XA resource rmid:120 branch id: 131077:36:18:0_ffffac14147a_-308dc3dd_533ae6c2_40120:1:11:26:804488

2014-04-01 18:22:26,804 [0x6237b70] DEBUG (TxXAWrapper              :59  ) - encoded name: 131077%3a120%3a1%3a11%3a26%3a804488

2014-04-01 18:22:26,804 [0x6237b70] INFO  (TxHttpTxManager          :127 ) - GWL : enlist methode  begin

2014-04-01 18:22:26,804 [0x6237b70] TRACE (TxManager                :553 ) - guard:553:ENTER

2014-04-01 18:22:26,804 [0x6237b70] INFO  (TxHttpTxManager          :130 ) - GWL : enlist methode  guard isOpen TX_OK

2014-04-01 18:22:26,804 [0x6237b70] DEBUG (TxHttpTxManager          :132 ) - info tx=0xf02029c8

2014-04-01 18:22:26,804 [0x6237b70] INFO  (TxHttpTxManager          :138 ) - GWL : enlistUrl null  txnUrl http://172.20.20.122:8080/rest-at-coordinator/tx/transaction-manager/0_ffffac14147a_-308dc3dd_533ae6c2_40

=> here as i said enlistUrl is null (or default value on stack) then "Enlisted branch" failed

=> may be the case is not seen in your txfooapp because transaction commit is OK , but it's underlying xa_commit is not executed (silently ..) due to failed enlistement

I hope this information helps you better understand the problem

[zhfeng]

Hi Mike,

I'd checked the CI jobs and it seems that the txfooapp is not working. I've raised the [JBTM-2139] update the narayana-quickstart jobs to make sure the txfooapp example is working - JBoss Issue Tracker

Amos

[mmusgrov]

It is known to fail on windows (JBTM-1572) - I meant to check it on linux where it should still be working

[mmusgrov]

Hmm this looks to have been broken for a while. When the transaction is recreated at the server, the second HttpControl (tx/src/main/cpp/HttpControl.cxx) constructor should be repopulating the _enlistUrl and _endUrl by calling HttpControl::headRequest(). As you correctly diagnosed this means _enlistUrl is not initialised so the resources don't get enlisted. I will raise a JIRA to get it fixed. Thanks for figuring this out for us