How to analyze the delays in interaction with the Arcot State Manager given a TokenID ?
search cancel

How to analyze the delays in interaction with the Arcot State Manager given a TokenID ?

book

Article ID: 10807

calendar_today

Updated On:

Products

CA Advanced Authentication CA Strong Authentication CA Risk Authentication

Issue/Introduction

This document will help in troubleshooting interaction with the Arcot StateManager.

a.  Determine if Arcot Statemanager contributed to the delay Requests to the StateManager are at times being delayed or the issue is at the network level.

    b.  Determine if the issue is user specific or environment specific (Load Balancer configuration etc.)

c.  Determine if the issue is a load issue and purely looks like an intermittent network issue. Please test in your lower environment removing any Loadbalancer to eliminate configuration / routing issues.

 Some log analysis hints and background

1.  TokenID in the logs should be used to differentiate requests distinctly. AFM and SHIM should not be confused when investigating for a specific timestamp, so using TokenID helps.  Also, StateManager proactive clean up should not be confused, CA Statemanager deletes idle token periodically (clean up interval configured via arcotafm.properties)

    2.  Adapter SHIM connects to State Manager for the following operations:

a. Creating a new token

b. Reading an existing token

c. Updating a token

d. Deleting a token

    3. AFM connects to the State Manager for Reading of the token mainly.

Environment

Release : 9.1.x

Component :

CA Strong Authentication

CA Risk Risk Authentication

Resolution

**** Any user specific URLs and info has been masked in this document for privacy reasons ****************

1.  Count the transactions that completed successfully with Response code = 200 as opposed to once that failed.

Delete Token

Thu Aug 24 20:04:46.888 2017 INFO:    pid 2136 tid 2652: 0 Connected to State Manager

Thu Aug 24 20:04:46.888 2017 LOW:     pid 2136 tid 2652: 0 Delete command posted successfully to State Manager [20170825000434.475.7e7fd6a6]

Thu Aug 24 20:04:58.588 2017 LOW:     pid 2136 tid 2652: 0 Response code = 200 [20170825000434.475.7e7fd6a6]

 

2. In some cases the delay like 11 second below in getting the request to the Statemanager is the root cause.

Thu Aug 24 20:04:35.624 2017 INFO:    pid 2136 tid 2652: 0 Connected to State Manager

Thu Aug 24 20:04:46.685 2017 LOW:     pid 2136 tid 2652: 0 HTTP response code (200)

Thu Aug 24 20:04:46.685 2017 LOW:     pid 2136 tid 2652: 0 Token retrieved successfully

 

Read Token

Now if we try to examine the above slow transaction done at 20:04:35:624 on Aug 24th

As per SHIM logs below, the request is to READ  the token (7e7fd6a690c1c5b2d3a9539d4976ff74ead48df2)

 

Thu Aug 24 20:04:35.609 2017 LOW:     pid 2136 tid 2652: 0 Start ShimToken::readToken

Thu Aug 24 20:04:35.609 2017 LOW:     pid 2136 tid 2652: 0 Read URL is
http://<host name>:<port number>/arcotsm/servlet/tokens/7e7fd6a690c1c5b2d3a9539d4976ff74ead48df2

Thu Aug 24 20:04:35.609 2017 LOW:     pid 2136 tid 2652: 0 Read connection created...

Thu Aug 24 20:04:35.609 2017 LOW:     pid 2136 tid 2652: 0 Query string : TokenId=7e7fd6a690c1c5b2d3a9539d4976ff74ead48df2

Thu Aug 24 20:04:35.609 2017 INFO:    pid 2136 tid 2652: 0 Configured value for TokenServerRetries: [3]

Thu Aug 24 20:04:35.624 2017 INFO:    pid 2136 tid 2652: 0 Connected to State Manager

 

The request sent by SHIM is received by State Manager 11 seconds later:

2017-08-24 20:04:46,945 [ajp-apr-8009-exec-10] DEBUG server.tsmimpl.iBatisTSMImpl(125)  -> Asked to read token: 7e7fd6a690c1c5b2d3a9539d4976ff74ead48df2

2017-08-24 20:04:46,945 [ajp-apr-8009-exec-10] DEBUG server.tsmimpl.iBatisTSMImpl(61)  -> Asked to read token 7e7fd6a690c1c5b2d3a9539d4976ff74ead48df2, 'include risk' flag: false

 

The request has been received after 11 seconds by State Manager. The request as soon as it is received, is processed and response sent back to SHIM

Thu Aug 24 20:04:46.685 2017 LOW:     pid 2136 tid 2652: 0 HTTP response code (200)

Thu Aug 24 20:04:46.685 2017 LOW:     pid 2136 tid 2652: 0 Token retrieved successfully

 

3. Note that this is not a user specific issue – Processing for userxxx has completed in a timely fashion as well as in a slow fashion.

 

Untimely Completion for a user

Thu Aug 24 20:04:35.624 2017 INFO:    pid 2136 tid 2652: 0 Connected to State Manager

Thu Aug 24 20:04:46.685 2017 LOW:     pid 2136 tid 2652: 0 HTTP response code (200)

Thu Aug 24 20:04:46.685 2017 LOW:     pid 2136 tid 2652: 0 Token retrieved successfully

Thu Aug 24 20:04:46.685 2017 INFO:    pid 2136 tid 2652: 0 userID = CN=userxxx,OU=Users,OU=IAM,OU=UAT,DC=XXTEST,DC=XXX

Thu Aug 24 20:04:46.685 2017 INFO:    pid 2136 tid 2652: 0 loginId = userxxx

 

Timely Completion for the same user

Other transactions with same user finish properly

Tue Aug 22 16:58:30.897 2017 INFO:    pid 2136 tid 2804: 0 Connected to State Manager

Tue Aug 22 16:58:31.021 2017 LOW:     pid 2136 tid 2804: 0 HTTP response code (200)

Tue Aug 22 16:58:31.021 2017 LOW:     pid 2136 tid 2804: 0 Token retrieved successfully

Tue Aug 22 16:58:31.021 2017 INFO:    pid 2136 tid 2804: 0 userID = CN=userxxx,OU=Users,OU=IAM,OU=UAT,DC=XXTEST,DC=XXX

Tue Aug 22 16:58:31.021 2017 INFO:    pid 2136 tid 2804: 0 loginId = userxxx

 

 

 

 

 

 

Powered by Wolken Software