20 March 2012

Sharepoint Guidance Logger: usage, setup and extension

Introduction

Log records are essential to any application for troubleshooting problems. When beginning a new Sharepoint project, one of the first needs is to have a core logging component that can be used throughout the application code. In this post I will talk about the logging solution that we are using (based on the Patterns & Practices Sharepoint Logger), how to set it up, configure and read logs.

SharePoint 2010 includes enhanced functionality for logging and tracing. You can now throttle reporting to the Windows Event Log and the Office Server Unified Logging Service (ULS) trace logs by area and by category. Areas represent broad regions of SharePoint functionality, such as Access Services, Business Connectivity Services, and Document Management Server. Within each area, categories define more specific aspects of functionality. In our solution we use a single Area for the whole project’s custom code, and different categories inside it for the different components, like Caching, UserProfile, News, Workflows, etc…

In addition to areas and categories, SharePoint 2010 makes substantial improvements to event correlation. Every trace log entry now includes a correlation ID that identifies all the events that correspond to a particular action, such as a user uploading a document. Administrators can use tools such as the ULS Viewer to filter the trace logs by correlation ID. The Sharepoint Error Page shows the user the date and correlation Id. It is important to capture this information when an error occurs, to make it easier for administrators to track for a particular issue.

The Framework

In the project I’m working on we are using a common framework for logging, which is based on the Patterns & Practices Sharepoint Logger, included in the SharePoint Guidance Library. The P&P logger provides support to write to the Windows Event log and the ULS trace logs and support for creating your own areas and categories and use them when you write to the event log or the trace logs. Two external assemblies are needed for using it: Microsoft.Practices.ServiceLocation.dll and Microsoft.Practices.SharePoint.Common.dll.

Examples of how to call the logger thru code can be found on the SP logger documentation, but just as a sample, it is something like this:

P&P Logger usage
// Log an event with a message, an event ID, a severity level, and a category.
string area = "Custom Area";
string category = "Execution";
string areaCategory = string.Format("{0}/{1}", area, category);
logger.LogToOperations(msg, (int) EventLogEventId.MissingPartnerID, EventSeverity.Error, areaCategory);


Our logging component adds a small utility layer above the P&P logger to simplify this lines a little more. For example, as we have our custom area and categories predefined, we included them in an enumeration, and use the enums as parameters to the LogToOperations method. This way developers don’t need to type the area and categories names every time, which can lead to a lot of errors. It also provides the option to add parameters to the message and then does the String.Format to combine the message with the parameters inside the utility class, this saves some repeated code to the developers as well. Regarding the log event ids, they are also set automatically by the utility class, using a different number for each category, starting with 5000.



This leads to the logger utility having two overrides of the LogToOperations method, one for logging messages and the other for logging exceptions:




Custom logger utility


public class Logger


{


    private ILogger logger = SharePointServiceLocator.GetCurrent().GetInstance<ILogger>();





    public void LogToOperations(MyCustomCategories category, EventSeverity severity, string message, params object[] args)


    {


        try


        {


            logger.LogToOperations(String.Format(message, args), GetEventId(category),


                    severity, category.ToLoggerString());


        }


        catch


        {


            //don't want the app to fail because of failures in logging


        }


    }





    public void LogToOperations(Exception ex, MyCustomCategories category, EventSeverity severity, string message, params object[] args)


    {


        try


        {


            logger.LogToOperations(ex, String.Format(message, args), GetEventId(category),


                    severity, category.ToLoggerString());


        }


        catch


        {


            //don't want the app to fail because of failures in logging


        }


    }





    private int GetEventId(MyCustomCategories category)


    {


        return 5000 + (int)category;


    }


}



  And this is a simple example of usage:




Usage example


static void Main(string[] args)


{


    string user = "Peter John";


    int id = 3;


    Logger logger = new Logger();


    logger.LogToOperations(MyCustomCategories.Test, Microsoft.SharePoint.Administration.EventSeverity.Verbose,


        "Testing logging with user '{0}' and id '{1}'", user, id);





    try


    {


        string firstArg = args[0];


    }


    catch (Exception ex)


    {


        logger.LogToOperations(ex,MyCustomCategories.Test, Microsoft.SharePoint.Administration.EventSeverity.Error, "Error ocurred in test program for user '{0}' and id '{1}'",


            user, id);


    }


}



Setup and Configuration



In order for all this to work, we first need to create our custom diagnostic areas and categories. We are doing it inside a feature event receiver. The code adds the custom area and then iterates thru the Categories enum to add all the associated categories. The advantage is that when a developer needs to add a category, he just adds the value to the enum and the feature will automatically add it to Sharepoint. At the moment of crating the categories, the severity level must be set. We are setting all of them as verbose which is the most useful at a development stage, but this should be changed after deployment, especially in production. A level of Warning is recommended to save disk space and increase general performance of the application.




Installer helper called by the feature event receiver


class LoggingInstallerHelper


{


    public static void AddCustomAreaAndCategories()


    {


        DiagnosticsArea customArea = new DiagnosticsArea(Areas.MyCustomArea.ToString());


        var categories = Enum.GetNames(typeof(MyCustomCategories));


        foreach (var category in categories)


        {


            customArea.DiagnosticsCategories.Add(new DiagnosticsCategory(category, EventSeverity.Verbose, TraceSeverity.Verbose));


        }


        AddArea(customArea);


    }





    public static void RemoveCustomAreaAndCategories()


    {


        RemoveArea(Areas.MyCustomArea.ToString());


    }





    #region Private Methods





    private static void AddArea(DiagnosticsArea newArea)


    {


        DiagnosticsAreaCollection areas = GetCurrentAreas();


        var existingArea = areas.FirstOrDefault(area => area.Name == newArea.Name);


        if (existingArea == null)


        {


            areas.Add(newArea);


        }


        else


        {


            int index = areas.IndexOf(existingArea);


            foreach (DiagnosticsCategory item in newArea.DiagnosticsCategories)


            {


                var existingCateg = areas[index].DiagnosticsCategories.FirstOrDefault(categ => categ.Name == item.Name);


                if (existingCateg == null)


                {


                    areas[index].DiagnosticsCategories.Add(item);


                }


            }


        }


        areas.SaveConfiguration();


    }


        
    private static DiagnosticsAreaCollection GetCurrentAreas()


    {


        IServiceLocator serviceLocator = SharePointServiceLocator.GetCurrent();


        IConfigManager config = serviceLocator.GetInstance<IConfigManager>();


        DiagnosticsAreaCollection areaCollection = new DiagnosticsAreaCollection(config);


        return areaCollection;


    }





    private static void RemoveArea(string areaName)


    {


        DiagnosticsAreaCollection areas = GetCurrentAreas();


        if (ExistArea(areas, areaName))


        {


            while (areas[areaName].DiagnosticsCategories.Count != 0)


            {


                areas[areaName].DiagnosticsCategories.Clear();


            }


            areas.RemoveAt(areas.IndexOf(areas[areaName]));


            areas.SaveConfiguration();


        }


    }





    private static bool ExistArea(DiagnosticsAreaCollection collection, string areaName)


    {


        foreach (DiagnosticsArea item in collection)


        {


            if (item.Name.Trim().ToUpper() == areaName.Trim().ToUpper())


                return true;


        }


        return false;


    }





    #endregion





}



To verify the proper installation of the custom area and categories and modify their severity level, you can go to the Admin Site -> Monitoring -> (Reporting) Configure diagnostic logger. In the Event Throttling section select desired area or particular categories and change the event and trace levels. Then click ok.



LoggingConfig



You can also configure the logs folder path (the default is c:\Program Files\Common Files\Microsoft Shared\Web Server Extensions\14\LOGS\), storage day and size limits on this page under the trace logs section.



Viewing logs



You can see the log messages on the Event Viewer and trace logs using the ULS Viewer.



In the Event Viewer you will find the custom events under Windows Logs/ Application. You can filter by Source = MyCustomArea, by severity and/or Event ID.



EventLog



You can also find trace logs in the ULS log files, and use a tool, like the ULS Viewer for a friendlier interface and filtering capabilities. The ULS Viewer is very useful for filtering by correlation id.



ULS



This are the basic tools. There are also tools for viewing log information remotely, or for aggregating log entries in a farm environment.

17 March 2012

Sharepoint Expiration Policy not working

I have a Sharepoint 2010 list with a custom content type with an associated retention policy. The policy consists of a custom formula and then the Send to Recycle Bin action. However, I realized that the items were not being deleted. I verified the list settings and the retention policy was configured:

CustomExpirationFormula

I run the Expiration Policy job several times but no items were deleted and no errors found in the logs. I also added logging to the custom formula but no logging was found neither. Finally, I found one thing that I didn’t know: There is another job that needs to be run before the Expiration Policy job, it is the Information Management Policy job.

The two are Sharepoint OOB jobs:

  • Expiration Policy: This job processes items that are due for a retention action, such as deleting items passed their expiration date.
  • Information Management Policy: This job performs background processing for information policies, such as calculating updated expiration dates for items with a new retention policy.

So as in this case I have a new retention policy, I needed to run this job first. When I did it, I got an error in the logs:

Error processing policy updates for site http://mysite.com for list MyList.

Error: Object reference not set to an instance of an object.

Source: Document Management Server

Event ID: 7997

Task Category: Information Policy Management

The error didn’t tell much, but after digging a little more I realized that the problem was that the custom expiration formula was not installed, so the Information Management Policy job couldn’t calculate the expiration date.