Debugging OpenAM sessions

par | Nov 2, 2016 | Gestion des Identités, Sécurité, SSO

In this article are displayed various tips and tricks to help and understand how to debugging OpenAM Sessions.

1) Maximum of openAM session reached

When maximum of openAM session is reached an error message SESSION_MAX_LIMIT_REACHED is reached in :

/openam/log/amSSO.error
amSSO.error
2016-10-24 16:18:57" SESSION_MAX_LIMIT_REACHED "Not Available" "cn=dsameuser,ou=DSAME Users,dc=openam,dc=example,dc=com" "cn=dsameuser,ou=DSAME Users,dc=openam,dc=example,dc=com" "Not Available" amSSO.error "Not Available" "Not Available" "Not Available" "Not Available" SESSION-13
"2016-10-24 16:18:57" SESSION_MAX_LIMIT_REACHED "Not Available" "cn=dsameuser,ou=DSAME Users,dc=openam,dc=example,dc=com" "cn=dsameuser,ou=DSAME Users,dc=openam,dc=example,dc=com" "Not Available" amSSO.error "Not Available" "Not Available" "Not Available" "Not Available" SESSION-13
"2016-10-24 16:18:57" SESSION_MAX_LIMIT_REACHED "Not Available" "cn=dsameuser,ou=DSAME Users,dc=openam,dc=example,dc=com" "cn=dsameuser,ou=DSAME Users,dc=openam,dc=example,dc=com" "Not Available" amSSO.error "Not Available" "Not Available" "Not Available" "Not Available" SESSION-13

2) Session Statistics

Sessions statistics are returned in the file
<install-dir>/openam/stats/amMasterSessionTableStats

10/24/2016 04:13:09:000 PM CEST: Thread[SystemTimer,5,ServerService ThreadGroup]
Max sessions in session table Current/Peak:5012/5037
Max active sessions Current/Peak:4961/5000
Session Notifications in Queue Current/Peak:0/0
10/24/2016 04:14:09:000 PM CEST: Thread[SystemTimer,5,ServerService ThreadGroup]
Max sessions in session table Current/Peak:5014/5037

The maximum number of sessions in openAM est given by variable com.iplanet.am.sdk.cache.maxSize.
The default maximum value is 5000 concurrent sessions.
It is also possible to configure this value with the graphical console of amadmin.

Go to Configuration -> Server and Sites -> Default Server Settings -> Session-> Session Limits (Property 'Maximum Sessions')

It is even possible to adjust this setting to a higher value, where some guidance is given below:

21.1.4 Session Settings
https://docs.oracle.com/cd/E19462-01/819-4671/gbaxi/index.html
Maximum Sessions 5000 In production this value can safely be set into the 100,000s. The maximum session limit is really controlled by the maximum size of the JVM heap which must be tuned appropriately to match the expected number of concurrent sessions.
https://docs.oracle.com/cd/E19462-01/819-4673/gfyci/index.html

3) openAM authencation/ Deconnection
OpenAM connection/deconnection are tracked in the file

<install-dir>/openam/log/amAuthentication.access

AUTHENTICATION-100 indicates a successful authentication

"2016-10-10 17:35:35" "Login Success|isNoSession=false" 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" DataStore 531b520fbdff245b01 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 AUTHENTICATION-100

AUTHENTICATION-300 indicates a successful deconnection

"2016-10-10 17:40:16" Logout 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" DataStore d593555aed5b3f7901 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 AUTHENTICATION-300

AUTHENTICATION-201 indicates an authentication failure tracked in /openam/log/amAuthentication.error

4) Session lifecycle
It is also possible to follow session lifecycle of openAM provided in file:

<install-dir>/openam/log/amSSO.access
"2016-10-28 11:31:44" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access a73a93986f87a6fe01 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-2
"2016-10-28 11:31:44" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access a73a93986f87a6fe01 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-6
"2016-10-28 11:32:30" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access e09860f3f79670f301 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-2
"2016-10-28 11:32:30" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access e09860f3f79670f301 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-6
"2016-10-28 11:32:32" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access e81217d90f0d90b401 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-2
"2016-10-28 11:32:32" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access e81217d90f0d90b401 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-6
"2016-10-28 11:33:38" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access 515f117deaabd02201 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-2
"2016-10-28 11:33:38" id=demo 127.0.0.1 "cn=dsameuser,ou=DSAME Users,dc=openam,dc=forgerock,dc=org" id=demo,ou=user,dc=openam,dc=forgerock,dc=org "Not Available" amSSO.access 515f117deaabd02201 dc=openam,dc=forgerock,dc=org INFO 127.0.0.1 SESSION-6

The definition of it is given at:
https://docs.oracle.com/cd/E19681-01/820-3886/ghhth/index.html

Table 10–12 Log Reference Document for SessionLogMessageIDs

SESSION-1: Session is Created, 
User is authenticated.

SESSION-2: Session has idle timedout
User session idle for long time.

SESSION-3:Session has Expired
User session has reached its maximun time limit.

SESSION-4: User has Logged out
User has logged out of the system.

SESSION-5: Session is Reactivated
User session state is active.

SESSION-6: Session is Destroyed
User session is destroyed and cannot be referenced.

SESSION-7:Session's property is changed.
User changed session's unprotected property.

SESSION-8: Session received Unknown Event
Unknown session event

SESSION-9: Attempt to set protected property
Attempt to set protected property

SESSION-10: User's session quota has been exhausted.
Session quota exhausted

SESSION-11: Session database used for session failover and session constraint is not available.
Unable to reach the session database.

SESSION-12: Session database is back online.

SESSION-13: The total number of valid sessions hosted on the OpenSSO server has reached the max limit.
Session max limit reached.

5) Retrieving SSO access token associated with a session
You need to have the debug set to its maximum level.

SSO Token authentication is tracked in

<install-dir>/openam/debug/Authentication

and in (case of a deconnection, end of session)

<install-dir> /openam/debug/Session

The command used to tracked Authentication token is:

grep -P "\t"Principal: Authentication

(This command allows to track the subject with its associated token)

cd <install-dir>/openam/debug/Authentication
grep -P "\t"Principal: Authentication
sid string is.. AQIC5wM2LY4Sfcws4p5wvbTEyOiFrmCc4mYf3zSD1luLn8U.*AAJTSQACMDEAAlNLABM2NTU2ODU2NjAwMzI2MjE3NTEx*
amAuth:10/26/2016 04:24:09:967 AM AWST: Thread[http-nio-18080-exec-4,5,main]
Subject is.. :Subject:
Principal: DataStorePrincipal: demo
Principal: SSOTokenPrincipal: AQIC5wM2LY4Sfcws4p5wvbTEyOiFrmCc4mYf3zSD1luLn8U.*AAJTSQACMDEAAlNLABM2NTU2ODU2NjAwMzI2MjE3NTEx*

amAuth:10/26/2016 04:24:09:967 AM AWST: Thread[http-nio-18080-exec-4,5,main]
LoginState getSession = com.iplanet.dpro.session.service.InternalSession@75f2ff8

Session destruction is tracked in

<install-dir>/openam/debug/Session

The commend to be used is:

grep SSOToken Session
grep AQIC5wM2LY4Sfcw_iMcmIiwElNtEDZK6CTyF0Q16X5yx5Hk.*AAJTSQACMDEAAlNLABM2NTU2ODU2NjAwMzI2MjE3NTEx Session

amSession:10/26/2016 04:29:15:619 AM AWST: Thread[http-nio-18080-exec-1,5,main]
Local destroy for shandle:AQIC5wM2LY4Sfcw_iMcmIiwElNtEDZK6CTyF0Q16X5yx5Hk.*AAJTSQACMDEAAlNLABM2NTU2ODU2NjAwMzI2MjE3NTEx*
amSession:10/26/2016 04:29:15:620 AM AWST: Thread[http-nio-18080-exec-1,5,main]
Running sendEvent, type = 5
amSession:10/26/2016 04:29:15:621 AM AWST: Thread[http-nio-18080-exec-1,5,main]
SESSION NOTIFICATION :

 

janua
Les derniers articles par janua (tout voir)