An authentication trace is logged to the catalina.out file of the Identity Server that authenticates the user. If the Access Gateway initiates the authentication because of a user request to a protected resource, the embedded service provider log file of the Access Gateway also contains entries for the authentication sequence. Identity Server logging must be enabled to produce authentication traces (see Section 32.2, Configuring Identity Server Logging).
This section describes the following types of authentication traces:
The following trace is an example of a user logging directly into the Identity Server to access the End User Portal. The log entries have been modified to add numbers, so that they can be described.
1. <amLogEntry> 2007-06-14T17:14:30Z INFO NIDS Application: AM#500105015: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Processing login request with TARGET = http://10.10.15.19:8080/nidp/app, saved TARGET = . </amLogEntry> 2. <amLogEntry> 2007-06-14T17:14:30Z INFO NIDS Application: AM#500105009: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Executing contract Name/Password - Form. </amLogEntry> 3. <amLogEntry> 2007-06-14T17:14:30Z INFO NIDS Application: AM#500105010: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Contract Name/Password - Form requires additional interaction. </amLogEntry> 4. <amLogEntry> 2007-06-14T17:14:39Z INFO NIDS Application: AM#500105015: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Processing login request with TARGET = http://10.10.15.19:8080/nidp/app, saved TARGET = http://10.10.15.19:8080/nidp/app. </amLogEntry> 5. <amLogEntry> 2007-06-14T17:14:39Z INFO NIDS Application: AM#500105009: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Executing contract Name/Password - Form. </amLogEntry> 6. <amLogEntry> 2007-06-14T17:14:39Z INFO NIDS Application: AM#500105014: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Attempting to authenticate user cn=bcf,o=novell with provided credentials. </amLogEntry> 7. <amLogEntry> 2007-06-14T17:14:39Z WARNING NIDS Application: Event Id: 3014666, Target: cn=bcf,o=novell, Sub-Target: F35A3C7AD7F2EEDEB3D17F99EC3F39D1, Note 1: Local, Note 2: This Identity Provider, Note 3: name/password/uri, Numeric 1: 0 </amLogEntry> 8. <amLogEntry> 2007-06-14T17:14:39Z WARNING NIDS Application: Event Id: 3015456, Note 1: F35A3C7AD7F2EEDEB3D17F99EC3F39D1, Note 2: Manager, Note 3: Document=(ou=xpemlPEP,ou=mastercdn,ou=Content PublisherContainer,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(Manager),Rule=(1::RuleID_1181251958207),Action=(AddRole::ActionID_1181252224665), Numeric 1: 0 </amLogEntry> 9. <amLogEntry> 2007-06-14T17:14:39Z WARNING NIDS Application: Event Id: 3015456, Note 1: F35A3C7AD7F2EEDEB3D17F99EC3F39D1, Note 2: authenticated, Note 3: system-generated-action, Numeric 1: 0 </amLogEntry> 10. <amLogEntry> 2007-06-14T17:14:39Z INFO NIDS Application: AM#500199050: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: IDP RolesPep.evaluate(), policy trace: ~~RL~1~~~~Rule Count: 1~~Success(67) ~~RU~RuleID_1181251958207~Manager~DNF~~1:1~~Success(67) ~~CS~1~~ANDs~~1~~True(69) ~~CO~1~LdapGroup(6645):no-param:hidden-value:~ldap-group-is-member-of~SelectedLdapGroup(66455):hidden-param:hidden-value:~~~True(69) ~~PA~ActionID_1181252224665~~AddRole~Manager~~~Success(0) ~~PC~ActionID_1181252224665~~Document=(ou=xpemlPEP,ou=mastercdn, ou=ContentPublisherContainer,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(Manager),Rule=(1::RuleID_1181251958207),Action=(AddRole::ActionID_1181252224665)~AdditionalRole(6601):unknown():Manager:~~~Success(0) </amLogEntry> 11. <amLogEntry> 2007-06-14T17:14:39Z INFO NIDS Application: AM#500105013: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Authenticated user cn=bcf,o=novell in User Store Local Directory with roles Manager,authenticated. </amLogEntry> 12. <amLogEntry> 2007-06-14T17:14:39Z INFO NIDS Application: AM#500105017: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: nLogin succeeded, redirecting to http://10.10.15.19:8080/nidp/app. </amLogEntry>
Table 42-4 Log Entry Descriptions for an Authentication Trace from an Identity Server
|
Entry |
Description |
|---|---|
|
1 |
Indicates that a login request is in process. This is the first entry for a login request. The requester, even though login has not been successful, is assigned an authentication ID. You can use this ID to find the log entries related to this user. The entry also specifies the URL of the requested resource, in this case the /nidp/app resource called the End User Portal. The saved TARGET message does not contain a value, so this step will be repeated. |
|
2 |
Specifies the contract that is being used to perform the login. |
|
3 |
Indicates that the contract requires interaction with the user. |
|
4 |
Indicates that the a login request is in process. The saved TARGET message contains a value, so the required information has been gathered to start the authentication request. The AM# correlation tag is AM#500105015, which is the same value as the first log entry. |
|
5 |
Indicates that an exchange is occurring between the client and the Identity Server to obtain the required credentials. Each contract requires a different exchange. The AM# correlation tag is AM#500105009, which is the same value as the second log entry. |
|
6 |
Provides the DN of the user attempting the log in and indicates that the user’s credentials are being sent to the LDAP server for verification. |
|
7 |
Provides information about an auditing event. If you have not enabled auditing or you have not selected the login events, this entry does not appear in your log file. This event contains information about who is logging in and the contract that is being used. |
|
8 |
Provides information about an auditing event. If you have not enabled auditing or you have not selected the login events, this entry does not appear in your log file. This event contains information about the Manager policy that is evaluated during login. |
|
9 |
Provides information about an auditing event. If you have not enabled auditing or you have not selected the login events, this entry does not appear in your log file. |
|
10 |
Contains the entry for processing a Role policy. When a user logs in, all Role policies are evaluated and the user is assigned any roles that the user has the qualifications for. For more information, see Section 39.2, Understanding Policy Evaluation Traces. |
|
11 |
Contains a summary of who logged in from which user store and the names of the Role policies that successfully assigned roles to the user. |
|
12 |
Contains the final results of the login, with the URL that the request is redirected to. |
When a protected resource is configured to require authentication, both the Identity Server and the embedded service provider of the Access Gateway (or J2EE Agent) generate log entries for the process. The following sections explain how to correlate the entries from the logs.
<amLogEntry> 2007-07-31T17:36:39Z INFO NIDS Application: AM#500105016: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Processing login resulting from Service Provider authentication request. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:39Z INFO NIDS Application: AM#500105009: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Executing contract Name/Password - Form. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:39Z INFO NIDS Application: AM#500105010: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Contract Name/Password - Form requires additional interaction. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:49Z INFO NIDS Application: AM#500105016: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Processing login resulting from Service Provider authentication request. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:49Z INFO NIDS Application: AM#500105009: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Executing contract Name/Password - Form. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:49Z INFO NIDS Application: AM#500105014: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Attempting to authenticate user cn=admin,o=novell with provided credentials. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:49Z INFO NIDS Application: AM#500105012: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Authenticated user cn=admin,o=novell in User Store Internal with no roles. </amLogEntry>
<amLogEntry> 2007-07-31T17:36:49Z INFO NIDS Application: AM#500105018: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Responding to AuthnRequest with artifact AAMoz+rm2jQjDSHjea8U9zm3Td/U2ax0YZCo/qBNool8WkZiTCt7N7Jx </amLogEntry>
<amLogEntry> 2007-07-31T17:36:49Z INFO NIDS Application: AM#500105019: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#C2D8D52704918AF2D5D62F6EDC2FFAC6: Sending AuthnResponse in response to artifact AAMoz+rm2jQjDSHjea8U9zm3Td/U2ax0YZCo/qBNool8WkZiTCt7N7Jx </amLogEntry>
<amLogEntry> 2007-07-31T17:35:05Z INFO NIDS Application: AM#500105005: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Processing proxy request for login using contract name/password/uri and return url http://jwilson.provo.novell.com/ </amLogEntry> <amLogEntry> 2007-07-31T17:35:05Z INFO NIDS Application: AM#500105015: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Processing login request with TARGET = http://jwilson.provo.novell.com/, saved TARGET = . </amLogEntry> <amLogEntry> 2007-07-31T17:35:05Z INFO NIDS Application: AM#500105009: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Executing contract IDP Select. </amLogEntry> <amLogEntry> 2007-07-31T17:35:05Z INFO NIDS Application: AM#500105010: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Contract IDP Select requires additional interaction. </amLogEntry> <amLogEntry> 2007-07-31T17:35:15Z INFO NIDS Application: AM#500105020: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Received and processing artifact from IDP - AAMoz+rm2jQjDSHjea8U9zm3Td/U2ax0YZCo/qBNool8WkZiTCt7N7Jx </amLogEntry> <amLogEntry> 2007-07-31T17:35:15Z INFO NIDS Application: AM#500105021: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Sending artifact AAMoz+rm2jQjDSHjea8U9zm3Td/U2ax0YZCo/qBNool8WkZiTCt7N7Jx to URL http://jwilson1.provo.novell.com:8080/nidp/idff/soap at IDP </amLogEntry>
You can tell that these two trace sequence are for the same authentication request because the artifact (AAMoz+rm2jQjDSHjea8U9zm3Td/U2ax0YZCo/qBNool8WkZiTCt7N7Jx) that is exchanged is the same. You can use the AMAUTHID in each file to search for other requests that this user has made.
To associate a distinguished name with the AMAUTHID, use the catalina.out file of the Identity Server. Event AM#500105014 contains the DN of the user.