Log4PostSharp 1.0.1

Today I've uploaded an update for the Log4PostSharp that has the following changes:

• recompiled against PostSharp 1.0 RTM,
• code that is injected no longer caches values of the log.IsDebugEnabled properties - this resolves some settings related issues and enables support for the log4net's ability to reload settings in run-time.

The new version can be downloaded from http://postsharp-user-plugins.googlecode.com/files/Log4PostSharp-1.0.1.0-Release-2.0.zip.

Log4PostSharp - logging with AOP

Introduction

Log files are crucial when it comes to troubleshooting an application or finding exact source of a bug. Unfortunately, the more information the application logs, the more its code gets cluttered with logging statements. Readability of source code decreases and, in a team of developers, it may be hard to keep consistency of logged data.
If these problems sound familiar to you, Log4PostSharp is for you. It inserts logging statements without touching your source code. It injects calls to log4net methods into the DLL and EXE files automatically right after they are compiled. This guarantees consistency of log files and allows you forgetting about logging at all.

Quick comparison

To illustrate the difference Log4PostSharp makes, this section compares two snippets of code.
In the first snippet, the logging has been added in the traditional way:

public void Save()
{
try
{
 if (log.IsDebugEnabled)
 {
  log.Debug("Saving file.");
 }

 Configuration.Save();

 if (log.IsDebugEnabled)
 {
  log.Debug("File has been saved.");
 }
}
catch (Exception ex)
{
 if (log.IsErrorEnabled)
 {
  log.Error("Failed to save file.", ex);
 }
 throw;
}
}

Note that, out of the total 10 lines of code (not counting lines containing only braces), only 1 line has any business value (the one in bold). Remaining 9 lines are there only to ensure that the progress of the method execution gets logged. And this is only single method, real-life applications consist of thousands of them. That means a lot of lines which introduce no business value and make the code harder to read.
This is where Log4PostSharp comes to rescue. Check the second snippet; it shows method that performs exactly same business action as the first one, but relies on Log4PostSharp to do the logging:

[Log]
public void Save()
{
Configuration.Save();
}

It does not contain even a single logging statement but still produces log output which is very similar to the first version of the method. And as the latter part of this article will show, even the Log attribute that the method is decorated with can be removed.

Demo

If you want to quickly see some sample application that uses Log4PostSharp, you can download the demo project from http://code.google.com/p/postsharp-user-plugins/downloads/list. Remember to download and install the latest version of PostSharp first from http://www.postsharp.org/.

How does it work?

To achieve its goal, Log4PostSharp uses PostSharp, an excellent tool that allows injecting code into .NET assemblies. Normally the injection occurs automatically after the project is compiled (PostSharp installer configures .NET build process to make this possible, for more details please visit http://www.postsharp.org/).
To see how the injection works, please first see the ReadNumber method in the demo project:

[Log(EntryLevel = LogLevel.Debug, ExitLevel = LogLevel.Debug, ExceptionLevel = LogLevel.Fatal)]
private static int ReadNumber() {
// Display prompt.
Console.Write("Please enter a number: ");

// Read the line from the console.
string line = Console.ReadLine();

// Convert the data into the integer.
return int.Parse(line, CultureInfo.CurrentCulture);
}

It does not contain any logging statements – just three lines of code and the Log attribute. Now compile the demo application and open the resulting executable inside Lutz Roeder’s Reflector. Decompile the ReadNumber method back to C#. This is what you will see:

private static int ReadNumber()
{
int ~returnValue~2;
try
{
 if (~log4PostSharp~isDebugEnabled)
 {
  ~log4PostSharp~log.Debug("Entering method: Int32 ReadNumber().");
 }

 Console.Write("Please enter a number: ");
 int CS$1$0000 = int.Parse(Console.ReadLine(), CultureInfo.CurrentCulture);
 ~returnValue~2 = CS$1$0000;

 if (~log4PostSharp~isDebugEnabled)
 {
  ~log4PostSharp~log.Debug("Exiting method: Int32 ReadNumber().");
 }
}
catch (Exception ~ex~3)
{
 if (~log4PostSharp~isFatalEnabled)
 {
  ~log4PostSharp~log.Fatal("Exception thrown from method: Int32 ReadNumber().", ~ex~3);
 }
 throw;
}
return ~returnValue~2;
}

Note that the Log attribute has been removed and the new code has been added to the method body. You may also note that the class has new six static fields and the static constructor that initializes them. Injected logging code reads the fields instead of invoking some log4net methods to improve logging performance.
Code that gets injected follows the log4net recommendations and is optimized to achieve the best performance. In the static constructor, the logger is created for every class as:

 ~log4PostSharp~log = LogManager.GetLogger(typeof(Program));

This means that logger name is same as class name (including namespace).
Log4PostSharp does not interfere with any manually added logging code and requires that developer configures log4net the usual way.
NOTE: Remember that Log4PostSharp caches some information (like indications whether loggers are enabled). If you configure the log4net by placing "[assembly: XmlConfigurator(Watch = true)]" line somewhere in the AssemblyInfo.cs file and then enable/disable loggers while the application is already running, these changes will have no effect.

Customization

The Log attribute exposes few properties that allows you customizing the code that gets injected.

EntryLevel, ExitLevel, ExceptionLevel

Values of these properties are of LogLevel type and determine what log4net method is used to write the message to the log. Names of values specified in the LogLevel enumeration correspond to names of respective log4net logging methods. The only exception is the LogLevel.None which indicates that no code is injected at all.

EntryText, ExitText, ExceptionText

Determines the text that gets logged. It can contain placeholders which then get replaced with actual values:

• {signature} – replaced with the signature of the method [weave-time],
• {@parameter_name} – replaced with the value of the specified parameter [run-time],
• {paramvalues} – replaced with the comma-separated list of values of all method parameters [run-time],
• {returnvalue} – replaced with the value that the method is about to return [run-time].

Note that placeholders are marked as being either weave-time or run-time. Values of the weave-time placeholders are determined when the code is being injected. Hence, performance of the generated code is exactly same as if the placeholders were not used (build may take little longer though). On the other hand, values of the run-time ones cannot be determined until the method gets called (and may vary between two different method calls). Therefore, if run-time placeholders are specified, code generated by Log4PostSharp needs to find proper values and then put them into the message. Such code looks like:

 if (log.IsDebugEnabled)
{
 object[] args = new object[] { left, top, width, height };
 log.DebugFormat(CultureInfo.InvariantCulture, "Drawing box: '{0}', '{1}', '{2}', '{3}'.", args);
}

Examples of messages using placeholders:

• ...EntryText = "Entering method: {signature}."...
• ...EntryText = "Authenticating user: {@userName}."...
• ...EntryText = "Drawing box: {paramvalues}."...
• ...ExitText = "Exiting method: {signature}."...
• ...ExitText = "Authentication result for {@userName} is {returnvalue}."...
• ...ExceptionText = "Exception has been thrown from the method: {signature}."...

Notes and limitations:

• Value of the ExceptionText property can contain only weave-time placeholders.
• Output parameters and return value can be referenced only in the ExitText.
• If a method returns no value (void), the {returnvalue} placeholder still can be used and its value is assumed to be null.

Multicast

Adding the attribute to every method separately would be not only tedious but would also defeat one of the biggest benefits of the library: automatization. Fortunately PostSharp features custom attribute multicasting, which allows applying any attribute to multiple methods at once. You can use the feature by dropping the following line into the AssemblyInfo.cs file:

[assembly: Log(AttributeTargetTypes = "*", EntryLevel = LogLevel.Debug, ExitLevel = LogLevel.Debug, ExceptionLevel = LogLevel.Error, AttributePriority = 1)]

The line adds the attribute to every single method in the assembly. This also includes property setters and getters and event addition and removal handlers. To exclude them, add the following lines:

[assembly: Log(AttributeTargetTypes = "*", AttributeTargetMembers = "get_*", AttributeExclude = true, AttributePriority = 2)]
[assembly: Log(AttributeTargetTypes = "*", AttributeTargetMembers = "add_*", AttributeExclude = true, AttributePriority = 2)]
[assembly: Log(AttributeTargetTypes = "*", AttributeTargetMembers = "remove_*", AttributeExclude = true, AttributePriority = 2)]

The lines prevent the attribute from being added to property getters and event addition and removal handlers respectively. Note the AttributePriority property, which is the only way that you can order your attibutes (order in which they appear in the file is irrelevant). Exclusion must always occur after inclusion to make it work. For information on more multicast features see PostSharp documentation.
Multicast attributes can be customized just like the ordinary ones.

How to use it in own projects

If you have a project where you want to use the automated logging, you have to follow few simple steps.

Get libraries

Download PostSharp from http://www.postsharp.org/ and install it.
Download Log4PostSharp from http://code.google.com/p/postsharp-user-plugins/downloads/list and copy Log4PostSharp.Weaver.dll and Log4PostSharp.psplugin files into the Plugins directory under your PostSharp installation folder. Copy the Log4PostSharp.dll into the directory where you store other libraries for your project.

Add references

In the project, add references to the Log4PostSharp.dll and PostSharp.Public.dll (you can find this library on the ".NET" tab of the "Add reference..." dialog). Remember that these DLL files are required only by the compiler and weaver. You do not need to deploy them with your application or library.

Decorate methods with attribute

Decorate desired methods with the Log attribute or just add the attribute to all methods using the multicast feature. Compile and run the application to see that it works. From this moment you can start removing old logging code (or just stop adding new logging code).

Other options

If you do not want to install the Log4PostSharp into the PostSharp's Plugins folder, you will need to provide .psproj file for your project. For more details please refer to PostSharp documentation.

Final words

The Log4PostSharp is published under the BSD license which allows using it freely even in commercial products.

AssemblyInfo, csproj and MSBuild

Introduction

Recently I've assigned myself ;) a task to clean up build process for one of the projects I participate in. Our previous build script had some issues - it was tied to our build server, tried to do everything (from checking out code from source control to creating installers) and none of its parts could be reused in our other projects. We wanted a script that can be easily invoked on any machine (simple check out source then build on a clean machine should work), can be easily customized and (at least partially) reused by our future projects.

The key to our new solution was the fact that since VS2005, the csproj files are in fact MSBuild scripts. They can be built on a machine without the IDE by invoking MSBuild. Furthermore, the csprojs are very short scripts - they define only a set of properties (like configuration or paths) and items (like files to compile or references to other projects) and then refer to default scripts shipped with MSBuild to do the real job (compilation, XML documentation files generation, etc). These MSBuild default scripts are highly customizable - they allow adding custom behavior at any stage of the build process.

I thought that instead of writing a new "external" build script (which would then invoke child MSBuild process on the csproj or sln files) I can extend these default scripts to make our behaviors integral part of the build process. This would guarantee us that no matter how the software is built (from within IDE or by CI server) our custom actions are executed, policies enforced, etc. Also sharing customizations between project seemed to be simpler.

This text assumes that the reader has minimal knowledge of MSBuild, i.e. its syntax and concepts of targets, tasks, properties and items.

Versioning

The first step was to create custom targets file that would contain all the custom functionality that we wanted to be shared by all our C# projects. This includes targets for version number generation and AssemblyInfo.cs manipulation.

I started with the version determining target. Version number consists of four numbers, which are: major, minor, build and revision. In our approach, the first three numbers are embedded into the script and are adjusted manually by us after every major or minor release. The last one (revision) is determined automatically and is set to the number of the last change in the source control. (This will not work good if we want to build some previous version of the application, but we don't worry about this now.) This feature (source control integration) is disabled by default (in which case revision defaults to 0) to speed up the build at developer machines.

After version number is known, the target that generates AssemblyInfo.cs can be built. We use AssemblyInfo task from the MSBuild Community Tasks Project. It creates a new file with the details that are specified as task parameters. These include various version numbers, copyright notice, producer, etc.

However, I don't like the idea of such automated modifications being made to files that are under source control. The solution to this problem is simple - remove AssemblyInfo.cs from the source control and C# project. Instead, add the following lines to the script:

   <ItemGroup>
       <Compile Include="Properties\AssemblyInfo.cs">
   </ItemGroup>

This ensures that the file is passed to the compiler. On the other hand, when Visual Studio populates the solution explorer, by default it ignores all files that are not included directly in the csproj file (this does not affect the compiler - only what is visible in the solution explorer). Thanks to this, IDE will not complain that it cannot find the AssemblyInfo.cs in a freshly checked out source.

At this point we are ready to inject our custom build targets into the build process. This can be achieved by overriding certain targets or changing property values. I chose to do the latter, as target overriding does not provide such flexibility we wanted. Default MSBuild projects expose properties like BuildDependsOn, CleanDependsOn, etc. These contains names of targets that are executed to build or clean the project. We changed the properties by putting:

   <PropertyGroup>
       <BuildDependsOn>SetVersionNumber;CreateAssemblyInfo;$(BuildDependsOn)</BuildDependsOn>
   </PropertyGroup>

into the shared script. This causes that every time the project is built, our targets are called before actual compilation starts.

What is left now is to reference the shared script (include it) by our C# projects. This unfortunately requires opening csproj files in an external editor (like Notepad). We need to add the following line into every our csproj:

 <Import Project="..\Client.CSharp.targets">

somewhere after the line:

 <Import Project="$(MSBuildToolsPath)\Microsoft.CSharp.targets">

which completes the first stage of our build process improvement task. Our targets are now executed every time the MSBuild is invoked on the project. From now on we can easily add new tasks as doing this requires us only changing this single, shared build file.

This is of course not the whole story - we did not stop changes after adding versioning targets. But I will leave this for the next part of the article.

--
Michal Dabrowski