Dec 30

Written by: Javier Callico
12/30/2010 

The native support for tracing in WCF is very good but as sometimes is the case is missing a functionality that I happen to need right now: The ability to rotate the trace files or in other words automatically switching to a new trace file based on a time based criteria.

Why do I need this?

I’ve been working on a project that has come to rely heavily in the trace files as a way to keep track of all the calls made by partners. If something goes wrong the trace files are the place to go to find out what really happened. Tracing, which in my opinion should only be enabled to troubleshoot a given problem, is now always on and the trace file gets big, really big, so finding a given message comes with the price of downloading this trace file and then searching for a given text.

The Service Trace Viewer Tool does a decent job opening these big trace files and even lets you define what segment of the trace file gets loaded based on a given time frame but still trying to restrict the size of the trace files has become a necessity.

There is built in support for Circular Tracing which basically switches between two files back and forth when a given size threshold is reached but this is not exactly what I need.

How I would like trace file rotation to be configured

Configuring tracing is a very straight forward process which involves adding the following section to your configuration file.

<system.diagnostics>
  <sources>
    <source name="System.ServiceModel" propagateactivity="true"
            switchvalue="Information,ActivityTracing">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
    <source name="System.ServiceModel.MessageLogging">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
  </sources>
  <sharedlisteners>
    <add name="xml" type="System.Diagnostics.XmlWriterTraceListener"
       initializedata="D:\applog\MyServiceTracingAndLogging-client.svclog" />
  </sharedlisteners>
  <trace autoflush="true" />
</system.diagnostics>

Ideally I would like to use standard string formatting to timestamp the trace file. For example in order to get a daily trace file I would like to only have to add the following placeholders to the file name:

<add name="xml" type="System.Diagnostics.XmlWriterTraceListener" 
initializedata="D:\applog\MyServiceTracingAndLogging-client-{0:yyyy}-{0:MM}-{0:dd}.svclog" />

Extending XmlWriterTraceListener class

If you pay attention to the configuration section above you will notice that the XmlWriterTraceListener class is used to generate the trace file. After taking a look at how this class is implemented I came with the simple idea of inheriting from this class, intercepting the calls to Flash(), Write() and WriteLine() and generating a new file name when it’s needed.

Here is all the code you need. You can copy this class in the App_Code folder in your project.

namespace Callicode.System.Diagnostics
{
    using global::System;
    using global::System.Diagnostics;
    using global::System.IO;
    using global::System.Text;

    /// 

    /// Extends the System.Diagnostics.XmlWriterTraceListener class to include 
    /// datetime formating as part of the trace filename.
    /// Caution:
    /// Because System.Diagnostics.XmlWriterTraceListener is not thread-safe, 
    /// the trace source may lock resources exclusively when outputting traces.
    /// 
    public class TimeStampedXmlWriterTraceListener : XmlWriterTraceListener
    {
        protected string originalFilename = string.Empty;
        protected string formatedFilename = string.Empty;

        public TimeStampedXmlWriterTraceListener(Stream stream)
            : base(stream)
        {
        }

        public TimeStampedXmlWriterTraceListener(Stream stream, string name)
            : base(stream, name)
        {
        }

        public TimeStampedXmlWriterTraceListener(TextWriter writer)
            : base(writer)
        {
        }

        public TimeStampedXmlWriterTraceListener(TextWriter writer, string name)
            : base(writer, name)
        {
        }

        public TimeStampedXmlWriterTraceListener(string filename)
            : base(GetFormatedFileName(filename))
        {
            originalFilename = filename;
            formatedFilename = GetFormatedFileName(filename);
        }

        public TimeStampedXmlWriterTraceListener(string filename, string name)
            : base(GetFormatedFileName(filename), name)
        {
            originalFilename = filename;
            formatedFilename = GetFormatedFileName(filename);
        }

        public override void Flush()
        {
            RecreateWriterIfObsolete();
            base.Flush();
        }

        public override void Write(string message)
        {
            RecreateWriterIfObsolete();
            base.Write(message);
        }

        public override void WriteLine(string message)
        {
            RecreateWriterIfObsolete();
            base.WriteLine(message);
        }

        protected virtual void RecreateWriterIfObsolete()
        {
            string newFormatedFileName;

            if (this.Writer == null || string.IsNullOrEmpty(originalFilename) || string.IsNullOrEmpty(formatedFilename) ||
                formatedFilename.Equals(
                    newFormatedFileName = GetFormatedFileName(originalFilename), StringComparison.InvariantCultureIgnoreCase))
            {
                return;
            }

            // closing existing writer
            this.Writer.Close();

            // creating a new writer using the new filename
            // this is pretty much what the base EnsureWriter method does but since it's internal can't be used here
            Encoding encodingWithFallback = GetEncodingWithFallback(new UTF8Encoding(false));
            string fullPath = Path.GetFullPath(newFormatedFileName);
            for (int i = 0; i < 2; i++)
            {
                try
                {
                    this.Writer = new StreamWriter(fullPath, true, encodingWithFallback, 0x1000);
                    break;
                }
                catch (IOException)
                {
                    newFormatedFileName = Guid.NewGuid() + newFormatedFileName;
                    fullPath = Path.GetFullPath(newFormatedFileName);
                }
                catch (UnauthorizedAccessException)
                {
                    break;
                }
                catch (Exception)
                {
                    break;
                }
            }

            // updating field with new filename
            this.formatedFilename = newFormatedFileName;
        }

        protected static Encoding GetEncodingWithFallback(Encoding encoding)
        {
            // Exactly the base GetEncodingWithFallback was declared private.
            Encoding encoding2 = (Encoding)encoding.Clone();
            encoding2.EncoderFallback = EncoderFallback.ReplacementFallback;
            encoding2.DecoderFallback = DecoderFallback.ReplacementFallback;
            return encoding2;
        }

        protected static string GetFormatedFileName(string filename)
        {
            return string.Format(filename, DateTime.Now);
        }
    }
}

In order to use the new class simply modify the line containing the reference to the XmlWriterTraceListener class.

<add name="xml" type="Callicode.System.Diagnostics.TimeStampedXmlWriterTraceListener, App_Code" 
initializedata="D:\applog\MyServiceTracingAndLogging-client-{0:yyyy}-{0:MM}-{0:dd}.svclog" />

Caveats

- The XmlWriterTraceListener class was not written with inheritance in mind and some key methods like EnsureWrite were declared private or internal making necessary to duplicate some code that could have been reused otherwise.
- Having to check for the filename every time Flush(), Write() or WriteLine() are invoked adds more latency to the process but it was the only safe way I found to make sure that the data was written to the right file.