[Skip to Content]

Windows Azure Diagnostics – Why the Trace.WriteLine method only sends Verbose messages

Logging diagnostic information plays a key part for any application. The .Net framework provides a number of Diagnostic features, which can be used to provide logging functionality in your application.

However, in Windows Azure, the diagnostic API available in early CTPs was very limited. In the November release of Windows Azure, a new feature for  Windows Azure Diagnostics was launched. I will not delve into details of how to use the Azure diagnostic API. You can read about this here and also here.

In this article, I will be focusing only on a recent challenge we came across while implementing the Windows Azure Diagnostics API for ScrumWall (http://scrumwall.cloudapp.net). ScrumWall uses a factory pattern to determine which concrete log writer to use. It had both a trace listener logger and a custom Windows Azure Table storage logger. The trace listeners implementation could be configured in web.config.

The section for trace listeners in web.config for ScrumWall is:

<system.diagnostics>
    <switches>
      <!-- Off = 0, Error 1, Warning = 2, Info = 3,
 Verbose = 4 -->
      <add name="logLevel" value="2" />
    </switches>
    <trace autoflush="true" indentsize="2">
      <listeners>
       <!-- add file logger outside Azure -->
        <add name="TextWriterTraceListener" 
             type="System.Diagnostics.TextWriterTraceListener" 
             initializeData="TextWriterOutput.log"/>
      </listeners>
    </trace>
</system.diagnostics> 

A static Logger class provides a facade which writes to the underlying trace listeners using the static overloaded method of System.Diagnostics.Trace class WriteLine(string message) using our TraceListenerLogWriter:

public class TraceListenerLogWriter : ILogWriter
{
    private static TraceSwitch _logLevelConfigured = 
        new TraceSwitch("logLevel", "Switch log level");

    public void WriteLog(string message)
    {
        Trace.WriteLine(message);
    }

    public bool ShouldLog(TraceLevel traceLevel)
    {
        if ((int)_logLevelConfigured.Level >= (int)traceLevel)
        {
            return true;
        }
        else
        {
            return false;
        }
    }
}

The Windows Azure trace listener is provided by “DiagnosticMonitorTraceListener”, which we added in the existing web.config :

<!-- add file logger for Azure -->
<add type="Microsoft.WindowsAzure.Diagnostics.DiagnosticMonitorTraceListener, Microsoft.WindowsAzure.Diagnostics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
     name="AzureDiagnostics">          
</add>

and in our WebRole, which  is responsible for Diagnostic Monitor start up, we have the following Diagnostic configuration.

//set Trace logs to Warning and above every 5 minutes 
DiagnosticMonitorConfiguration dmc = 
     DiagnosticMonitor.GetDefaultInitialConfiguration(); 
 
dmc.Logs.ScheduledTransferPeriod = TimeSpan.FromMinutes(5);   
dmc.Logs.ScheduledTransferLogLevelFilter = LogLevel.Warning;  

DiagnosticMonitor.Start("DiagnosticsConnectionString", dmc); 

A very odd behaviour was observed when running the application, it would only store Verbose level messages. When setting the Diagnostic monitor log level filter for Warning no log messages were logged.

It was quite a puzzle!

How are we filtering our trace messages?

In configuration, a TraceSwitch is defined called “logLevel”. The static Logger applies the filter using the ShouldLog method of TraceListenerLogWriter. All of the attached listeners then receive trace messages appropriate to the filter.

However, Azure Diagnostic has another level of filtering, which is used to send the logged messages to Azure storage at a particular interval defined through DiagnosticMonitorConfiguration.

You might still be wondering why this filtering will affect it.

How is the Trace.WriteLine method in DiagnosticMonitorTraceListener class implemented?

As explained earlier that Azure Diagnostic operates with two levels of filtration:

a. Filter for logging to attached trace listeners.

b. Filter for sending the logged messages to Azure storage.

The underlying logger requires the log level in message so that the filter can be applied before sending to Azure storage.

But looking at the DiagnosticMonitorTraceListener class in Reflector, the WriteLine method calls an overridden method Write, which is hijacked to be Verbose only:

public override void Write(string message)   
{   
    this.WriteStringEtw(TraceEventType.Verbose, 0, message);   
}

The use of Verbose does make sense, as a default value for use by the second level filter. But this is hidden inside the implementation of the trace listener. This is why just replacing the trace listener did not work for our application.

What is the solution?

The solution is quite straightforward. Instead of using Trace.WriteLine, use Trace.TraceError, Trace.TraceWarning, Trace.TraceInformation appropriately and Trace.WriteLine for the Verbose event.

The modified version of our TraceListenerLogWriter looks like :

public class TraceListenerLogWriter : ILogWriter   
{  
    public void WriteLog(TraceLevel level, string message)   
    {  
        switch (tracelevel)   
        {  
            case TraceLevel.Error:  
                Trace.TraceError(message);  
                break;  
            
            case TraceLevel.Warning:
                Trace.TraceWarning(message); 
                break;  
            
            case TraceLevel.Info: 
                Trace.TraceInformation(message);
                break;  
            
            case TraceLevel.Verbose:
                Trace.WriteLine(message);
                break;
            
            default:
            //no logging
            break;
        }  
    }
} 

In summary, only use the Trace.WriteLine method to log Verbose messages. Keep in mind that Trace.WriteLine is Trace.TraceVerbose within the Azure trace listener.

Comments

comments powered by Disqus