A policy log entry starts with the standard log entry elements: <amLogEntry> followed by the correlation tags. (For information about correlation tags, see Section 42.2.1, Understanding the Correlation Tags in the Log Files.) The following log entry is a trace of an evaluation of a Role policy:
<amLogEntry> 2007-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 39-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 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.
A 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 39-1 describes the fields found in a RL trace.
Table 39-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. |
A RU trace has the following fields:
~<RuleID>~<ParentPolicyName>~<ConditionSetJoinType>~~<ConditionSetCount:ActionCount>~~<Result>
A RU trace looks similar to the following:
~~RU~RuleID_1181251958207~Manager~DNF~~1:1~~Success(67)
Table 39-2 describes the fields of a Rule Evaluation Result trace.
Table 39-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:
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. |
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 39-3 describes the fields in a Condition Set trace.
Table 39-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 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. |
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 39-4 describes the fields in a Condition trace.
Table 39-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:
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. |
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 39-5 describes the fields in a Policy Action trace.
Table 39-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) and indicates that the action was successfully assigned to the user. |
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 39-6 describes the fields in a Policy Action Completion trace.
Table 39-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:
|
<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. |
The last field in a trace string is the <result> field. Table 39-7 lists the possible values:
Table 39-7 Result Values from Policy Traces
Roles are assigned at authentication, so this type of trace is found in the catalina.out file 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 39-1).
<amLogEntry> 2007-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 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 catalina.out file of the Identity Server 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.
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> 2007-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 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> 2007-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.
The following traces explain what to look for in an Identity Injection policy that injects an authorization header:
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> 2007-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> 2007-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.
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> 2007-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> 2007-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 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.
The following is a successful trace of an Authorization policy that requires the user to have the value of Manager in an LDAP attribute, title. 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> 2007-08-02T15:55:05Z INFO NIDS Application: AM#501101050: AMDEVICEID#esp-2FA73CE1A376FD91: PolicyID#459O8443-N8P5-KO21-68OM-K172P107N4O5: NXPESID#1743: Evaluating policy </amLogEntry> <amLogEntry> 2007-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> 2007-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 the 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.
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> 2007-08-03T16:30:48Z INFO NIDS Application: AM#501101050: AMDEVICEID#esp-2FA73CE1A376FD91: PolicyID#216660PM-429P-O660-N25N-L58L08MN4N5M: NXPESID#4515: Evaluating policy </amLogEntry> <amLogEntry> 2007-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> 2007-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.
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:
Two modules evaluate the Form Fill policy and log entries:
The embedded service provider of the Access Gateway evaluates the Form Fill policy and logs entries to its file. For the Linux Access Gateway, the embedded service provider sends the messages to the catalina.out file. For the NetWare Access Gateway, the embedded service provider sends the messages to the system console. To enable embedded service provider logging, see Section 39.1, Turning on Logging for Policy Evaluation.
The proxy service of the Access Gateway reports on the process of finding the form data and filling it in. Each platform uses a different method to enable verbose logging of this process.
Linux Access Gateway: For verbose entries on a Form Fill policy, you need to use the SOAP messages logged to the /var/log/lagsoapmessages file. For more information, see Configuring Logging of SOAP Messages and HTTP Headers.
NetWare Access Gateway: On the NetWare® Access Gateway, you can add a command to the startup NCF file that increases the detail generated from a Form Fill event.
Edit the sys:system\ap_start.ncf file, and add the following to the load sso line.
load sso /D<number> L<number>
Replace <number> with a value of 1 to 5, with 5 specifying the most detail.
Table 39-8 describes these options:
Table 39-8 Logging Options
For this setting to take effect, you need to restart the NetWare Access Gateway.
Figure 39-2 illustrates the simple form that was used for the trace.
Figure 39-2 Form Used for the Trace
<!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>
The name of the form and the fields that need to be filled in by the policy are in bold typeface.
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 39-3 The Form Fill Policy for the mylogin Form
This policy is configured so that the user never sees it. 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.
When looking 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. The entries have been number 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> 2007-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> 2007-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> 2007-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 doesn’t occur, make sure 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.
When looking 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. 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 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: ***************************************************** Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Name : (mastercdnsimpleform3310) Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Type : (FILL) Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: CGI Matching Criteria: () Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Page Matching Criteria: Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Not Configured. Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Form Number : (-1) Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Form Name: (mylogin) Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Form Id: () Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Login Fail Redirect: () Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Login Fail Delete Rem: () Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Error Redirect: () Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Post options (silent = yes), (debug = no), (masked = no), (enabled = yes) Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: InsertText: () Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: JavaScriptHandling: Sep 19 08:04:50 jwilson : AM#504507000: AMDEVICEID#ag-: AMAUTHID#0: AMEVENTID#0: Not configured. Sep 19 08: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 08: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 08: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, 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.