Tracing with Code Injection

Continuing from one of my previous blog posts 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 the 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 the 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, the above trace entry tells the 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.

We don’t want to write the code ourselves to call the Trace.WriteLine method in all the methods across the entire application and all libraries, as that would be a lot of 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, another will write the signature partially, the 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. 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 cru 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 the following two IL instructions at the start of method body
   1. ldstr <method signature> // Loads (pushes) method signature string on to the evaluation stack
   2. 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 the definition of LogMethodExecutionEntryAttribute class 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):

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

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.

CodeProject