The following sections describe the logging features available in Access Manager and provide information on how you can use them for troubleshooting problems:
For information about policy tracing, see Understanding Policy Evaluation Traces
in the Novell Access Manager 3.1 SP2 Policy Guide.
Each Access Manager device has configuration options for logging:
Identity Server:
Logging is turned off and must be enabled. When you enable Identity Server logging, you also enable logging for the Embedded Service Providers that are configured to use the Identity Server for authentication. For configuration information, see Configuring Component Logging
in the Novell Access Manager 3.1 SP2 Identity Server Guide.
Embedded Service Providers: Each Access Manager device has an Embedded Service Provider that communicates with the Identity Server. Its log level is controlled by configuring Identity Server logging.
Access Gateway Appliance:
A log notice level of logging is enabled by default. You can change the level from the command line interface. For information, see Access Gateway Appliance Logs
in the Novell Access Manager 3.1 SP2 Access Gateway Guide.
Access Gateway Service:
The Gateway Service logs contain the messages sent between the Gateway Service and the Embedded Service Provider and between the Gateway Service and the Web server. This type of logging is turned off and must be enabled. For information, see Access Gateway Service Logs
in the Novell Access Manager 3.1 SP2 Access Gateway Guide
Access Manager does not have a fixed format for file log entries. However, to facilitate the use of non-interactive stream-oriented editors such as sgrep, sed, awk, and grep and to improve log entry readability, the log entries in the catalina.out files use some standard elements. These entries use the beginning and ending log entry tags and the log entry correlation tags. The data portion of log entries is the most flexible part. A log entry has the following fields:
<amLogEntry> [\n] time-date-stamp [log preamble]: AM#event-code: AMDEVICE#device-id: AMAUTHID#auth-id: AMEVENTID#event-id: [..additional correlating information][\n] [supplementary log entry data and text ... \n] </amLogEntry> [\n]
Most log entries do not use the optional line breaks ([\n]). Notice that the time-date-stamp, the log preamble, the correlation tags, and optional additional correlating information are on the same line so that stream-oriented editors that use only one line (such as grep) can be used to locate log entries that are related. The following entry is a typical entry that is logged when a user has initiated a login sequence.
<amLogEntry> 2009-06-08T21:06:25Z INFO NIDS Application: AM#500105014: AMDEVICEID#9921459858EAAC29: AMAUTHID#BB11C254B7521B5E836D8703826287 AF: Attempting to authenticate user cn=jwilson,o=novell with provided credentials. </amLogEntry>
Table 4-1 Fields in a Log Entry
|
Field |
Description |
|---|---|
|
Beginning, ending tags |
The <amLogEntry> and </amLogEntry> tags mark the beginning and the end of a log entry. These tags allow stream-oriented editors to extract log entries for processing. |
|
Time-date-stamp tag |
The date and time is specified in the W3C profile format of ISO 8061. It has the following fields: year-month-day-T-hour-minutes-seconds-time zone. The Z value for the time zone indicates that the time is specified in UTC. |
|
Log preamble |
This information is optional, and usually consists of a string indicating the logging level (such as warning, informational, or debug) and a string identifying the type of module making the entry. In the example log entry, the preamble has a log level and a module identifier and contains the following strings: INFO NIDS Application: |
|
Correlation tags |
The correlation tags uniquely identify the event, the device that produced the event, and the user who requested the action. The example log entry contains the following correlation tags: AM#500105014: AMDEVICEID#9921459858EAAC29: AMAUTHID#BB11C254B7521B5E836D8703826287AF: For more information, see Understanding the Correlation Tags in the Log Files. |
|
Additional correlation information |
This information is optional, and contains correlation tags and data unique to a specific type of trace. For example, a policy evaluation trace created by the Embedded Service Provider contains the following additional tags:
The example log entry does not contain any additional correlation information. For a log entry that does, see |
|
Supplementary information |
This information is optional, and contains information that is specific to the log entry. It can be as simple as an informational string, such as the string in the example log entry: Attempting to authenticate user cn=jwilson,o=novell with provided credentials. The supplementary information can have a very specific format. For an example and explanation of the policy trace information, see |
There is no fixed field format for log file entries. However, because most requests handled by Access Manager are processed by multiple Access Manager components, there is a mechanism that facilitates the correlation of log entries for a single Access Manager request in the various component log files. A correlation tag has the following general format:
<tag name>#<tag value>:
The <tag name> is a fixed value, defined in the Format column of Table 4-2. It is always terminated by the # character. The <tag value> immediately follows the # character and is always terminated by the : character. The <tag value> is not a fixed value, but a uniquely assigned value to identify an event, a user, or a transaction. Table 4-2 lists the defined correlation tags:
Table 4-2 Correlation Tags
|
Type |
Format |
Description |
|---|---|---|
|
Event code |
AM#<Event-Code>: |
An event number defined in Novell Access Manager 3.1 SP2 Event Codes. This tag is included in all log entries that record an event and in all events that are presented to the user as an informational or error page. |
|
User ID |
AMAUTHID#<ID>: |
An authentication identifier that the Identity Server or the Embedded Service Provider assigns to each authenticated user. This tag is included in all entries that pertain to a request made by an authenticated user. Currently the Identity Server and the Embedded Service Provider (ESP) assign different authentication IDs. When correlating the flow of events between the Identity Server and the ESP for an authentication sequence, you can use the event code of the authentication events and find the artifact that the ESP and the Identity Server exchange. In the catalina.out file of the Identity Server, search for AM#500105018 events. This is the event that sends the artifact to the ESP. Search for a corresponding artifact in the Access Gateway log. Events AM#500105020 and AM#500105021 contain the artifact value. |
|
Device ID |
AMDEVICE#<ID> |
An identifier that uniquely identifies the Access Manager device that is generating the log entry. You can view the identifier that is assigned to each device on the General Logging page in the Administration Console (click > ). The ID begins with a prefix that identifies the type of device such as idp for Identity Server, ag for an Access Gateway, and idp-esp for the Embedded Service Provider of the device. The prefix is followed by a 16-digit hexadecimal number. In log entries, the idp prefix is not recorded. For example, the General Logging page displays idp-AA257DA77ED48DB0 for the ID of the Identity Server, but in the catalina.out file, the value is AMDEVICE#AA257DA77ED48DB0. |
|
Transaction ID |
AMEVENTID#<ID>: |
An identifier assigned to each Access Manager or system administration transaction. Access Manager transactions are actions such as authenticating a user, processing a request for access to a resource, and federating an identity. If a user requests access to multiple resources, each request is given a separate transaction ID. When the Access Gateway evaluates a policy for a protected resource page and the page contains links, the policy is evaluated for each link, and each of these evaluations generates a new transaction ID. System administration transactions are actions such as importing a device, deleting a device, stopping or starting a device, and configuring or modifying the configuration of a device. |
The following scenario illustrates how these tags can be used. A user receives an error page indicating that he or she has been refused access to a protected resource. The error page contains an event code. The user contacts the system administrator and reports the event code contained in the message. The code displayed to the user includes both an event number and an identifier indicating the device detecting the error, for example, 300101023-92E1B234. The 300101023 value is the event number and 92E1B234 is the device identifier. The device identifier is the number assigned to the Access Manager device reporting the error. You can make a textual search of log entries using the tags and values AM#300101023: and AMDEVICEID#92E1B234: to locate candidate log entries of the target Access Manager transaction flow. When the desired log entry is found, the AMEVENTID# tag and value and the AMAUTHID# tag (assuming the user has been authenticated) from the log entry can be used to locate all other log entries pertaining to the user in the context of the transaction.
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 Configuring Component Logging
in the Novell Access Manager 3.1 SP2 Identity Server Guide).
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 are numbered, so that they can be described.
1. <amLogEntry> 2009-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> 2009-06-14T17:14:30Z INFO NIDS Application: AM#500105009: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Executing contract Name/Password - Form. </amLogEntry> 3. <amLogEntry> 2009-06-14T17:14:30Z INFO NIDS Application: AM#500105010: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Contract Name/Password - Form requires additional interaction. </amLogEntry> 4. <amLogEntry> 2009-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> 2009-06-14T17:14:39Z INFO NIDS Application: AM#500105009: AMDEVICEID#9921459858EAAC29: AMAUTHID#F35A3C7AD7F2EEDEB3D17F99EC3F39D1: Executing contract Name/Password - Form. </amLogEntry> 6. <amLogEntry> 2009-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> 2009-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> 2009-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> 2009-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> 2009-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> 2009-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> 2009-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 4-3 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 to 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 |
|
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> 2009-07-31T17:36:39Z INFO NIDS Application: AM#500105016: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Processing login resulting from Service Provider authentication request. </amLogEntry> <amLogEntry> 2009-07-31T17:36:39Z INFO NIDS Application: AM#500105009: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Executing contract Name/Password - Form. </amLogEntry> <amLogEntry> 2009-07-31T17:36:39Z INFO NIDS Application: AM#500105010: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Contract Name/Password - Form requires additional interaction. </amLogEntry> <amLogEntry> 2009-07-31T17:36:49Z INFO NIDS Application: AM#500105016: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Processing login resulting from Service Provider authentication request. </amLogEntry> <amLogEntry> 2009-07-31T17:36:49Z INFO NIDS Application: AM#500105009: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Executing contract Name/Password - Form. </amLogEntry> <amLogEntry> 2009-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> 2009-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> 2009-07-31T17:36:49Z INFO NIDS Application: AM#500105018: AMDEVICEID#AA257DA77ED48DB0: AMAUTHID#83778AE09DCA5A35B57842D754A60D67: Responding to AuthnRequest with artifact AAMoz+rm2jQjDSHjea8U9zm3Td/U2ax0YZCo/qBNool8WkZiTCt7N7Jx </amLogEntry>
<amLogEntry> 2009-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> 2009-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> 2009-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> 2009-07-31T17:35:05Z INFO NIDS Application: AM#500105009: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Executing contract IDP Select. </amLogEntry> <amLogEntry> 2009-07-31T17:35:05Z INFO NIDS Application: AM#500105010: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#C6D119FD93EEBBEBEC50BEB27B9E2832: Contract IDP Select requires additional interaction. </amLogEntry> <amLogEntry> 2009-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> 2009-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 see that these two trace sequences 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.