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

CLR Journey from PInvoke to WinRT

clock June 21, 2013 11:20 by author Girish Jain

 

In this blog post, I am going to talk about Microsoft .Net Common Language Runtime (CLR) journey from its early days to latest Windows Runtime (WinRT) platform, which is released with Windows 8. I would suggest you read my previous blog post on WinMD files before reading further to gain better understanding of WinMD files introduced with Windows 8.

WinRT is the new platform released with Microsoft’s latest operating system Windows 8 and .Net Framework 4.5. It is important to remember that for WinRT APIs to work it needs at least Windows 8 as operating system (or Windows Server 2012 for server family of operating systems), and hence, WinRT is not available for previous platforms.

Coming back to WinRT, did we need another set of runtime libraries and a new file extension, WinMD? I am sure you are having this basic question in mind for what good this new WinRT library is going to do and why on earth Microsoft added a new file type? I will try and answer it in this blog post.

 

Windows Runtime (WinMD at heart)

WinRT is the new platform which exposes underlying operating system APIs in object-oriented manner to developers (across languages) and enables them to make best use of underlying platform capabilities to build great immersive apps.

WinMD files are at the heart of new Windows Runtime (WinRT) concept. These new WinMD files only contain metadata for WinRT types. WinMD files themselves do not contain any code. Hence, when you open any WinMD file using ILDAsm tool you see that all class methods are marked as "runtime managed" which, as per ECMA-335 CLI specification, means the managed implementation for the method will be provided by CLR. Please read my earlier blog post for more details on WinMD files.

Underneath, CLR bridges the gap of converting managed calls to low-level operating system (native) API calls and vice versa i.e. invoking managed callback functions from native world. This is a great step forward now because CLR is taking care of lot of complexities related to making these native API calls from managed code and vice-versa. Native APIs are written as C/C++ libraries, and before WinRT was introduced, these were consumed using Platform Invoke feature of CLR, commonly referred to as PInvoke.

With the introduction of WinRT, there has been a paradigm shift for managed developers for how they consume platform capabilities which otherwise are not already wrapped up in BCL. Let’s understand this evolution starting from its early days to latest WinRT platform. This will help you understand the internal workings of CLR and role of WinMD files too. We have come a long way with introduction of WinRT, it’s time for a little flashback.

 

.Net is Born!

To be able to best understand why we need Windows Runtime (WinRT) and WinMD files or how it is helpful, we need to go back a little into history and understand what kind of problems were there, before WinRT was born, which are now addressed by it. With the introduction of CLR, Microsoft developed rich metadata to describe types and their members in libraries (which is defined in ECMA-335 spec). This was a great step forward as existing libraries (DLLs) did not have a way to manifest it in themselves but we had to separately produce type library (TLB) files for components so that these components could be consumed in other applications. For example, you could write a COM component in C++ and then consume it in VB6 application. With the advent of .NET, assemblies themselves contained code as well as rich metadata, which was great as assemblies could describe its own types, members, and the external assemblies that it references (this was key feature which solved lot of DLL referencing related issues along with CLR assembly binder), which made assemblies self-contained and deployable unit. Hence, referencing and consuming these assemblies from other applications was a lot easier as compared to olden days, where referencing correct version of DLL, building code, and deploying binaries itself was a big challenge, commonly known as “DLL Hell”. The single biggest factor which helped solve DLL hell problem in .Net world was the ability to manifest all the rich metadata within the assembly (library) itself. Traditionally, components had very tight binary linking whereas CLR assemblies had metadata based linking.

 

PInvoke is born (Re-use existing investment)

To begin with, .Net developers did not have everything in the form of these assemblies, especially when it came to underlying low-level operating system APIs (such as APIs exposed by kernel32.dll) because, these were written and available in the form of C/C++ libraries. Microsoft did wrap certain APIs with managed wrappers over native Windows APIs, such as those for logging entries to event viewer, EventLog*classes in System.Diagnostics namespace which, are just managed wrappers over underlying native APIs. But, Microsoft could not have done it for all APIs (simply because there would be no value addition with creating and maintaining tons of managed wrappers over native APIs).

Therefore, Microsoft provided a way to enable .Net developers to consume these libraries using PInvoke. The way PInvoke works is that you would define API method signature in code and mark it as external i.e. the method implementation being available in another DLL (mentioned using attributes). Underneath, CLR would create Runtime Callable Wrapper (RCW) stub which would take care of marshalling calls between .Net Apps and native libraries. CLR would rely on method signature which you re-create in code to take care of marshalling requirements. Methods, marked as external, and type definitions re-created in source code helped CLR get the required metadata for it to be able to generate the RCW stub for marshalling and forwarding calls to libraries. In essence, metadata for native types/structures and methods was key input for CLR to make its magic and connect the two worlds.

 

PInvoke Limitations

PInvoke was great but it had its own limitations because there was still considerable amount of work to be done for .Net developers to recreate types in code (which were needed for the API call), define marshalling rules for these types, their memory layout, and so on (which was ugly and to make even a basic API call work, it took considerable amount of effort). Lots of these underlying APIs work with pointers whereas .Net developers don't directly work with pointers so they struggled with making API calls using PInvoke (working with IntPtr did not come easy to VB.Net or C# developers, to say the least). Although, they used familiar programming language such as VB .Net or C# but concepts were alien, such as pointers, memory layout, etc.

With PInvoke, CLR would use types and method signature created in source code to derive metadata, which it needed to create RCW stub, required for marshalling the call to native library. Lot of problems with this approach were derived from the fact that developers found it difficult to re-create method signatures and types in C#/VB code equivalents as they were required by CLR. In fact, there was a site (http://pinvoke.net) available, just for managed developers, to help with signature of these native methods and types such that these can be specified in their C#/VB counterparts, and this site proved to be a great asset for .Net developers trying to make native API calls using PInvoke. I am sure every developer who has created CLR applications, would have used this site at some point in time.

Therefore, Microsoft provided a way to enable .Net developers to consume these libraries using PInvoke. The way PInvoke works is that you would define API method signature in code and mark it as external i.e. the method implementation being available in another DLL (mentioned using attributes). Underneath, CLR would create Runtime Callable Wrapper (RCW) stub which would take care of marshalling calls between .Net Apps and native libraries. CLR would rely on method signature which you re-create in code to take care of marshalling requirements. Methods, marked as external, and type definitions re-created in source code helped CLR get the required metadata for it to be able to generate the RCW stub for marshalling and forwarding calls to libraries. In essence, metadata for native types/structures and methods was key input for CLR to make its magic and connect the two worlds.

For example:

[DllImport("kernel32.dll", CharSet=CharSet.Auto, SetLastError=true)]
internal static extern IntPtr GetProcAddress([In] IntPtr hModule, [In, MarshalAs(UnmanagedType.LPStr)] string lpProcName);

 

WinRT to Rescue (Partially)

.Net developers had to re-create metadata in source code such as method signatures and type definitions for CLR to do RCW magic. And this was the biggest pain area for most developers. This is where WinRT makes life easy for developers as Microsoft came up with these new WinMD files which define WinRT libraries classes and methods in rich metadata format supported and understood by CLR . Now, developers don’t need to re-create method signatures in code but just add WinMD files as reference to the project.

Now, with following three things falling in place with Windows 8 (and Windows Server 2012),

1. underlying operating system providing runtime libraries (WinRT), exposing native APIs in object-oriented manner

2. rich metadata available for WinRT classes from WINMD files and

3. RCW magic of CLR already in place,

Microsoft added new WinRT Interop functionality (on top of COM Interop infrastructure) to CLR and made life easy for managed developers. Now we can consume WinRT APIs just as you would consume any other managed API (in natural and familiar manner). With Windows Runtime you don’t have to deal with pointers and lot of complexities related with native Windows APIs but they are dealt for you by CLR. You still write code in managed language which you are familiar with.

So, WinMD files enable developers to consume native APIs from .Net apps in a natural and familiar manner (which they otherwise had to do painfully using PInvoke). So this solved an existing pain area for developers and then Microsoft went a step further which enabled developers to consume these native APIs from an array of programming languages, which are traditionally not used for .Net apps development, such as JavaScript by introducing a new feature called as "language projection".

So, to answer the question as WHY Microsoft introduced new WINMD files - it was to manifest rich metadata for operating system APIs so that developers can consume these platform APIs from managed code in a natural and familiar manner. This is the reason why Microsoft says that WinRT is NOT a new layer in itself BUT only exposes underlying operating system APIs to managed world developers.

 

Does WinRT replace PInvoke?

WinRT does not replace PInvoke as WinRT does not cover every API supported by native Windows libraries and hence, for certain APIs you would still need to use PInvoke. Rather, WinRT is enhanced version of PInvoke minus its complexities. WinRT builds on top of existing PInvoke and COM Interop infrastructure and build on existing concepts of RCW and CCW, which is great as it is re-using existing infrastructure and at the same time reducing complexities of it.

 

WinRT only for .Net?

Windows Runtime libraries (for e.g. Windows.UI.dll) are not implemented in managed code but some low-level language (my guess is C++) and made available to managed code using Windows Runtime Interop (built on top of COM Interop infrastructure) and .winmd files. The types which we see in WinMD files are defined and actually implemented by these WinRT libraries. But is WinRT only available for .Net developers? Not really, WinRT libraries can be accessed from outside CLR as well, for example, when you use JavaScript to build Metro apps, you are not using CLR to host your application but “Chakra” engine, which is used by Internet Explorer too, and internally it is consuming these WinRT libraries. So that proves the point that WinRT is not just for managed developers.

In fact, you can create classic-style COM components using Windows Runtime C++ Template Library (WRL) which can consume WinRT APIs and the COM component can then be accessed from any COM enabled technology including classic desktop apps.

 

WinRT Duplicates APIs?

Why Windows Runtime libraries duplicate certain sets of classes, especially those related to UI controls and thread pool when these are already available with .Net Framework? Why this duplication? – This duplication is there for a reason. As we saw above, WinRT is not just for managed developers but is consumed from other application hosts as well and it became necessary to make these basic sets of classes available through WinRT too. Managed developers had some of these classes already available to them and it looks like duplication for them but these classes exist in WinRT for a reason.

 

WinRT for Desktop Apps

Only a subset of WinRT Classes/APIs are available to desktop apps. Also, it is important to remember that WinRT is only available Windows 8 onwards so your target platform for the desktop app must be at least Windows 8 for the ability to access WinRT APIs.

S Hanslman has written this excellent blog post which shows manual steps for how to access WinRT APIs from desktop apps.

 

Summary

Microsoft has introduced new set of runtime libraries for Windows platform, commonly referred to as WinRT library, which expose native functionality in object oriented manner. These new libraries are based on solid principles of COM but Microsoft has shielded developers from complexities of COM. To make it easy for developers to interact with this underlying platform library, Microsoft developed WinMD files and supporting interop functionality to different runtime environments such as CLR and Chakra engine so that developers can consume these libraries from different languages (Java Script, VB .NET, C#, C++, etc) in natural and familiar manner. WinRT and its interop with runtime environments makes platform capabilities available to an array of programming languages in natural and familiar manner.

 

In my next blog post, I will try to go further into this new magical world of WinRT and further explore its internal working.

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 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




Intercept raw SOAP Message

clock April 3, 2012 21:26 by author Girish Jain

Intercept raw SOAP Message

Download source code - SOAPExtensionsLib.zip (8 kb)

While working with web services, often there are situations when you want to extract the raw SOAP message coming in to and going out of your web service. This is specially the case when you are exposing a web service and the client application is not written by you but some other company and you want to debug a scenario such as when the incoming message is not getting de-serialized to object instance, namespace issues, and so on. If you are writing your web service in ASP .Net then good news is that it is very much possible to intercept the raw SOAP message. In fact, you can work with these raw SOAP messages and do some additional works such encrypt/decrypt its contents, modify message header details, and so on. All this is possible by creating a SOAP extension which can be plugged into HTTP pipeline of ASP .Net engine.

You will find many articles on internet which tell you how to write a SOAP extension and different possibilities that can be achieved with it. But if you are like majority of developers, you just want to get raw SOAP message and want the bare minimum implementation to achieve the same, and I did not find a simple implementation for this purpose with my google skills so I decided to write one myself, of course with the help of other articles which I found on internet.

I am essentially after a very basic functionality which logs the raw SOAP message to a configured trace listener, and that is exactly what I am going to show you as part of this post. I am going to write a SOAP extension which will intercept the raw SOAP message and log it. The logging destination is to be chosen by you by adding a trace listener to the application so you don’t have to modify the SOAP extension if you choose a different logging destination and so on. You can choose to log to a file, event log, database table, etc, take your pick.

The incoming SOAP message is relatively easy to intercept and requires far less code whereas intercepting outgoing SOAP message requires relatively more work. To keep the matter simple I am going to create a SOAP Extension Library project and write two separate extensions, one which intercepts just the incoming SOAP message and the second one which intercepts incoming as well as outgoing SOAP message.

Below diagram explains the SOAP message processing extremely well. As part of creating a new SOAP extension we will need to override ProcessMessage method, which is invoked for four different stages of message processing. We will also need to override few more methods which are defined as abstract in the base SoapExtension class such as ChainStream.

SOAP Request Handling

Source: http://msdn.microsoft.com/en-us/magazine/cc164007.aspx

As we can see in above diagram, ChainStream method will be called twice in the lifecycle of SOAP message processing, first BEFORE the actual web service method is called and second time AFTER the web method call is finished. This method provides us with an opportunity to chain a new stream instance based on our requirements. Let’s see it in action with two new SOAP extensions.

Intercept Incoming SOAP Message

In case of incoming SOAP message, the stream initialized by .Net framework is accessible and you can reset the position (i.e. CanSeek property returns true). Hence, we don’t really need to chain another stream instance and can reuse the same. Find below its implementation:

using System;
using System.Collections.Generic;
using System.Text;
using System.Web.Services.Protocols;
using System.IO;
using System.Diagnostics;

namespace SOAPExtensionsLib
{
    public class IncomingSOAPMessageInterceptExtension : SoapExtension
    {
        public override Stream ChainStream(Stream stream)
        {
            // ChainStream method is called twice in the lifecycle of the SOAP
            // message processing. BEFORE the actual web service operation is
            // invoked and AFTER it has completed. 
            // 
            // In case you just want to intercept the incoming SOAP message then
            // you can read the stream initialized by .Net framework and hence, 
            // you dont need to chain a new stream. Therefore, pass the same 
            // stream back.
            //------------------------------------------------------------
            return stream;
        }

        public override object GetInitializer(Type serviceType)
        {
            return null;
        }

        public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute)
        {
            return null;
        }

        public override void Initialize(object initializer)
        {
            // do nothing...
        }

        public override void ProcessMessage(SoapMessage message)
        {
            switch (message.Stage)
            {
                case SoapMessageStage.BeforeDeserialize:
                    // Incoming message
                    LogMessageFromStream(message.Stream);
                    break;

                case SoapMessageStage.AfterDeserialize:
                    break;

                case SoapMessageStage.BeforeSerialize:
                    break;

                case SoapMessageStage.AfterSerialize:
                    break;
            }
        }

        private void LogMessageFromStream(Stream stream)
        {
            string soapMessage = string.Empty;

            // Just making sure again that we have got a stream which we 
            // can read from AND after reading reset its position 
            //------------------------------------------------------------
            if (stream.CanRead && stream.CanSeek)
            {
                stream.Position = 0;

                StreamReader rdr = new StreamReader(stream);
                soapMessage = rdr.ReadToEnd();


                // IMPORTANT!! - Set the position back to zero on the original 
                // stream so that HTTP pipeline can now process it
                //------------------------------------------------------------
                stream.Position = 0;
            }

            // You have raw SOAP message, log it the way you want. I am using 
            // Trace class as I have configured a trace listener which will 
            // write it to a database table, read:
            // http://girishjjain.com/blog/post/Advanced-Tracing.aspx
            //------------------------------------------------------------
            Trace.WriteLine(soapMessage);
        }
    }
}

You just need to make couple of changes to your web.config file, to make the extension work

1. In order to enable the new SOAP extension, you need to add it to soap extensions list using following:

2. You need to add a trace listener as follows (I am using a custom database trace listener but feel free to use anything else like EventLogTraceListener, TextWriterTraceListener, etc):

That’s it, a simple SOAP extension which logs every incoming SOAP message to a configured trace listener. Voila!

Intercept Incoming & Outgoing SOAP Message

Now if you want to intercept output SOAP message as well then, there is little more work needed to be done in the SOAP extension and hence, I have created a separate extension for the purpose. In case of incoming SOAP message, the stream instance created by ASP .Net engine is read-able so you can access it, read its contents, reset position, etc. whereas, in case of outgoing SOAP message (web service method response), the output stream created by ASP .Net engine is an instance of SoapExtensionStream class which does NOT support read operations but write only. Essentially speaking, you cannot read output stream contents but you can write to it. Hence, in this case we need to chain a new memory stream which we can read from and will pass this memory stream instance to HTTP pipeline to process the message and capture web service method response, and once done we will read its contents (SOAP response) and copy its contents to the original stream created by ASP .Net engine (of type SoapExtensionStream). Find below its code:

using System;
using System.Collections.Generic;
using System.Text;
using System.Web.Services.Protocols;
using System.Diagnostics;
using System.IO;

namespace SOAPExtensionsLib
{
    public class IncomingOutgoingSOAPMessageInterceptExtension : SoapExtension
    {
        Stream _originalStream;
        Stream _workingStream;

        public override Stream ChainStream(Stream stream)
        {
            // ChainStream method is called twice in the lifecycle of the SOAP
            // message processing. BEFORE the actual web service operation is
            // invoked and AFTER it has completed. 
            //
            // In case of outgoing response, .Net framework initializes a stream
            // as an instance of type SoapExtensionStream which does NOT support
            // reading from but write operations only. Therefore, we will chain
            // a local stream instance which will be passed to for processing by
            // actual web service method and will be read from when web service
            // method finishes processing. 
            //
            // Therefore, we need to copy contents from original stream to
            // working stream instance before 
            // Once we have read outgoing SOAP message, we will write contents 
            // from working stream to the original (SoapExtensionStream) instance, 
            // for HTTP pipeline to return it to caller.


            // Store reference to incoming stream locally
            _originalStream = stream;

            // Create a new working stream to work with
            _workingStream = new MemoryStream();
            return _workingStream;
        }

        public override object GetInitializer(Type serviceType)
        {
            return null;
        }

        public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute)
        {
            return null;
        }

        public override void Initialize(object initializer)
        {
            // do nothing...
        }

        public override void ProcessMessage(SoapMessage message)
        {
            switch (message.Stage)
            {
                case SoapMessageStage.BeforeDeserialize:
                    // Incoming message
                    Copy(_originalStream, _workingStream);
                    LogMessageFromStream(_workingStream);
                    break;

                case SoapMessageStage.AfterDeserialize:
                    break;

                case SoapMessageStage.BeforeSerialize:
                    break;

                case SoapMessageStage.AfterSerialize:
                    // Outgoing message
                    LogMessageFromStream(this._workingStream);
                    Copy(this._workingStream, this._originalStream);
                    break;
            }
        }

        private void LogMessageFromStream(Stream stream)
        {
            string soapMessage = string.Empty;

            // Just making sure again that we have got a stream which we 
            // can read from AND after reading reset its position 
            //------------------------------------------------------------
            if (stream.CanRead && stream.CanSeek)
            {
                stream.Position = 0;

                StreamReader rdr = new StreamReader(stream);
                soapMessage = rdr.ReadToEnd();
                

                // IMPORTANT!! - Set the position back to zero on the original 
                // stream so that HTTP pipeline can now process it
                //------------------------------------------------------------
                stream.Position = 0;
            }

            // You have raw SOAP message, log it the way you want. I am using 
            // Trace class as I have a configured a trace listener which will 
            // write it to database table
            // http://girishjjain.com/blog/post/Advanced-Tracing.aspx
            //------------------------------------------------------------
            Trace.WriteLine(soapMessage);
        }

        private void Copy(Stream from, Stream to)
        {
            TextReader reader = new StreamReader(from);
            TextWriter writer = new StreamWriter(to);
            writer.Write(reader.ReadToEnd());
            writer.Flush();
        }
    }
}

Feel free to use the extension depending upon your requirements, all that you would need to do is place the dll in the bin folder and make couple of changes to web.config file and you are done, absolutely no changes required to your application. Simple implementation for intercepting raw SOAP messages, that’s what I was after to begin with.

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