42.2 Understanding Log Format

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> 2007-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 42-2 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 Section 42.2.1, 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:

  • NXPESID#value

  • POLICYID#value

The example log entry does not contain any additional correlation information. For a log entry that does, see Section 39.2.4, Identity Injection Traces.

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 Section 39.2, Understanding Policy Evaluation Traces.

42.2.1 Understanding the Correlation Tags in the Log Files

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 defined 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 42-3. It is always terminated by the # character. The <tag value> begins immediately following 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 42-3 lists the defined correlation tags:

Table 42-3 Correlation Tags

Type

Format

Description

Event code

AM#<Event-Code>:

An event number defined in 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 Access Gateways > Auditing > General Logging). 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 such actions 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 such actions as importing a device, deleting a device, stopping or starting a device, and configuring or modifying the configuration of a device.

42.2.2 Sample Scenario

The following scenario illustrates how these tags can be used. A user receives an error page indicating 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.