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
- Code injection approach frees the developer from manually writing tracing code at the start of their method body.
- 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:
- 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). - Mark methods with the custom attribute
[LogMethodExecutionEntryAttribute]
. - 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).
- 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)
- Load the input assembly
- Loop over all its modules
- For each module, loop over all its types
- For each type, loop over all its methods
- For each method, check whether it is marked with
LogMethodExecutionEntryAttribute
custom attribute. - If method is marked with the known custom attribute, then inject following IL instructions at the start of method body.
- 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:
- Load (push) each argument value using
ldarg
instruction. - If the parameter is passed by reference, then use
ldind
instruction to de-reference the pointer and push actual value to stack. - If the parameter is value-type, then box the value type instance using box instruction.
- 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.
- Load (push) method signature
string
to the evaluation stack using ldstr
"method signature". - 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.
- 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)
{
bool logWithData = false;
bool isAssemblyInjected = false;
bool pointerToValueTypeVariable = false;
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;
if (!Directory.Exists(outputDirectory))
{
Directory.CreateDirectory(outputDirectory);
}
try
{
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<instruction> objTracingInstructions = new List<instruction>();
asmDef = AssemblyDefinition.ReadAssembly(assemblyPath);
foreach (ModuleDefinition modDef in asmDef.Modules)
{
typeObject = modDef.TypeSystem.Object;
foreach (TypeDefinition typDef in modDef.Types)
{
foreach (MethodDefinition metDef in typDef.Methods)
{
if (this.TryGetCustomAttribute(metDef,
"AdvancedTracing.LogMethodExecutionEntryAttribute", out customAttr))
{
Trace.WriteLine("Found method " + metDef.ToString());
isAssemblyInjected = true;
if (customAttr.HasConstructorArguments)
{
if (customAttr.ConstructorArguments != null
&& customAttr.ConstructorArguments.Count > 0)
{
if (!bool.TryParse
(customAttr.ConstructorArguments[0].Value.ToString(),
out logWithData))
{
logWithData = false;
}
}
}
else
{
logWithData = false;
}
ILProcessor ilProcessor = metDef.Body.GetILProcessor();
int intMethodParamsCount = metDef.Parameters.Count;
int intArrayVarNumber = metDef.Body.Variables.Count;
objTracingInstructions.Clear();
objTracingInstructions.Add(ilProcessor.Create(
OpCodes.Ldstr,
metDef.ToString()
));
if (intMethodParamsCount > 0 && logWithData)
{
ArrayType objArrType = new ArrayType(typeObject);
metDef.Body.Variables.Add(new VariableDefinition
((TypeReference)objArrType));
metDef.Body.InitLocals = true;
objTracingInstructions.Add(
ilProcessor.Create(OpCodes.Ldc_I4, intMethodParamsCount)
);
objTracingInstructions.Add(
ilProcessor.Create(OpCodes.Newarr, typeObject)
);
objTracingInstructions.Add(
ilProcessor.Create(OpCodes.Stloc, intArrayVarNumber)
);
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)
{
break;
}
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldloc, intArrayVarNumber));
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldc_I4, i));
if (metDef.IsStatic)
{
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldarg, i));
}
else
{
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldarg, i + 1));
}
pointerToValueTypeVariable = false;
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)
{
case MetadataType.Boolean:
case MetadataType.SByte:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_I1));
pointerToValueTypeVariable = true;
break;
case MetadataType.Int16:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_I2));
pointerToValueTypeVariable = true;
break;
case MetadataType.Int32:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_I4));
pointerToValueTypeVariable = true;
break;
case MetadataType.Int64:
case MetadataType.UInt64:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_I8));
pointerToValueTypeVariable = true;
break;
case MetadataType.Byte:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_U1));
pointerToValueTypeVariable = true;
break;
case MetadataType.UInt16:
case MetadataType.Char:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_U2));
pointerToValueTypeVariable = true;
break;
case MetadataType.UInt32:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_U4));
pointerToValueTypeVariable = true;
break;
case MetadataType.Single:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_R4));
pointerToValueTypeVariable = true;
break;
case MetadataType.Double:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_R8));
pointerToValueTypeVariable = true;
break;
case MetadataType.IntPtr:
case MetadataType.UIntPtr:
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldind_I));
pointerToValueTypeVariable = true;
break;
default:
if (referencedTypeSpec.ElementType.IsValueType)
{
objTracingInstructions.Add
(ilProcessor.Create(
OpCodes.Ldobj,
referencedTypeSpec.ElementType));
pointerToValueTypeVariable = true;
}
else
{
objTracingInstructions.Add
(ilProcessor.Create
(OpCodes.Ldind_Ref));
pointerToValueTypeVariable = false;
}
break;
}
}
else
{
}
}
if (paramType.IsValueType || pointerToValueTypeVariable)
{
if (pointerToValueTypeVariable)
{
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Box, referencedTypeSpec.ElementType));
}
else
{
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Box, paramType));
}
}
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Stelem_Ref));
}
objTracingInstructions.Add(ilProcessor.Create
(OpCodes.Ldloc, intArrayVarNumber));
objTracingInstructions.Add(ilProcessor.Create(
OpCodes.Call,
metDef.Module.Import(
loggingMethodWithData.GetElementMethod()
)
));
}
else
{
objTracingInstructions.Add(ilProcessor.Create(
OpCodes.Call,
metDef.Module.Import(
loggingMethod.GetElementMethod()
)
));
}
objTracingInstructions.AddRange(metDef.Body.Instructions);
metDef.Body.Instructions.Clear();
foreach (var IL in objTracingInstructions)
{
metDef.Body.Instructions.Add(IL);
}
}
}
}
}
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
{
throw;
}
return true;
}
public bool InjectTracingLine(string assemblyPath)
{
Trace.WriteLine("InjectTracingLine called minus outputDirectory, " +
"will default to application config file value");
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
Girish Jain works on Microsoft .Net framework technologies and is a big fan of WPF, WCF, and LINQ technologies. When not spending time with family, Girish enjoys creating small tools, utilities, frameworks to improve developer productivity and also writes Windows Phone applications.
Loves economics, technology, family, and tennis. Pity liars and politicians.