Girish Jain on .Net Framework

I will be writing about my favorite technology which is Microsoft .Net Framework and how to use it to improve developer productivity

ASP.NET 5 Logging using Trace Listeners and How-to Filter Log Entries

clock January 13, 2016 05:47 by author Girish Jain

Source code available at GitHub

Pluggable logging framework by ASP.NET 5...

ASP.NET 5 is the new open-source and cross-platform framework for building modern web applications using .NET. The new framework has in-built support for logging and it allows you to integrate with other logging frameworks too. You may need to write some code as a bridge between ASP.NET logging framework and your preferred logging provider by implementing interfaces provided by ASP.NET 5 such as ILoggingProvider and ILogger.

Can we plug trace listeners...?

In this post, I am going to cover how to use existing tracing framework in ASP.NET 5 projects. Tracing has been available in .NET since its inception. People have made investments into using trace listeners which write trace messages to a variety of destinations such as local file, database table, etc. They should be able to reuse their investment in ASP.NET 5 project as well. Let’s see how.

No more web.config...

Using tracing in in ASP.NET 4.x was fairly straight forward. You would define trace source and add trace listeners using web.config file. Something very simple as follows:

<system.diagnostics>
  <trace autoflush="true"></trace>
  <sources>
    <source name="MyServiceTraceSource" switchvalue="All">
      <listeners>
        <add name="MyServiceListener" type="System.Diagnostics.TextWriterTraceListener" initializedata="MyServiceLog.txt"></add>
      </listeners>
    </source>
  </sources>
</system.diagnostics>
And then in your code, you would write messages to trace source which would be received by the trace listener configured for trace source. That has changed with ASP.NET 5, as it does not use web.config file, we’ve lost that configuration-ability that we are so used to. Though, there’s nothing stopping us from defining trace listener configuration using new JSON config file and then using the same in code to create trace listeners that would listen for specific trace sources. For now, in this article, I am going to use trace listeners directly in code. 

Add tracing provider...

ASP.NET 5 has its own logging framework so we would need to plug trace listener provider to ASP.NET 5 logging framework. To use trace listeners in ASP.NET 5, you would need to add a NuGet package to your project called, Microsoft.Extensions.Logging.TraceSource. It has been developed by asp.net team as part of aspnet/Logging project. It lets you use TraceSource and TraceListener in your ASP.NET 5 project by using TraceSourceLogger class. 

You need to add Microsoft.Extensions.Logging.TraceSource package to your project as a dependency in project.json file as shown below:

"dependencies": {
    "Microsoft.AspNet.IISPlatformHandler": "1.0.0-rc1-final",
    "Microsoft.AspNet.Mvc": "6.0.0-rc1-final",
    "Microsoft.AspNet.Server.Kestrel": "1.0.0-rc1-final",
    "Microsoft.AspNet.StaticFiles": "1.0.0-rc1-final",
    "Microsoft.Extensions.Configuration.FileProviderExtensions": "1.0.0-rc1-final",
    "Microsoft.Extensions.Configuration.Json": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Console": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Debug": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.TraceSource": "1.0.0-rc1-final"
},

 

Add Trace Listener...

Next, you need to add a trace source listener to logger factory:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    loggerFactory.AddTraceSource(
        new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
        new TextWriterTraceListener("AspNet5LoggingService.txt")
    );
    ...
}
    

Note: TextWriterTraceListener is not available in .Net Core but .Net Framework only so once you use it in your code, you may get compile error for the same. If you do, you would need to remove dnxcore50 target framework from your project by modifying project.json file i.e. remove highlighted line below:

    "frameworks": {
      "dnx451": { },
      "dnxcore50": { }
    },

 

Get Logger...

Lastly, you need to get logger instance in your classes by injecting a dependency to your class for logger instance. There is couple of options available for adding a dependency to class constructor for logger instance:

1. One option is to use ILoggerFactory type as a dependency and then manually creating a logger by calling CreateLogger method on factory instance and passing in a category name.

2. Another option is to use Logger<T> as a dependency in your constructor by specifying generic type parameter.

When using ILoggerFactory, you need to manually create a logger whereas with Logger<T> you could directly start using it for logging. For most situations, using Logger<T> would suffice but when you don’t know the generic type parameter to be used or if you would like to create a logger with a certain category name, you could use ILoggerFactory. Let’s look at an example using both approaches:

    [Route("api/[controller]")]
    public class ValuesController : Controller
    {
        private readonly ILogger<ValuesController> logger;
        public ValuesController(ILogger<ValuesController> logger)
        {
            this.logger = logger;
        }
        ...
    }
OR
    [Route("api/values2")]
    public class ValuesController2 : Controller
    {
        private readonly ILogger logger;
        public ValuesController2(ILoggerFactory loggerFactory)
        {
            this.logger = loggerFactory.CreateLogger("AspNet5LoggingService");
        }
        ...
    }

 

Use Logger...

Voila! You are done and now you can start using this logger instance to write log entries.

    [Route("api/[controller]")]
    public class ValuesController : Controller
    {
        private readonly ILogger logger;
        public ValuesController(ILogger logger)
        {
            this.logger = logger;
        }
        // GET: api/values
        [HttpGet]
        public IEnumerable Get()
        {
            logger.LogInformation("Processing GET request for values.");
            return new string[] { "value1", "value2" };
        }
    }

When executed, it would write log entry in trace destination by trace listener, which in my case was the log file specified with TextWriterTraceListener.

 

Noisy log entries...

You would find that log file is created in wwwroot folder and it contains all log entries. But as you would have noticed, the log file also contains all log entries which are generated by ASP.NET 5 framework. You would see something like this:

    
    Microsoft.AspNet.Hosting.Internal.HostingEngine Verbose: 4 : Hosting starting
    Microsoft.AspNet.Hosting.Internal.HostingEngine Verbose: 5 : Hosting started
    Microsoft.AspNet.Hosting.Internal.HostingEngine Information: 1 : Request starting HTTP/1.1 GET http://localhost:50998/api/values
    Microsoft.AspNet.Hosting.Internal.HostingEngine Information: 1 : Request starting HTTP/1.1 DEBUG http://localhost:50998/ text/html
    Microsoft.AspNet.StaticFiles.StaticFileMiddleware Verbose: 1 : DEBUG requests are not supported
    Microsoft.AspNet.StaticFiles.StaticFileMiddleware Verbose: 4 : The request path /api/values does not match a supported file type
    ...
    ...
    AspNet5LoggingService Information: 0 : Processing GET request for values.    

This behavior is by design. All logging providers will get all logging messages and it’s for individual provider to filter the "category" of messages they are interested in. Most likely, you wouldn’t want all those entries in log file along with log entries created by your service code and that brings us to next step.

 

How to filter for log entries...?

You can filter log entries by adding a filter to TraceListener, which is defined as a property on TraceListener base class. It’s of type TraceFilter:

public System.Diagnostics.TraceFilter Filter { get; set; }

 

If you lookup TraceFilter class definition, you would notice that it’s an abstract class. There are few default TraceFilter implementations available and you could use them or create your own filter very easily. All you would need to do is derive a class from TraceFilter and override ShouldTrace method. For this example, I am going to use existing SourceFilter class, which comes with .NET.

You could add a TraceFilter to your listener as follows:

    var listener = new TextWriterTraceListener("AspNet5LoggingService.txt");
    listener.Filter = new SourceFilter("AspNet5LoggingService");
    loggerFactory.AddTraceSource(
        new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
        listener
    );

 

Where are my filtered log entries...?

Depending upon your project and the number of log entries being generated, it may happen that you don’t see any new trace messages in your log file, especially after you filtered for trace messages generated by your service code. If you are using a TextWriterTraceListener, you may not see your log entries immediately in log file, though the log file would be created immediately (if it does not exist already). This is where I struggled and ended up spending quite some time debugging why I don't see log entries in my file, only to find out later about a feature with the specific listerner that I was using. This happens because TextWriterTraceListener writes data to the file stream and those trace messages are buffered. It does not flush the buffered data with each write. In previous versions of .NET, you would normally add following to your web.config file.

<trace autoflush="true" />

 

which would cause trace listeners to flush trace messages immediately. To achieve the same in ASP.NET 5, you can add following in code:

    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
    {
        loggerFactory.AddConsole(Configuration.GetSection("Logging"));
        loggerFactory.AddDebug();

        // This would prevent TextWriterTraceListener from buffering trace messages but cause
        // it to flush them as each trace message is sent to listener
        if (env.IsDevelopment())
        {
            Trace.AutoFlush = true;
        }        

        var listener = new TextWriterTraceListener("AspNet5LoggingService.txt");
        listener.Filter = new SourceFilter("AspNet5LoggingService");
        loggerFactory.AddTraceSource(
            new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
            listener
        );
        ...
    }

I am opting for AutoFlush behavior only in case of development environment because that's where we would need log entries to be reflected in file immediately whereas in production environment buffering log messages would give better performance. If you don’t set AutoFlush property, you would need to wait until buffered data in stream is written to file on disk.

Summary...

In this article we saw how to

1. Use trace listener in ASP.NET 5 project

2. Filter trace entries at the trace listener level

3. Use Trace.AutoFlush in code to prevent trace messages from being buffered in memory

NOTE: Please note that this article was written using ASP.NET 5 RC1 and by the time RTM comes out, which is expected in another couple of months, there may be some changes.

Happy Coding.

Vande Mataram!

(A salute to motherland)




Tracing with Code Injection Part II

clock April 27, 2012 06:41 by author Girish Jain

Download source code - Advanced Tracing with Code Injection Part II.zip (171 kb)

Overview

Welcome to part II of this blog post series where I show you how to inject code into an assembly to trace method execution at runtime, along with its parameter values and, all of this being achieved without writing any code in your method’s body.

Before you read further, I would suggest you read first blog post to get fair idea of code injection approach developed in earlier post and how tracing works. In the first post, I have created an application that uses Mono.Cecil library to inject code into any CLR assembly (DLL or EXE). The application will inject code to all methods marked with a known attribute in the given assembly.

Objective of this blog post series is to develop an automated solution (using code injection) which logs certain key information from a running application, of course, only when tracing is turned on for the application (which is called as runtime instrumentation). Now, I want to achieve this without manually writing tracing code for the same. CLR tracing framework is great as you can turn tracing on/off using application’s configuration file, and when turned on you can further control the type of information (such as verbose, information, warning, or error), which gets logged to trace listener, using trace switch. So the key objective is to develop a code injection solution which injects tracing code to a given assembly which will log method signature and its parameters values each time the method executes.

Advantages

1. Code injection approach frees developer from manually writing tracing code at the start of their method body.

2. Information logged during runtime would be a great help when diagnosing a production environment issue, especially for a large distributed application as it will tell you the sequence in which methods executed, and it would be helpful during debugging in development phase as well.

Done so far

The first post has created an application which logs method signature to trace listener each time the method executes. Please note that tracing code is injected only to methods marked with a custom attribute. Now, all that you had to do to achieve this functionality in your own application was to follow these simple steps:

1. Add reference to AdvancedTracing library in your project (a light-weight library which defines custom attribute you need to apply to your methods and a custom database trace listener)

2. Mark methods with the custom attribute [LogMethodExecutionEntryAttribute]

3. Add a post-build event to project to invoke CodeInjection.exe (or you can use any other automated mechanism such as a .bat file to pass project's output, DLL/EXE, to CodeInjection.exe application to inject tracing code).

4. Add a trace listener to application configuration file

Voila! All methods marked with the custom attribute will start logging method signature to trace destination each time the method executes, as follows:

16/04/2012 11:20:03 : System.Int32 InjectedCalc::Add(System.Int32,System.Int32) invoked 

What Next?

Sounds good so far but, just the method signature would not be end of the world, let’s see if we can get more. What if we get method parameters values being logged as well to trace listener? Just the method signature being logged will not be very helpful but the data passed to method would be of great help while diagnosing any issue. With the same objective in mind, I started modifying CodeInjection.exe application to inject code to log method parameters data as well, along with method signature. So for example, for a simple Add method, such as:

[LogMethodExecutionEntry(true)] 
static public int Add(int i1, int i2) 
{ 
    return i1 + i2; 
} 

I want to see the values passed to its parameters being logged as well, as follows:

16/04/2012 11:23:10 : System.Int32 InjectedCalc::Add(System.Int32,System.Int32) invoked with data:10,20,

With this objective, I modified the original logic as follows: (sub-points 6.x are new changes)

1. Load the input assembly

2. Loop over all its modules

3. For each module, loop over all its types

4. For each type, loop over all its methods

5. For each method, check whether it is marked with LogMethodExecutionEntryAttribute custom attribute

6. If method is marked with the known custom attribute, then inject following IL instructions at the start of method body

a. If method has any parameters defined, then load an array of type object to stack, with array’s size being equal to number of method parameters using newarr instruction. Now loop over all the parameters and inject code as below:

i. Load (push) each argument value using ldarg instruction

ii. If the parameter is passed by reference, then use ldind instruction to de-reference the pointer and push actual value to stack

iii. If the parameter is value-type then box the value type instance using box instruction

iv. By now you will have either a boxed representation for value type parameters or a managed pointer for reference types on the stack. Store the value on stack to object array, created earlier, using stelem instruction

b. Load (push) method signature string to the evaluation stack using ldstr "method signature"

c. Now you have a string instance and an object array at the top of your evaluation stack, in the same order. Use call instruction and call AdvancedTracing::Utility::WriteTraceLineWithData method which will pop the method signature string and object array from the evaluation stack and pass these two to WriteTraceLineWithData method as parameters. This leaves evaluation stack as it was when method execution began.

7. Lastly, save modified assembly back to disk

The entire source code for the application has been attached to the post, you can find it at the top. I am making the core code of TraceInjection class available on this page as well.

Before you start understanding code, I want to remind you that I am a big fan of tracing code in method body to explain logical flow in code as it helps a lot during development/debugging cycle, especially for a large application and a big team of developers. Hence, I strongly recommend everyone to write lot of Trace.WriteLine or similar methods calls from Trace class in code. The code injection approach shown in this post simply automates some bit of it and saves you from doing it manually across entire code base and helps you keep it up to date and consistent as that will almost be a mission impossible. At the same time, I also believe that tracing is one of the best way to comment your code as well. So use this application to your advantage and make best use of CLR tracing framework.

Lastly I would strongly recommend you to read the Advanced Tracing blog post which creates a new database trace listener and explains nuances of CLR tracing and its advantages.

Here’s the entire code for TraceInjection class with the updated logic for logging method parameter values as well:


using Mono.Cecil;
using Mono.Cecil.Cil;
using System.Configuration;
using System.IO;
using System.Diagnostics;
using System.Collections.Generic;
using System;
using System.Linq;

namespace CodeInjection
{
    public class TraceInjection
    {
        public bool InjectTracingLine(string assemblyPath, string outputDirectory)
        {
            bool logWithData = false;                           // Boolean value to store developer's preference, whether he wants to inject code which wll dump parameters value as well.
            bool isAssemblyInjected = false;                    // Boolean flagt to indicate whether we have injected code to the assembly under consideration
            bool pointerToValueTypeVariable = false;            // Boolean flag to indicate whether we have a ByRef parameter where the underlying/referenced type is a value type
            MetadataType paramMetaData;                         // Meta data type enum from Mono.Cecil

            TypeSpecification referencedTypeSpec = null;

            CustomAttribute customAttr;
            AssemblyDefinition asmDef;
            TypeReference typeObject;

            Trace.WriteLine(string.Format("InjectTracingLine called for assembly: {0} and outputDirectory: {1}", assemblyPath, outputDirectory));

            string fileName = Path.GetFileName(assemblyPath);
            string newPath = outputDirectory + @"\" + fileName;


            // Check if Output directory already exists, if not, create one
            // ------------------------------------------------------------
            if (!Directory.Exists(outputDirectory))
            {
                Directory.CreateDirectory(outputDirectory);
            }

            try
            {
                // We need reference to AdvancedTracing.Utility type and its 
                // WriteTraceLineWithData method
                // ------------------------------------------------------------
                ModuleDefinition advancedTacingModule = ModuleDefinition.ReadModule(AppDomain.CurrentDomain.BaseDirectory + @"\AdvancedTracing.dll");
                TypeDefinition utilityType = advancedTacingModule.Types.First(t => t.Name == "Utility");
                MethodDefinition loggingMethod = utilityType.Methods.First(m => m.Name == "WriteTraceLine");
                MethodDefinition loggingMethodWithData = utilityType.Methods.First(m => m.Name == "WriteTraceLineWithData");

                // List of new tracing IL instructions which will be added to the method
                List objTracingInstructions = new List();

                // Load assembly
                // ------------------------------------------------------------
                asmDef = AssemblyDefinition.ReadAssembly(assemblyPath);
                
                foreach (ModuleDefinition modDef in asmDef.Modules)
                {
                    // Get System.Object type reference
                    typeObject = modDef.TypeSystem.Object;

                    foreach (TypeDefinition typDef in modDef.Types)
                    {
                        foreach (MethodDefinition metDef in typDef.Methods)
                        {
                            // Check if method has the required custom attribute set
                            // ------------------------------------------------------------
                            if (this.TryGetCustomAttribute(metDef, "AdvancedTracing.LogMethodExecutionEntryAttribute", out customAttr))
                            {
                                // Method has the desired attribute set, edit IL for method
                                Trace.WriteLine("Found method " + metDef.ToString());

                                // Now we gonna inject code so you can flag that assembly has 
                                // been code injected so that updated assembly will be written
                                // back to disk
                                // ------------------------------------------------------------
                                isAssemblyInjected = true;

                                // Check developer's intention whether he wants to just log 
                                // method execution OR method's parameter values as well
                                if (customAttr.HasConstructorArguments)
                                {
                                    // Developer has expilicitly specified his intention
                                    if (customAttr.ConstructorArguments != null
                                        && customAttr.ConstructorArguments.Count > 0)
                                    {
                                        if (!bool.TryParse(customAttr.ConstructorArguments[0].Value.ToString(), out logWithData))
                                        {
                                            // We could not parse the constructor argument to a boolean value
                                            // so we will assume it to be false (which is the default behavior)
                                            logWithData = false;
                                        }
                                    }
                                }
                                else
                                {
                                    // Developer has NOT expilicitly specified his intention
                                    // so we will assume it to be false i.e. don't log data
                                    logWithData = false;
                                }

                                // Get ILProcessor
                                ILProcessor ilProcessor = metDef.Body.GetILProcessor();

                                // Get required counts for the method
                                // ------------------------------------------------------------
                                int intMethodParamsCount = metDef.Parameters.Count;
                                int intArrayVarNumber = metDef.Body.Variables.Count;


                                // Clear the list so that we can reuse the existing list object
                                // ------------------------------------------------------------
                                objTracingInstructions.Clear();

                                
                                // Load method signature string
                                // ------------------------------------------------------------
                                objTracingInstructions.Add(ilProcessor.Create(
                                    OpCodes.Ldstr,
                                    metDef.ToString()
                                ));


                                // If method contains parameters, then emit code to log parameter 
                                // values as well
                                // ------------------------------------------------------------
                                if (intMethodParamsCount > 0 && logWithData)
                                {
                                    // Add metadata for a new variable of type object[] to method body
                                    // .locals init (object[] V_0)
                                    // ------------------------------------------------------------
                                    ArrayType objArrType = new ArrayType(typeObject);
                                    metDef.Body.Variables.Add(new VariableDefinition((TypeReference)objArrType));


                                    // Set InitLocals flag to true. At times, this is set to false
                                    // in case of static mehods and currently Mono.Cecil does not have 
                                    // capability to detect need of this flag and emit it automatically
                                    // ------------------------------------------------------------
                                    metDef.Body.InitLocals = true;

                                    // Create an array of type system.object with 
                                    // same number of elements as count of method parameters
                                    // ------------------------------------------------------------
                                    objTracingInstructions.Add(
                                        ilProcessor.Create(OpCodes.Ldc_I4, intMethodParamsCount)
                                    );

                                    objTracingInstructions.Add(
                                        ilProcessor.Create(OpCodes.Newarr, typeObject)
                                    );

                                    // This instruction will store the address of the newly created 
                                    // array in local variable
                                    // ------------------------------------------------------------
                                    objTracingInstructions.Add(
                                        ilProcessor.Create(OpCodes.Stloc, intArrayVarNumber)
                                    );


                                    // Loop over all the parameters of method and add their value to object[]
                                    // ------------------------------------------------------------
                                    for (int i = 0; i < intMethodParamsCount; i++)
                                    {
                                        paramMetaData = metDef.Parameters[i].ParameterType.MetadataType;
                                        if (paramMetaData == MetadataType.UIntPtr ||
                                            paramMetaData == MetadataType.FunctionPointer ||
                                            paramMetaData == MetadataType.IntPtr ||
                                            paramMetaData == MetadataType.Pointer)
                                        {
                                            // We don't want to log values of these parameters, so skip
                                            // this iteration
                                            break;
                                        }

                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldloc, intArrayVarNumber));
                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldc_I4, i));

                                        // Instance methods have an an implicit argument called "this"
                                        // and hence, we need to refer to actual arguments with +1 position
                                        // whereas, in case of static methods, "this" argument is not there
                                        // ------------------------------------------------------------
                                        if (metDef.IsStatic)
                                        {
                                            objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldarg, i));
                                        }
                                        else
                                        {
                                            objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldarg, i + 1));
                                        }

                                        // Reset boolean flag variable to false
                                        pointerToValueTypeVariable = false;

                                        // If aparameter is passed by reference then you need to use ldind
                                        // ------------------------------------------------------------
                                        TypeReference paramType = metDef.Parameters[i].ParameterType;
                                        if (paramType.IsByReference)
                                        {
                                            referencedTypeSpec = paramType as TypeSpecification;
                                            Trace.WriteLine(string.Format("Parameter Name:{0}, Type:{1}", metDef.Parameters[i].Name, metDef.Parameters[i].ParameterType.Name));

                                            if(referencedTypeSpec != null)
                                            {
                                                switch (referencedTypeSpec.ElementType.MetadataType)
                                                {
                                                    //Indirect load value of type int8 as int32 on the stack
                                                    case MetadataType.Boolean:
                                                    case MetadataType.SByte:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_I1));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type int16 as int32 on the stack
                                                    case MetadataType.Int16:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_I2));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type int32 as int32 on the stack
                                                    case MetadataType.Int32:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_I4));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type int64 as int64 on the stack
                                                    // Indirect load value of type unsigned int64 as int64 on the stack (alias for ldind.i8)
                                                    case MetadataType.Int64:
                                                    case MetadataType.UInt64:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_I8));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type unsigned int8 as int32 on the stack
                                                    case MetadataType.Byte:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_U1));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type unsigned int16 as int32 on the stack
                                                    case MetadataType.UInt16:
                                                    case MetadataType.Char:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_U2));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type unsigned int32 as int32 on the stack
                                                    case MetadataType.UInt32:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_U4));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type float32 as F on the stack
                                                    case MetadataType.Single:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_R4));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type float64 as F on the stack
                                                    case MetadataType.Double:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_R8));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    // Indirect load value of type native int as native int on the stack
                                                    case MetadataType.IntPtr:
                                                    case MetadataType.UIntPtr:
                                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_I));
                                                        pointerToValueTypeVariable = true;
                                                        break;

                                                    default:
                                                        // Need to check if it is a value type instance, in which case
                                                        // we use ldobj instruction to copy the contents of value type
                                                        // instance to stack and then box it
                                                        if (referencedTypeSpec.ElementType.IsValueType)
                                                        {
                                                            objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldobj, referencedTypeSpec.ElementType));
                                                            pointerToValueTypeVariable = true;
                                                        }
                                                        else
                                                        {
                                                            // It is a reference type so just use reference the pointer
                                                            objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldind_Ref));
                                                            pointerToValueTypeVariable = false;
                                                        }
                                                        break;
                                                }
                                            }
                                            else
                                            {
                                                // We dont have complete details about the type of referenced parameter
                                                // So we will just ignore this parameter value
                                            }
                                        }

                                        // If it is a value type then you need to box the instance as we are going 
                                        // to add it to an array which is of type object (reference type)
                                        // ------------------------------------------------------------
                                        if (paramType.IsValueType || pointerToValueTypeVariable)
                                        {
                                            if (pointerToValueTypeVariable)
                                            {
                                                // Box the dereferenced parameter type
                                                objTracingInstructions.Add(ilProcessor.Create(OpCodes.Box, referencedTypeSpec.ElementType));
                                            }
                                            else
                                            {
                                                // Box the parameter type
                                                objTracingInstructions.Add(ilProcessor.Create(OpCodes.Box, paramType));
                                            }
                                        }

                                        // Store parameter in object[] array
                                        // ------------------------------------------------------------
                                        objTracingInstructions.Add(ilProcessor.Create(OpCodes.Stelem_Ref));
                                    }

                                    // Load address of array variable on evaluation stack, to pass
                                    // it as a paremter 
                                    // ------------------------------------------------------------
                                    objTracingInstructions.Add(ilProcessor.Create(OpCodes.Ldloc, intArrayVarNumber));


                                    // Call the method which would write tracing info with data
                                    // ------------------------------------------------------------
                                    objTracingInstructions.Add(ilProcessor.Create(
                                        OpCodes.Call,
                                        metDef.Module.Import(
                                            loggingMethodWithData.GetElementMethod()
                                        )
                                    ));
                                }
                                else
                                {
                                    // Call the method which would write tracing info minus data
                                    // ------------------------------------------------------------
                                    objTracingInstructions.Add(ilProcessor.Create(
                                        OpCodes.Call,
                                        metDef.Module.Import(
                                            loggingMethod.GetElementMethod()
                                        )
                                    ));
                                }


                                // Add the new MSIL to the existing body of method
                                // ------------------------------------------------------------
                                objTracingInstructions.AddRange(metDef.Body.Instructions);
                                metDef.Body.Instructions.Clear();

                                foreach (var IL in objTracingInstructions)
                                {
                                    metDef.Body.Instructions.Add(IL);
                                }
                            }
                        }
                    }
                }

                // Save modified assembly, if code injected
                // ------------------------------------------------------------
                if (isAssemblyInjected)
                {
                    Trace.WriteLine(string.Format("Saving injected assembly at: {0}", newPath));
                    asmDef.Write(newPath, new WriterParameters() { WriteSymbols = true });
                }
                else
                {
                    Trace.TraceInformation(string.Format("No code has been injected to assembly {0}", asmDef.Name.ToString()));
                }
            }
            catch
            {
                // Nothing to be done, just let the caller handle exception 
                // or do logging and so on
                throw;
            }

            return true;
        }

        public bool InjectTracingLine(string assemblyPath)
        {
            Trace.WriteLine("InjectTracingLine called minus outputDirectory, will default to application config file value");
            // New assembly path
            string outputDirectory = ConfigurationManager.AppSettings["OutputDirectory"].ToString();
            return this.InjectTracingLine(assemblyPath, outputDirectory);
        }

        public bool TryGetCustomAttribute(MethodDefinition type, string attributeType, out CustomAttribute result)
        {
            result = null;
            if (!type.HasCustomAttributes)
                return false;

            foreach (CustomAttribute attribute in type.CustomAttributes)
            {
                if (attribute.Constructor.DeclaringType.FullName != attributeType)
                    continue;

                result = attribute;
                return true;
            }

            return false;
        }
    }
}

Happy Coding!!

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain




Tracing with Code Injection

clock December 2, 2011 02:17 by author Girish Jain

Source: http://valuestockphoto.com/downloads/14852-2/needle_injection.jpg

Continuing from one of my previous blog post on advanced tracing, today I am going to talk about going to the next level of tracing, which is using code injection to insert tracing calls in method body. CLR assembly files (dll or exe) have a very well documented file format/structure (Standard ECMA-335 Common Language Infrastructure), which makes it possible for tools to inspect the code (such as reflector tool) or inject the code using Reflection or other API/libraries such as Mono.Cecil.

Download entire source code (167 KB)

Requirement/Need

After our application goes live, we get lot of support calls; this is especially true for large distributed applications. Support team attempts to reproduce the scenario in dev environment, debug through the code, and finds root cause of the issue. They find the issue and fix it, happy days!

But that’s not how it always turns out to be in reality. For those who have developed the application AND then supported the same in live as well, know that very well. Sometimes (unfortunately), support team or the developer is not able to reproduce the scenario in dev environment as there will be many external/data dependencies which they cannot reproduce in dev environment. The developer tries his best to go through the code with assumed data values, assuming how the method would have executed, and so on. If lucky, he finds it soon, otherwise, he struggles a lot but eventually finds the root cause and provides the fix.

How about a situation where we can turn tracing on for an application at runtime and it starts writing all the information that a developer needs, most important of all being the code execution flow i.e. the sequence of methods which were executed at a point in time. If developer had this information at hand, it will make his life very easy in fault finding. Remember, tracing offers great advantage such that you can selectively turn it on or off at application/service level and you can filter the trace information as well using trace switches. You can define following values for a given trace switch: Off, Error, Warning, Info, and Verbose. This helps you control the information that gets logged to trace destination from your application.

 

Manual solution and its constraints

One solution to this requirement would be that we insert a tracing call at the start of each method as follows:

    private void DisplayProcessedInformation(bool pblnStartUp)
    {
    Trace.WriteLine(string.Format("{0} : {1} invoked", DateTime.Now.ToString(), "System.Void MyNamespace.ClassName::DisplayProcessedInformation(System.Boolean)"));
    // Method logic continues ...
    }
    

And if you are using DBTraceListener from previous post then it will log an entry to tracelog table in database each time the method executes, as follows:

<TraceLog> <Message>23/11/2011 17:17:33 : System.Void MyService.NavisionUpdate::DisplayProcessedInformation(System.Boolean) invoked</Message> </TraceLog>

As you can see, above trace entry tells developer the exact time a particular method was invoked. Now imagine, manually writing one line of extra code in each method with the correct method signature as its data. You ask your developers to do this and the very next day they will come back and tell you it’s not feasible. J

We don’t want to write the code ourselves to call the Trace.WriteLine method in all the methods across entire application and all libraries, as that would be a lot manual work and it will be very difficult (almost impossible) to maintain consistency across the entire codebase. The quality of trace information being written to configured trace destination will depend upon the developer. For example, one developer will write method name, other will write the signature partially, third one will not write method return type, and so on. There will be hundreds of possible ways to write one piece of trace information and it will be dependent upon the developer, which one he chooses.

Let’s not be dependent upon the developer for the reasons mentioned above. Let’s automate the step of writing one piece of information to trace destination i.e. the method signature as the method executes.

 

Code Injection Approach

What if, we don’t ask developers to write any additional code for tracing but only to mark each method with a certain attribute? And methods marked with that attribute will automatically be logged to trace destination each time they are executed (of course, only if tracing is turned on and trace level is set to Verbose). Tell this to your developers and they will love you. J That’s what I am going to do as part of this post. I am going to write a console application which takes a CLR assembly as input, traverses through all its types and their methods and checks for a custom attribute on each method. For a method marked with the custom attribute, this application will inject some code so that it will write to the trace destination whenever that method gets executed.

 

Actual code

Reflection API is available as part of .Net framework (System.Reflection and System.Reflection.Emit namespaces) but it is not so simple and straight forward to work with. At the same time, Mono.Cecil project overcomes the complexities of Reflection APIs and makes it possible for you to inject code into existing CLR assemblies (dll or exe) very easily. Hence, I have decided to use Mono.Cecil for the purpose.

The TraceInjection class and its InjectTracingLine method contain crux of this application. Its logic is as follows:

  1. Loads the input assembly

  2. Loops over all its modules

  3. For each module, loops over all its types

  4. For each type, loops over all its methods

  5. For each method, checks whether it is marked with LogMethodExecutionEntryAttribute custom attribute

  6. If method is marked with custom attribute, then inject following two IL instructions at the start of method body

     a. ldstr <method signature> // Loads (pushes) method signature string on to the evaluation stack

     b. call AdvancedTracing::Utility::WriteTraceLine method // Pops the method signature from the evaluation stack and passes it to WriteTraceLine method as argument

  7. Saves modified assembly back to disk

The injected code calls the WriteTraceLine method which is defined in Utility class of AdvancedTracing library and it simply calls the Trace.WriteLine method as follows:

    static public void WriteTraceLine(string methodName) {
    Trace.WriteLine(string.Format("{0} : {1} invoked", DateTime.Now.ToString(), methodName));
    } 

Mono.Cecil library has ILProcessor class which lets you generate IL code i.e. create Instruction instances, which are then inserted into method body. The IL code injected by CodeInjection application leaves the evaluation stack in a clean state i.e. the new values “pushed” onto the stack are “popped”. After the injected IL instructions are executed, stack is in similar state to how it was when the method execution had actually begun.

Here’s the entire code for TraceInjection class:

using Mono.Cecil;
using Mono.Cecil.Cil;
using System.Configuration;
using System.IO;
using System.Diagnostics;

namespace CodeInjection
{
    class TraceInjection
    {
        public bool InjectTracingLine(string assemblyPath, string outputDirectory)
        {
            CustomAttribute customAttr;
            AssemblyDefinition asmDef;

            // New assembly path
            // moved to new overload
            //string outputDirectory = ConfigurationManager.AppSettings["OutputDirectory"].ToString();
            string fileName = Path.GetFileName(assemblyPath);

            string newPath = outputDirectory + @"\" + fileName;

            // Check if Output directory already exists, if not, create one
            if (!Directory.Exists(outputDirectory))
            {
                Directory.CreateDirectory(outputDirectory);
            }

            try
            {
                // Load assembly
                asmDef = AssemblyDefinition.ReadAssembly(assemblyPath);

                foreach (ModuleDefinition modDef in asmDef.Modules)
                {
                    foreach (TypeDefinition typDef in modDef.Types)
                    {
                        foreach (MethodDefinition metDef in typDef.Methods)
                        {
                            // Check if method has the required custom attribute set
                            if (this.TryGetCustomAttribute(metDef, "AdvancedTracing.LogMethodExecutionEntryAttribute", out customAttr))
                            {
                                // Method has the desired attribute set, edit IL for method
                                Trace.WriteLine("Found method " + metDef.ToString());

                                // Get ILProcessor
                                ILProcessor ilProcessor = metDef.Body.GetILProcessor();

                                // Load fully qualified method name as string
                                Instruction i1 = ilProcessor.Create(
                                OpCodes.Ldstr,
                                metDef.ToString()
                                );
                                ilProcessor.InsertBefore(metDef.Body.Instructions[0], i1);

                                // Call the method which would write tracing info
                                Instruction i2 = ilProcessor.Create(
                                OpCodes.Call,
                                metDef.Module.Import(
                                typeof(AdvancedTracing.Utility).GetMethod("WriteTraceLine", new[] { typeof(string) })
                                )
                                );
                                ilProcessor.InsertAfter(i1, i2);
                            }
                        }
                    }
                }

                // Save modified assembly
                asmDef.Write(newPath, new WriterParameters() { WriteSymbols = true });
            }
            catch
            {
                // Nothing to be done, just let the caller handle exception
                // or do logging and so on
                throw;
            }

            return true;
        }

        public bool InjectTracingLine(string assemblyPath)
        {
            // New assembly path
            string outputDirectory = ConfigurationManager.AppSettings["OutputDirectory"].ToString();
            return this.InjectTracingLine(assemblyPath, outputDirectory);
        }

        public bool TryGetCustomAttribute(MethodDefinition type, string attributeType, out CustomAttribute result)
        {
            result = null;
            if (!type.HasCustomAttributes)
                return false;

            foreach (CustomAttribute attribute in type.CustomAttributes)
            {
                if (attribute.Constructor.DeclaringType.FullName != attributeType)
                    continue;

                result = attribute;
                return true;
            }

            return false;
        }
    }
}
    

And the LogMethodExecutionEntryAttribute is defined as follows:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

namespace AdvancedTracing
{
    [AttributeUsage(AttributeTargets.Method, AllowMultiple = false, Inherited = true)]
    public class LogMethodExecutionEntryAttribute : Attribute
    {
    }
}
    

How-to Use it

It is very simple to use CodeInjection application with your existing projects. You need to follow the following steps:

  1. Add reference to AdvancedTracing library in your project (This is the project which contains definition of LogMethodExecutionEntryAttribute class in in my case and a custom database trace listener implementation as well. But you can choose to use your own trace listener and create your own project)

  2. Mark method which you wish to be code injected with LogMethodExecutionEntryAttribute attribute.

  3. Add a post-build action for your project under project property as follows (under Compile tab, click on Build Events button):

project post-build event example

The CodeInjection.exe takes assembly file and the output directory as arguments. Code injected assembly will be dropped at the output directory specified. The %CD% specifies current directory, as argument value for output directory parameter.

  4. You need to add a trace listener to your application configuration file. If you want to log trace data to database table then you can use below configuration example (for detailed steps and script for DB trace listener refer the Advanced Tracing post) :

tracing configuration example

Important!

  1. Please note that this application uses Mono.Cecil library which is freely available but I needed to copy its copyright and permission notice to the source code folder. If you use this application or its source code, make sure to copy the same notice to your application as well.

  2. Although, CodeInjection application also generates a PDB file for debugging purpose but, for some reason (don’t know why) it has never worked for me. Therefore, for debugging, I always use the DLL and PDB generated by Visual Studio minus injected code.

In some future post, I will improve the code injection application and log to trace destination all the data passed to methods as well i.e. argument values for method parameters.

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share quick posts, tips, links, etc. My Twitter handle is: @girishjjain

 

[Edit] Please read part II of this series of blog post here, wherein I have improved the code injection application to inject code to method body such that it logs method parameters values as well. Also, the source code has been updated and few bugs fixed.



Advanced Tracing

clock April 26, 2011 18:35 by author Girish Jain

Download source code (8 KB)

Objective of this article is to show how easy it is to get information from your running application and how you could store the same in a destination of your choice with very little development, making it easier for you to query available information and assist in diagnosing live system issues. We will start with basic understanding of Tracing with an example and then move on to the concept of advanced tracing.

Tracing provides a way to instrument your running application. It helps you trace code execution and you can emit information from your code during execution. Let us try to build a small application to understand the benefits of tracing. The two most important classes of concern to us from application code perspective is Debug and Trace, both are in System.Diagnostics namespace, former is mainly for debug build and latter for release build of your application.

To understand tracing in .Net Framework, let’s use most basic application which greets user, every programmer’s favorite Hello World!

using System;
using System.Diagnostics;

public class BasicTracingSample
{
      public static void Main()
      {
            Trace.WriteLine("Program execution started...");

            Console.WriteLine("Enter your name :");
            string strName = Console.ReadLine();

            Console.WriteLine(string.Format("Hello {0}!", strName));

            Trace.WriteLine(string.Format("Greeted User {0}", strName));
            Trace.WriteLine("Program finished...");

            Console.ReadLine();
      }
}

And let’s define the tracing settings for above program using application configuration file as follows:  

Compile the above application and execute it using the following commands:

Note that you have to define the TRACE constant as part of compilation for tracing to work. When working with projects in Visual Studio, you can achieve this using project property page under Build tab as follows:

Let’s now execute the application. You would notice that as part of the execution, it has created a log file with following contents:

In summary, using application configuration file and Trace.WriteLine method calls in code, we were able to get information from executing application to a log file. In our case, information was logged to a log file because we chose the TextWriterTraceListener If we use EventLogTraceListener provided by .Net Framework, it would start logging to windows event viewer. So you can choose your own logging destination by selecting trace listeners provided by .Net Framework.


Trace Methods

Trace class offers following methods which can be used for emitting information during application execution:

  1. Write

  2. WriteLine

  3. TraceInformation

  4. TraceWarning

  5. TraceError

These methods are tracing framework API for your application to simply call a relevant Trace method and the configured TraceListener would take care of dumping information to its known destination. These different methods help in determining the type of trace and additional information for that type so that trace listener can accordingly log it. For example, in case of EventLogTraceListener, it will log the type i.e. information, warning, or error as a value in “Type” column so that you can easily filter on it. It is basically for the trace listener implementation class to make best use of the information passed to it. These methods also use the trace switch defined for the trace listener in determining whether to log the trace. Let’s understand trace switches.


Trace Switches

The following table defines possible trace switches and how they affect trace output:

Enumerated value Integer value Type of message displayed (or written to a specified output target)
Off 0 None
Error 1 Only error messages
Warning 2 Warning messages and error messages
Info 3 Informational messages, warning messages, and error messages
Verbose 4 Verbose messages, informational messages, warning messages, and error messages

Source: http://msdn.microsoft.com/en-us/library/aa983740(v=vs.71).aspx

Trace switch gives you further ability to filter for only relevant information that you are interested in. During different stages of an application, you may want to switch between different switch values to control the output. For example, when a new application goes live for the first time, you may want to set the trace switch as Verbose so that you capture all the information but once the application has been stable for some time and you are not interested in logging all the information coming out of your application, then you may set the trace switch as Warning, and so on. And best part of it is that you can configure all this with application configuration file changes and you don’t need to recompile your application.


Need Something More

So far so good but we need something more! You have choice of using listeners available as part of .Net Framework such as ConsoleTraceListener, TextWriterTraceListener, EventLogTraceListener, XmlWriterTraceListener and so on. All these existing trace listeners are very good for some small application but for a large distributed application, you need a more robust approach for collecting and processing information (*making any good out of it*) from your executing application. Trace listeners provided by .net framework log to destinations which are not ideal for most distributed applications as functionality is spread across multiple applications, several components running on different servers across server estate and your application is logging large amount of information, which mostly is the case in a large distributed application. It becomes very difficult to search for information in a text file or event viewer, or group related information. Let’s take the most common requirement, say you want to search all the information logged for a particular transaction based on the transaction number or some other identifier for it. It would not be easy to extract such information from a text file or event viewer as the information that you are looking for would be scattered throughout the file/event viewer making it difficult to extract the real information you need.

To add to the woes, you need to work out your own approach for maintaining these destinations such as periodically moving the log files to some backup store and so on. Basically, we need a tracing solution which:

  1. Supports logging all the information from multiple applications to a central destination

  2. Provides ability to query the information in as simple manner as a database table (select, filter, sort, group, and so on)

  3. Provides an easy approach for maintenance of the logging destination

When I thought of such requirements for tracing solution, the immediate response was logging to a database table. If we are able to log trace information from an application to a database table then it meets all of the above requirements.


Custom Trace Listener to Rescue!

And a custom trace listener comes to the rescue! Tracing offers a pluggable framework for .Net applications to log information during execution. By pluggable, I mean you can add your custom trace listeners and provide your custom implementation of where you want to log the information and how. For example, you can write a custom trace listener to dump information to a table in database.

There are few major advantages of using a database table as logging destination, such as:

  1. It provides ability to use all DBMS constructs to query, filter, and summarize the information available. It is as good as any other transaction table and you can use the information available in the best possible manner.

  2. Maintenance becomes much easy with DB tables such that you can delete rows with unwanted information by simply writing a query. You can easily identify rows with unwanted data and delete these selectively. Alternatively, you can also schedule a DB job which deletes information more than 3 months old, etc. And many similar possible approaches as you would otherwise use with a database table.


There are some disadvantages of using a database table as logging destination and hence, it would not be a recommended approach if:

  1. Your application is emitting a LOT of information in a very short span of time as it would cause lot of database hits in very quick succession and may affect database performance, network bandwidth, and in turn your application performance.

  2. There is any kind of latency involved in accessing database such as network latency as it could be overburdening an already slow network and result in underutilization of network resources for core business purpose and could affect overall performance of your application and network.

You should measure performance of your application with respect to database and consider above factors before deciding to use database table as a destination for tracing. Also, since you can use multiple trace listeners for your application, you can decide to switch between these available trace listeners as and when required and make the best use of their features for diagnosing the issue and you don’t need to recompile your application either. You can control the trace listeners for application from the configuration file itself but for certain types of applications, you may need to restart the application for trace listener changes in configuration file to take effect.

Let’s move on to start designing a custom database trace listener and them its implementation.


Design Considerations

Let’s design the table in which we will log all our trace entries:

tracelog
PK traceid int identity
message xml
type varchar Default 'Verbose'
componentname varchar Default NULL
loggeddate datetime Default getdate()

Let’s highlight key requirements that this custom DB trace listener should support:

  1. To be able to categorize the information coming from application properly instead of dumping it all as part of a long string (and you are not sure where one part ends and other begins as your eye ball takes effort to scan it slowly). We need something like XML tree where each element represents certain information which can be easily identified and searched upon.

We define the data type of the message column in our table as XML and trace listener implementation to take care of converting the information coming its way into an XML string

  2. To be able to define connection string for the database in configuration file

This can be defined as part of initializeData attribute already supported on trace listener in application configuration file and we would be supporting an additional attribute for this purpose as well namely connectionString.

  3. It should provide the ability to assign an identifier at application/service level to trace entries so that you can filter/group entries from one same application

Trace listener implementation would support an additional attribute namely componentName which can be defined in the application configuration file to separately identify all the trace entries from an application. The value defined for this attribute would be stored in the componentname column in table

  4. Ability to switch tracing level without the need to restart application (such as in case of windows services)

Trace listener implementation would support an additional attribute namely refreshTraceConfig of type boolean to decide whether tracing needs to refresh the trace switch value.

  5. If there are any errors during the execution of custom trace listener, these should be logged to a text file separately.


Custom Database Trace Listener Implementation

Let’s understand how we have achieved the goals set forward for us by looking at the actual code. Find below the entire source code for the custom trace listener which uses a database table as its destination:

using System;
using System.Data;
using System.Data.SqlClient;
using System.Diagnostics;
using System.IO;
using System.Xml.Linq;
using System.Threading;
using System.Linq;

namespace AdvancedTracing
{
    // Delegate definition for the real method responsible for logging
    internal delegate void LogIt(string message, string type, string componentName);

    // Delegate for DBTraceFailed event 
    public delegate void DBTraceFailedHandler (string exceptionText);

    // IMPORTANT!!!IMPORTANT!!!IMPORTANT!!!IMPORTANT!!!
    // --------------------------------------------------
    // Dont write any debugging statements anywhere in this
    // class such as Debug.WriteLine or Trace.WriteLine
    // simply because it would go into an endless loop
    // --------------------------------------------------
    public class DBTraceListener : TraceListener
    {
        public event DBTraceFailedHandler DBTraceFailed;
 
        #region Constants

        private const string STORED_PROC_NAME = "prc_writetraceentry";
        private const string STORED_PROC_MESSAGE_PARAM_NAME = "@message";
        private const string STORED_PROC_MESSAGETYPE_PARAM_NAME = "@type";
        private const string STORED_PROC_COMPONENTNAME_PARAM_NAME = "@componentname";
        private const string TRACE_SWITCH_NAME = "DBTraceSwitch";
        private const string TRACE_SWITCH_DESCRIPTION = "Trace switch defined in config file for configuring trace output to database";

        // Not defining it as readonly string so that in future it could come
        // from an external source and we can provide initializer for it
        private static readonly string DEFAULT_TRACE_TYPE = "Verbose";

        #endregion

        #region Class Data

        // Database connection object
        private SqlConnection _cn;

        // Database command object
        private SqlCommand _cm;

        // Connection string for database
        private string _connectionString;

        // Flag for DBTraceListener object disposal status
        private bool _disposed = false;

        // Trace Switch object for controlling trace output, defaulting to Verbose
        private TraceSwitch TraceSwitch = new TraceSwitch(TRACE_SWITCH_NAME, TRACE_SWITCH_DESCRIPTION, DEFAULT_TRACE_TYPE);

        // Delegate to point to the method which would do actual operation of logging
        private LogIt workerMethod;

        // Component Name 
        private string _componentName;

        // Lock object
        private object _traceLockObject = new object();
        private object _fileLockObject = new object();

        // Timer to refresh trace configuration information
        private Timer _traceSwitchTimer;

        // Flag to indicate whether trace configuration data needs to be refreshed
        private bool _refreshTraceConfig = false;

        #endregion

        #region Properties

        public override bool IsThreadSafe
        {
            // TODO: We are logging to database and the core method responsible
            // for this places lock on the core code responsible for executing
            // database command to ensure that only one thread can access it at
            // a time. Considering this, we can really return true for this 
            // property but before doing that, just need to do some testing.
            get { return false; }
        }

        public string ConnectionString
        {
            get
            {
                if ( string.IsNullOrEmpty(this._connectionString))
                {
                    this.LoadAttributes();
                }
                return this._connectionString;
            }
            set { this._connectionString = value; }
        }

        public string ComponentName
        {
            get
            {
                if (string.IsNullOrEmpty(this._componentName))
                {
                    this.LoadAttributes();
                }
                return this._componentName;
            }
            set { this._componentName = value; }
        }

        /// 
        /// Setting this property to True would refresh Trace configuration
        /// data from system.diagnostics section in your application configuration
        /// file. It is important to note that it would only refresh trace configuration
        /// data and not entire configuration file. For example, while your application
        /// is running, if you change one of the appSettings values, it would not be 
        /// refreshed but changing trace switch value would be refreshed.
        /// 
        public bool RefreshTraceConfig 
        {
            get 
            {
                this.LoadAttributes();
                return this._refreshTraceConfig;
            }
            set
            {
                if (value)
                {
                    // Refresh trace section every 15 minutes
                    if (!this._refreshTraceConfig)
                    {
                        // i.e. If timer is not already active
                        this._refreshTraceConfig = true;
                        this._traceSwitchTimer = new Timer(new TimerCallback(RefreshSwitch), null, new TimeSpan(0, 15, 0), new TimeSpan(0, 15, 0));
                    }
                }
                else
                {
                    // If timer is active, stop it
                    this._refreshTraceConfig = false;
                    this._traceSwitchTimer.Dispose();
                    this._traceSwitchTimer = null;
                }
            }
        }

        #endregion

        #region Methods

        void RefreshSwitch(object o)
        {
            // Trace.Refresh call is not expected to throw any exception, but if it DOES
            // catch the exception and do nothing
            try
            {
                if (this.RefreshTraceConfig)
                {
                    Trace.Refresh();
                }
            }
            catch(Exception ex)
            {
                this.WriteLine(
                    string.Format("Trace.Refresh failed with following exception: {0}, ", ex.ToString()),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.Refresh failed with following exception: {0}, ", ex.ToString()));
            }
        }

        private void WriteEntryToInternalLog(string msg)
        {
            lock (this._fileLockObject)
            {
                try
                {
                    File.AppendAllText(AppDomain.CurrentDomain.BaseDirectory + @"\DBTraceListener.log",
                        string.Format("{0}{1}: {2}", Environment.NewLine, DateTime.Now.ToString(), msg));
                }
                catch
                {
                    // Do nothing
                }
            }
        }

        /// 
        /// Another method useful for testing if DBTraceListener is
        /// able to establish connection to database
        /// 
        /// void
        public bool TestDBConnection()
        {
            try
            {
                using (SqlConnection cn = new SqlConnection(this.ConnectionString))
                {
                    cn.Open();
                }
                return true;
            }
            catch
            {
                // In case of any exception just return false
                return false;
            }
        }

        internal bool ShouldLogTrace(TraceEventType eventType)
        {
            bool shouldLog = true;

            switch (eventType)
            {
                case TraceEventType.Critical:
                case TraceEventType.Error:
                    shouldLog = this.TraceSwitch.TraceError;
                    break;

                case TraceEventType.Warning:
                    shouldLog = this.TraceSwitch.TraceWarning;
                    break;

                case TraceEventType.Information:
                    shouldLog = this.TraceSwitch.TraceInfo;
                    break;

                case TraceEventType.Start:
                case TraceEventType.Stop:
                case TraceEventType.Suspend:
                case TraceEventType.Resume:
                case TraceEventType.Transfer:
                case TraceEventType.Verbose:
                    shouldLog = this.TraceSwitch.TraceVerbose;
                    break;
            }

            return shouldLog;
        }

        #region TraceEvent

        public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id)
        {
            this.TraceEvent(eventCache, source, eventType, id, string.Empty);
        }

        public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string message)
        {
            XElement msg;

            try
            {
                if (!this.ShouldLogTrace(eventType))
                    return;

                if (eventType == TraceEventType.Critical ||
                        eventType == TraceEventType.Error ||
                        eventType == TraceEventType.Warning)
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", message),
                                            new XElement("Id", id),
                                            new XElement("CallStack", eventCache.Callstack.ToString()),
                                            new XElement("ThreadId", eventCache.ThreadId),
                                            new XElement("ProcessId", eventCache.ProcessId)
                                       );
                }
                else
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", message));
                }

                this.WriteLineInternal(msg.ToString(), eventType.ToString(), null);
            }
            catch(Exception ex)
            {
                this.WriteLine(
                    string.Format("AdvancedTracing::DBTraceListener - Trace.TraceEvent failed with following exception: {0}, for message {1} ", ex.ToString(), message),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.TraceEvent failed with following exception: {0}", ex.ToString()));
            }
        }

        public override void TraceEvent(TraceEventCache eventCache, string source, TraceEventType eventType, int id, string format, params object[] args)
        {
            XElement msg;

            try
            {
                if (!this.ShouldLogTrace(eventType))
                    return;

                if (eventType == TraceEventType.Critical ||
                        eventType == TraceEventType.Error ||
                        eventType == TraceEventType.Warning)
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", string.Format(format, args)),
                                            new XElement("Id", id),
                                            new XElement("CallStack", eventCache.Callstack.ToString()),
                                            new XElement("ThreadId", eventCache.ThreadId),
                                            new XElement("ProcessId", eventCache.ProcessId)
                                       );
                }
                else
                {
                    msg = new XElement("TraceLog",
                                            new XElement("Message", string.Format(format, args)));
                }

                this.WriteLineInternal(msg.ToString(), eventType.ToString(), null);
            }
            catch (Exception ex)
            {
                this.WriteLine(
                    string.Format("AdvancedTracing::DBTraceListener - Trace.TraceEvent failed with following exception: {0}, for message {1}", ex.ToString(), format),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.TraceEvent failed with following exception: {0}", ex.ToString()));
            }
        }

        #endregion

        #region TraceTransfer

        public override void TraceTransfer(TraceEventCache eventCache, string source, int id, string message, Guid relatedActivityId)
        {
            try
            {
                if (this.ShouldLogTrace(TraceEventType.Transfer))
                {
                    XElement msg = new XElement("TraceLog",
                            new XElement("Message", message),
                            new XElement("Source", source),
                            new XElement("Id", id),
                            new XElement("RelatedActivityId", relatedActivityId.ToString()),
                            new XElement("CallStack", eventCache.Callstack.ToString()),
                            new XElement("ThreadId", eventCache.ThreadId),
                            new XElement("ProcessId", eventCache.ProcessId));

                    this.WriteLine(msg.ToString(), TraceEventType.Verbose.ToString(), null);
                }
            }
            catch (Exception ex)
            {
                this.WriteLine(
                    string.Format("AdvancedTracing::DBTraceListener - Trace.TraceTransfer failed with following exception: {0}, for message {1} ", ex.ToString(), message),
                    "Error",
                    "DBTraceListener"
                );

                this.WriteEntryToInternalLog(string.Format("Trace.TraceTransfer failed with following exception: {0}", ex.ToString()));
            }
        }

        #endregion

        public override string ToString()
        {
            return string.Format("DBTraceListener for Component: {0} using ConnectionString: {1}", this.ComponentName, this.ConnectionString);
        }

        #region Write Methods

        public override void Write(object o)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), null);
            }
        }

        public override void Write(string message)
        {
            this.WriteLine(message, null);
        }

        public override void Write(object o, string category)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), category);
            }
        }

        public override void Write(string message, string category)
        {
            this.WriteLine(message, category);
        }

        #endregion

        #region WriteLine Methods

        public override void WriteLine(object o)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), null);
            }
        }

        public override void WriteLine(object o, string category)
        {
            if (o != null)
            {
                this.WriteLine(o.ToString(), category);
            }
        }

        public override void WriteLine(string message)
        {
            this.WriteLine(message, null);
        }

        override public void WriteLine(string message, string category)
        {
            try
            {
                if (!this.ShouldLogTrace(TraceEventType.Verbose))
                    return;

                // IMPORTANT!!!!
                // DO NOT WRITE ANY Debug.WriteLine or Trace.WriteLine statements in this method
                XElement msg = new XElement("TraceLog",
                                   new XElement("Message", message));

                this.WriteLineInternal(msg.ToString(), category, null);
            }
            catch (Exception ex)
            {
                this.WriteEntryToInternalLog(string.Format("WriteLine failed with following exception: {0}", ex.ToString()));
            }
        }

        /// 
        /// This is a non-standard WriteLine method i.e. Trace class does not provide
        /// a WriteLine method taking three parameters. It is used by internal implementation
        /// of this class to provide functionality to log a different component name,
        /// **primarily aimed towards helping in debugging some particular scenario**
        /// 
        /// 
        /// 
        /// 
        public void WriteLine(string message, string category, string componentName)
        {
            try
            {
                if (!this.ShouldLogTrace(TraceEventType.Verbose))
                    return;

                // IMPORTANT!!!!
                // DO NOT WRITE ANY Debug.WriteLine or Trace.WriteLine statements in this method
                XElement msg = new XElement("TraceLog",
                                   new XElement("Message", message));

                this.WriteLineInternal(msg.ToString(), category, componentName);
            }
            catch (Exception ex)
            {
                this.WriteEntryToInternalLog(string.Format("WriteLine failed with following exception: {0}", ex.ToString()));
            }
        }
        #endregion

        private void WriteLineInternal(string message, string category, string componentName)
        {
            // Perform the actual operation of logging **asynchronously**
            workerMethod = SaveLogEntry;
            workerMethod.BeginInvoke(message, category, componentName, null, null);
        }

        private void SaveLogEntry(string message, string category, string componentName)
        {
            // IMPORTANT!!!!
            // DO NOT WRITE ANY Debug.WriteLine or Trace.WriteLine statements in this method
            lock (_traceLockObject)
            {
                try
                {
                    // save trace message to database
                    if (this._cn.State == ConnectionState.Broken ||
                        this._cn.State == ConnectionState.Closed)
                    {
                        this._cn.ConnectionString = this.ConnectionString;
                        this._cn.Open();
                    }

                    this._cm.Parameters[STORED_PROC_MESSAGE_PARAM_NAME].Value = message;
                    this._cm.Parameters[STORED_PROC_MESSAGETYPE_PARAM_NAME].Value = category;

                    if (string.IsNullOrEmpty(componentName))
                    {
                        // No value provided by caller. Look for the value defined 
                        // in application configuration file
                        if (string.IsNullOrEmpty(this.ComponentName))
                        {
                            this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = DBNull.Value;
                        }
                        else
                        {
                            this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = this.ComponentName;
                        }
                    }
                    else
                    {
                        // Specific value provided by caller for this specific trace/log
                        // Need to use the same
                        this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = componentName;
                    }
                    
                    this._cm.ExecuteNonQuery();
                }
                catch (Exception ex)
                {
                    // Raise event to let others know, just in case 
                    // someone interested
                    if (this.DBTraceFailed != null)
                    {
                        DBTraceFailed(ex.ToString());
                    }

                    // Write entry to internal log file
                    this.WriteEntryToInternalLog(ex.ToString());
                }
                finally
                {
                    // Nothing to dispose in case of exception
                }
            }
        }

        protected override string[] GetSupportedAttributes()
        {
            return new string[] { "connectionString", "componentName", "refreshTraceConfig" };
        }

        private void LoadAttributes()
        {
            if (Attributes.ContainsKey("connectionString"))
            {
                this.ConnectionString = this.Attributes["connectionString"];
            }

            if (Attributes.ContainsKey("componentName"))
            {
                this.ComponentName = this.Attributes["componentName"];
            }

            if (Attributes.ContainsKey("refreshTraceConfig"))
            {
                bool val;
                bool.TryParse(this.Attributes["refreshTraceConfig"], out val);
                this.RefreshTraceConfig = val;
            }
        }

        protected override void Dispose(bool disposing)
        {
            if (!this._disposed)
            {
                if (disposing)
                {
                    if (this._cn != null)
                        this._cn.Dispose();

                    if (this._cm != null)
                        this._cm.Dispose();

                    if (this._traceSwitchTimer != null)
                        this._traceSwitchTimer.Dispose();
                }

                this._disposed = true;
            }

            this._cm = null;
            this._cn = null;

            base.Dispose(disposing);
        }

        #endregion

        #region Constructors

        public DBTraceListener() : this(string.Empty) { }

        public DBTraceListener(string initializeData)
            : base(initializeData)
        {
            // Initialize connection object
            this._cn = new SqlConnection();
            this._cn.ConnectionString = initializeData;
            this.ConnectionString = initializeData;
            
            try
            {
                this._cn.Open();
            }
            catch(Exception ex)
            {
                // Write to internal 
                this.WriteEntryToInternalLog(string.Format("Could not connect to database from the provided connection string. Exception: {0}", ex.ToString()));

                // Let the caller know that this listener object cannot do its 
                // work because it cannot establish connection to database
                //
                // Since Tracing framework is initialized by CLR, you would 
                // in all likelihood get Could not create type... error
                throw;
            }

            // Setup command object
            this._cm = this._cn.CreateCommand();
            this._cm.CommandText = STORED_PROC_NAME;
            this._cm.CommandType = CommandType.StoredProcedure;
            this._cm.Parameters.Add(new SqlParameter(STORED_PROC_MESSAGE_PARAM_NAME, DBNull.Value));
            this._cm.Parameters.Add(new SqlParameter(STORED_PROC_MESSAGETYPE_PARAM_NAME, DBNull.Value));
            this._cm.Parameters.Add(new SqlParameter(STORED_PROC_COMPONENTNAME_PARAM_NAME, DBNull.Value));
        }
        #endregion
    }
}

The above piece of code is what you need for a custom database trace listener. You need to run additional database scripts to create the table and stored procedure required for this, the scripts for the same are as follows:

-- tracelog table
------------------------------------------------------------
if exists (select * from sys.tables where [name]='tracelog')
begin					
	print 'table tracelog already exists.'
end
else
begin
	print 'creating table tracelog...'

	create table [dbo].[tracelog](
		[traceid] [bigint] identity(1,1) not null,
		[message] [xml] null,
		[type] [varchar](20) null default ('Verbose'),
		[componentname] [varchar](200) null default (null),
		[loggeddate] [datetime] null default (getdate()),
	primary key clustered 
	(
		[traceid] asc
	)with (ignore_dup_key = off) on [primary]
	) on [primary]

	print 'table tracelog created.';
end	
go

-- stored procedure to write trace log entry
------------------------------------------------------------
if  exists (select * from sys.objects where object_id = object_id(N'[dbo].[prc_writetraceentry]') and type in (N'p', N'pc'))
	drop procedure [dbo].[prc_writetraceentry]
go

create proc prc_writetraceentry
	@message xml = null,
	@type varchar(100) = 'Verbose',
	@componentname varchar(200) = null
as
begin
	insert tracelog([message], type, componentname)
	values(@message, @type, @componentname)
end
go

-- add index to speed up data retrieval in case the table 
-- gets too big
------------------------------------------------------------
create nonclustered index [idx_tracelog_loggeddate] on [dbo].[tracelog] 
(
	[loggeddate] desc,
	[componentname] asc,
	[traceid] asc
)
go

Now, let’s modify the application configuration file and add the newly created trace listener. You need to add the trace listener as follows:

And execute the application and you would see the following in tracelog table in database:

In summary, salient features of custom db trace listener are as follows:

  1. Writes trace entries to database table as XML data

  2. Provides additional column to identify entries with the source application/component

  3. Writes to a text file the errors generated within DB trace listener implementation

In some future post (I don’t like to say next post as I might write about something completely different in my next post), we would try to look at advanced tracing techniques such as code injection to inject code into assembly which would log additional information at the start of each method execution so that you can trace each method as it executes in your application.

Happy Coding!!

Vande Mataram!

(A salute to motherland)

P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain




About the author

Girish Jain works on Microsoft .Net framework technologies and is a big fan of WPF, WCF, and LINQ technologies. He is currently based in India with his wife and a daughter. When not spending time with family, Girish enjoys creating small tools, utilities, frameworks to improve developer productivity.

Sign In