Thursday, December 23, 2010

Writing Trace Output to ULS Log in SharePoint 2010

SharePoint 2010 supports writing custom messages to ULS log. A blog post by Waldek Mastykarz of Mavention provides a good example of how to do this. UPDATE 02/24/2011: Andrew Connell's article on MSDN from December 2010 provides essential information on diagnostics logging.

Ability to send messages from System.Diagnostics.Trace.Write() and Trace.Fail() method overloads to ULS is yet another “logging novelty” I will be focusing on in this post.

There is a new type in Microsoft.SharePoint assembly, which was not there in version 12 – Microsoft.SharePoint.SPULSTraceListener. As its name suggests it allows sending trace messages to ULS.

If you are instrumenting your custom SharePoint code and need to write diagnostic traces to ULS then you can wire up SPULSTraceListener type in your web.config and use tracing infrastructure available in System.Diagnostics.Trace.  Here are the steps:

1. Add a trace listener element to web.config. For more information see description of system.diagnostics element on MSDN.

<system.diagnostics>
<trace>
<listeners>
<remove name="Default"/>
<add
name="ULSTraceListener"
type="Microsoft.SharePoint.SPULSTraceListener, Microsoft.SharePoint, version=14.0.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c" />
</listeners>
</trace>
</system.diagnostics>

In this XML snippet note the <remove name=”Default”>. This is done to remove default trace listener, which is wired up by default and displays a pop-up window with the message when Trace.Fail() is called.

2. In central administration site configure diagnostic logging (Central Administration >> Diagnostic Logging). If you are using Trace.Write() method calls then they are logged as Verbose and so in order to actually see them in ULS logs you need to make sure that throttling level is set to Verbose for SharePoint Foundation > Service Connections category. If you use Trace.Fail() overloaded methods then the message will be written as a High level, which by default is on, so the message will normally end up being written to a log file. And yes, all messages will be written to the log under Service Connections category.


What About TraceContext.Write()?

UserControl, Page and HttpContext classes have a property named Trace of type System.Web.TraceContext. It allows tracing messages using ASP.NET trace infrastructure, for example: HttpContext.Current.Trace.Write(string message);. You can send ASP.NET trace messages to ULS using standard technique but with a caveat:

Add trace configuration element under system.web element in your web.config as follows:


<system.web>
<trace enabled="true" requestLimit="1000" mostRecent="true" writeToDiagnosticsTrace="true"/>
...

Here the key attribute is writeToDiagnosticsTrace instructing ASP.NET trace to use tracing infrastructure from System.Diagnostics. Now trace messages written using TraceContext.Write() will be sent to ULS.
Now the caveat: adding system.web/trace element appears to destabilize SharePoint. I have tried this on SharePoint Foundation and SharePoint Server 2010 with October 2010 CU, and although tracing does work as expected I have got a consistent error when trying to create a new web part page:
UIErrorFromTracing
Looking at the ULS log, I found these messages logged under SharePoint Foundation category:

SharePoint Foundation    General    b9y3    High    Failed to open the file 'C:\Program Files\Common Files\Microsoft Shared\Web Server Extensions\14\Resources\wss.resx'.

SharePoint Foundation    General    b9y4    High    #20015: Cannot open "": no such file or folder.   
SharePoint Foundation    General    b9y4    High    (#2: Cannot open "": no such file or folder.)   
SharePoint Foundation    General    b9y9    High    Failed to read resource file "C:\Program Files\Common Files\Microsoft Shared\Web Server Extensions\14\Resources\wss.resx" from feature id "(null)".

 
As soon as I disable the system.web/tracing the error disappears. I am not sure if this is a bug or adding <trace> element under <system.web> is not supported. In any case there is enough of rich diagnostic features available, and if you are using tracing in your application then just avoid System.Web.TraceContext.Write() in favor of System.Diagnostics.Trace.Write() or at least use it temporarily if you need to. By the way System.Diagnostics.Debug.Write() also sends messages to trace log.

UPDATE (01-16-2011): There is yet another issue caused by turning on trace that I ran into today: SharePoint designer cannot open a site in a web application for which tracing is enabled, and keeps prompting for credentials. If you check out traffic with Fiddler, you will find that SPD makes requests to http://devserver2010/_vti_bin/shtml.dll/_vti_rpc, which return a 401 UNAUTHORIZED. Not even verbose logging reveals anything useful. Well, commenting out <trace> element in web.config restores normal functionality.

No comments:

Post a Comment