PostSharp. Problem solving logging and auditing

Hello again! Last time, when discussing AOP, we talked about solving caching problems. Today we will talk about an equally frequent task - the task of logging and auditing. We often have to deal with situations such as, for example, analyzing someone else's code. Imagine that you were given the task of integrating with a third-party library. The core tools of almost every developer - .net reflector, ILSpy, dotPeek give an excellent idea of ​​the program code. About its algorithms, structure, possible locations of errors. And cover a large percentage of questions to the software product. However, this happens until you begin to actively use it. There may be both performance problems and incomprehensible “bugs” inside a third-party product, which, if you do not have a disassembler with the debugger function, are not so easy to find. Or, for example, you just need to monitor the values ​​of variables, without stopping the product at breakpoints, real-time. Such places often need to be urgently and quickly corrected. And how, when correcting this code, do not write a program that will then be in the top of the site govnokod.ru ? We will talk about such situations now.


Logging and auditing are opportunities where PostSharp is one of the best. This is one of the fundamental examples showing the principle of "cross-cutting". After all, instead of interspersing the logging code in each place where it should be done, you enter logging in only one point, automatically distributing the code to all the necessary methods. And, of course, you can do it selectively, on several methods, fields, or properties. You can write to the log a lot of very useful information, however, during the lifetime of the framework and the practice of working with it, I will highlight the following popular categories:

• Information about executable code: function name, class name, parameter values, and so on. This can greatly help you in reducing the various scenarios that could lead to a result;
• Performance information: you can find out how long it took to execute methods;
• Exceptions: it is possible to intercept an exception, save information about it to the log and regenerate this exception in order not to violate the logic of the original application.

In addition to logging / tracing, which are actually more technical issues, you can also audit an application, which is very similar to logging / tracing, except that audit is tracking information that carries more “business” activity. For example, you can take the logging of the values ​​of any parameter when searching for errors, or you or your manager want to find out how often and how long deposit operations are performed. You can put all the information in a report file or in the tables of your database and display it on the corporate website in the form of beautiful graphs.
Let's use some bank teller program. And let's assume that this application can use bill counters, as well as written using WinForms. Also (in our very naive and simplified model), let the bank have only one client (for example, the president), and let us have only one static class that provides all the business logic.
')

public class BankAccount
{
static BankAccount()
{
Balance = 0;
}
public static decimal Balance { get ; private set ; }

public static void Deposit( decimal amount)
{
Balance += amount;
}

public static void Withdrawl( decimal amount)
{
Balance -= amount;
}

public static void Credit( decimal amount)
{
Balance += amount;
}

public static void Fee( decimal amount)
{
Balance -= amount;
}
}

* This source code was highlighted with Source Code Highlighter .

Of course, in a real application, you will use a specialized layer of services, dependency injection and other architectural solutions instead of just a static class. And maybe you would even want to use lazy loading of dependencies, but let's drop all unnecessary and concentrate on the main thing - logging and auditing.
The app works great all the time, as long as the company has honest employees and customers. However, the financial director of this bank is at the stage of dismissal, since millions of dollars are suddenly missing, and no one can understand why. She hires you, a modest postsharp specialist, to find out what's the matter with your help. She wants you to change the program in such a way as to keep records of all transactions and transactions (yes, there are records, but she wants to do this at the level of the program’s methods in order to find out their actual number, and not what appears in the reports). In such a situation, you could have patience and enter business logic programs into each method (in our example these will be only 4 methods, but there could be several thousand of them in a real application). Or, you can write just one method, and apply it to all the methods of a particular group of classes or methods, right away, without monotonous monkey work. Moreover, placing the code throughout the program, you set yourself traps, because you will need to delete it later (or take additional steps so that it is not in the release build). And the second reason for the inconvenience of such an approach is that you can make mistakes while writing it. Let's take a look at the code we write using PostSharp :

[ Serializable ]
public class TransactionAuditAttribute : OnMethodBoundaryAspect
{
private string _methodName;
private Type _className;
private int _amountParameterIndex = -1;

public override bool CompileTimeValidate(MethodBase method)
{
if (_amountParameterIndex == -1)
{
Message.Write(SeverityType.Warning, "999" ,
"TransactionAudit was unable to find an audit 'amount' in {0}.{1}" ,
_className, _methodName);
return false ;
}
return true ;
}

public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
{
_methodName = method.Name;
_className = method.DeclaringType;

var parameters = method.GetParameters();
for ( int i=0;i<parameters.Length;i++)
{
if (parameters[i].Name == "amount" )
{
_amountParameterIndex = i;
}
}
}

public override void OnEntry(MethodExecutionArgs args)
{
if (_amountParameterIndex != -1)
{
Logger.Write(_className + "." + _methodName + ", amount: "
+ args.Arguments[_amountParameterIndex]);
}
}
}

* This source code was highlighted with Source Code Highlighter .

Recall that CompileTimeInitialize is used to get the name of methods and parameters at compile time, to minimize the amount of reflection used while the application is running (by the way, using reflection can generally be reduced to zero using build-time code) and to make sure that the amount parameter exists, which we will follow. If we do not find it, then notify the developer with the help of warning.
Using this aspect and any repository for storing the collected data, you can create some analytical information for your financial director.

However, while the investigation is underway, you begin to understand that there may be other problems with the system: for example, you will learn that the interface to the user is not stable and the application constantly “crashes”. In order to find out the place of the falls, you can arrange try / catch in different places of the program (which can be a huge set) in order to understand which particular place is failing. Alternatively, you can write one class, after which the audit of exceptions will be enabled on all interface methods automatically (yes, you can easily limit the scope of this class). Not to be unfounded, let's see a simple example:

[ Serializable ]
public class ExceptionLoggerAttribute : OnExceptionAspect
{
private string _methodName;
private Type _className;

public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
{
_methodName = method.Name;
_className = method.DeclaringType;
}

public override bool CompileTimeValidate(MethodBase method)
{
if (! typeof (Form).IsAssignableFrom(method.DeclaringType))
{
Message.Write(SeverityType.Error, "003" ,
"ExceptionLogger can only be used on Form methods in {0}.{1}" ,
method.DeclaringType.BaseType, method.Name);
return false ;
}
return true ;
}

public override void OnException(MethodExecutionArgs args)
{
Logger.Write(_className + "." + _methodName + " - " + args.Exception);
MessageBox.Show( "There was an error!" );
args.FlowBehavior = FlowBehavior.Return;
}
}

* This source code was highlighted with Source Code Highlighter .

And, again, I use CompileTimeInitialize only in order to reduce the number of references to reflection. To apply this aspect (for a couple of functions), you must mark the corresponding methods / classes / assemblies / namespaces (in this case, the assembly is marked, the filter is additionally indicated by the full name of the assembly member) with the attribute:



To mark a class, you can either mark the class itself, or mark the assembly by specifying the class name:

// in AssemblyInfo.cs
[assembly: ExceptionLogger(AttributeTargetTypes = "LoggingAuditing.BankAccountManager" )]

* This source code was highlighted with Source Code Highlighter .

After you enabled logging and audited the application, terrible things came out:

• Customers can withdraw negative amounts from their accounts, and less honest customers often use this!
• When entering information into forms of the interface, people constantly make typos without checking the input. For example, if the cashier enters "$ 5.19", this will cause an unhandled exception and the collapse of the entire application!

With two very simple aspects, you can solve these glaring application flaws quickly enough, giving business users audit of the transaction flow, and giving developers in your team logging and tracking exceptions in the process of shipping and working with the user. You have to recognize that a hard-broken application at the installation stage to the end user, at the user’s work stage, can create a huge number of problems. Especially with the development team. However, if you use aspects, you can diagnose and correct them very quickly.
Now, let's look under the hood and see what kind of code is actually generated. Do not panic if you still do not understand. PostSharp is very easy to use and its results can be easily opened in any disassembler. But let's still look at the resulting code. We want to understand everything.
Here is the “Credit” method without using PostSharp. As you can see, it is quite simple:

public static void Credit( decimal amount)
{
Balance += amount;
}

* This source code was highlighted with Source Code Highlighter .

Next, look at the same method, after applying the TransactionAudit aspect. Remember that this code will be only in the resulting assembly (dll and exe files) and will not be in your source code:

public static void Credit( decimal amount)
{
Arguments CS$0$0__args = new Arguments();
CS$0$0__args.Arg0 = amount;
MethodExecutionArgs CS$0$1__aspectArgs = new MethodExecutionArgs( null , CS$0$0__args);
CS$0$1__aspectArgs.Method = <>z__Aspects.m11;
<>z__Aspects.a14.OnEntry(CS$0$1__aspectArgs);
if (CS$0$1__aspectArgs.FlowBehavior != FlowBehavior.Return)
{
try
{
Balance += amount;
<>z__Aspects.a14.OnSuccess(CS$0$1__aspectArgs);
}
catch (Exception CS$0$3__exception)
{
CS$0$1__aspectArgs.Exception = CS$0$3__exception;
<>z__Aspects.a14.OnException(CS$0$1__aspectArgs);
CS$0$1__aspectArgs.Exception = null ;
switch (CS$0$1__aspectArgs.FlowBehavior)
{
case FlowBehavior.Continue:
case FlowBehavior.Return:
return ;
}
throw ;
}
finally
{
<>z__Aspects.a14.OnExit(CS$0$1__aspectArgs);
}
}
}

* This source code was highlighted with Source Code Highlighter .

And again: do not panic! :) This code may seem muddled due to the use of automatically generated variable names, but in reality it is very simple. A try / catch wrapper is added to the original code and the code for a specific aspect is called. As you can see, only the overridden onEntry method is actually used here, in which you will do your actions. However, you can override other methods (onExit, onSuccess, onException), if you solved any problems where overriding them would be necessary.
The above code generates a free version of the postsharp. The full-featured version of the program works by optimizing the resulting code, as shown below. In our case, the program will understand that you only use the onEntry method and that in this case there is no need to generate a huge amount of code. And in this case, you will receive such a short code:

public static void Credit( decimal amount)
{
Arguments CS$0$0__args = new Arguments();
CS$0$0__args.Arg0 = amount;
MethodExecutionArgs CS$0$1__aspectArgs = new MethodExecutionArgs( null , CS$0$0__args);
<>z__Aspects.a14.OnEntry(CS$0$1__aspectArgs);
Balance += amount;
}

* This source code was highlighted with Source Code Highlighter .

A fully functional version of the smart generates only the code that you need. If you are writing an application with full use of the postsharp aspects, using a fully functional version would be a good solution to improve the performance of the application.
However, despite the funny names of the automatically generated members of classes and local variables, I hope you get a good idea of ​​what PostSharp is.

References:

• Official site
• We solve the problem of caching
• Intel blogs: PostSharp. Part 1
• Intel blogs: PostSharp. Alternatives
• Aspect-oriented programming vs Dependency Injection