One of the new nice and cool features of Sharepoint 2010 is the new Logging database. What it allows us to do is to collect all sorts of usage and health information and store it in a database that we can later use for querying and reporting. When I first heard about that I was pretty exited, specially when I read that it could be used to store all of our farm ULS logs as well! No more having to connect to each server in the farm and browse the log files trying to diagnose an error, even with the new Merge-SPLogFile powershell command this was still a tedious process.
To test this new feature the first thing we have to do is to create the logging database. We can do so from central administration, by navigating to Monitoring - Configure usage and health data collection. We need to enable there the Health Data Collection checkbox and configure the Logging Database by providing a SQL Server and a database name. After clicking Ok, the new logging database should be created (if it's not, wait for the Timer Service to quick off)
If we browse to the Logging database we will see it contains several tables and views used to populate various usage and health reports. However we will notice that there is no view for returning ULS Logs (which is what we are trying to cover in this article!). The reason being that ULS trace logs are populated by a Sharepoint Timer Job that is probably not enabled in the server. The timer job responsible for populating the Logging database with the ULS logs is called 'Diagnostic Data Provider: Trace Log', what we have to do then is navigate to Central Administration in Sharepoint and make sure this job is running on a scheduled basis. We can even use the new fancy 'Run Now' feature to run the job now.
After the job has run we can return to the Logging database and we should see that a new View has been created, the ULSTraceLog view! If we open this view, we will notice that it contains some ULS logs from our Sharepoint Farm. It is interesting to notice the MachineName column, since the 'Diagnostic Data Provider: Trace Log' runs on every server in our farm, they will all store their ULS Logs in the database and we can use this field to filter logs by server. That looks exactly what we were looking for !
However, something seems to be wrong with the ULS logs from our Logging database... We seem to be missing many ULS logs! Even if we wait for some minutes for the timer job to quick off again, not all logs from our trace files seem to be moved to the Logging database. We can try to configure diagnostic logging in Sharepoint to enable Verbose logs to trace files and the database is missing hundred of logs. Examining the populated logs will reveal that only logs for a certaing trace severity level are being created. This is not the behaviour we were expecting, troubleshooting Sharepoint issues usually requires analysing lots of ULS logs and most of the time we require viewing Information severity level entries but sometimes we even need to enable Verbose for a short period of time.
I tried to find out if there was any setting that would allow us to configure the severity level of the ULS logs that we want to copy to the Logging database with no success. When I was about to resign and get back to reviewing the log files at every server I tried one last thing. I first managed to find the class that implemented the 'Diagnostic Data Provider: Trace Log' timer job. This class is called Microsoft.SharePoint.Diagnostics.SPDiagnosticsULSProvider and can be found in the Microsoft.SharePoint.dll assembly. I then used .net reflector to take a look at the source code that this class implemented and here is what I found !
I have marked the important bits in the code. First, we can see that there is a Sync() method that is the responsible for populating the Logging database with data from the ULS logs. We can see that this method uses a ULSLogFileProcessor object to retrieve a list of all the logs. This class is initialized with a configuration object that contains a FilterDefinition instance used to filter the results of the GetRecords() operation that returns all the logs. Interestingly, we can see that this filter has a Level property of type TraceLevel that is set to a member property of the SPDiagnosticsULSProvider class called m_Level, we can see as well that in the constructor of this class that is called when the timer job is instantiated, this member property is initialized with TraceLevel.Monitorable
Here is then the answer to our questions! This timer job will always filter the ULS logs and populate only the ones with a severity of at least Monitorable, this means that Information or Verbose level logs will always be discarded.
Is there anything we can do to change this? And the answer is yes. We cannot change the behaviour of the default timer job, this is going to create a new instance of the SPDiagnosticsULSProvider class on every execution and we now know how this object populates the Logging database. However, looking at the reflector code we will notice that there is a parameterless constructor that don't initialize the m_Level property and that we can use to our advantage. The idea is to create ourselves an instance of that object calling the parameterless constructor, assign our own trace severity level and then call the Sync() method. To do so, I created a simple application that would run on a Sharepoint server and call the following method:
And amazingly, this small piece of code does exactly what we were looking for!!! After running this code we will see that all ULS trace logs from the server where this code was executed are copied to the Logging database.
To ensure this code runs on every server of the farm, an ideal solution would be to wrap it on our own Sharepoint timer job, we can also create an application as I did to run this code on demand. It is important to notice that this code will get all ULS entries created in the log files since the last time the Synchronization was run. Notice the filter DateTime time = base.GetLastSyncUtc(machineName).ToLocalTime(); in the Sync() method, this method will call the prc_GetLastUTCDate Stored Procedure in the Logging database and will use the LogTime column to determine the last time the logs were imported. It is necessary then that we disable the 'Diagnostic Data Provider: Trace Log' since if this happens to run in between executions of our custom timer job, it will update the tables with additional logs and the next time our job runs it will only populate data since the last time the out of the box timer job run.
And to finish with this article I would like to point out that you should be very careful when implementing this solution. While trace log files are managed by Sharepoint and we have configuration settings to control how they grow and for how long to keep those files, the same is not true for the Logging database. This database can grow under normal circumstances really fast, it is even advised to host it on a separate database server other than the one used by the Sharepoint Farm. If we start populating the database with Verbose level logs, the size of it will increase even quicker. Careful measures need to be taken to ensure it is always under control and performance of the Sharepoint Farm is not affected.
Created on 17/05/2011
