Context trace

April 8, 2014 · 3 min read

jPOS project founder

In jPOS 1.9.7 cce6a27 we've added a new transient trace flag to the Context that can be very useful during development.

Those of you using the TransactionManager with a large number of participants know that sometimes it becomes difficult to know who placed what in the Context.

You get to see a Context with many entries (REQUEST, RESPONSE, IRC, SOURCE, TRANLOG, TIMESTAMP, AMOUNT, PAN, ADDITIONAL_AMOUNT, etc.) but pin pointing where a given value is place gets difficult.

If the Context new trace boolean is set to true (something you can do via a configuration property in one of the initial participants such as PrepareContext or even closer to the incoming message, in the ISORequestListener when you create the Context), the Debug output would look like this:

REQUEST='2100 000000000162 29110001 ' [org.jpos.jcard.IncomingSupport.process(IncomingSupport.java:52)] [0.1/0.1] SS='JCARD' [org.jpos.jcard.IncomingSupport.process(IncomingSupport.java:53)] [0.0/0.2] TXNNAME='100.00' [org.jpos.jcard.IncomingSupport.process(IncomingSupport.java:68)] [0.0/0.2] SOURCE='org.jpos.iso.channel.CSChannel@2c42dc17' [org.jpos.jcard.IncomingSupport.process(IncomingSupport.java:69)] [0.0/0.2] WATCHDOG='org.jpos.jcard.IncomingSupport$1@1aad5bb2' [org.jpos.jcard.IncomingSupport.process(IncomingSupport.java:76)] [0.0/0.3] prepare-context [4.6/4.9] TIMESTAMP='Tue Apr 08 12:29:20 UYT 2014' [org.jpos.jcard.PrepareContext.prepare(PrepareContext.java:33)] [0.0/5.0] TXNMGR='txnmgr' [org.jpos.jcard.PrepareContext.prepare(PrepareContext.java:38)] [0.0/5.0] DB='org.jpos.ee.DB@3f3fd620' [org.jpos.transaction.TxnSupport.getDB(TxnSupport.java:157)] [0.1/5.1] TX='org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction@4d0ee1de' [org.jpos.transaction.Open.prepare(Open.java:38)] [37.4/42.5] open [0.0/42.5] SWITCH='100.00 (authorization prepareresponse logit close sendresponse)' [org.jpos.jcard.Switch.select(Switch.java:39)] [0.0/42.6] PCODE='000000' [org.jpos.jcard.CheckFields.putPCode(CheckFields.java:163)] [0.0/42.7] PCODE_TXN_TYPE='00' [org.jpos.jcard.CheckFields.putPCode(CheckFields.java:164)] [2.6/45.3] PCODE_ACCOUNT_TYPE='00' [org.jpos.jcard.CheckFields.putPCode(CheckFields.java:165)] [0.0/45.4] PCODE_ACCOUNT2_TYPE='00' [org.jpos.jcard.CheckFields.putPCode(CheckFields.java:166)] [0.0/45.4] TRANSMISSION_TIMESTAMP='Tue Apr 08 12:29:20 UYT 2014' [org.jpos.jcard.CheckFields.putTransmissionTimestamp(CheckFields.java:301)] [0.0/45.5] LOCAL_TRANSACTION_TIMESTAMP='Tue Apr 08 12:29:20 UYT 2014' [org.jpos.jcard.CheckFields.putLocalTransactionTimestamp(CheckFields.java:297)] [0.0/45.5] AMOUNT='100.01' [org.jpos.jcard.CheckFields.putAmount(CheckFields.java:231)] [0.0/45.6] CURRENCY='840' [org.jpos.jcard.CheckFields.putAmount(CheckFields.java:232)] [0.0/45.6] PAN='6009330000000033' [org.jpos.jcard.CheckFields.putPAN(CheckFields.java:180)] [0.0/45.7] EXP='4912' [org.jpos.jcard.CheckFields.putPAN(CheckFields.java:181)] [0.0/45.7] TID='29110001 ' [org.jpos.jcard.CheckFields.assertFields(CheckFields.java:127)] [0.0/45.7] NETWORK_CAPTURE_DATE='Tue Apr 08 12:00:00 UYT 2014' [org.jpos.jcard.CheckFields.putCaptureDate(CheckFields.java:275)] [0.0/45.8] MID='001001' [org.jpos.jcard.CheckFields.assertFields(CheckFields.java:130)] [0.0/45.8] TRANLOG='org.jpos.ee.TranLog@7dcadb39[id=166]' [org.jpos.jcard.CreateTranLog.doPrepare(CreateTranLog.java:99)] [2.6/48.5] CAPTURE_DATE='Tue Apr 08 00:00:00 UYT 2014' [org.jpos.jcard.CreateTranLog.doPrepare(CreateTranLog.java:100)] [0.0/48.5] create-tranlog [0.0/48.6] CARD='org.jpos.ee.Card@42c613bd[id=5,pan=600933...0033]' [org.jpos.jcard.CheckCard.prepare(CheckCard.java:65)] [10.0/58.6] ISSUER='org.jpos.ee.Issuer@61188c80[id=1,name=1]' [org.jpos.jcard.CheckCard.prepare(CheckCard.java:97)] [2.8/61.5] CARDPRODUCT='org.jpos.ee.CardProduct@60ea1534[id=3,name=3]' [org.jpos.jcard.CheckCard.prepare(CheckCard.java:98)] [0.0/61.5] check-card [0.0/61.5] check-terminal [6.3/67.9] ACQUIRER='org.jpos.ee.Acquirer@2b001c59[id=1,name=1]' [org.jpos.jcard.CheckAcquirer.prepare(CheckAcquirer.java:51)] [6.6/74.5] check-acquirer [0.0/74.5] ACCOUNT='org.jpos.gl.FinalAccount@7f7a1bec[id=28,code=22.0000000002]' [org.jpos.jcard.SelectAccount.prepare(SelectAccount.java:49)] [1.0/75.6] select-account [0.0/75.6] check-previous-reverse [3.2/79.1] check-velocity [18.2/97.3] authorization-start [0.0/97.4] GLSESSION='org.jpos.gl.GLSession@5976dbd8[DB=org.jpos.ee.DB@3f3fd620]' [org.jpos.jcard.JCardTxnSupport.getGLSession(JCardTxnSupport.java:146)] [1.7/99.2] authorization-pre-lock-journal [0.0/99.2] authorization-post-lock-journal [1.7/101.0] authorization-compute-balance [7.0/108.0] ACCOUNT='org.jpos.gl.FinalAccount@7f7a1bec[id=28,code=22.0000000002]' [org.jpos.jcard.Authorization.prepare(Authorization.java:110)] [0.1/108.2] authorization-get-credit-line [8.1/116.3] RC='not.sufficient.funds' [org.jpos.jcard.Authorization.prepare(Authorization.java:195)] [0.8/117.1] EXTRC='Credit line is 0.00, issuer fee=6.75' [org.jpos.jcard.Authorization.prepare(Authorization.java:197)] [0.0/117.1] authorization [0.0/117.2] create-cache-ledger [6.3/123.5] create-cache-pending-and-credit [8.4/132.0] create-cache-pending [47.5/179.5] LEDGER_BALANCE='100.00' [org.jpos.jcard.ComputeBalances.prepare(ComputeBalances.java:84)] [0.1/179.6] AVAILABLE_BALANCE='100.00' [org.jpos.jcard.ComputeBalances.prepare(ComputeBalances.java:85)] [0.0/179.7] compute-balances [0.0/179.7] IRC='1016' [org.jpos.jcard.PrepareResponse.setRetCode(PrepareResponse.java:142)] [2.9/182.6] RESPONSE='2110 000000000162 29110001 ' [org.jpos.jcard.PrepareResponse.prepareForAbort(PrepareResponse.java:56)] [19.9/202.6] close [9.5/212.1] REQUEST='2100 000000000162 29110001 ' [org.jpos.jcard.ProtectDebugInfo.protect(ProtectDebugInfo.java:43)] [647.9/860.1] end [0.2/860.3]

Although it may look verbose, this could be very useful while coding, it helps you spot problems and assist on debugging.

I just found one issue in the jCard system while writing this blog post, look at this, we set the ACCOUNT in SelectAccount

ACCOUNT='org.jpos.gl.FinalAccount@7f7a1bec[id=28,code=22.0000000002]' [org.jpos.jcard.SelectAccount.prepare(SelectAccount.java:49)] [1.0/75.6]

then we set it again in Authorization.

ACCOUNT='org.jpos.gl.FinalAccount@7f7a1bec[id=28,code=22.0000000002]' [org.jpos.jcard.Authorization.prepare(Authorization.java:110)] [0.1/108.2]

Not a big deal, it's the same account, but worth checking why we are doing that.