Tracing with Code Injection: Part II

• Download source code - 170.2 KB
• Download source code (external link)

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 a fair idea of the code injection approach developed in the 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 the 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.
   1. 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:
      1. Load (push) each argument value using ldarg instruction.
      2. If the parameter is passed by reference, then use ldind instruction to de-reference the pointer and push actual value to stack.
      3. If the parameter is value-type, then box the value type instance using box instruction.
      4. 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.
   2. Load (push) method signature string to the evaluation stack using ldstr "method signature".
   3. 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 the 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 ways 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)
        {
            // Boolean value to store developer's preference, whether
            // he wants to inject code which will dump parameters value as well.
            bool logWithData = false;
            // Boolean flag to indicate whether we have
            // injected code to the assembly under consideration
            bool isAssemblyInjected = false;
            // Boolean flag to indicate whether we have a ByRef
            // parameter where the underlying/referenced type is a value type
            bool pointerToValueTypeVariable = false;
            // Meta data type enum from Mono.Cecil
            MetadataType paramMetaData;

            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<instruction> objTracingInstructions = new List<instruction>();

                // 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 are going to 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 explicitly specified his/her 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 explicitly 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 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 a parameter 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 don't 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 parameter 
                                    // ------------------------------------------------------------
                                    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!!

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