30.15 Using Log Files for Troubleshooting
The following sections provide information about how to use log files for troubleshooting problems:
30.15.2 Understanding Policy Evaluation Traces
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.)
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 30-9 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 30-4 describes the fields found in an RL trace.
Table 30-4 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 30-5 describes the fields of a Rule Evaluation Result trace.
Table 30-5 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:
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 30-6 describes the fields in a Condition Set trace.
Table 30-6 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 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 30-7 describes the fields in a Condition trace.
Table 30-7 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:
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 , 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 . |
|
<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 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 30-8 describes the fields in a Policy Action trace.
Table 30-8 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 30-9 describes the fields in a Policy Action Completion trace.
Table 30-9 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:
|
|
<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. |
Policy Result Values
The last field in a trace string is the <result> field. Table 30-10 lists the possible values:
Table 30-10 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. |
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 of 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 30-9).
<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.
-
The RL trace indicates that the policy has one rule and that the policy evaluated without error.
-
The RU trace indicates that the rule (RuleID_1181251958207) has one condition and one action and that the rule evaluated without error.
-
The CS trace indicates that the condition set evaluated to False (the user logging in does not match the conditions of the set).
-
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 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 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 ESP log file of 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.
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. Access Gateway injects the information, so the trace for this type of policy is in the ESP log file of 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:
-
In the correlation tags (AM... tags), notice the ID assigned to the authenticated user making the request (AMAUTHID#61D5D5B3FF98156F8E4F2875981D4A6E).
-
After the correlation tags, the trace specifies the ID of the policy (51N4214K-74L1-491L-7190-2M9K04K21393).
-
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.
-
The first PA trace indicates that the uid (called LDAP User Name in the UI) of the Credential Profile has been successfully retrieved.
-
The second PA trace indicates that the password of the Credential Profile has been successfully retrieved.
-
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 Has Not 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.
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 ESP processes the request. Even if Access Gateways are clustered, the policy evaluation request stays with 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 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.
Form Fill Traces
The following sections describe how to enable logging for the 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:
-
Embedded Service Provider (ESP) of Access Gateway evaluates the Form Fill policy and logs entries to its file. ESP sends the messages to the catalina.out fileof Access Gateway. To enable ESP logging, see Section 21.6, Turning on Logging for Policy Evaluation.
-
The proxy service of Access Gateway reports on the process of finding the form data and filling it in.
For Access Gateway Appliance, see the /var/log/novell-apache2/soapmessages file.
You can configure a custom filter and file to log Form Fill entries. For the filter, enable the events in the section.
Sample Form and Policy Used for the Trace
Figure 30-10 illustrates the simple form that was used for the trace.
Figure 30-10 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 Form_Fill. 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 30-11 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 Form_Fill policy in the Embedded Service Provider trace, you can use the following strings to find the entries:
-
The name of the Form Fill policy: Form_Fill
-
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 an 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~Form_Fill~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=(Form_Fill),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>
-
The first log entry is the request to evaluate the policy. If this entry does not’ occur, ensure that the Form Fill policy is enabled for the protected resource.
-
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.
-
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 Access Gateway log, you can use the following strings to find the entries:
-
The name of the Form Fill policy: Form_Fill
-
The name of the form: mylogin
-
The names of the fill option fields: username, password, title
The sample trace is from the error_log file of a Access Gateway Appliance. Some of the lines are very long, and extra white space has been added to make them easier to read.
Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#40: FF:fillSilent: mastercdnForm_Fill3310 Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#40: FF:Filling: username Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#40: FF:Filling: password Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#40: FF:Filling: title Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#40: FF: No Match <formNum> Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#40: FF:fillInteractive FormFill Policy :mastercdnForm_Fill3310 Inject JavaScript Policy: mastercdnForm_Fill3510 Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#42: FF:fillSilent: mastercdnForm_Fill3310, referer: http://www.ag1.com/identity/forms/simple.html Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#42: FF:Not Found: <form>, referer: http://www.ag1.com/identity/forms/simple.html Sep 9 17:05:08 nam40-mag1 httpd[16354]: [warn] AMEVENTID#42: FF:no <Form pol:mastercdnForm_Fill3310, referer: http://www.ag1.com/identity/forms/simple.html
On Access Gateway Appliance, you can get more detailed information about the process that was used to fill the form when you turn on logging to the soapmessages file.