Procedure and tip to debug NextLabs SharePoint entitlement policy issues based on architecture

NextLabs’ Entitlement Manager for SharePoint is a content aware Entitlement Management solution that provides the capability to authorize, classify, enforce and audit enterprise resources across Microsoft SharePoint. This solution allows large enterprises to enjoy secure internal/external collaboration while helping them achieve obligatory compliance, protecting data both on and off the SharePoint Environment.

If you are using NextLabs’ Entitlement Manager for SharePoint, you might wonder how to debug if the policy not enforced. Let’s review the NextLabs’ Entitlement Manager for SharePoint architecture so it the debugging procedure will be much clear.

The Entitlement Manager for SharePoint Architecture includes several two parts that are Policy Control Center and Entitlement Manager for SharePoint. Entitlement Manager for SharePoint includes Policy Controller and SharePoint enforcer (Policy Adaptor) two components.

1. The Policy Control Center runs inside J2EE container like Tomcat: Stores policy in a central repository and deploys policy sets to distributed Entitlement Managers for SharePoint across the enterprise.

2.1 Policy Controller runs inside IIS as a Windows Service:  Applies all context information to the events and enforces policy. 

2.2 SharePoint enforcer (Policy Adaptor) deployed as event receivers inside SharePoint and Http module: Detects end-user or system events and send to Policy Control to enforce policy.

 

Now, it's time to have some fun to debug the policy issues. My assumption at this point you have successfully installed Policy Control Center, Policy Controller, and Enforcer. Configured and deployed the policy. Here are the procedures I would recommend to get to the root cause quickly.

I would use policy example to deny one user from one site collection.

1. The first thing is to verify whether we have the correct policy deployed. You can verified the deployed policy from Policy Studio by the following steps. 

• Login to Policy Studio 
• Click “Window” Tab 
• Click “Policy Manager” 
• Click “Deployed” tab 
• Expend “Policies” 
• Select your policy and right click 
• Select “Export” to local xml file 
• Verify file has the correct user component, actions, and portal components like the site URLs

You can also verify which SharePoint servers the policy has been deployed by selecting “Version History”, highlighting the active one, and clicking “SharePoint servers”. The servers that have policy deployed will be displayed as in the following screen shot.

2. The second thing is to verify whether the SharePoint site has NextLabs feature activated and enabled. You can use the following powershell to verify NextLabs features on farm, web application, and web level as in then screen shot. If any of the features are missing, we might have issues. 

# Get farm level NextLabs features
Get-SPFeature -Limit ALL | Where-Object {$_.DisplayName -like "*nextlabs*"}

# Get web application level NextLabs features
Get-SPFeature -WebApplication https://sharepoint.mycompany.com | Where-Object {$_.DisplayName -like "*nextlabs*"}

# Get web level NextLabs features. Please note there is no site level NextLabs feature
Get-SPSite https://sharepoint.mycompany.com | Get-SPWeb -Limit ALL | %{ Get-SPFeature -Web $_ } | Where-Object {$_.DisplayName -like "*nextlabs*"}

 3. Next you should verify whether site collections have been enabled for NextLabs policies.

• Login to SharePoint central administration 
• Click "NextLabs Entitlement Manager"
• Click "Enable or disable policy enforcement"

Your should see the green icon for the web application that indicates policy has been enabled for the web application.

The site collection should be selected so policy can be applied.  

4. The forth thing is to change Policy Controller log level on SharePoint side to display how enforcer intercept the end-user URL and whether any policy applied. You could see NextLabs Control Center Administrator’s Guide for details.

A. Stop the Policy Controller on the host where the reconfiguration is required. This requires the Administrator password.

B. Delete all logs under  C:\Program Files\NextLabs\Policy Controller\logs.

C. Open C:\Program Files\NextLabs\Policy Controller\config\logging.properties and change logging leve and increase log file size.

com.bluejungle.level = FINEST (Note default is SEVERE)

java.util.logging.FileHandler.limit = 5000000 (Note default is 500000) 

D. Restart Policy Controller on the host from servcies

5. Verify logs C:\Program Files\NextLabs\Policy Controller\agentLog\Agent0.log and verify user action. You should see the result like this.

Please check the URL, user, and action (deny/allow). The most common issue is the URL capture is not listed in the policy. Then you have to add this URL to the polciy.

6. If the URL is in the policy but policy not applied to the site, you need to verify whether policy deployed from Policy Control Center to Policy Controller on SharePoint. You could verify the policy file C:\Program Files\NextLabs\Policy Controller\bundle.bin time stamp and content.

Run C:\Program Files\NextLabs\Policy Controller\bin\Decrypt.exe and the policy will be decripted to C:\Program Files\NextLabs\Policy Controller\bundle.out. You could open the file and search whether the site URL included in the policy. If not, you need to modify policy through Policy Studio and try again.

7. If site URL is included in the boundle.bin and policy not enforced, you need to verify whether Controller Enforcer Service is running. Start it if not already.

 

8. If you have tried all the four steps listed above and you still have not identify the issue, you might need to debug the SharePoint enforcer to verify how the policy is executed by enforce. You could modify the file ..NextLabs\SharePoint Enforcer\config\log.config and change defaul log level from "WARN" to "DEBUG".  You need to do IISRESET in order to pick up the changes.

    <appender name="SharePointCELogAppender" type="Nextlabs.Diagnostic.log4net.Appender.CELogAppender" >

                                <celevel value="DEBUG" />

        <layout type="log4net.Layout.PatternLayout">

            <param name="ConversionPattern" value="[%t] - %m%n" />

        </layout>

    </appender>    

This change will enable NextLabs SharePoint Enforcer to write all the execution step to the file ..\NextLabs\SharePoint Enforcer\Logs\SharepointEnforcer.log. Here is example of the debug log. In this case, there is permission issue that application pool account could not access the search database tables.

Tue Oct 07 15:21:27.929 2014: DEBUG [233380] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 279

Tue Oct 07 15:21:27.929 2014: DEBUG [83068] - [Caller:Nextlabs SPEnforcer]Init for application Handler: enter, thread ID = 244

Tue Oct 07 15:21:27.929 2014: DEBUG [137596] - [Caller:Nextlabs SPEnforcer]Init for application Handler: leave, thread ID = 244

Tue Oct 07 15:21:27.929 2014: DEBUG [188388] - [Caller:Nextlabs SPEnforcer]Init for application Handler: enter, thread ID = 233

Tue Oct 07 15:21:27.929 2014: DEBUG [249468] - [Caller:Nextlabs SPEnforcer]Init for application Handler: leave, thread ID = 233

Tue Oct 07 15:21:27.929 2014: DEBUG [46676] - [Caller:Nextlabs SPEnforcer]Init for application Handler: leave, thread ID = 110

Tue Oct 07 15:21:27.929 2014: DEBUG [249468] - [Caller:Nextlabs SPEnforcer]Init for application Handler: leave, thread ID = 108

Tue Oct 07 15:21:27.929 2014: DEBUG [188388] - [Caller:Nextlabs SPEnforcer]Init for application Handler: enter, thread ID = 108

Tue Oct 07 15:21:27.929 2014: DEBUG [81312] - [Caller:Nextlabs SPEnforcer]Init for application Handler: enter, thread ID = 110

Tue Oct 07 15:21:27.929 2014: DEBUG [233948] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 244

Tue Oct 07 15:21:27.929 2014: DEBUG [233948] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 244

Tue Oct 07 15:21:27.929 2014: DEBUG [55556] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 233

Tue Oct 07 15:21:27.929 2014: DEBUG [187428] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 233

Tue Oct 07 15:21:27.929 2014: DEBUG [55556] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 108

Tue Oct 07 15:21:27.929 2014: DEBUG [233948] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 108

Tue Oct 07 15:21:27.929 2014: DEBUG [55556] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 110

Tue Oct 07 15:21:27.929 2014: DEBUG [102152] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 110

Tue Oct 07 15:21:27.929 2014: DEBUG [112144] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 242

Tue Oct 07 15:21:27.929 2014: DEBUG [181928] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 242

Tue Oct 07 15:21:27.929 2014: DEBUG [115404] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 228

Tue Oct 07 15:21:27.929 2014: DEBUG [115404] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 228

Tue Oct 07 15:21:27.929 2014: DEBUG [221180] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 227

Tue Oct 07 15:21:27.929 2014: DEBUG [221180] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 227

Tue Oct 07 15:21:27.929 2014: DEBUG [156836] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 242

Tue Oct 07 15:21:27.929 2014: DEBUG [169568] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 242

Tue Oct 07 15:21:27.929 2014: DEBUG [216000] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 97

Tue Oct 07 15:21:27.929 2014: DEBUG [160084] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 97

Tue Oct 07 15:21:27.961 2014: DEBUG [1004] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 90

Tue Oct 07 15:21:27.961 2014: DEBUG [1004] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 90

Tue Oct 07 15:21:27.961 2014: DEBUG [36604] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 166

Tue Oct 07 15:21:27.961 2014: DEBUG [36604] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 166

Tue Oct 07 15:21:27.961 2014: DEBUG [100564] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 249

Tue Oct 07 15:21:27.961 2014: DEBUG [54928] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 249

Tue Oct 07 15:21:27.976 2014: DEBUG [193980] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 71

Tue Oct 07 15:21:27.976 2014: DEBUG [148360] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 71

Tue Oct 07 15:21:27.992 2014: DEBUG [194136] - [Caller:Nextlabs SPEnforcer]BeginRequest: enter, thread ID = 69

Tue Oct 07 15:21:27.992 2014: DEBUG [56972] - [Caller:Nextlabs SPEnforcer]BeginRequest: leave, thread ID = 69

Tue Oct 07 15:21:27.992 2014: DEBUG [89128] - [Caller:Nextlabs PLE]PreRequestHandlerExecute: PreRequest come at time: 10/7/2014 3:21:27 PM

Tue Oct 07 15:21:27.992 2014: DEBUG [201604] - [Caller:Nextlabs PLE]PreRequestHandlerExecute: enter, thread ID = 71, URL = https://sharepoint.mycompany.com:45000/_layouts/15/accessdenied.aspx?closeConnection=03, method = GET

Tue Oct 07 15:21:27.992 2014: INFO [122704] - [Caller:Nextlabs SPEnforcer]SPE3.6 TRACE LOG Exception IsDefaultIndexingAccount:exception: Cannot open database "SVC_SEARCH" requested by the login. The login failed.

Login failed for user 'NA\spdev4'. happend stack trace:    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)

   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)

   at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)

   at System.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)

   at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)

   at System.Data.SqlClient.SqlConnection.Open()

   at Microsoft.Office.Server.Data.SqlSession.OpenConnection()

9. If you have multiple WFEs, you need to verify each server. We normally disable all WFes but leave only one running during debugging session.

Now, you should have enough knowledge to debug the issue. I would recommend you read the following NextLabs documents.

• User's Guide
• Administrator’s Guide
• Installation Guide
• Policy Studio User’s Guide
• Reporter User’s Guide

Now you have all the tricks to debug NextLabs issues and it would be much easier to help you to trouble any policy issues.