Logging and instrumentation

Why

There are at least two reasons for an application to register what tfhe user do.

The first one and the most important is to see what is happening when a user has an error: what have been done, on which path did he go and what additional data(method parameters, usually) do you need for reproducing the bug.

The second one is to provide the application a way to record in-obtrusive messages for same actions that may seems not so right(check the event log for your computer for more examples 😉 )

Requirements for a logging system

The logging system should be:

1. Robust – if it can not write the message, it should not fail the entire app

2. Multi-write-data : it can write easily to multiple systems(such as databases, files on disk, send emails and so on)

3. Flexibility : the configuration of the logging system should be easy to modify. More, the modifications should be applied and “re-loaded” without re-compiling or re-starting the application

An implementation

For the implementation I will use log4net , http://logging.apache.org/log4net/ that it is satisfies all three conditions.

We will do a console application that sends a random error

using System;

using System.Collections.Generic;

using System.Linq;

using System.Text;

namespace ConsoleDemo1

{

class Program

{

static void Main(string[] args)

{

long ticks = DateTime.Now.Ticks;

FirstFunction(ticks);

}

static void FirstFunction(long i)

{

if (i % 2 == 0)

{

throw new ArgumentException("from first function");

SecondFunction(i);

}

static void SecondFunction(long i)

{

if (i % 2 == 1)

{

throw new ArgumentException("from second function");

}

}

}

}

As you see this application will have an error no matter if the ticks are even or odd. Download project from here : http://msprogrammer.serviciipeweb.ro/wp-content/uploads/loggingDemo.zip

Now we will see how the log4net writes data and error to a physical storage, in order to can be retrieved later.

Download log4net, add reference to it and make the following 4 steps

1. add a config file (I will name it log4net.config ) and in properties put “Copy to output Directory” to “Copy always” .

Examples of log4net config files you will find everywhere on internet . If you look at the project you will see a bunch of “appenders” : ConsoleAppender, RollingLogFileAppender , SmtpAppender . The appender appends the log to the storage provided (Console, File, Email ). You will find a list of appenders at http://logging.apache.org/log4net/release/sdk/log4net.Appender.html and, if you do not found some appender you can wrote your own – just look at the source code.

For this application I want to use just ConsoleAppender and RollingFileAppender

<root>

<level value=”DEBUG” />

<appender-ref ref=”ConsoleAppender” />

<appender-ref ref=”RollingLogFileAppender” />

</root>

2. In order to see the file, put

log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo("log4net.config"));

(for asp.net application ,put

log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(Server.MapPath("~/log4net.config")));

)

3. Add a variable to log the errors :

private static readonly log4net.ILog _logger = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

4. Add a try/catch to log errors :

try

{

FirstFunction(ticks);

}

catch (Exception ex)

{

if (_logger.IsErrorEnabled)

{

_logger.Error("see an error!", ex);

}

throw;

}

Now, if you run the ConsoleDemoLog4net project, then you will see how to exception is logged twice and you will find the currentlog.txt in the same folder as your application executable.

Automatically instrument an application(dll, exe, asp.net)

This was pretty good – but what about putting a log to every method to see where the application flow has been gone and with which arguments?

You can do this with postsharp / log4postsharp. Postsharp is … Log4Postsharp is …

Let’s make the application do this automatically.

We download Postsharp 1.0 (not 1.5!) from http://www.softpedia.com/progDownload/PostSharp-Download-114994.html (you can found a more good paid version at http://www.sharpcrafters.com/downloads/ )

Now we will do the following :

1. Add the log4net.config from the previous project

2. Add log4net , PostSharp.Public and PostSharp reference

3. Add to the main just:

log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo("log4net.config"));

Do NOT add the log4net code to intercept!

4. Modify AssemblyInfo.cs and put

using Log4PostSharp;

[assembly: Log(AttributeTargetTypes = "*", EntryLevel = LogLevel. Error, EntryText = "postsharp :entering {signature} {paramvalues}", ExitLevel = LogLevel. Error, ExceptionLevel = LogLevel.Error, ExitText = "postsharp :exit {signature} {paramvalues} => {returnvalue}", ExceptionText = "postsharp : error in {signature} ")]

5. Add a text file named <yourprojectname>.psproj (in this case, ConsoleDemoPostSharp.psproj ) with the following content:

<?xml version=”1.0″ encoding=”utf-8″ ?>

<Project xmlns=”http://schemas.postsharp.org/1.0/configuration”>

<SearchPath Directory=”bin/{$Configuration}”/>

<SearchPath Directory=”{$SearchPath}” />

<SearchPath Directory=”lib” />

<Tasks>

<AutoDetect />

<Compile TargetFile=”{$Output}” IntermediateDirectory=”{$IntermediateDirectory}” CleanIntermediate=”false” />

</Tasks>

</Project>

6. Edit by hand the csproj file and add this :

<PropertyGroup>

<DontImportPostSharp>True</DontImportPostSharp>

<PostSharpDirectory> ..\libs\ postsharp\</PostSharpDirectory>

<PostSharpUseCommandLine>True</PostSharpUseCommandLine>

</PropertyGroup>

<Import Project="$(PostSharpDirectory)PostSharp.targets" Condition=" Exists('$(PostSharpDirectory)PostSharp.targets') " />

7. If there is a screen to ask you about a project modification, please tell “Load project normally”

So now , when it’s compiling , it says :

“D:\programe\youtube\loggingDemo\libs\postsharp\PostSharp.exe” “D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\ConsoleDemoPostSharp.psproj” “D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\obj\Release\Before-PostSharp\ConsoleDemoPostSharp.exe” “/P:Output=obj\Release\ConsoleDemoPostSharp.exe ” “/P:ReferenceDirectory=D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp ” “/P:Configuration=Release ” “/P:Platform=AnyCPU ” “/P:SearchPath=bin\Release\,obj\Release\, ” “/P:IntermediateDirectory=obj\Release\PostSharp ” “/P:CleanIntermediate=False ” “/P:MSBuildProjectFullPath=D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\ConsoleDemoPostSharp.csproj ” “/P:SignAssembly=False ” “/P:PrivateKeyLocation= ”

PostSharp 1.0 [1.0.12.469] – Copyright (c) Gael Fraiteur, 2005-2008.

EXEC : warning PS0064: A new version of PostSharp 1.0 is available. You have currently 1.0.12.469 and you could download the version 1.0.13.630 from http://www.sharpcrafters.com/postsharp/download.

info PS0035: C:\Windows\Microsoft.NET\Framework\v2.0.50727\ilasm.exe “D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\obj\Release\PostSharp\ConsoleDemoPostSharp.il” /QUIET /EXE /PDB “/RESOURCE=D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\obj\Release\PostSharp\ConsoleDemoPostSharp.res” “/OUTPUT=D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\obj\Release\ConsoleDemoPostSharp.exe” /SUBSYSTEM=3 /FLAGS=1 /BASE=19595264 /STACK=1048576 /ALIGNMENT=512 /MDV=v2.0.50727

ConsoleDemoPostSharp -> D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\bin\Release\ConsoleDemoPostSharp.exe

Done building project “ConsoleDemoPostSharp.csproj”.

We then run the program and enjoy the power of PostSharp :

2010-04-17 23:29:12,705 [1] ERROR 2010-04-17 23:28:43,265 [1] ERROR D:\programe\youtube\loggingDemo\ConsoleDemoPostSharp\Program.cs ConsoleDemoPostSharp.Program [(null)] – postsharp :entering Void FirstFunction(Int64) “634071437232634478”

[more data]

So , as you see it gives you not only the trace , but also the value : 634071437232634478

You can download code from http://msprogrammer.serviciipeweb.ro/wp-content/uploads/loggingDemo.zip

Additional resources

Tracing : http://www.15seconds.com/Issue/020910.htm

Enterprise logging : http://msdn.microsoft.com/en-us/library/cc309257%28v=MSDN.10%29.aspx

VS2010 with Dotfuscator : http://msdn.microsoft.com/en-us/library/ff460257.aspx

CCI metadata : http://ccisamples.codeplex.com

Postsharp 2.0 improvements over 1.0 : one of many examples here : http://www.sharpcrafters.com/blog/post/introducing-postsharp-2-0-1-notifypropertychanged.aspx