6.2 Understanding Policy Evaluation Traces

6.2.1 Format

A policy log entry starts with the standard log entry elements: <amLogEntry> followed by the correlation tags. (For information about correlation tags, see Understanding the Correlation Tags in the Log Files in the Novell Access Manager 3.1 SP2 Administration Console Guide.) The following log entry is a trace of an evaluation of a Role policy:

<amLogEntry> 2009-06-07T21:40:25Z INFO NIDS Application: AM#500199050: AMDEVICEID#9921459858EAAC29: AMAUTHID#503EFFA4BC21ACA307796EC7D96E5532: IDP RolesPep.evaluate(), policy trace:
   ~~RL~0~~~~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>

The Role policy evaluated in this entry has the following definition:

Figure 6-1 Manager Policy Definition

The following sections use this policy and its trace to explain the information contained within each line of a policy trace. The policy trace part of the entry starts with a policy trace:, which is followed by one or more of the following types:

Elements within a type are separated from each other with the tilde (~) character. If an element does not have a value, no value is inserted, which results in two or more tildes between values. Two tildes means one element didn’t have a value, three tildes means that two elements didn’t have values, and so forth.

Rule List Evaluation Result

An RL trace has the following fields:

~<RuleListID>~~~~<RuleCount>~~<Result>

A RL trace looks similar to the following:

~~RL~1~~~~Rule Count: 1~~Success(67)

Table 6-1 describes the fields found in an RL trace.

Table 6-1 Fields in a Rule List Trace

Element

Description

<RuleListID>

The identifier assigned to the rule list.

In the sample RL trace, this is 1.

<RuleCount>

The number of rules defined for the policy.

In the sample RL trace, this is Rule Count: 1, indicating that there is one rule in the policy.

<Result>

A string followed by a number that specifies the result of the evaluation. See Policy Result Values.

In the sample RL trace, this is Success(67), indicating success.

Rule Evaluation Result

An RU trace has the following fields:

~<RuleID>~<ParentPolicyName>~<ConditionSetJoinType>~~<ConditionSetCount:
ActionCount>~~<Result>

An RU trace looks similar to the following:

~~RU~RuleID_1181251958207~Manager~DNF~~1:1~~Success(67)

Table 6-2 describes the fields of a Rule Evaluation Result trace.

Table 6-2 Fields in a Rule Evaluation Result Trace

Element

Description

<RuleID>

The identifier assigned to the rule.

In this sample RU trace, this element is set to RuleID_1181251958207.

<ParentPolicyName>

The name of the parent policy to which the rule is assigned.

In this sample RU trace, this element is set to Manager.

<ConditionSetJoinType>

The type of joining that occurs between conditions and condition sets. It is set to one of the following:

  • CNF: Indicates that sets are ANDed and conditions within a condition group are ORed.

  • DNF: Indicates that sets are ORed and conditions within a condition group are ANDed.

In the sample RU trace, this element is set to DNF.

<ConditionSetCount:ActionCount>

The number of condition sets and actions defined for this rule.

In the sample RU trace, this is 1:1, for one condition set and one action.

<Result>

A string followed by a number that specifies the result of the evaluation. See Policy Result Values.

In the sample RU trace, this is Success(67), indicating that the rule was successfully evaluated.

Condition Set Evaluation Result

A CS trace has the following fields

~<ConditionSetID>~<JoinType>~<NOT>~<ConditionCount>~~<Result>

A CS trace looks similar to the following:

~~CS~1~~ANDs~~1~~True(69)

Table 6-3 describes the fields in a Condition Set trace.

Table 6-3 Fields in a Condition Set Trace

Element

Description

<ConditionSetID>

The identifier assigned to the condition set. Rules can have multiple condition sets.

In this sample CS trace, this is 1, for the first and only condition set defined for the rule.

<JoinType>

Specifies how the condition results are combined, if there are multiple condition sets. Possible values include ANDs and ORs.

In this sample CS trace, this is ANDs.

<NOT>

The string NOT if the result was negated prior to reporting; otherwise the field has no value. This is the If Not option when creating a condition group.

In the sample CS trace, the condition group was not negated, therefore the field is not present.

<ConditionCount>

The number of conditions defined in the condition group.

In the sample CS trace, this element has the value of 1.

<Result>

A string followed by a number that specifies the result of the evaluation. See Policy Result Values.

In the sample CS trace, this is True (69), indicating that the condition evaluated to True.

Condition Evaluation Result

A CO trace has the following fields:

~<ConditionID>~<LHSOperand>~<Operator>~<RHSOperand>~<NOT>~<Result>[~<ResultOnError>]

A CO trace looks similar to the following:

~~CO~1~LdapGroup(6645):no-param:hidden-value:~ldap-group-is-member-of~SelectedLdapGroup(66455):hidden-param:hidden-value:~~~True(69)

Table 6-4 describes the fields in a Condition trace.

Table 6-4 Fields in a Condition Trace

Element

Description

<ConditionID>

The identifier assigned to the conditions in the condition group. The first condition is assigned 1.

In the sample CO trace, this is 1.

<LHSOperand>

The enumerative value and parameter list of the left operand. It is the first value specified for the comparison and has the following format:

<Condition Name(Data ID)>: <Parameter> : <Value>

The Condition Name is the string assigned to the condition type specified in the policy. The Data ID is a numerical value assigned to the condition type.

<Parameter> contains one of the following strings:

  • no-param when no parameters are specified for the operand, followed by a colon, followed by one of the following: the value, no-value, or hidden-value when the value contains sensitive information.

  • hidden-param followed by a colon, and then hidden-value. This string is used when both the parameter and its value contain sensitive information.

In the sample CO trace, this is LdapGroup(6645):no-param:hidden-value. LdapGroup is the string for the LDAP Group condition. The policy specified [Current], so no parameters were specified. The groups that the user belongs to are considered sensitive data, so the log file displays hidden-value for the names of the groups.

<Operator>

The display name of the comparison operator.

In the sample CO trace, this is ldap-group-is-member-of. In the policy, this is displayed as LDAP Group: Is Member of.

<RHSOperand>

The enumerative value and parameter list of the right operand. It is the second value specified for the comparison and has the same format as the <LHSOperand>.

In the sample CO trace, this is SelectedLdapGroup(66455):hidden-param:hidden-value. The actual policy specifies LDAP Group as the parameter, and the value is the DN of the group.

<NOT>

The string NOT if the result was negated prior to reporting; otherwise the field has no value. This is the If Not option when creating a condition.

In the sample CO trace, this condition result was not negated, therefore the field is represented by a tilde.

<Result>

A string followed by a number that specifies the result of the comparison. See Policy Result Values.

In the sample CO trace, this is True (69), indicating that the condition evaluated to True—the user is a member of the specified LDAP group.

<ResultOnError>

A string describing the error that occurred. This is an optional field that only appears when the condition evaluation results in an error.

The sample CO trace did not result in an error, so it has no string.

Policy Action Initiation

A PA trace has the following fields

~<ActionID>~<TraceString1>~<TraceString2>~<TraceString3>~<Result>

A PA trace looks similar to the following:

~~PA~ActionID_1181252224665~~AddRole~Manager~~~Success(0)

Table 6-5 describes the fields in a Policy Action trace.

Table 6-5 Fields in a Policy Action Trace

Element

Description

<ActionID>

The identifier assigned to the action.

In the sample PA trace, this is ActionID_1181252224665.

<TraceString1>

The message specified with the action.

In the sample PA trace, this is AddRole.

<TraceString2>

The second part of the specified message.

In the sample PA trace, this is Manager.

<TraceString3>

The third part of the specified message.

In the sample PA trace, this field has no value and is not present.

<Result>

A string followed by a number that specifies the result of the assigning the action. See Policy Result Values.

In the sample PA trace, this is Success(0), which indicates that the action of assigning the Manager role to the user was successful.

Policy Action Completion

A PC trace has the following fields

~<ActionID>~<ActionName>~<ActionParmeters>~~~<Result>[~<ActionError>]

A PC trace looks similar to the following:

~~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)

Table 6-6 describes the fields in a Policy Action Completion trace.

Table 6-6 Fields in a Policy Action Completion Trace

Element

Description

<ActionID>

The ID assigned to the action.

In the sample PC trace, this is ActionID_1181252224665.

<ActionName>

The fully distinguished name of the action.

In the sample PC trace, the action has the following parts in its name:

  • 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)

<ActionParmeters>

A list of the action parameters passed to the action handler.

In this sample PC trace, the Role policy has an action and a parameter. The value of this element is AdditionalRole(6601):unknown(): Manager:

<Result>

A string followed by a number that specifies the result. See Policy Result Values.

In the sample PC trace, this is Success(0)and indicates success.

<ActionError>

A string describing the error that occurred when invoking the action. This is an optional field that only appears when the Result field contains an error code.

The sample PC trace did not result in an error, so it has no string.

6.2.2 Policy Result Values

The last field in a trace string is the <result> field. Table 6-7 lists the possible values:

Table 6-7 Result Values from Policy Traces

Value

Name

Description

0

Success

The policy evaluation was successful.

1

Error: No memory

The system is out of memory.

2

Error: Bad data

The data sent for evaluation is invalid.

3

Error: Configuration initialization

An error was detected during the policy configuration processing.

4

Error: General failure

An error was detected during policy processing.

5

Pending

The policy processing is in progress.

64

Permit

The rule produced a Permit action.

65

Deny

The rule produced a Deny action.

66

Obligation

The rule triggered an obligation, indicating that additional processing is required. Identity Injection policies trigger obligations.

67

No action

The rule did not initiate any action.

68

Condition false

The condition evaluated to False.

69

Condition true

The condition evaluated to True.

70

Condition unknown

Condition input was not available, so the results are unknown.

71

Cancel

The current operation has been canceled.

72

Error: Interface unavailable

The current operation is unavailable.

73

Error: Data unavailable

The data required for evaluation was unavailable.

74

Error: Illegal state

Processing error; report it to Novell® Support.

6.2.3 Role Assignment Traces

The following sections walk you through a few sample role traces. When you understand these traces, you should be able to understand any role trace.

When the User Is Assigned Roles

Roles are assigned at authentication, so this type of trace is found in the catalina.out file (Linux) or the stdout.log file (Windows) of the Identity Server. This is a trace of a user who does not match the requirements to be assigned the Manager Role (for a definition of this Role policy, see Figure 6-1). 

<amLogEntry> 2009-06-11T15:38:38Z INFO NIDS Application: AM#500199050: AMDEVICEID#9921459858EAAC29: AMAUTHID#0CE611AAE4D0301F26DD4865476BDA1 4: IDP RolesPep.evaluate(), policy trace:
   ~~RL~0~~~~Rule Count: 1~~Success(67)
   ~~RU~RuleID_1181251958207~Manager~DNF~~1:1~~Success(67)
   ~~CS~1~~ANDs~~1~~False(68)
   ~~CO~1~LdapGroup(6645):no-param:hidden-value:~ldap-group-is-member-of~SelectedLdapGroup(66455):hidden-param:hidden-value:~~~False(68)
</amLogEntry>

This trace describes the following about the policy.

  1. The RL trace indicates that the policy has one rule and that the policy evaluated without error.

  2. The RU trace indicates that the rule (RuleID_1181251958207) has one condition and one action and that the rule evaluated without error.

  3. The CS trace indicates that the condition set evaluated to False (the user logging in does not match the conditions of the set).

  4. The CO trace indicates that the condition evaluated to False (the user logging in does not match the condition).

When you are troubleshooting why a user is not granted access to a resource that uses a role in its Authentication policy, the first step should be to look at the Identity Server file and determine whether the user was assigned the role. In this trace, you can see that the user was not assigned the role. To fix this problem, you can either change the conditions of the Role policy to match the user or change the user’s information so that the user matches the existing condition in the Role policy.

When the Role Policy Is Not Enabled

Sometimes a Role policy is created, but the Role policy is not enabled for the Identity Server. When this happens, the trace looks similar to the following:

<amLogEntry> 2009-06-11T16:06:03Z INFO NIDS Application: AM#500199050: AMDEVICEID#9921459858EAAC29: AMAUTHID#FDE680ABE320B682038947EA5F59D6B F: IDP RolesPep.evaluate(), policy trace:
   ~~RL~0~~~~Rule Count: 0~~Success(67)
 </amLogEntry>

When you see Role policy traces that contain only the RL trace line, you need to enable the Role policy.

When an Authorization Policy Uses a Role

When a user requests access to a resource that has an Authorization policy that uses a role, the user is checked for the role assignment. The trace of this evaluation is in the Embedded Service Provider log file of the Access Gateway that is processing the request. Such a trace looks similar to the following: 

<amLogEntry> 2009-07-13T22:13:29Z INFO NIDS Application: AM#501102050: AMDEVICEID#esp-51A474B83BFDDF4F: AMAUTHID#4538DB6F6E2A237FDE674F0C6E1 6DCEC: PolicyID#N748097P-3507-3KP7-4241-410PN4152094: NXPESID#1718: AGAuthorization Policy Trace:
   ~~RL~1~~~~Rule Count: 1~~Success(0)
   ~~RU~RuleID_1182876316974~Allow_Sales~DNF~~1:1~~Success(0)
   ~~CS~1~~ANDs~NOT~1~~True(69)
   ~~CO~1~CurrentRoles(6660):no-param:authenticated~com.novell.nxpe. condition.NxpeOperator@string-substring~SelectedRole(6661):hidden-param:hidden-value:~~~False(68)
   ~~PA~1~~Deny Access Messasge~Sorry, you must work in sales today.~~~Success(0)
   ~~PC~1~~Document=(ou=xpemlPEP,ou=mastercdn,ou=ContentPublisherCon tainer,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(Allow_Sales),Rule=(1::RuleID_1182876316974),Action=(Deny::1)~~~~Success(0)
</amLogEntry>

This trace is for a Deny policy that denies access if the user has not been assigned the Sales role. The CO line indicates that the condition is looking for a role and that the user did not match the condition.

The CS line indicates that the condition is a negative condition, meaning that the user matches the condition set when the user does not match the condition. This is the case for this user, so the condition set evaluates to True, and the action is then applied.

The PA line describes the action that was applied.

6.2.4 Identity Injection Traces

The following traces explain what to look for in an Identity Injection policy that injects an authorization header:

When the User Has Authenticated

The following trace is for an Identity Injection policy that successfully inserts an authentication header. The policy inserts LDAP credentials for the user’s name and password. The Access Gateway injects the information, so the trace for this type of policy is in the Embedded Service Provider log file of the Access Gateway.

<amLogEntry> 2009-06-11T19:02:44Z INFO NIDS Application: AM#501103050: AMDEVICEID#esp-534FD0D0E32FE4BD: AMAUTHID#61D5D5B3FF98156F8E4F2875981D 4A6E: PolicyID#51N4214K-74L1-491L-7190-2M9K04K21393: NXPESID#726: AGIdentityInjection Policy Trace:
   ~~RL~0~~~~Rule Count: 1~~Success(67)
   ~~RU~RuleID_1181251426062~basic_auth_ii~DNF~~0:1~~Success(67)
   ~~PA~ActionID_1181251427701~~Inject Auth Header~uid~uid(1): CredentialProfile(7010:):NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22LDAPCredentials~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22UserName~22~5D:~Ok~Success(0)
   ~~PA~ActionID_1181251427701~~Inject Auth Header~password~pwd(1): CredentialProfile(7010:):NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22LDAPCredentials~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22UserPassword~22~5D:~Ok~Success
(0)
   ~~PC~ActionID_1181251427701~~Document=(ou=xpemlPEP,ou=mastercdn, ou=ContentPublisherContainer,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(basic_auth_ii),Rule=(1::RuleID_1181251426062),Action=(InjectAuthHeader::ActionID_1181251427701)~~~~Success(0)
 </amLogEntry>

<amLogEntry> 2009-06-11T19:02:44Z INFO NIDS Application: AM#501101021: AMDEVICEID#esp-534FD0D0E32FE4BD: AMAUTHID#61D5D5B3FF98156F8E4F2875981D 4A6E: PolicyID#51N4214K-74L1-491L-7190-2M9K04K21393: NXPESID#726: Response sent: Status - success </amLogEntry>

Each identity injection policy generates two log entries. The first entry indicates whether the policy could successfully retrieve the information and inject it into the header. The second entry specifies whether the response is successfully sent to the Web server.

This first log entry describes the following about this policy:

  1. In the correlation tags (AM... tags), notice the ID assigned to the authenticated user making the request (AMAUTHID#61D5D5B3FF98156F8E4F2875981D4A6E).

  2. After the correlation tags, the trace specifies the ID of the policy (51N4214K-74L1-491L-7190-2M9K04K21393).

  3. The RU trace indicates that the policy name is basic_auth_ii, that the policy has no conditions, and that the policy has one action rule.

  4. The first PA trace indicates that the uid (called LDAP User Name in the UI) of the Credential Profile has been successfully retrieved.

  5. The second PA trace indicates that the password of the Credential Profile has been successfully retrieved.

  6. The PC trace indicates that these items have been successfully injected into the header.

You can use the user’s ID and the policy ID to find log entry that traces the response to the Web server. The second log entry indicates that the response was successfully sent to the Web server.

When the User Hasn’t Authenticated

If the user has not authenticated and therefore has no authentication credentials, the trace for an Identity Injection policy with an authentication header looks similar to the following:

<amLogEntry> 2009-06-11T20:16:51Z INFO NIDS Application: AM#501103050: AMDEVICEID#esp-534FD0D0E32FE4BD: PolicyID#OL8659PL-0K69-0N0N-0845-5PN113KM3842: NXPESID#2539: AGIdentityInjection Policy Trace:
   ~~RL~0~~~~Rule Count: 1~~Success(67)
   ~~RU~RuleID_1181251426062~basic_auth_ii~DNF~~0:1~~Success(67)
   ~~PA~ActionID_1181251427701~~Inject Auth Header~uid~uid(1): CredentialProfile(7010:):NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22LDAPCredentials~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22UserName~22~5D:~Ok~Success(0)
   ~~PA~ActionID_1181251427701~~Inject Auth Header~password~pwd(1):CredentialProfile(7010:):NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry ~40~40~40~40WSCQSSToken~40~40~40~40~2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22LDAPCredentials~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22UserPassword~22~5D:~Ok~Success(0)
   ~~PC~ActionID_1181251427701~~Document=(ou=xpemlPEP,ou=mastercdn, ou=ContentPublisherContainer,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(basic_auth_ii),Rule=(1::RuleID_1181251426062),Action=(InjectAuthHeader::ActionID_1181251427701)~~~~Success(0)
 </amLogEntry>

<amLogEntry> 2009-06-11T20:16:51Z INFO NIDS Application: AM#501101021: AMDEVICEID#esp-534FD0D0E32FE4BD: PolicyID#OL8659PL-0K69-0N0N-0845-5PN113KM3842: NXPESID#2539: Response sent: Status - success </amLogEntry>

These entries look very similar to the entries for a successful injection of data. This is because injecting NULL data for data that is not available is considered a successful action. The trace displays data unavailable errors only when errors occur retrieving data. The key to determining whether the data was available for injection into an authentication header is to look for the AMAUTHID correlation tag in the log entry. The log entries for the OL8659PL-0K69-0N0N-0845-5PN113KM3842 policy do not contain an AMAUTHID correlation tag, which indicates that the user is not logged in.

6.2.5 Authorization Traces

Authorization policies for a protected resource might require a user to be authenticated before the data required by the policy can be obtained, but Authorization policies can be configured to use data that is available without authentication. The following traces show how the log entries for an Authorization policy trace are slightly different when the user is not authenticated.

For a trace of an Authorization policy that uses a role, see When an Authorization Policy Uses a Role.

When the Protected Resource Requires Authentication

The following is a successful trace of an Authorization policy that requires the user to have the value of Manager in the title attribute. To obtain this data, the user must be authenticated.

The policy contains two rules: a Permit rule if the user has the value of Manager in the title attribute, and a Deny rule that denies all other users. This policy has been assigned to protect an Access Gateway resource.

<amLogEntry> 2009-08-02T15:55:05Z INFO NIDS Application: AM#501101050: AMDEVICEID#esp-2FA73CE1A376FD91: PolicyID#459O8443-N8P5-KO21-68OM-K172P107N4O5: NXPESID#1743: Evaluating policy </amLogEntry>

<amLogEntry> 2009-08-02T15:55:06Z INFO NIDS Application: AM#501102050: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#838976482579AF372C31C4727 4E9CB28: PolicyID#459O8443-N8P5-KO21-68OM-K172P107N4O5: NXPESID#1743: AGAuthorization Policy Trace:
   ~~RL~1~~~~Rule Count: 2~~Success(0)
   ~~RU~RuleID_1186068489688~Title_auth~DNF~~1:1~~Success(0)
   ~~CS~1~~ANDs~~1~~True(69)
   ~~CO~1~LdapAttribute(6647):NEPXurn~3Anovell~3Aldap~3A2006-02~2Fldap~3AUserAttribute~40~40~40~40WSCQLDAPToken~40~40~40~40~2FUserAttribute~5B~40ldap~3AtargetAttribute~3D~22title~22~5D:hidden-value:~com.novell.nxpe.condition.NxpeOperator@string-equals~(0):hidden-param:hidden-value:~~~True(69)
   ~~PA~1~~Permit Access~~~~Success(0)
   ~~PC~1~~Document=(ou=xpemlPEP,ou=mastercdn,ou=ContentPublisher Container,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(Title_auth),Rule=(1::RuleID_1186068489688),Action=(Permit::1)~~~~Success(0)
</amLogEntry>

<amLogEntry> 2009-08-02T15:55:06Z INFO NIDS Application: AM#501101021: AMDEVICEID#esp-2FA73CE1A376FD91: AMAUTHID#838976482579AF372C31C47274E 9CB28: PolicyID#459O8443-N8P5-KO21-68OM-K172P107N4O5: NXPESID#1743: Response sent: Status - success </amLogEntry>

The first log entry is the request to evaluate the policy. The second log entry is the evaluation of the policy. The third log entry is the response that is returned. These three log entries can be tied together by using the following tags:

AMDEVICEID#esp-2FA73CE1A376FD91: When a policy evaluation request is made, the same Embedded Service Provider processes the request. Even if the Access Gateways are clustered, the policy evaluation request stays with the Access Gateway that initiated the request.

PolicyID#459O8443-N8P5-KO21-68OM-K172P107N4O5: Each policy is assigned a unique ID, and this is the ID assigned to the policy called Title_auth in the Administration Console. To search for all log entries for a policy, use the policy ID. To search for log entries that evaluate the policy, use the policy name.

AMAUTHID#838976482579AF372C31C47274E9CB28: The request to evaluate a policy does not contain the ID of the user the request is being made for, but the log entries for the evaluation and for the response status always contain the ID of an authenticated user. If the policy can be evaluated without the user being authenticated, these entries do not contain the ID of the user. This kind of policy might be assigned to a public resource (no authentication required) and use the time of day condition or day of the week condition for its evaluation criteria. See When the Protected Resource Does Not Require Authentication.

When the Protected Resource Does Not Require Authentication

The following trace is for an Authorization policy that uses data that is available without authentication. Authorization policies support a number of these conditions, such as Current Date, Current Day of Week, Current Day of Month, Current Time Of Day, Client IP, and the URL conditions. As long as you do not select to compare what is currently in the HTTP request with a value that requires authentication (such as LDAP attribute), the Authorization policy can be evaluated for an unauthenticated user. The following trace is for a policy with a Current Time of Day condition. The protected resource does not require authentication, so everyone can access the resource if their request comes in between 8:00 am and 5:30 pm, local time.

<amLogEntry> 2009-08-03T16:30:48Z INFO NIDS Application: AM#501101050: AMDEVICEID#esp-2FA73CE1A376FD91: PolicyID#216660PM-429P-O660-N25N-L58L08MN4N5M: NXPESID#4515: Evaluating policy </amLogEntry>

<amLogEntry> 2009-08-03T16:30:48Z INFO NIDS Application: AM#501102050: AMDEVICEID#esp-2FA73CE1A376FD91: PolicyID#216660PM-429P-O660-N25N-L58L08MN4N5M: NXPESID#4515: AGAuthorization Policy Trace:
   ~~RL~1~~~~Rule Count: 2~~Success(0)
   ~~RU~RuleID_1186082720202~time_of_day~DNF~~1:1~~Success(0)
   ~~CS~1~~ANDs~~1~~True(69)
   ~~CO~0~TimeOfDay(1005):::Fri Aug 03 10:30:48 MDT 2007(9:30):~com.novell.nxpe.condition.NxpeOperator@time-in-range~(0)::::~~~True(69)
   ~~PA~1~~Permit Access~~~~Success(0)
   ~~PC~1~~Document=(ou=xpemlPEP,ou=mastercdn,ou=ContentPublisherCon tainer,ou=Partition,ou=PartitionsContainer,ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContentCollectionXMLDoc),Policy=(time_of_day),Rule=(1::RuleID_1186082720202),Action=(Permit::1)~~~~Success(0)
 </amLogEntry>

<amLogEntry> 2009-08-03T16:30:48Z INFO NIDS Application: AM#501101021: AMDEVICEID#esp-2FA73CE1A376FD91: PolicyID#216660PM-429P-O660-N25N-L58L08MN4N5M: NXPESID#4515: Response sent: Status - success </amLogEntry>

The first log entry is the request to evaluate the policy. The second log entry is the evaluation of the policy, and from it you can tell that the user is not authenticated because the AMAUTHID# tag is missing. The third log entry is the response that is returned, and it indicates that a success was returned. The user is allowed access to the resource.

6.2.6 Form Fill Traces

The following sections describe how to enable logging for Form Fill policies, describe the form that was used to create the Form Fill trace, then describe the entries that can be found in the logs:

Enabling Form Fill Logging

Two modules evaluate the Form Fill policy and log entries:

Sample Form and Policy Used for the Trace

Figure 6-2 illustrates the simple form that was used for the trace.

Figure 6-2 Form Used for the Trace

Source HTML for the Form

The name of the form and the fields that need to be filled in by the policy are in bold typeface.

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN"> 
<html> 
<head> 
  <meta http-equiv="Content-type" content="text/html; charset=utf-8"> 
  <title>kelly</title> 
</head> 
<body> 
  <form name="mylogin" action="double.php" method="post" id="mylogin"> 
    <center> 
      <table border="0" cellpadding="4" cellspacing="4" width="570"> 
        <tr> 
          <td width="121" height="285" align="left" valign="top"> 
          </td> 
          <td width="449" height="285" align="center" valign="top"> 
            <p align="center">
              <font size="5">Novell Services Login<br></font>
            </p> 
            <table border="0" width="86%"> 
              <tr> 
                <td width="25%">Username:</td> 
                <td width="75%">
                  <input type="TEXT" name="username">
                </td> 
              </tr> 
              <tr> 
                <td width="25%">Password:</td> 
                <td width="75%">
                  <input type="PASSWORD" name="password" size="30">
                </td> 
              </tr>
              <tr>
                <td width="25%">title:</td>
                <td width="75%">
                  <input type="TEXT" name="title" size="30">
                </td>
              </tr>
            </table>
          </td>
        </tr>

         <tr>
            <td colspan="2" align="center">
             <input type="hidden" name="formNum" value="1">
             <input type="submit" value="Login">
             <input type="reset">
            </td>
          </tr>
        </table> 
      </center>
    </form> 
</body>
</html>

Form Fill Policy

The following Form Fill policy was created for the mylogin form. The policy is called simpleform. You can use the name of the policy to find entries for it in the log files. The policy was assigned to the /identity/forms/simple.html protected resource. Because the URL path identifies a specific file on the Web server, the policy does not require any CGI or page matching criteria.

Figure 6-3 The Form Fill Policy for the mylogin Form

This policy is configured so that the user never sees the form. Even on first login, the form is filled in for authenticated users because the user’s authentication credentials are used for the username and password fields, and the title field value is obtained from the LDAP user store. If the user does not have a value for the title attribute, the user sees the form every time the page is accessed. If you want the value to be saved for these users, you need to change the policy to use a secret store rather than an LDAP attribute.

Embedded Service Provider Trace

When you look for entries for the simpleform policy in the Embedded Service Provider trace, you can use the following strings to find the entries:

  • The name of the Form Fill policy: simpleform

  • The string identifying a Form Fill trace: AGFormFill Policy Trace

  • The policy ID (after you have found it): PolicyID#06OO287L-06LO-KKP4-207M-6971PPM6147L

The following trace is from the catalina.out file of the Embedded Service Provider of a Linux Access Gateway Appliance. The entries have been numbered so that they can be described, and a few extra line breaks and spaces have been added to make the entries easier to read.


1. <amLogEntry> 2009-09-14T00:15:52Z INFO NIDS Application: AM#501101050: AMDEVICEID#esp-917A1174C8A270FC: PolicyID#06OO287L-06LO-KKP4-207M-6971PPM6147L: NXPESID#2663: Evaluating policy </amLogEntry>

2. <amLogEntry> 2009-09-14T00:15:52Z INFO NIDS Application: AM#501104050: AMDEVICEID#esp-917A1174C8A270FC: PolicyID#06OO287L-06LO-KKP4-207M-6971PPM6147L: NXPESID#2663: AGFormFill Policy Trace: 
   ~~RL~1~~~~Rule Count: 1~~Success(67)
   ~~RU~RuleID_1189711482510~simpleform~DNF~~0:1~~Success(67)
   ~~PA~ActionID_1189711485006~~Added Form Selection Group~~~~Success
       (0)
   ~~PA~ActionID_1189711485006~~Added Fill Options Group~~~~Success(0)
   ~~PA~ActionID_1189711485006~~Added Submit Options Group~~~~Success
       (0)
   ~~PC~ActionID_1189711485006~~Document=(ou=xpemlPEP,ou=mastercdn,
     ou=ContentPublisherContainer,ou=Partition,ou=PartitionsContainer,
     ou=VCDN_Root,ou=accessManagerContainer,o=novell:romaContent
     CollectionXMLDoc),Policy=(simpleform),Rule=(1::RuleID_11897114
     82510),Action=(FormFill::ActionID_1189711485006)~~~~Success(0)
 </amLogEntry>

3. <amLogEntry> 2009-09-14T00:15:52Z INFO NIDS Application: AM#501101021: AMDEVICEID#esp-917A1174C8A270FC: PolicyID#06OO287L-06LO-KKP4-207M-6971PPM6147L: NXPESID#2663: Response sent: Status - success </amLogEntry>

  1. The first log entry is the request to evaluate the policy. If this entry doesn’t occur, make sure that the Form Fill policy is enabled for the protected resource.

  2. The second entry is the actual policy trace. For a Form Fill policy, it is fairly basic information about the three types of actions in the policy: matching the form, filling in the field options, and adding the submit options. To determine what information was put in the options, you need to view the proxy service trace.

  3. The third entry indicates the type of response that is returned from the evaluation. In this entry, success is returned.

Proxy Service Trace

When you look for entries in the proxy trace of the Access Gateway log, you can use the following strings to find the entries:

  • The event code of a Form Fill event: AM#504507000

  • The name of the Form Fill policy: simpleform

  • The name of the form: mylogin

  • The names of the fill option fields: username, password, title

The sample trace is from a ics_dyn.log file of a Linux Access Gateway Appliance. Some of the lines are very long, and extra white space has been added to make them easier to read. The first occurrence of an item you can search for is displayed in a bold typeface.


Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: *****************************************************  
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Name : (mastercdnsimpleform3310) 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Type : (FILL)
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: CGI Matching Criteria: ()
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Page Matching Criteria: 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Not Configured. 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Form Number : (-1) 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Form Name: (mylogin)
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Form Id: () 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Login Fail Redirect: ()
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Login Fail Delete Rem: () 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Error Redirect: ()
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Post options (silent = yes), (debug = no), (masked =
  no), (enabled = yes) 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: InsertText: ()
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: JavaScriptHandling: 
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Not configured.
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Fill Option 0 : ( Name=username, Value=NEPXurn~
  3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~
  2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~2Fcp~3ASecrets~
  2Fcp~3ASecret~5Bcp~3AName~3D~22LDAPCredentials~22~5D~2Fcp~3AEntry~
  5Bcp~3AName~3D~22UserName~22~5D, DataConversion=None,
  valType=CREDENTIAL_PROFILE, inputType=TEXT, isDuplicate=false)
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
  AMEVENTID#0: Fill Option 1 : ( Name=password, Value=NEPXurn~
  3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~
  3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~2Fcp~
  3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22LDAPCredentials~22~5D
  ~2Fcp~3AEntry~5Bcp~3AName~3D~22UserPassword~22~5D,
  DataConversion=None, valType=CREDENTIAL_PROFILE, inputType=PASSWORD,
  isDuplicate=false)
Sep 19 09:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0:
   AMEVENTID#0: Fill Option 2 : ( Name=title, Value=NEPXurn~
   3Anovell~3Aldap~3A2006-02~2Fldap~3AUserAttribute~40~40~40~
   40WSCQLDAPToken~40~40~40~40~2FUserAttribute~5B~40ldap~
   3AtargetAttribute~3D~22title~22~5D, DataConversion=None,
   valType=LDAP_ATTRIBUTE, inputType=TEXT, isDuplicate=false)

On the Linux Access Gateway Appliance, you can get more detailed information on the process that was used to fill the form when you turn on logging to the lagsoapmessages file. For more information, see Configuring Logging of SOAP Messages and HTTP Headers in the Novell Access Manager 3.1 SP2 Access Gateway Guide.