Thursday, December 13, 2012

NextLabs’ Entitlement Manager Issue #6 - Potential memory leaking on SharePoint

In order to deny certain group to certain SharePoint site collections, we have evaluated NextLabs. With some know issues reported and will be fixed in future releases, we plan to move the current version 6.0 to production.

After we deployed the NextLabs SharePoint components Policy Controller and Enforcer, we stopped the Policy Controller but leave all other components in place. We plan to verify policies during night time to assure no user impact. The second day, many users got the “Cannot complete this action” error as in the screen shot when they modify or create view on some lists or document libraries. Here is the summary of the issues related.


  • “Cannot complete this action” when modifying/creating views in SharePoint
  • “Cannot complete this action” when creating webaprt page in SharePoint
  • Similar error when using designer to edit master pages in SharePoint
  • Lots of error written to SharePoint, Agent, and controller center

This issue happens on different WFE front servers and different webapps. If this happens, it will affect to all users on all issues listed above. The issues seem to be resolved immediate IIS reset but come back after a while.


After looking at SharePoint ULS logs, we suspect NextLabs might have memory leaking while handling exception. In this case, the Policy Controller is stopped. Here is the steps we tried to isolate the issue. You might need to be careful to keep Policy Controller running after you implement NextLabs.

1. Identified the “Cannot complete this action” from log listed below as heighted in RED.

2. Search the GUID for the message and get the GUID. In this cases it’s "02321c08-2c1e-44a0-b453-cfbb4abb9b34

3. Search log and display all information associated to the same thread with same GUID and you will identify it’s caused by NextLabs components as highlighted in RED 

4. We also found many potential memory leaking exception from SharePoint ULS log:
Detected use of SPRequest for previously closed SPWeb object.  

5. Other exceptions from SharePoint ULS logs related to enforcer:
Thu Dec 13 11:14:52.359 2012: ERROR [24316] - [Caller:Nextlabs SPEnforcer]SPE3.6 TRACE LOG Exception GetSPListContent():Object reference not set to an instance of an object.

6. There are many errors inside Controller center Agent:
Dec 11, 2012 6:44:45 PM com.bluejungle.destiny.agent.controlmanager.PolicyEvaluatorImpl queryDecisionEngine
SEVERE:   Result: Exception thrown
  
7. We use SPDisposeCheck tool and checked  Nextlabs.Common.dll deployed to GAC. It seems like three is potential memory leaking.  There are also potential memory leaking for NextLabs.SPEnforcer.dll (6 leaking),
NextLabs.PLE.dll (2), and NextLabs.SPSecurityTrimming.dll (3). This might be worse if there is exception such as Policy Controller is stopped.

Here is the SPDisposeCheckreport for Nextlabs.Common.dll
==============================================================
ID: SPDisposeCheckID_110

Module: NextLabs.Common.dll

Method: NextLabs.Common.CommonVar.GetSPObjectContent(System.Object,System.String

,System.String)

Statement: local4 := new Microsoft.SharePoint.SPSite(_url)

Notes:   Disposable type not disposed: Microsoft.SharePoint.SPSite

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_110

----------------------------------------------------------





ID: SPDisposeCheckID_120

Module: NextLabs.Common.dll

Method: NextLabs.Common.CommonVar.GetSPObjectContent(System.Object,System.String

,System.String)

Statement: local2 := local4.{Microsoft.SharePoint.SPSite}OpenWeb()

Notes:   NOTE: This instance was returned from the method and can likely be igno

red as long as the type is disposed in the caller.

         SPDisposeCheck will automatically determine if the instance was dispose

d in the calling method

         Disposable type not disposed: Microsoft.SharePoint.SPWeb

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_120

----------------------------------------------------------





ID: SPDisposeCheckID_110

Module: NextLabs.Common.dll

Method: NextLabs.Common.Utilities.CheckObjectType(System.Object,System.String,Sy

stem.String)

Statement: local1 := new Microsoft.SharePoint.SPSite(_url)

Notes:   Disposable type not disposed: Microsoft.SharePoint.SPSite

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_110

----------------------------------------------------------





ID: SPDisposeCheckID_120

Module: NextLabs.Common.dll

Method: NextLabs.Common.Utilities.CheckObjectType(System.Object,System.String,Sy

stem.String)

Statement: local0 := local1.{Microsoft.SharePoint.SPSite}OpenWeb()

Notes:   NOTE: This instance was returned from the method and can likely be igno

red as long as the type is disposed in the caller.

         SPDisposeCheck will automatically determine if the instance was dispose

d in the calling method

         Disposable type not disposed: Microsoft.SharePoint.SPWeb

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_120

----------------------------------------------------------





ID: SPDisposeCheckID_110

Module: NextLabs.Common.dll

Method: NextLabs.Common.Utilities.CheckObjectType(System.Object,System.String,Sy

stem.String)

Statement: local4 := new Microsoft.SharePoint.SPSite(_url)

Notes:   Disposable type not disposed: Microsoft.SharePoint.SPSite

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_110

----------------------------------------------------------





ID: SPDisposeCheckID_120

Module: NextLabs.Common.dll

Method: NextLabs.Common.Utilities.CheckObjectType(System.Object,System.String,Sy

stem.String)

Statement: local0 := local4.{Microsoft.SharePoint.SPSite}OpenWeb()

Notes:   NOTE: This instance was returned from the method and can likely be igno

red as long as the type is disposed in the caller.

         SPDisposeCheck will automatically determine if the instance was dispose

d in the calling method

         Disposable type not disposed: Microsoft.SharePoint.SPWeb

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_120

----------------------------------------------------------





ID: SPDisposeCheckID_110

Module: NextLabs.Common.dll

Method: NextLabs.Common.Utilities.CheckObjectType(System.Object,System.String,Sy

stem.String)

Statement: local7 := new Microsoft.SharePoint.SPSite(_url)

Notes:   Disposable type not disposed: Microsoft.SharePoint.SPSite

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_110

----------------------------------------------------------





ID: SPDisposeCheckID_120

Module: NextLabs.Common.dll

Method: NextLabs.Common.Utilities.CheckObjectType(System.Object,System.String,Sy

stem.String)

Statement: local0 := local7.{Microsoft.SharePoint.SPSite}OpenWeb()

Notes:   NOTE: This instance was returned from the method and can likely be igno

red as long as the type is disposed in the caller.

         SPDisposeCheck will automatically determine if the instance was dispose

d in the calling method

         Disposable type not disposed: Microsoft.SharePoint.SPWeb

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_120

----------------------------------------------------------





ID: SPDisposeCheckID_110

Module: NextLabs.Common.dll

Method: NextLabs.Common.Globals.GetValidSPSite(System.String,System.Web.HttpCont

ext)

Statement: local0 := new Microsoft.SharePoint.SPSite(requestUrl)

Notes:   NOTE: This instance was returned from the method and can likely be igno

red as long as the type is disposed in the caller.

         SPDisposeCheck will automatically determine if the instance was dispose

d in the calling method

         Disposable type not disposed: Microsoft.SharePoint.SPSite

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_110

----------------------------------------------------------





ID: SPDisposeCheckID_110

Module: NextLabs.Common.dll

Method: NextLabs.Common.Globals.GetValidSPSite(System.String,System.Web.HttpCont

ext,System.String@)

Statement: local0 := new Microsoft.SharePoint.SPSite(requestUrl)

Notes:   NOTE: This instance was returned from the method and can likely be igno

red as long as the type is disposed in the caller.

         SPDisposeCheck will automatically determine if the instance was dispose

d in the calling method

         Disposable type not disposed: Microsoft.SharePoint.SPSite

         ***This may be a false positive depending on how the type was created o

r if it is disposed outside the current scope


07-and-wss-3-0-dispose-patterns-by-example.aspx#SPDisposeCheckID_110

----------------------------------------------------------



Total Found: 10
 

Here is the SharePoint ULS log:
============================================================================================================================================

Search "02321c08-2c1e-44a0-b453-cfbb4abb9b34" (14 hits in 1 files)


               Line 331847: 12/12/2012 12:05:25.92        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Logging Correlation Data               xmnv     Medium               Name=Request (GET:http://sharepoint:80/qct/DHW/Cores/Modem/MP/BOLT/Documents/Forms/AllItems.aspx?RootFolder=%2Fqct%2FDHW%2FCores%2FModem%2FMP%2FBOLT%2FDocuments%2FHDD%2FDemback)    02321c08-2c1e-44a0-b453-cfbb4abb9b34
 
                 Line 331975: 12/12/2012 12:05:25.94        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Monitoring                         b4ly        High       Leaving Monitored Scope (GetFileAndMetaInfo). Execution Time=18.8723439467309               02321c08-2c1e-44a0-b453-cfbb4abb9b34


                Line 331976: 12/12/2012 12:05:25.94        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Monitoring                         b4ly        High       Leaving Monitored Scope (GetWebPartPageContent). Execution Time=19.077774454198 02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 331978: 12/12/2012 12:05:25.94        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Logging Correlation Data               xmnv     Medium
                Site=/qct/DHW 02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 331979: 12/12/2012 12:05:25.94        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Monitoring                         b4ly        High       Leaving Monitored Scope (PostResolveRequestCacheHandler). Execution Time=20.8264296523386               02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 331981: 12/12/2012 12:05:25.95        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         General                                90hv      Unexpected       Detected use of SPRequest for previously closed SPWeb object.  Please close SPWeb objects when you are done with all objects obtained from them, but not before.  Stack trace:    at Microsoft.SharePoint.SPWeb.get_CurrentUser()     at NextLabs.Common.CommonVar.GetSPWebContent(SPWeb SPObject, String content)     at Nextlabs.PLE.PageModule.PortletPageResource.Process(HttpRequest Request, SPWeb _webObj)     at NextLabs.PLE.HttpModule.PLEHttpModule.PreRequest(Object source, EventArgs e)     at NextLabs.HttpEnforcer.HttpEnforcerModule.Application_PreRequestHandlerExecute(Object source, EventArgs e)     at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()     at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchro...              02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 331982: 12/12/2012 12:05:25.95*     w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         General                                90hv      Unexpected       ...nously)     at System.Web.HttpApplication.PipelineStepManager.ResumeSteps(Exception error)     at System.Web.HttpApplication.BeginProcessRequestNotification(HttpContext context, AsyncCallback cb)     at System.Web.HttpRuntime.ProcessRequestNotificationPrivate(IIS7WorkerRequest wr, HttpContext context)     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr managedHttpContext, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr managedHttpContext, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr managedHttpContext, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)     at System....   02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 331983: 12/12/2012 12:05:25.95*     w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         General                                90hv      Unexpected       ...Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr managedHttpContext, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)      02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 332153: 12/12/2012 12:05:26.08        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Server                             General                                81vt       High       Exception of type 'System.ArgumentException' was thrown.  Parameter name: value       02321c08-2c1e-44a0-b453-cfbb4abb9b34

                Line 333082: 12/12/2012 12:05:26.58        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Monitoring                         b4ly        High       Leaving Monitored Scope (EnsureListItemsData). Execution Time=501.001233734992               02321c08-2c1e-44a0-b453-cfbb4abb9b34
                Line 333084: 12/12/2012 12:05:26.58        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Monitoring                         b4ly        High       Leaving Monitored Scope (DataBinding DataFormWebPart (Documents)). Execution Time=505.087188931174          02321c08-2c1e-44a0-b453-cfbb4abb9b34
                Line 333092: 12/12/2012 12:05:27.00        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         General                                8kh7      High       Cannot complete this action.  Please try again.<nativehr>0x80004005</nativehr><nativestack></nativestack>              02321c08-2c1e-44a0-b453-cfbb4abb9b34
                Line 333093: 12/12/2012 12:05:27.00        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Monitoring                         b4ly        High       Leaving Monitored Scope (ToolBarMenuButton.CreateChildControls for NewMenu). Execution Time=406.259371566959                02321c08-2c1e-44a0-b453-cfbb4abb9b34
                Line 333422: 12/12/2012 12:05:27.56        w3wp.exe (0x5EC8)                       0x25EC  SharePoint Foundation                         Performance                     nask       High       An SPRequest object was not disposed before the end of this thread.  To avoid wasting system resources, dispose of this object or its parent (such as an SPSite or SPWeb) as soon as you are done using it.  This object will now be disposed.  Allocation Id: {016746EC-D4E4-4DD0-A49D-BF52AB556225}  To determine where this object was allocated, set Microsoft.SharePoint.Administration.SPWebService.ContentService.CollectSPRequestAllocationCallStacks = true.                02321c08-2c1e-44a0-b453-cfbb4abb9b34