Random Musings of Jeremy Jameson

  • Creating Wireframes for Page Layouts

    When helping customers migrate their Internet sites to Microsoft Office SharePoint Server (MOSS) 2007, I've found it very helpful to create wireframes showing the various fields, Web Parts, and master page content. For the last several years, I've been doing this in Microsoft Office Visio, but you could certainly achieve similar results with other tools, such as Expression Design.

    I start by taking a series of screenshots of the existing Web site using Screengrab! (which makes it very easy to capture entire Web pages). For example, here is a screenshot of a "Generic" page on the Agilent Technologies - LSCA site that I captured a couple of years ago.

    Figure 1: "Generic" page

    I then paste the screenshot into Visio.

    Next, I deemphasize the portions of the page rendered by the master page. To accomplish this, add a rectangle with the text Header (Master Page) over the top portion of the page. Then fill the rectangle with light gray (Shade 15%) and set the transparency to 30%. Repeat similar steps for the footer and other content provided by the master page.

    The next step is to emphasize the various fields that we need to define in the corresponding content type. In Figure 1, it is easy to discern that we have a Title (i.e. "Glycomics Solution"), a Page Image (i.e. the circular image on the right side of the page), and some arbitrary amount of Page Content (i.e. the "stuff" in the middle). I also chose to provide a Subtitle field for the bold text at the top of the page. Isolating the Subtitle allows us to provide "semantic markup" and better control the formatting and layout of this content.

    To highlight these various fields, I create rectangles with corresponding text and fill them with a very light red (Tint 35%) and again set the transparency to 30%.

    We now have a "wireframe" that shows the various portions of the page with just enough visibility of the underlying content to understand what each portion refers to.

    Figure 2: "Generic" page (Page Layout)

    Here is another example, based on a press release.

    Figure 3: Sample Press Release

    Figure 4 shows the corresponding page layout.

    Figure 4: Press Release (Page Layout)

    Note the importance of choosing good sample pages when mocking up the wireframes for page layouts. I chose the example press release above based on the fact that it had "additional contact" information. In other words, all press releases have primary contact information (which I chose to map to the out-of-the-box Contact Name, Contact Phone, and Contact E-mail Address fields), but only some press releases have additional contacts -- which may consist of one more more individuals. Rather than attempting to create separate fields for each individual's name, phone number, and e-mail address, we chose to simply provide a single field for greater flexibility.

    Some pages may be comprised of both fields and Web Parts. For example, consider the following product detail page.

    Figure 5: Sample product detail page

    In this scenario, the "Buy Zone" and "Announcements" features are both implemented as individual Web Parts (due to the dynamic nature of this content). Figure 6 shows the corresponding page layout, highlighting the Web Parts in a different color.

    Figure 7: Product Detail (Page Layout)

    Wireframes like these are valuable when you are trying to define the various content types and page layouts, as well as when it comes time to document your various feature specs. So the next time you start a SharePoint project -- or any Web development project for that matter -- I recommend creating a Screenshots library right from the start and adding artifacts like these. I also keep a copy of the Visio file (typically named Models - Page Layouts.vsd) so I can quickly make changes as the content types and page layouts evolve over time.

  • Configuring Logging in SharePoint Application Pages

    In my previous post I showed how my simple, but highly effective approach to logging can be used with ASP.NET Web applications -- including Microsoft Office SharePoint Server (MOSS) and Windows SharePoint Services (WSS).

    Note that SharePoint application (i.e. _layouts) pages are served from a different virtual directory than content pages within the Web application. Consequently, in order to view log messages when, for example, activating a feature (e.g. using http://fabrikam/en-US/Products/_layouts/ManageFeatures.aspx) the System.Web.WebPageTraceListener must be specified in the Web.config file within the following folder:

    %ProgramFiles%\Common Files\Microsoft Shared\Web Server Extensions\12\template\layouts

    Also be sure to enable tracing using the <trace> element within <system.web> in that Web.config file, as shown in my previous post.

    Now you can easily view log messages from a feature receiver that uses the custom Logger class regardless of whether the feature is "activated" via Site Settings, through stsadm.exe, or from within Visual Studio via a unit test.

  • Configuring Logging in ASP.NET Applications (and SharePoint)

    This post continues on the original post for my simple, but highly effective approach to logging and the follow-up post which introduced configuring logging for console applications.

    Obviously not all solutions are simple console-based applications. With ASP.NET Web services and applications -- including Microsoft Office SharePoint Server (MOSS) and Windows SharePoint Services (WSS) -- you can still view log messages from the Logger class very easily on a per-request basis.

    Note that the System.Web.WebPageTraceListener can be specified in Web.config to enable logging to the ASP.NET tracing feature:

      <system.diagnostics>
        <sources>
          <source name="defaultTraceSource" switchName="allTraceLevel">
            <listeners>
              <add name="webPageTraceListener" />
            </listeners>
          </source>
        </sources>
        <sharedListeners>
          <add type="System.Web.WebPageTraceListener, System.Web, Version=2.0.0.0,
    Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
            name="webPageTraceListener" traceOutputOptions="None" />
        </sharedListeners>
        <switches>
          <add name="allTraceLevel" value="All" />
          <add name="verboseTraceLevel" value="Verbose" />
          <add name="infoTraceLevel" value="Info" />
          <add name="warningTraceLevel" value="Warning" />
          <add name="errorTraceLevel" value="Error" />
          <add name="offTraceLevel" value="Off" />
        </switches>
      </system.diagnostics>

    Also note that ASP.NET tracing must be enabled using the <trace> element within <system.web>:

      <system.web>
        <trace enabled="true" pageOutput="false" requestLimit="50" localOnly="true" />
      </system.web>

    Be sure to set the requestLimit high enough to enable access to the page trace you are interested, but also be aware that you can easily clear the captured traces and then browse to the page of interest again.

    Once configured, browse to the page on the site. Then modify the URL to browse to Trace.axd (e.g. http://fabrikam-local/Trace.axd) to display the Trace Viewer.

    Figure 1: ASP.NET Trace Viewer

    Locate the request that you want to view log messages for and click the corresponding View Details link.

    Figure 2: ASP.NET Trace Viewer

    Notice that the WebPageTraceListener even formatted the warning message in red. How cool is that?! [For all you SharePoint developers out there, compare this with "diving" into the ULS logs to find an error or warning for a particular page request!]

    Be aware that the Web.config file you use for SharePoint applications varies depending on whether you want to view log messages for a content page or for an application (i.e. _layouts) page. This is covered in my next post.

  • Configuring Logging in a Console Application

    In my previous post, I introduced my simple, but highly effective approach to logging. As promised, this post introduces how to configure logging (based on a simple console application).

    As noted in my previous post, one or more trace listeners can be configured for a particular System.Diagnostics.TraceSource.

    To understand the configuration of various trace listeners, consider the following console application:

    using System;
    using System.Diagnostics;
    using System.Globalization;
    using System.Text;
    
    using Fabrikam.Demo.CoreServices.Logging;
    
    namespace Fabrikam.Demo.AdminConsole
    {
        class Program
        {
            static void Main(
                string[] args)
            {
                try
                {
                    LogCommandLine("AdminConsole.exe", args);
    
                    // Parse the command line arguments and initialize the work
                    // ...
    
                    // Process the work
                    Process();
                }
                catch (Exception ex)
                {
                    Logger.LogCritical(ex.Message + "\n" + ex.StackTrace );
                    Logger.Flush();
                    Environment.Exit(1);
                }
    
                Logger.LogInfo("Program complete.");
                Logger.Flush();
            }
    
            private static void LogCommandLine(
                string program,
                string[] args)
            {
                Debug.Assert(string.IsNullOrEmpty(program) == false);
                Debug.Assert(args != null);
    
                StringBuilder commandLineBuilder = new StringBuilder(program);
                for (int i = 0; i < args.Length; i++)
                {
                    commandLineBuilder.Append(" ");
                    commandLineBuilder.Append(args[i]);
                }
    
                string commandLine = commandLineBuilder.ToString();
                Logger.LogInfo(commandLine);
            }        
    
            private static void Process()
            {
                Logger.LogDebug("Starting processing...");
                
                // Simulate the processing of a work item queue.
                for (int i = -1; i <= 4; i++)
                {
                    ProcessWorkItem(i);
                }            
    
                Logger.LogInfo("Successfully completed processing.");
            }
            private static void ProcessWorkItem(
                int workItemId)
            {
                // If an error occurs processing a work item, we want to
                // log a warning, but continue processing the next work item.
                try
                {
                    // Simulate processing of the work item by simply
                    // showing the square root of the work item Id.
                    ShowSquareRoot(workItemId);
                }
                catch (ArgumentException ex)
                {
                    Logger.LogWarning(
                        CultureInfo.InvariantCulture,
                        "Unable to process work item {0} ({1}).",
                        workItemId,
                        ex.Message);
                }
            }
    
            private static void ShowSquareRoot(
                double d)
            {
                if (d < 0.0)
                {
                    throw new ArgumentException(
                        "The value must be greater than or equal to zero.",
                        "d");
                }
    
    
                Logger.LogDebug(
                    CultureInfo.InvariantCulture,
                    "Computing square root of {0}...",
                    d);
    
                double sqrt = Math.Sqrt(d);
                Debug.Assert(double.IsNaN(sqrt) == false);
    
                Console.WriteLine(
                    "The square root of {0} is {1:0.000}.",
                    d,
                    sqrt);
            }
        }
    }
    

    Running this program without configuring any trace listeners results in the following output to the console:

    The square root of 0 is 0.000.
    The square root of 1 is 1.000.
    The square root of 2 is 1.414.
    The square root of 3 is 1.732.
    The square root of 4 is 2.000.

    Notice that none of the log messages are displayed in the console output.

    However, if we start DebugView before running the program, then we can easily view all of the log messages.

    Figure 1: DebugView (a.k.a. Dbgview.exe)

    To show the log messages in the console, we simply need to configure a listener. For a console application, this is done using the application configuration file (which is located in the folder with the application executable and has the name of the application with the ".config" file name extension added).

    <?xml version="1.0" encoding="utf-8" ?>
    <configuration>
      <system.diagnostics>
        <sources>
          <source name="defaultTraceSource" switchValue="All">
            <listeners>
              <add name="consoleListener" />
              <!--
                Remove the Default listener to avoid duplicate messages
                being sent to the debugger for display
              -->
              <remove name="Default" />
            </listeners>
          </source>
        </sources>
        <sharedListeners>
          <add
            type="System.Diagnostics.ConsoleTraceListener"
            name="consoleListener"
            traceOutputOptions="None" />
        </sharedListeners>
      </system.diagnostics>
    </configuration>

    With this configuration, the console output shows:

    defaultTraceSource Information: 0 : AdminConsole.exe
    defaultTraceSource Verbose: 0 : Starting processing...
    defaultTraceSource Warning: 0 : Unable to process work item -1 (The value must be greater than or equal to zero.
    Parameter name: d).
    defaultTraceSource Verbose: 0 : Computing square root of 0...
    The square root of 0 is 0.000.
    defaultTraceSource Verbose: 0 : Computing square root of 1...
    The square root of 1 is 1.000.
    defaultTraceSource Verbose: 0 : Computing square root of 2...
    The square root of 2 is 1.414.
    defaultTraceSource Verbose: 0 : Computing square root of 3...
    The square root of 3 is 1.732.
    defaultTraceSource Verbose: 0 : Computing square root of 4...
    The square root of 4 is 2.000.
    defaultTraceSource Information: 0 : Successfully completed processing.
    defaultTraceSource Information: 0 : Program complete.

    Notice that System.Diagnostics.ConsoleTraceListener outputs the name of the TraceSource (which in this case is "defaultTraceSource") as well as the event Id (which, for my simple Logger class is always 0). It can also be configured to show other fields, such as thread Id.

    A TraceSwitch can also be configured to control tracing and debug output. For example, the following configuration specifies that the trace source should ignore low-level debugging and information messages, and only show warning and error messages.

    <?xml version="1.0" encoding="utf-8" ?>
    <configuration>
      <system.diagnostics>
        <sources>
          <source name="defaultTraceSource" switchName="warningTraceLevel">
            <listeners>
              <add name="consoleListener" />
              <!--
                Remove the Default listener to avoid duplicate messages
                being sent to the debugger for display
              -->
              <remove name="Default" />
            </listeners>
          </source>
        </sources>
        <sharedListeners>
          <add
            type="System.Diagnostics.ConsoleTraceListener"
            name="consoleListener"
            traceOutputOptions="None" />
        </sharedListeners>
        <switches>
          <!-- Use this switch to output all log messages -->
          <add name="allTraceLevel" value="All" />
          <!-- Use this switch to output low-level debugging, informational,
            warning, and error messages -->
          <add name="verboseTraceLevel" value="Verbose" />
          <!-- Use this switch to output informational, warning,
            and error messages -->
          <add name="infoTraceLevel" value="Info" />
          <!-- Use this switch to output warning and error messages -->
          <add name="warningTraceLevel" value="Warning" />
          <!-- Use this switch to output error messages -->
          <add name="errorTraceLevel" value="Error" />
          <!-- Use this switch to output no tracing messages -->
          <add name="offTraceLevel" value="Off" />
        </switches>
      </system.diagnostics>
    </configuration>

    With this configuration, the console output is:

    defaultTraceSource Warning: 0 : Unable to process work item -1 (The value must be greater than or equal to zero.
    Parameter name: d).
    The square root of 0 is 0.000.
    The square root of 1 is 1.000.
    The square root of 2 is 1.414.
    The square root of 3 is 1.732.
    The square root of 4 is 2.000.

    With just a little more configuration, we can specify that we want all log messages to go to the console (for example, so the person running the utility can easily monitor the progress of some long-running operation) but only output information, warning, and error messages to a file (possibly for later review).

    In the following configuration, note the new logFileTraceListener and the corresponding <filter> element used to limit the file output to level "Information" (and above -- which includes warning and error messages).

    <?xml version="1.0" encoding="utf-8" ?>
    <configuration>
      <system.diagnostics>
        <sources>
          <source name="defaultTraceSource" switchName="allTraceLevel">
            <listeners>
              <add name="consoleListener" />
              <add name="logFileTraceListener" />
              <!--
                Remove the Default listener to avoid duplicate messages
                being sent to the debugger for display
              -->
              <remove name="Default" />
            </listeners>
          </source>
        </sources>
        <sharedListeners>
          <add
            type="System.Diagnostics.ConsoleTraceListener"
            name="consoleListener"
            traceOutputOptions="None" />
          <add
            type="System.Diagnostics.TextWriterTraceListener"
            name="logFileTraceListener"
            initializeData="AdminConsole.log"
            traceOutputOptions="DateTime">
            <!--
              Use a filter so that log file excludes low-level debugging messages
            -->
            <filter type="System.Diagnostics.EventTypeFilter"
              initializeData="Information" />
          </add>
        </sharedListeners>
        <switches>
          <!-- Use this switch to output all log messages -->
          <add name="allTraceLevel" value="All" />
          <!-- Use this switch to output low-level debugging, informational,
            warning, and error messages -->
          <add name="verboseTraceLevel" value="Verbose" />
          <!-- Use this switch to output informational, warning,
            and error messages -->
          <add name="infoTraceLevel" value="Info" />
          <!-- Use this switch to output warning and error messages -->
          <add name="warningTraceLevel" value="Warning" />
          <!-- Use this switch to output error messages -->
          <add name="errorTraceLevel" value="Error" />
          <!-- Use this switch to output no tracing messages -->
          <add name="offTraceLevel" value="Off" />
        </switches>
      </system.diagnostics>
    </configuration>

    This produces a file named AdminConsole.log with the following content:

    defaultTraceSource Information: 0 : AdminConsole.exe
        DateTime=2009-06-18T16:57:54.4488429Z
    defaultTraceSource Warning: 0 : Unable to process work item -1 (The value must be greater than or equal to zero.
    Parameter name: d).
        DateTime=2009-06-18T16:57:54.4798429Z
    defaultTraceSource Information: 0 : Successfully completed processing.
        DateTime=2009-06-18T16:57:54.4818429Z
    defaultTraceSource Information: 0 : Program complete.
        DateTime=2009-06-18T16:57:54.4828429Z

    Unfortunately the TextWriterTraceListener class appends the timestamp onto a separate line, but you can easily substitute a custom listener that formats results like the following, if necessary:

    2009-06-18T17:17:43 Information: AdminConsole.exe
    2009-06-18T17:17:43 Warning: Unable to process work item -1 (The value must be greater than or equal to zero.
    Parameter name: d).
    2009-06-18T17:17:43 Information: Successfully completed processing.
    2009-06-18T17:17:43 Information: Program complete.
    

    When I wrote the Logger class a few years ago, I also wrote a SimpleTraceListener class to do just this:

    using System;
    using System.Collections;
    using System.Diagnostics;
    using System.Globalization;
    using System.IO;
    using System.Runtime.InteropServices;
    using System.Security.Permissions;
    
    namespace Fabrikam.Demo.CoreServices.Logging
    {
        /// <summary>
        /// 
        /// </summary>
        [HostProtection(SecurityAction.LinkDemand, Synchronization = true)]
        public class SimpleTraceListener : TextWriterTraceListener
        {
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class.
            /// </summary>
            public SimpleTraceListener()
            {
            }
    
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class, using the specified stream as the recipient of the debugging
            /// and tracing output.
            /// </summary>
            /// <param name="stream">A <see cref="Stream"/> that represents the
            /// stream the <see cref="SimpleTraceListener"/> writes to.</param>
            public SimpleTraceListener(
                Stream stream)
                : base(stream, string.Empty)
            {
            }
    
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class, using the specified writer as the recipient of the debugging
            /// and tracing output.
            /// </summary>
            /// <param name="writer">A <see cref="TextWriter"/> that receives the
            /// output from the <see cref="SimpleTraceListener"/>.</param>
            public SimpleTraceListener(
                TextWriter writer)
                : base(writer, string.Empty)
            {
            }
    
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class, using the specified file as the recipient of the debugging
            /// and tracing output.
            /// </summary>
            /// <param name="fileName">The name of the file the
            /// <see cref="SimpleTraceListener"/> writes to.</param>
            public SimpleTraceListener(
                string fileName)
                : base(fileName)
            {
            }
    
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class with the specified name, using the specified stream as the
            /// recipient of the debugging and tracing output.
            /// </summary>
            /// <param name="stream">A <see cref="Stream"/> that represents the
            /// stream the <see cref="SimpleTraceListener"/> writes to.</param>
            /// <param name="name">The name of the new instance.</param>
            public SimpleTraceListener(
                Stream stream,
                string name)
                : base(stream, name)
            {
            }
    
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class with the specified name, using the specified writer as the
            /// recipient of the debugging and tracing output.
            /// </summary>
            /// <param name="writer">A <see cref="TextWriter"/> that receives the
            /// output from the <see cref="SimpleTraceListener"/>.</param>
            /// <param name="name">The name of the new instance.</param>
            public SimpleTraceListener(
                TextWriter writer,
                string name)
                : base(writer, name)
            {
            }
    
            /// <summary>
            /// Initializes a new instance of the <see cref="SimpleTraceListener"/>
            /// class with the specified name, using the specified file as the
            /// recipient of the debugging and tracing output.
            /// </summary>
            /// <param name="fileName">The name of the file the
            /// <see cref="SimpleTraceListener"/> writes to.</param>
            /// <param name="name">The name of the new instance.</param>
            public SimpleTraceListener(
                string fileName,
                string name)
                : base(fileName, name)
            {
            }
    
            private bool IsEnabled(
                TraceOptions options)
            {
                return ((options & this.TraceOutputOptions) != TraceOptions.None);
            }
    
            /// <summary>
            /// Writes trace information, a message, and event information to the
            /// listener specific output.
            /// </summary>
            /// <param name="eventCache">A TraceEventCache object that contains the
            /// current process ID, thread ID, and stack trace information.</param>
            /// <param name="source">A name used to identify the output, typically
            /// the name of the application that generated the trace event.</param>
            /// <param name="eventType">One of the TraceEventType values specifying
            /// the type of event that has caused the trace.</param>
            /// <param name="id">A numeric identifier for the event.</param>
            /// <param name="message">A message to write.</param>
            [ComVisible(false)]
            public override void TraceEvent(
                TraceEventCache eventCache,
                string source,
                TraceEventType eventType,
                int id,
                string message)
            {
                if ((this.Filter == null)
                    || this.Filter.ShouldTrace(
                        eventCache, source, eventType, id, message, null, null, null))
                {
                    this.WriteHeader(source, eventType, id, eventCache);
                    this.WriteLine(message);
                    this.WriteFooter(eventCache);
                }
            }
    
            /// <summary>
            /// Writes trace information, a formatted array of objects and event
            /// information to the listener specific output.
            /// </summary>
            /// <param name="eventCache">A TraceEventCache object that contains the
            /// current process ID, thread ID, and stack trace information.</param>
            /// <param name="source">A name used to identify the output, typically
            /// the name of the application that generated the trace event.</param>
            /// <param name="eventType">One of the TraceEventType values specifying
            /// the type of event that has caused the trace.</param>
            /// <param name="id">A numeric identifier for the event.</param>
            /// <param name="format">A format string that contains zero or more
            /// format items, which correspond to objects in the
            /// <paramref name="args"/> array.</param>
            /// <param name="args">An object array containing zero or more objects
            /// to format.</param>
            [ComVisible(false)]
            public override void TraceEvent(
                TraceEventCache eventCache,
                string source,
                TraceEventType eventType,
                int id,
                string format,
                params object[] args)
            {
                if ((this.Filter == null)
                    || this.Filter.ShouldTrace(
                        eventCache, source, eventType, id, format, args, null, null))
                {
                    this.WriteHeader(source, eventType, id, eventCache);
                    if (args != null)
                    {
                        this.WriteLine(string.Format(
                                CultureInfo.InvariantCulture, format, args));
                    }
                    else
                    {
                        this.WriteLine(format);
                    }
                    this.WriteFooter(eventCache);
                }
            }
    
            private void WriteFooter(
                TraceEventCache eventCache)
            {
                if (eventCache == null)
                {
                    return;
                }
    
                this.IndentLevel++;
                if (this.IsEnabled(TraceOptions.ProcessId))
                {
                    this.WriteLine("ProcessId=" + eventCache.ProcessId);
                }
                if (this.IsEnabled(TraceOptions.LogicalOperationStack))
                {
                    this.Write("LogicalOperationStack=");
                    Stack logicalOperationStack = eventCache.LogicalOperationStack;
                    bool flag = true;
                    foreach (object obj2 in logicalOperationStack)
                    {
                        if (!flag)
                        {
                            this.Write(", ");
                        }
                        else
                        {
                            flag = false;
                        }
                        this.Write(obj2.ToString());
                    }
                    this.WriteLine(string.Empty);
                }
                if (this.IsEnabled(TraceOptions.ThreadId))
                {
                    this.WriteLine("ThreadId=" + eventCache.ThreadId);
                }
                if (this.IsEnabled(TraceOptions.Timestamp))
                {
                    this.WriteLine("Timestamp=" + eventCache.Timestamp);
                }
                if (this.IsEnabled(TraceOptions.Callstack))
                {
                    this.WriteLine("Callstack=" + eventCache.Callstack);
                }
                this.IndentLevel--;
            }
    
            private void WriteHeader(
                string source,
                TraceEventType eventType,
                int id,
                TraceEventCache eventCache)
            {
                if (eventCache != null)
                {
                    if (this.IsEnabled(TraceOptions.DateTime))
                    {
                        DateTime localTime = eventCache.DateTime.ToLocalTime();
                        string formattedDate = localTime.ToString(
                            "s",
                            CultureInfo.InvariantCulture);
    
                        this.Write(formattedDate);
                        this.Write(" ");
                    }
                }
    
                this.Write(
                    string.Format(
                        CultureInfo.InvariantCulture,
                        "{0}: ",
                        eventType.ToString()));
            }
        }
    }
    

    Depending on your specific needs, you could modify the WriteHeader and WriteFooter methods to output additional fields on the same line as the log message. (In my scenario, I only needed to support the TraceOptions.DateTime option.)

    In my next post, I discuss logging to the ASP.NET tracing feature.

  • A Simple, but Highly Effective Approach to Logging

    A common question that frequently arises both with customers and fellow consultants is what do I recommend for logging? As experienced software developers, we know that there are going to be errors in our solution -- as well as other important events that we want to monitor -- and therefore we know we need a robust way of logging these.

    However, with numerous options available -- e.g. log4net, Enterprise Library, Common.Logging, SharePoint ULS, etc. -- it's no wonder this is frequently a "hot" topic.

    Several years ago, I created a simple, but highly effective approach to logging based on the (then) new System.Diagnostics features in the .NET Framework version 2.0.

    Before introducing my logging feature, it is first important to understand the goals (and non-goals) of the solution.

    Goals and Non-Goals

    The primary goals of the logging feature are:

    • Provide solution components a way of logging messages of various levels (e.g. errors, warnings, information) with minimal custom code.
    • Ensure log messages can be enabled in all environments (e.g. DEV, TEST, and PROD); in other words, in both Debug and Release builds (unlike the Debug.WriteLine method, which relies on the DEBUG conditional compilation constant).
    • Through configuration, enable log messages to be routed to various outputs such as a text file, the Windows Event Log, or ASP.NET tracing.
    • Ensure that different levels of log messages can be filtered and potentially routed to different outputs; for example, log all messages to the console, but only log errors and warnings to a text file.

    Non-goals of the logging feature include:

    • Providing the fastest possible logging implementation; rather the performance impact of logging should be insignificant when compared with the "real" work performed by the solution components.
    • Changing logging configuration without reinitializing the solution; for example, to change the logging for an ASP.NET application, it is acceptable to restart the corresponding application pool.
    • Filtering log messages based on subsystems (or feature areas) of the solution; for example, when logging is enabled for debug messages, then log messages from all components are output.
    Introducing the Logger Class

    With the custom Logger class, logging a debug message is simply a matter of calling a static method, specifying nothing more than a string containing the message :

        Logger.LogDebug("Successfully loaded search results into DataSet.");

    This example shows how the Logger class achieves the primary design goal. Note that there is no need to explicitly create objects within each class -- or create additional classes within an assembly -- for logging purposes.

    Also note that the Logger class provides additional overloads to easily format log messages:

        Logger.LogDebug(
            CultureInfo.InvariantCulture,
            "Successfully loaded embedded resource ({0})"
                + " ({1:n0} bytes) from assembly ({2}).",
            resourceName,
            resourceContent.Length,
            resourceAssembly.FullName);

    Note that the Logger.LogDebug method is simply a convenient alternative to the Logger.Log method:

        /// <summary>
        /// Logs an event to the trace listeners using the specified
        /// event type and message.
        /// </summary>
        /// <param name="eventType">One of the System.Diagnostics.TraceEventType
        /// values that specifies the type of event being logged.</param>
        /// <param name="message">The message to log.</param>
        public static void Log(
            TraceEventType eventType,
            string message)

    Other methods such as LogInfo and LogError provide similar overloads for convenience.

    The simplicity of the Logger class is made possible by the improved tracing functionality introduced in the .NET Framework version 2.0. Specifically, the Logger class is simply a "wafer-thin" wrapper around the System.Diagnostics.TraceSource class.

    The Logger class declares a singleton TraceSource that is used to log all messages:

        private static TraceSource defaultTraceSource =
            new TraceSource("defaultTraceSource");
    

    Various listeners can then be configured to output log messages. Each type of listener derives from TraceListener.

    Note that the .NET Framework includes listeners for logging to a file, the Windows Event Log, as well as ASP.NET tracing. Consequently, with just a little bit of custom code (i.e. the Logger class) combined with all the "goodness" baked into the core .NET Framework, we have a logging feature that meets all of the established goals.

    In my next post, I introduce how to configure logging (starting out with a console application).

    Here is the complete source for the Logger class:

    #define TRACE
    
    using System;
    using System.Diagnostics;
    using System.Globalization;
    using System.Text;
    
    namespace Fabrikam.Demo.CoreServices.Logging
    {
        /// <summary>
        /// Exposes static methods for logging various events (e.g. debug,
        /// informational, warning, etc.). This class cannot be inherited.
        /// </summary>
        /// <remarks>
        /// All methods of the <b>Logger</b> class are static
        /// and can therefore be called without creating an instance of the class.
        /// </remarks>
        public sealed class Logger
        {
            private static TraceSource defaultTraceSource =
                new TraceSource("defaultTraceSource");
    
            private Logger() { } // all members are static
    
            /// <summary>
            /// Flushes all the trace listeners in the trace listener collection.
            /// </summary>
            public static void Flush()
            {
                defaultTraceSource.Flush();
            }
    
            /// <summary>
            /// Logs an event to the trace listeners using the specified
            /// event type and message.
            /// </summary>
            /// <param name="eventType">One of the System.Diagnostics.TraceEventType
            /// values that specifies the type of event being logged.</param>
            /// <param name="message">The message to log.</param>
            public static void Log(
                TraceEventType eventType,
                string message)
            {
    #if DEBUG
                // Some debug listeners (e.g. DbgView.exe) don't buffer output, so
                // Debug.Write() is effectively the same as Debug.WriteLine().
                // For optimal appearance in these listeners, format the output
                // for a single call to Debug.WriteLine().
                StringBuilder sb = new StringBuilder();
    
                sb.Append(eventType.ToString());
                sb.Append(": ");
                sb.Append(message);
    
                string formattedMessage = sb.ToString();
                Debug.WriteLine(formattedMessage);
    #endif
    
                defaultTraceSource.TraceEvent(eventType, 0, message);
            }
    
            /// <summary>
            /// Logs a debug event to the trace listeners using the specified
            /// format string and arguments.
            /// </summary>
            /// <param name="provider">An System.IFormatProvider that supplies
            /// culture-specific formatting information.</param>
            /// <param name="format">A composite format string.</param>
            /// <param name="args">An System.Object array containing zero or more
            /// objects to format.</param>
            public static void LogDebug(
                IFormatProvider provider,
                string format,
                params object[] args)
            {
                string message = string.Format(
                    provider, format, args);
    
                LogDebug(message);
            }
    
            /// <summary>
            /// Logs a debug event to the trace listeners.
            /// </summary>
            /// <param name="message">The message to log.</param>
            public static void LogDebug(
                string message)
            {
                Log(TraceEventType.Verbose, message);
            }
    
            /// <summary>
            /// Logs a critical event to the trace listeners using the specified
            /// format string and arguments.
            /// </summary>
            /// <param name="provider">An System.IFormatProvider that supplies
            /// culture-specific formatting information.</param>
            /// <param name="format">A composite format string.</param>
            /// <param name="args">An System.Object array containing zero or more
            /// objects to format.</param>
            public static void LogCritical(
                IFormatProvider provider,
                string format,
                params object[] args)
            {
                string message = string.Format(
                    provider, format, args);
    
                LogCritical(message);
            }
    
            /// <summary>
            /// Logs a critical event to the trace listeners.
            /// </summary>
            /// <param name="message">The message to log.</param>
            public static void LogCritical(
                string message)
            {
                Log(TraceEventType.Critical, message);
            }
    
            /// <summary>
            /// Logs an error event to the trace listeners using the specified
            /// format string and arguments.
            /// </summary>
            /// <param name="provider">An System.IFormatProvider that supplies
            /// culture-specific formatting information.</param>
            /// <param name="format">A composite format string.</param>
            /// <param name="args">An System.Object array containing zero or more
            /// objects to format.</param>
            public static void LogError(
                IFormatProvider provider,
                string format,
                params object[] args)
            {
                string message = string.Format(
                    provider, format, args);
    
                LogError(message);
            }
    
            /// <summary>
            /// Logs an error event to the trace listeners.
            /// </summary>
            /// <param name="message">The message to log.</param>
            public static void LogError(
                string message)
            {
                Log(TraceEventType.Error, message);
            }
    
            /// <summary>
            /// Logs an informational event to the trace listeners using the specified
            /// format string and arguments.
            /// </summary>
            /// <param name="provider">An System.IFormatProvider that supplies
            /// culture-specific formatting information.</param>
            /// <param name="format">A composite format string.</param>
            /// <param name="args">An System.Object array containing zero or more
            /// objects to format.</param>
            public static void LogInfo(
                IFormatProvider provider,
                string format,
                params object[] args)
            {
                string message = string.Format(
                    provider, format, args);
    
                LogInfo(message);
            }
    
            /// <summary>
            /// Logs an informational event to the trace listeners.
            /// </summary>
            /// <param name="message">The message to log.</param>
            public static void LogInfo(
                string message)
            {
                Log(TraceEventType.Information, message);
            }
    
            /// <summary>
            /// Logs a warning event to the trace listeners using the specified
            /// format string and arguments.
            /// </summary>
            /// <param name="provider">An System.IFormatProvider that supplies
            /// culture-specific formatting information.</param>
            /// <param name="format">A composite format string.</param>
            /// <param name="args">An System.Object array containing zero or more
            /// objects to format.</param>
            public static void LogWarning(
                IFormatProvider provider,
                string format,
                params object[] args)
            {
                string message = string.Format(
                    provider, format, args);
    
                LogWarning(message);
            }
    
            /// <summary>
            /// Logs a warning event to the trace listeners.
            /// </summary>
            /// <param name="message">The message to log.</param>
            public static void LogWarning(
                string message)
            {
                Log(TraceEventType.Warning, message);
            }
        }
    }
    

    Note that the Logger.cs file actually includes #define TRACE at the top of the file. This is because I originally wrote this class with an old version of Visual Studio (which did not define this compilation constant by default when creating new projects). Visual Studio 2008 projects include this in the project options by default (for both Debug and Release configurations), so this is superfluous.

    As you can see, there's really not much to this class (which hopefully means there isn't much that can go wrong with it). Most, if not all, of it should be very straightforward. I'll explain the importance of the Logger.Flush method in my next post.

  • Environment Naming Conventions

    One of the challenges I see in organizations that I work with is the lack of naming conventions for various environments -- or sometimes naming conventions that provide little or no value.

    For about the last ten years, I've been a strong proponent of a simple "-suffix" naming convention that is not only very easy to learn (and remember!) but also makes things incredibly obvious to all team members and stakeholders on a project.

    Most enterprise IT organizations typically have a naming convention for servers that includes things like the Active Directory domain the server is a member of, the role of the server, and usually some unique identifier to distinguish multiple servers in a farm. Other "ingredients" such as the datacenter the server is physically located in may also be included.

    For example, my favorite fictitious manufacturing company, Fabrikam Technologies, has Production servers named:

    • FAB-DC-01 (the first domain controller for the FABRIKAM domain),
    • FAB-DC-02,
    • FAB-WEB-01 (the first Web server in a farm),
    • FAB-WEB-02,
    • FAB-SQL-01A (the first node in a SQL Server cluster, for which the cluster is named FAB-SQL-01),
    • FAB-SQL-01B,
    • etc.

    This is a great start. As you can see from these examples, it's pretty easy to tell what the role of each server is.

    However, in any organization of reasonable size, we certainly need more than just the Production environment (PROD). At a minimum, I recommend using a Test environment (TEST) and a Development environment (DEV). Note that this is in addition to individual developer environments -- which I typically refer to as "local" evironments (LOCAL). Depending on how much parallel development is planned -- and the corresponding release schedule -- you might also need a Maintenance environment (MAINT). However, many organizations can function effectively with just the DEV-TEST-PROD triad.

    So this begs the question, what names should we use for DEV and TEST?

    Here is what I recommend:

    Monikers in the Development environment utilize a “-dev” suffix. For example, the Web server in DEV corresponding to the FAB-WEB-01 server in PROD is named FAB-WEB-01-DEV. Likewise, the SQL Server in the Development environment is named FAB-SQL-01A-DEV. Note that typically Development environments do not have a cluster, but I still recommend following the same naming convention and even adding a DNS entry for the DEV "cluster" name (e.g. FAB-SQL-01-DEV). Test environments often do have a SQL Server cluster configuration (which is a great place to validate your failover configuration and load testing).

    Host headers in the Development environment also follow the “-dev” naming convention. For example, if the internal name of the Fabrikam Web site in Production is http://fabrikam, then http://fabrikam-dev is the corresponding URL used in the Development environment.

    In order to distinguish sites on the local development VMs, the “-local” suffix is used. For example, http://fabrikam-local is the URL on an individual developer’s VM corresponding to http://fabrikam in Production. The %WINDIR%\System32\Drivers\etc\hosts file is then used to associate these URLs with the loopback address (127.0.0.1). [Be sure you are aware of the workaround in KB 896861 when using the loopback address.]

    Similarly, monikers and host headers in the Test environment utilize a “-test” suffix (e.g. FAB-WEB-01-TEST, FAB-SQL-01A-TEST, and http://fabrikam-test).

    Also note that organizations typically create separate service accounts within Active Directory for the Development, Test, and Production environments (and if you are not currently doing this, I strongly recommend it). For example, suppose FABRIKAM\svc-web is the service account for the application pool running http://fabrikam in Production. Then we would expect the Web site in DEV to be running as FABRIKAM\svc-web-dev and the site in TEST to be running as FABRIKAM\svc-web-test.

    This ensures that only the minimal number of people need to know the passwords for a particular environment. For example, either the whole Development team -- or just a small subset of team leads -- needs to know the password for FABRIKAM\svc-web-dev, but they certainly don't know the password for FABRIKAM\svc-web-test (since that environment is managed by the Test team). Likewise, the Test team had better not know the password for the service account in Production (since -- at least hopefully -- that environment is owned by a separate Release Management team).

    It is also important to point out how this naming convention is applied to fully qualified domain names (FQDNs). For example, suppose the external address of http://fabrikam is http://www.fabrikam.com. What then should we use for the corresponding FQDN in DEV, or should we even configure an FQDN for DEV? The answer to that latter question is a resounding "Yes!" and the answer to the former is http://www-dev.fabrikam.com. Note that we almost certainly won't to expose DEV on the Internet -- although we may choose to expose TEST ( http://www-test.fabrikam.com)

    The primary reason I recommend using these FQDNs (aside from the fact that we are following the simple "-suffix" naming convention) is that browsers behave differently between intranet names (e.g. http://fabrikam-dev) and FQDNs (e.g. http://www-dev.fabrikam.com). In other words, when you are trying to simulate a problem on the external site, you should ensure that you are simulating the same security "zone" in DEV, or even in your local environment (e.g. http://www-local.fabrikam.com).

    Lastly, I want to mention documentation. Whenever I sit down to write an Installation Guide -- or similar documentation -- I typically only specify the values for the Production environment, even though I fully expect the document to also be used to install and configure the Test and Development environments. I simply include a brief section at the beginning of the document describing the naming convention and that it is the responsibility of the developer or tester to modify the server names, host headers, and service accounts appropriately as he or she is following along when configuring DEV or TEST.

    Since we typically have "infrastructure models" (i.e. Visio diagrams showing the physical architecture of DEV, TEST, and PROD), identifying servers and host headers in various environments is really straightforward.

  • SPLimitedWebPartManager.AddWebPart Mysteriously Increments zoneIndex

    One of the common tasks when using the "DR.DADA" approach to SharePoint development is programmatically creating and configuring pages on a site. This often requires adding numerous Web Parts to various zones on a page -- for example, to configure search results pages.

    Over the past couple of years, my teammates and I have created numerous "helper" classes that simplify this task in Windows SharePoint Services (WSS) 3.0 and Microsoft Office SharePoint Server (MOSS) 2007 -- including SharePointWebPartHelper.

    /// <summary>
    /// Exposes static methods for commonly used helper functions for
    /// SharePoint Web Parts. This class cannot be inherited.
    /// </summary>
    /// <remarks>
    /// All methods of the <b>SharePointWebPartHelper</b> class are static and
    /// can therefore be called without creating an instance of the class.
    /// </remarks>    
    public sealed class SharePointWebPartHelper

    SharePointWebPartHelper contains public methods like EnsureWebPart and FindWebPartByTitle. As you can probably tell from the names of these methods, this allows you to locate an existing Web Part on a page or create one if the specified Web Part doesn't currently exist on the page.

    EnsureWebPart attempts to find a Web Part based on the specified webPartId and if the Web Part is not found, then it uses the CreateWebPart method to create a new Web Part. Here is the original implementation of the CreateWebPart method:

        private static WebPart CreateWebPart(
            SPWebPartPages.SPLimitedWebPartManager wpm,
            string webPartId,
            string webPartFilename,
            string zoneId,
            ref int zoneIndex)
        {
            Debug.Assert(wpm != null);
            Debug.Assert(string.IsNullOrEmpty(webPartId) == false);
            Debug.Assert(string.IsNullOrEmpty(webPartFilename) == false);
            Debug.Assert(string.IsNullOrEmpty(zoneId) == false);
    
            Logger.LogDebug(
                CultureInfo.InvariantCulture,
                "Creating Web Part ({0}) on page ({1})...",
                webPartId,
                wpm.ServerRelativeUrl);
    
            WebPart webPart = null;
    
            SPFile wpFile = GetWebPartFileFromGallery(
                wpm.Web.Site,
                webPartFilename);
    
            Debug.Assert(wpFile != null);
    
            string errorMessage = string.Empty;
    
            using (Stream stream = wpFile.OpenBinaryStream())
            {
                XmlReader reader = XmlReader.Create(stream);
                webPart = wpm.ImportWebPart(reader, out errorMessage);
            }
    
            if (string.IsNullOrEmpty(errorMessage) == false)
            {
                string message =
                    "Error importing Web Part ("
                        + webPartFilename + "): "
                        + errorMessage;
    
                throw new ApplicationException(message);
            }
    
            webPart.ID = webPartId;
            wpm.AddWebPart(webPart, zoneId, zoneIndex);        
            zoneIndex++;
            
            Logger.LogDebug(
                CultureInfo.InvariantCulture,
                "Successfully created Web Part ({0}) on page ({1}).",
                webPartId,
                wpm.ServerRelativeUrl);
    
            return webPart;
        }

    Note that SPWebPartPages is simply an alias for the Microsoft.SharePoint.WebPartPages namespace (in order to avoid "collisions" with the System.Web.UI.WebControls.WebParts namespace). Also, please ignore the use of ApplicationException -- apparently there's still a little "code cleanup" to be done here.

    As I called out above, this code shows the original implementation of the method. It turns out there's a very obscure bug in it, that I only discovered within the last couple of months.

    As you can probably guess from the title of this post, the problem is that zoneIndex (i.e. the position of the Web Part relative to other Web Parts within the same Web Part zone) isn't always incremented as you would expect.

    When adding the first, second, third, and fourth Web Parts to a zone:

        SPLimitedWebPartManager.AddWebPart(webPart, zoneId, zoneIndex)

    behaves as expected, meaning that (webPart.ZoneIndex == zoneIndex).

    However, when adding the fifth and sixth Web Parts to a zone, then (webPart.ZoneIndex == zoneIndex + 1).

    I suspect it is due to the SPWebPartManager.MakeSpaceForWebpart method (which is called from SPLimitedWebPartManager.AddWebPart). However, the SPWebPartManager.MakeSpaceForWebpart method is obfuscated and therefore I can’t see what it is doing using Reflector.

    This behavior caused some Web Parts to appear in the wrong location, and therefore I had to come up with a hack for it. Here is my updated version of the CreateWebPart method:

        private static WebPart CreateWebPart(
            SPWebPartPages.SPLimitedWebPartManager wpm,
            string webPartId,
            string webPartFilename,
            string zoneId,
            ref int zoneIndex)
        {
            Debug.Assert(wpm != null);
            Debug.Assert(string.IsNullOrEmpty(webPartId) == false);
            Debug.Assert(string.IsNullOrEmpty(webPartFilename) == false);
            Debug.Assert(string.IsNullOrEmpty(zoneId) == false);
    
            Logger.LogDebug(
                CultureInfo.InvariantCulture,
                "Creating Web Part ({0}) on page ({1})...",
                webPartId,
                wpm.ServerRelativeUrl);
    
            WebPart webPart = null;
    
            SPFile wpFile = GetWebPartFileFromGallery(
                wpm.Web.Site,
                webPartFilename);
    
            Debug.Assert(wpFile != null);
    
            string errorMessage = string.Empty;
    
            using (Stream stream = wpFile.OpenBinaryStream())
            {
                XmlReader reader = XmlReader.Create(stream);
                webPart = wpm.ImportWebPart(reader, out errorMessage);
            }
    
            if (string.IsNullOrEmpty(errorMessage) == false)
            {
                string message =
                    "Error importing Web Part ("
                        + webPartFilename + "): "
                        + errorMessage;
    
                throw new ApplicationException(message);
            }
    
            webPart.ID = webPartId;
            wpm.AddWebPart(webPart, zoneId, zoneIndex);
    
            // Bug 68288:
            //
            // HACK: When adding the first, second, third, and fourth Web Parts
            // to a zone:
            //
            //    SPLimitedWebPartManager.AddWebPart(webPart, zoneId, zoneIndex)
            //
            // behaves as expected, meaning that
            // (webPart.ZoneIndex == zoneIndex).
            //
            // However, when adding the fifth and sixth Web Parts to a zone,
            // then (webPart.ZoneIndex == zoneIndex + 1).
            if (webPart.ZoneIndex > zoneIndex)
            {
                Debug.Assert(zoneIndex >= 4);
    
                Logger.LogDebug(
                    CultureInfo.InvariantCulture,
                    "HACK: webPart.ZoneIndex ({0})"
                        + " is greater than zoneIndex ({1})."
                        + " Setting zoneIndex to {0}...",
                    webPart.ZoneIndex,
                    zoneIndex);
    
                zoneIndex = webPart.ZoneIndex;
            }
    
            Debug.Assert(webPart.ZoneIndex == zoneIndex);
            zoneIndex++;
            
            Logger.LogDebug(
                CultureInfo.InvariantCulture,
                "Successfully created Web Part ({0}) on page ({1}).",
                webPartId,
                wpm.ServerRelativeUrl);
    
            return webPart;
        }
    

    I was curious to know why SharePoint behaves this way and to see if this behavior is documented somewhere and I just missed it. Unfortunately, the e-mail I sent back in March to an internal discussion list received no responses. So I guess this will just have to remain a mystery.

  • Why choose "Server Core" installation of Windows Server 2008?

    If you ever find yourself looking for reasons or evidence why you should choose the "Server Core" installation option for Windows Server 2008, try searching for the following:

    "Windows Server 2008 Server Core installation not affected" site:microsoft.com/technet/security

    You will find page after page of results similar to the following:

    Microsoft Security Bulletin MS08-054 – Critical
    Windows Server 2008 server core installation not affected. The vulnerability addressed by this update does not affect supported editions of Windows Server 2008 if Windows Server ...
    www.microsoft.com/technet/security/Bulletin/MS08-054.mspx · Cached page

    Microsoft Security Bulletin MS08-078 - Critical
    Windows Server 2008 server core installation not affected. The vulnerabilities addressed by this update do not affect supported editions of Windows Server 2008 if Windows Server ...
    www.microsoft.com/technet/security/bulletin/ms08-078.mspx · Cached page

    Microsoft Security Bulletin MS08-053 – Critical
    Windows Server 2008 server core installation not affected. The vulnerability addressed by this update does not affect supported editions of Windows Server 2008 if Windows Server ...
    www.microsoft.com/technet/security/Bulletin/MS08-053.mspx · Cached page

    Microsoft Security Bulletin MS08-024 - Critical: Cumulative Security ...
    Windows Server 2008 server core installation not affected. The vulnerabilities addressed by these updates do not affect supported editions of Windows Server 2008 if Windows Server ...
    www.microsoft.com/technet/security/Bulletin/MS08-024.mspx · Cached page

    Microsoft Security Bulletin MS08-052 – Critical
    Windows Server 2008 Server Core installation not affected. The vulnerabilities addressed by this update do not affect supported editions of Windows Server 2008 if Windows Server ...
    www.microsoft.com/technet/security/bulletin/ms08-052.mspx · Cached page

    ...

    Seeing all these results is refreshing when I think back on the challenges I had to overcome when building out my first Hyper-V server using the Server Core installation, such as configuring remote administration of Hyper-V, or whenever I need to view PerfMon data on a Server Core machine (which is trivial on a "Full" installation, but not quite so easy on a Server Core installation).

    Thanks to Ana Paula Moreira Franco, a Senior Consultant with Microsoft Consulting Services in Brazil, for pointing out these search terms.

  • Tell Mode vs. Ask Mode

    The project I am currently working on is nearing the end. Last week we reached our "Feature Complete" milestone and now we have formally transitioned into the "Stabilizing" phase.

    In a couple of team meetings this week, I mentioned the concepts of "Tell Mode" and "Ask Mode" -- a couple of terms I've been using for more years than I can remember. However, not everyone on the team was aware of these concepts. Consequently, I "recycled some bits" (meaning I searched through my e-mail archive and found a message I sent awhile back) in order to provide some more background and details on Tell Mode and Ask Mode.

    I thought this worth sharing with a broader audience.

    I'll warn you...this is a rather long post and not one I'm expecting many people to read in its entirety. Rather, I think a lot of people would benefit from reading just enough of my e-mail to understand the key concepts and perhaps skim the example bugs to get a feel for the level of detail expected during the "investigation" phase after switching to Ask Mode.


    From: JAMESON,JEREMY (Non-A-BPI-AM,unix1)
    Sent: Thursday, October 18, 2007 8:03 AM
    Subject: v2.0 Transition from "Tell Mode" to "Ask Mode"

    On Sunday night, October 21st, RC4 of the [Project] v2.0 solution will be deployed to TEST. This will mark the official transition from "Tell Mode" to "Ask Mode."

    What does this mean?

    Microsoft uses Tell Mode and Ask Mode to refer to different time periods after the Feature Complete milestone but prior to a release.

    During Tell Mode the Development team tells the rest of the team which issues are actively being worked on (resolved). In other words, Development is primarily driving the stabilization process based on what they think should be fixed -- as determined by priority, severity, complexity (i.e. risk), and effort required. This works for a while, but at some point you have to reign in Development in order to ship, er, release.

    Thus we transition into Ask Mode whereby Development must ask permission before resolving any issues. It is okay to investigate issues, but no code changes can be made to address an issue until approval by the “War Team” (er, Triage Team) is granted.

    During Ask Mode we look first at the scenario that is being fixed (i.e. the motivation for fixing it), we look at why the bug happens (regression, test hole, coding error, etc.), and then we investigate the necessary source code changes and associated risk. Every potential change is heavily scrutinized to evaluate whether it is worth the risk to fix it, because at this point in the schedule, every change -- even one that seems trivial -- has the potential to destabilize the solution and slip the schedule.

    While the overall process of the daily triage meetings stays the same as we transition from Tell Mode to Ask Mode, there is a noticeable shift in focus.

    During Tell Mode, work items are often immediately triaged as Approved, or work items triaged as Investigate are often just fixed without further review. This is no longer the case once we enter Ask Mode.

    In Ask Mode every work item is first assigned a triage of Investigate. The person responsible for investigating the item must thoroughly document details about the item -- in the Description field of the work item, unless a more formal DCR (Design Change Request) is deemed necessary.

    The investigator (typically a member of the Development team) documents the:

    • Motivation -- "Why are we making this change?"
    • Proposal -- "How should we resolve the issue?"
    • Risks -- "What is the worst case scenario if we make this change?"
    • Solution -- "What specifically needs to change?"
    • Teams Impacted -- "How much work is required by Development, Test, Release Management, and (potentially) Product Management teams?" (note that the estimates need to come from the respective team members -- the investigator should not "guess")

    Note that both Solution and Teams Impacted are not needed, one or the other is fine. If the necessary change (and associated risk) is very small -- such as a configuration change -- then just documenting the Solution should suffice. The goal is not to overburden ourselves with process -- but we also need to ensure that no change is made unless it has been thoroughly evaluated. If the change (or risk) is substantial, then document the impact on each of the various teams.

    You can see some example bugs from v1.0 for more details: 1592, 1505, 1533, 1582, and 1549.

    After documenting these details, the investigator then changes the Triage field to Recommend Approve (if the value in making the change is greater than the associated risk) or Recommend Reject (if the risk of making the change outweighs the value). The Triage Team then reviews the detailed information about the work item and either changes the Triage field to Approved or Not Approved (i.e. "punt to v.Next").

    Note that the Triage Team can certainly “overrule” the investigator, which is why it is critical that no work be done on actually resolving the work item until approval is received from the Triage Team (i.e. the Triage field is set to Approved). Also note that, unless you are a member of the Triage Team – and even then, only during a formal triage meeting – you should not change the Triage field to anything except Recommend Approve or Recommend Reject. Otherwise, you should fully expect a thorough hazing from virtually all team members.

    Everyone who was involved in v1.0 knows that we didn't strictly follow this process in the first release of [Project], but we also have the "scars" to remind us that we need to improve our process for this release.

    It is also important to note that Microsoft fully acknowledges that we had many more QFEs for v1.0 than we intended, and we never did deploy v1.1 as a separate release. We need to be committed to ensuring that we don't repeat this in v2.

    Yes, we will release v2.0 with known issues. By now, everyone has heard Jeremy's anecdote about the 64,000 "issues" in the RTM version of Windows 2000 -- so no sense repeating that. Rather we need to focus on making sure that most of the "issues" are known, we understand the impact of those issues on the user experience, and -- where necessary -- we find creative ways to circumvent the issues until the underlying changes can be implemented, tested, and deployed.

    Note that I have replaced the project code name with [Project] in order to protect the innocent. I also "spoofed" the links to the referenced bugs, since these referred to a "Work Items" list on a secured team site we used for the project (which obviously you wouldn't have access to -- unless you just happen to be one of my cohorts on the project).

    I have included slightly "scrubbed" versions of a couple of the bugs below, in case you are interested in seeing examples. If you don't understand all of the acronyms, terms, and technical details...don't worry, you're not supposed to -- unless you actually were a member of this project ;-)

    Bug 1592 - LiteratureResults.asp is not working
    Motivation:

    There appear to be (at least) two problems when following the repro steps:

    1. The Literature Summary list (rendered by LiteratureResults.asp when isortorder=9) should show the number of publications matching the specified criteria, grouped by Literature Type (a.k.a. publication type, a.k.a. Content Type in SharePoint, a.k.a. the ContentType2 managed property). The list should be ordered by Literature Type.
    2. Clicking on a publication type in the Literature Summary list should show the search results for publications of the selected type. According to the original description for this bug, an error occurred at this point.
    Proposal:

    Correct the Literature Summary view to properly group and order by publication type. Increase the maximum number of search results in this scenario from 200 to 1000.

    Ensure that clicking a publication type in the list shows the matching publications of the specified type.

    Risk:

    The current implementation of LiteratureResults.asp uses a hard-coded maximum of 200 search results (this limit was chosen for performance reasons since there is significant cost in sending large result sets from the SharePoint farm to the legacy ASP farm). Therefore, simply changing the sort order to publication type could potentially truncate the Literature Summary view such that it only showed one publication type (for example, if more than 200 Applications matched the specified criteria).

    While it is simple to increase the maximum number of results (for example, from 200 to 1000) when rendering the Literature Summary view, this will put considerable load on SharePoint Search for two reasons:

    1. We need to order first by ContentType2 in order to return the result set in the order expected by the legacy ASP code that generates the Literature Summary view.
    2. SharePoint Search is optimized to sort by rank first (since it is typically desired to show the "best" results at the top of the list). In order to return a result set of, say, 1000 items sorted by something other than rank, SharePoint must do a lot more work before it can trim the result set.

    Therefore it is quite possible that SharePoint Search will require > 10 seconds to generate these large result sets (although it is expected that duplicate searches will be cached and therefore return the result set much faster). As noted in bug 1151, this may cause "sporadic errors" in the legacy ASP pages.

    Teams Impacted

    Development
    Modify LiteratureSearchResults.asp to change the max number of results to be a variable with a default value of 200.

    Modify SetSortParameters in SearchModule.inc to set the sort expression used in ESI (strSortExpression) and to override the default max results value to allow 1000 results. (1 hour).
     
    Release Management
    Merge updated ASP files into legacy VSS and deploy to WCOSLSD and CAGCHEM (1 hour)
     
    Test
    Retest ESI Chromatogram searches through legacy General Site (2 hours)

    Bug 1505 - There are no results displayed in WCOSLSCD if a search is performed on few publication types
    Repro steps:
    1. Log on to http://wcoslscd.cos.fabrikam.com/scripts/library.asp
    2. Select the publication type as “Certificate of Analysis” or “Material Safety Data Sheet”  from the drop down and click on search
    3. There are no results displayed for these publication types even though there are lot of documents under these publication types in TEST
    Motivation:

    LiteratureResults.aspx currently excludes the following content types (since the number of publications of these types is disproportionately higher than other publication types and also because these publication types have separate search forms):

    • Chromatogram
    • Certificate of Analysis
    • Material Safety Data Sheet

    However, the current user experience is not desirable since the search form allows users to narrow their search results to just Certificate of Analysis or MSDS publications (which will never return results).

    Proposal:

    Remove Certificate of Analysis and MSDS from the search criteria. This would allow users to search specifically by these publication types and would also include these results by default.

    Risk:

    Of the roughly 33,000 publications in the EPI Warehouse, there are approximately 1,300 Certificate of Analysis and 7,100 MSDS publications.

    Since the new SharePoint search includes full-text indexing as well as metadata, including these two publication types by default may dramatically change the search results.

    Teams Impacted

    Development
    Modify LiteratureResults.asp to no longer exclude Certificate of Analysis and MSDS publications by default (0.5 hours).

    Release Management
    Merge updated ASP file into legacy VSS and deploy to WCOSLSCD and CAGCHEM (0.5 hours)

    Test
    Retest ESI Library searches through legacy General Site (2 hours)

    Product Management
    Review new Library search results on legacy General Site to determine if the large number of Certificate of Analysis and MSDS publications has a negative impact on search results. (2 hours)

  • Update on Patching and Disk Space Usage

    About a year ago, I wrote a post about saving huge amounts of disk space by slipstreaming service packs. Having just been through an ordeal installing Windows Server 2008 SP2, I thought it would be worthwhile to provide an update (since that original post refers to disk space usage with Windows Server 2003).

    Note that since my original post, I have switched from using Virtual Server in favor of Hyper-V. Among other things, this allows me to run x64 virtual machines (VMs). Many months ago, I consolidated numerous physical machines onto a couple of "Server Core" machines running Hyper-V. In that time, I've also switched to running Windows Vista x64 on my primary desktop and Windows Server 2008 x64 on my laptop.

    One of the things that I've noticed is that x64 versions of the operating system tend to use more disk space than their corresponding x86 equivalents. In particular, the "side-by-side" folder (WinSxS) is typically significantly larger on x64 installations. The storage differences are negligible on my physical machines, but on VMs I make a deliberate effort to "clamp down" the size of the VHDs. This can save me considerable time when copying VHDs from one server to another or from an internal hard drive to an external hard drive whenver I need to take one or more of them "on the road" with me.

    Minimizing VHD sizes also allows me to cram more VMs onto my 100 GB external drive [I know, these days this isn't very big from a capacity perspective, but at least it's 7200 RPM (a must for running VMs) and it isn't nearly as bulky as my larger drive enclosure. It also doesn't require a separate power supply either.]

    Here is a baseline of the disk space usage on a Windows Server 2008 Standard x64 VM:

    Figure 1: Disk usage on Windows Server 2008 Standard x64 VM (baseline)

    Notice that the total disk usage is about 7.5 GB and the Windows folder consumes a little over 7 GB. Also note that Windows Server 2008 included SP1 (i.e. Microsoft slipstreamed it into the initial installation in order to simplify the servicing model for both Windows Server 2008 and Windows Vista).

    I then immediately installed Windows Server 2008 SP2 and captured the following:

    Figure 2: Disk usage on Windows Server 2008 x64 VM (after installing SP2)

    Observe that the Windows folder now consumes a little over 10 GB of storage. Ouch...3 GB for a service pack. That seems a little, um, irritating -- for VMs, anyway. Obviously for physical machines with 100+ GB hard drives, the additional space is trivial.

    I then ran the Windows Component Clean tool (COMPCLN.exe) as described in my a href="http://blogs.msdn.com/jjameson/archive/2009/06/02/reclaiming-disk-space-after-installing-service-pack-2.aspx">previous post, which reclaimed approximately 900 MB of space.

    Figure 3: Disk usage on Windows Server 2008 x64 VM (after installing SP2 and running COMPCLN.exe)

    Notice that the Windows folder now consumes about 8.5 GB of space (but the overall free space on the 20 GB VHD increased from roughly 9.7 GB to 10.6 GB). In other words, SP2 adds roughly 3 GB, but COMPCLN.exe trims this to a little over 2 GB.

    LLastly, I want to point out the current disk space usage on COLOSSUS -- an x64 VM that I run WSUS (Windows Server Update Services) for managing patches and updates on the various machines in the "Jameson Datacenter." Note that this server only has WSUS (which requires IIS and SQL Server) but nothing else. Consequently, after installing Windows Server 2008 SP2 and running COMPCLN.exe, I was hoping it would have comparable disk space usage to that shown in Figure 3 (after deducting the space used by the WSUS database, of course).

    Unfortunately, it isn't even close, as shown in the following figure./p>

    Figure 4: Disk usage on a patched WSUS server (after installing SP2)

    Notice that the Windows folder on COLOSSUS consumes almost 16.5 GB of space, of which roughly 10.5 GB is used by the WinSxS folder.

    The lesson here is that you should expect some "bloat" in the Windows folder over time (largely due to the WinSxS folder), and while the Windows Component Clean tool (COMPCLN.exe) undeniably reclaims some hard drive space after installing SP2, it's definitely not the same as starting with a "fresh" SP2 install.

  • Reclaiming Disk Space After Installing Service Pack 2

    In yesterday's post, I noted the errors I encountered when trying to install Windows Server 2008 Service Pack 2 (SP2) due to "insufficient" disk space. I ended up having to expand numerous VHDs (one for each of my VMs running Windows Server 2008 x64) in order to have roughly 5 GB of free space to allow SP2 to install.

    Note that SP2 certainly didn't use the 5 GB of free space, but apparently it insists on having that much for some "factor of safety" during the install.

    Note that SP2 for Windows Server 2008 and Windows Vista include a new tool which helps recover hard disk space: the Windows Component Clean Tool (COMPCLN.exe). According to the Windows Server 2008 SP2 Deployment Guide this tool permanently removes the files that are archived after Windows Vista SP2 or Windows Server 2008 SP2 is applied. It also removes the files that were archived after Windows Vista SP1 was applied, if they are found on the system.

    The deployment guide also states that "running this tool is optional" -- however I, personally, highly recommend it. Of course, you have to weigh this decision with the probability that you will need to uninstall SP2 -- which, in my case, is essentially "zilch."

    On my x64 VMs, running COMPCLN.exe freed up roughly 800 MB of disk space. This might not seem like a lot -- given that many hard drives these days exceed 1 TB -- but it is very significant on VHDs that you are trying to keep as "lean" as possible.

    Note that I'm still a little disappointed in the disk space requirements for SP2. Up until yesterday I had been running each of my domain controller VMs on 16 GB VHDs, and many of my other VMs on 20-22 GB VHDs. Note that on some of those VMs, disk space was certainly getting tight -- due to all of the patches that have been installed since I originally built them -- but they were functioning just fine until Windows Server 2008 SP2 came along. Although I have to say that on a 20 GB VHD, a WinSxS folder consuming 8-10 GB seems a little ridiculous.

    I ended up having to expand the system VHD for my MOSS 2007 development VM to 25 GB -- which I really didn't want to do -- since it essentially gives the SharePoint Unified Logging System another 5 GB of free space to fill with useless log messages. [That is, of course, until I get the April 2009 Cumulative Update installed -- which supposedly fixes this issue.]

  • Errors Installing Windows Server 2008 SP2

    Last week I approved Windows Server 2008 Service Pack 2 (SP2) and Windows Vista SP2 on my local WSUS (Windows Server Update Services) server. My expectation was that the various physical and virtual machines in the "Jameson Datacenter" would subsequently install the update around 3:00 AM the following morning.

    Unfortunately when I examined the WSUS console this morning, I found a number of computers reporting errors. After selecting one of the failed computers, I discovered the following:

    Windows Server 2008 Service Pack 2 Standalone x64-based Systems (KB948465) - English, French, German, Japanese, Spanish

    Event reported at 6/1/2009 3:02 AM:

    Installation Failure: Windows failed to install the following update with error 0x80070643: Windows Server 2008 Service Pack 2 Standalone x64-based Systems (KB948465) - English, French, German, Japanese, Spanish.

    A quick search for 0x80070643 led to the following KB article:

    You receive error code 0x80070643 or error code 0x643 when you use the Windows Update or Microsoft Update Web sites to install updates

    Unfortunately, this error code indicates "generic errors that basically state that an error was encountered by Windows Installer." Rather than immediately following the steps in the KB article to enable logging and try to reproduce the problem, I decided to take a quick look at the event logs and discovered the following:

    Log Name: System
    Source: Microsoft-Windows-Service Pack Installer
    Date: 6/1/2009 3:02:00 AM
    Event ID: 8
    Task Category: None
    Level: Error
    Keywords:
    User: SYSTEM
    Computer: dazzler.corp.technologytoolbox.com
    Description:
    Service Pack installation failed with error code 0x800f0826.

    Another quick search for 0x800f0826 suggested that the problem might be due to insufficient disk space. However, I checked the free space on DAZZLER and observed that it had 4.09 GB free. Surely, 4 GB of disk space is sufficient to install Windows Server 2008 SP2!

    Then I came across the following:

    Here are the disk space requirements according to the deployment guide:

    Disk Space Requirements for Windows Server 2008 SP2
    Installation method Approximate disk space requirements
    Stand-alone installation
    • x86-based: 1.8 GB to 2.9 GB
    • x64-based: 3.2 GB to 4.9 GB
    • ia64-based: 2.9 GB to 3.2 GB
    Windows Update
    • x86-based: 350 MB
    • x64-based: 600 MB
    • ia64-based: 2.25 GB
    Integrated installation
    • x86-based: 9 GB
    • x64-based: 12 GB
    • ia64-based: 13 GB

    Crikey! According to this table, DAZZLER needs up to 4.9 GB of free space in order to install the Service Pack (since it is an x64 VM). Wow!

    This, quite honestly, seems absolutely absurd!

    However, given that it is relatively easy to expand a VHD, I decided to just go ahead and add another 2 GB to the system drive on the VM and see if that eliminated the issue. After all, as long as SP2 doesn't actually use 4.9 GB of space, then the actual physical space consumed by the VHD should be significantly less than 5 GB.

    Using Hyper-V Manager, I expanded the VHD from 20 GB to 22 GB and then started the VM up again. I then logged into the VM and used the Disk Management console to extend the volume to include the additional 2 GB of available storage.

    Next, I kicked off the installation of Windows Server 2008 SP2 again. This time the installation completed without error. Woohoo!

    Note that DAZZLER is a dedicated Team Foundation Server "build server" -- so I didn't expect that it would need lots of disk space. In fact, it didn't -- at least not until Windows Server 2008 SP2 came along.

    Now all I have to do is add some more disk space to the other servers that are failing to install SP2.

  • Add sysadmin in SQL Server 2008 Using Local Administrator

    A couple of months ago, I had to SysPrep a copy of one of my VMs in order to remove dependencies on my home domain (I had to work out of the Microsoft office for a couple of days because my DSL router cratered).

    However, while the SysPrep process was quick and painless, after the reboot I found that I could no longer use my domain account to administer SQL Server. Sure, I had local Administrator access, but starting with SQL Server 2005, being a local Admin no longer grants you seamless and unlimited access to SQL Server.

    So the question that I had was: How do I add a user to the sysadmin role in SQL Server 2008 if all I have is local Administrator access?

    Based on my experience with SQL Server 2005, I remembered this was done as part of the installation using the Surface Area Configuration wizard. However, I couldn't find the equivalent in SQL Server 2008. The SQL Server Books Online clearly stated that the Surface Area Configuration tool was discontinued, but the "Replacement" information didn't help me in the slightest.

    I tried an Internet search (using both Windows Live Search and Google) for:

    add sysadmin SQL Server 2008

    However, neither search returned anything useful (at least not within the first two pages of results -- which is typically my threshold before I move on to a different approach to solving a problem).

    Fortunately for me, I didn't have to wait long for a response to my inquiry to one of the internal discussion lists. David Browne, a Technology Architect here at Microsoft, pointed me to the following:

    Troubleshooting: Connecting to SQL Server When System Administrators Are Locked Out

    I wish that would have come up in my search!

  • Be Careful Using PublishingWeb.GetPagesListName()

    A couple of years ago when we began evaluating Language Packs for Microsoft Office SharePoint Server (MOSS) 2007, we discovered that after installing certain Language Packs, the "Pages" library may be localized -- including both the list name as well as the URL.

    For example, after installing the Spanish Language Pack, if you had any code that referred to something like "/en-US/Products/Pages/default.aspx" then you would soon find that your code could break when referring to the equivalent page on a localized site. For example, on a Spanish site, the equivalent URL would be "/es-ES/Products/Paginas/default.aspx" (assuming you chose not to translate "Products" when creating the Spanish site).

    Fortunately, the SharePoint API provides the PublishingWeb.GetPagesListName method. In the following code sample, note how I use this method to avoid hard-coding the name of the Pages library:

            private static string GetDefaultSearchResultsPageUrl(
                SPWeb searchWeb)
            {
                Debug.Assert(searchWeb != null);
    
                string pageListName = PublishingWeb.GetPagesListName(searchWeb);
    
                string defaultSearchResultsPageUrl = string.Format(
                    CultureInfo.InvariantCulture,
                    "{0}/{1}/Results.aspx",
                    searchWeb.ServerRelativeUrl,
                    pageListName);
    
                return defaultSearchResultsPageUrl;
            }

    Consequently, this code works as expected, even on localized sites created with various Language Packs.

    The problem -- as we discovered on our project this week -- is that you have to be careful about how you use the "list name" returned from PublishingWeb.GetPagesListName().

    Last week, another developer on our team sent out an email inquiring about how to get the Pages list in a way that worked even with localized sites. I quickly responded pointing out the PublishingWeb.GetPagesListName() method.

    Unfortunately, the developer then added the following code to his feature:

    SPList pages = web.Lists[PublishingWeb.GetPagesListName(web)];

    This seems natural, after all, since web.Lists is simply an SPListCollection and SPListCollection provides the following property:

    public SPList this [string strListName] { get; }

    This appeared to work during his unit testing and so he checked in his changes. The problem is that this doesn't work in all cases (meaning for all Language Packs).

    If you look at the documentation for the PublishingWeb.GetPagesListName method, you will see that it states the method returns the "URL name of the pages list" (emphasis mine) -- which, in most cases, is the same as the "name of the pages list."

    Unfortunately, for certain Language Packs the "URL name" is different from the list "name." For example, in Chinese the URL name is "Pages" but the list name is "页面".

    The correct way to get the Pages list is to use the PublishingWeb.GetPagesListId method instead:

    SPList pages = web.Lists[PublishingWeb.GetPagesListId(web)];

    It looks like the PublishingWeb.GetPagesListName() method really should have been called GetPagesUrlName instead.

  • Minor Setback

    I haven't blogged in almost 8 weeks. Ouch.

    However, I like to think I have a good excuse -- at least for a good portion of that time.

    On April 17, 2009, I broke my left leg in 6 places skiing one of my favorite runs at Mary Jane called "Outhouse." I've skied it countless times before, but the snow had been falling very heavy the previous day and into the morning, and consequently the bumps were rather "choppy" and it was just one of those fluke accidents where my ski binding did not release when it should have. Let's just say that the human ankle isn't meant to rotate 90 degrees :-(

    It took two surgeries -- and a lot more metal than I'd prefer to have in my body -- to put me back together again.

    In the first operation (performed the night of my accident), the surgeon attached an "external fixator" to my shin, ankle, and foot in order to hold it all in place for about a week in order for the swelling to go down.

    Figure 1: Broken tibia - external fixator

    In the second operation, the surgeon removed the "external fixator" and implanted an "internal fixator." Let's just say that you really don't want to be behind me in the airport security screening line.

    In the last X-ray that I saw, the lower half of my left leg looks like one big metal lattice. It took the surgeon about 4-1/2 hours to complete the second surgery (an hour longer than originally planned).

    Unfortunately, while the first surgery was relatively noneventful, the second was not. It involved two of the worst nights -- from a physical pain perspective -- that I've ever experienced.

    The good news is that the pain is quite manageable now -- actually it has been since I left the hospital after my second surgery. The bad news is that I can't put any weight on my left leg for 12 weeks after the second operation. At least I've greatly improved my ability for going up and down stairs on crutches.

    I've even been working for the past 4 weeks, rejoining a project where we are helping a large, international company deploy an Internet platform based on Microsoft Office SharePoint Server 2007. I just prop my leg up on a filing cabinet here in my home office and I'm good to go ;-)

More Posts Next page »

© 2009 Microsoft Corporation. All rights reserved. Terms of Use  |  Trademarks  |  Privacy Statement
Microsoft
Page view tracker