Calculate CA Risk Auth Response times using log files

[Legacy User]

Hi,

 

For CA Risk Authentication 8.2 I am trying to calculate the time it takes to complete a transaction based on the entries in the arcotriskfort.log file.

 

Currently I am unable to do so as the logging does not effectively differentiate between the various instances and opening and closing of the connection. This is what I have tried. Please see below snippet from a log file:

 

 

 

In the above example I used line 4 as my starting point for transaction tid 4472:0 seeing as this is the SERVER_CB_ACCEPT entry. Starting time : 13:17:35:126.

 

I now look for the SERVER_CB_CLOSE with the matching tid but unfortunately the tid is not unique (see line 12 is another OPEN entry for same tid). 

 

Trying to narrow down instances and IP also does not work as multiple entries can be accepted by the same node (the numeric value after the colon symbol after the tid: ex. 4276:3). 3 is the instance.

 

The ACCEPT and CLOSE entries also does not reference the node and displays a 0 for all entries.

 

Lastly I tried to use the numeric value at the end of the tid, in line 5 this is 72992100 which seems to be unique. BUT once again the ACCEPT and CLOSE entries do not reference this number.

 

Is this even possible?

 

 

Thanks

[Awijit Singh]

Hi, I expected the arcotriskfort log to print same keywords like Txn-Begin and Txn-End like the webfort server prints in arcotwebfort log. But it seems that they are not printed in riskfort log. However you can still follow a TransactionID which will be unique to every risk evaluation. 

 

I ran a few risk evaluation transaction and it starts from below log line:

Thu Sep 21 17:08:20.390 2017 LOW:     pid 4808 tid 4768: 8: 0: Entering ArRFCacheManager::getInstance

 

AND end with a log line like below:

 

Thu Sep 21 17:08:20.702 2017 LOW:     pid 4808 tid 4768: 3: 0: RiskServer : Writing to Stream [<POLICYSERVERDOC DATATYPE="XML"><POLICYRES><SESSIONID>1:12049</SESSIONID><CALLERID>123456</CALLERID><MESSAGEID>0</MESSAGEID><TRANSACTIONID>1:12051</TRANSACTIONID><ERRORSTRING></ERRORSTRING><RESPONSECODE>7000</RESPONSECODE><REASONCODE>0</REASONCODE></POLICYRES></POLICYSERVERDOC>]

 

In the line above the TRANSACTIONID is 12051 .

 

You can follow transactionID in the log to track one transaction. 

 

The first instance of this transactionID printed in the log would look like below:

 

Thu Sep 21 17:08:20.593 2017 LOW:     pid 4808 tid 4768: 2: 1:12051: ArDBPoolManagerImpl::getLockedDBConnection: [primary] DSN [aadsn] is active. Will get the connection from this

 

Please note that I have trace and DETAIL logging enabled. But you should be able to see the above with TRACE disabled.

 

Thanks

Awijit

[Legacy User]

Thanks Awijit,

 

Just to confirm you enabled TRACE on the Riskfort log correct?

 

I will do some testing with your recommendations. I prefer not to have TRACE enabled as this does have a slight impact on the performance. Without TRACE I see you can track the unique transaction ID without the OPEN and CLOSE. Assuming the time between the next line which is now my time-start counter is not big:

 

Fri Sep 22 10:37:10.415 2017 LOW: pid 6548 tid 4564: 2: 7:72954904: Request Received - evaluateRisk
Fri Sep 22 10:37:10.415 2017 INFO: pid 6548 tid 4564: 2: 7:72954904: CallerID :LOGIN:, OrgName :ORG1:
Fri Sep 22 10:37:10.415 2017 INFO: pid 6548 tid 4564: 8: 7:72954904: CallerId[LOGIN], OrgName[ORG1]
Fri Sep 22 10:37:10.634 2017 LOW: pid 6548 tid 4564: 2: 7:72954904: Response sent - evaluateRisk

 

Taking this as my trasnactions would give me a total transaction time of 10:37:10.634 - 10:37:10.415 which is: 219 milliseconds.

[Awijit Singh]

Hi Francoisf, Yes I enabled TRACE on the riskfort log but it is not necessary. Yes the TRACE and DETAIL will have an impact. 

 

Thanks

Awijit

[Awijit Singh]

Hi Francoisf, Please mark the answer as correct if it helped.

 

Thanks

Awijit