Wednesday, June 27, 2012

Anonymous, Type-less, 100% Generic and Abstracted Logging and Tracing


The Challenge

Over the years I have used various mechanisms to de-couple logging and tracing specifics from the code that needs to send a message up.

Certainly, at the macro level, there are whole frameworks for this: Such as Enterprise Library, Log4N, etc.  But, these don’t really solve the problem when you get down to the micro-level, especially if you are developing libraries like Domain Specific Languages (DSL), Helper Libraries, and any other code that should be totally generic and not know anything about the higher level context that it is running within. Does my DSL Extension method really have know if it’s being used with EntLib or Log4N or whatever? The goal is certainly that it would know NOTHING and be completely transportable between such macro frameworks.

Note: For a discussion of the use of DSLs versus Helper Libraries, see my forthcoming blog: Death to Helper Libraries!!!

There are some patterns that attempt to deal with this level of abstraction. One of the most popular is the Inversion of Control (IOC) pattern, which I have certainly used extensively in the past, but this can still be way too heavy for there situation where all we need is for an Extension or Helper Method to be able to provide trace level messages to the higher level context.

Another common approach, and frankly the one I’ve used the most at this level in the past, is an event-ing mechanism where the Helper class, or other utility class advertises an Event (e.g. myClass.OnTraceMessage) that the higher level code can bind to, receive the events, and write to the then known tracing and logging mechanism.

Unfortunately, there is a fair amount of overhead code required by the class that will be firing the Events: local variable to track all the event listeners, methods to track listeners, methods to fire the Event.  YUK! Certainly, you can start to hide the complexity with another layer of abstraction, but now we're just moving the problem around and sweeping it under the rug.

Over the last few years, .NET has released new interfaces that standardized concepts like IObservable and IObserver. And if you want the whole thing to be Asynchronous, you have the new .NET Reactive Extensions (Rx) library.  But, again, these are all fairly heavy weight, especially at the lowest level of code like we are discussing.

There just HAS to be a way, at the lowest micro-level of code to be able to provide tracing and logging information to the higher-level caller, but without having to write more abstraction layers, more controllers, and more marshal-ing agents!

So, recently, while writing a some DSL libraries to connect Dynamics CRM to a customer’s enterprise Line of Business systems or Service Bus, I took the opportunity to ponder on this problem with a fresh perspective.


Being a big fan of Linq, which includes becoming familiar with Lambda expressions, and recalling .NET’s support for Delegates and Anonymous declarations and expressions, including functions…A VERY simple and VERY Elegant approach to this problem occurred to me, and turned out to be trivial to refactor into the DSL libraries.

Solution Approach

How to define a “Function Variable” [Delegate]

First, let’s think about what it means to have a 100% abstracted, generic approach to writing a log message. Basically, it’s like saying, “I just want to be able to call ANY function that takes a single string parameter (The trace/log message) and returns ‘void’. I don’t want to have to know what Assembly that function lives in. I don’t want to have to reference that assembly. I don’t want to have to “using” its namespace. I especially do NOT want to have to include any additional assemblies with my distribution!!!!  I want to live in complete and total ignorance and isolation.  Just point me to a similar to the following:

public void logger( string msg ){...}


Seems like a tall order to fill, but it’s actually very simple when we think about it this way.

.NET provides several mechanisms for defining an expected function like this. They’re called Delegates, and there are various forms to choose from:

On the simplistic explanation side, Func delegates require a return type while Action delegates return ‘void’.

In our case, we want the equivalent of ‘void’ functions, so let’s use the Action delegate.

This now lets us define exactly what we described:

“Give me ANY function that takes a single string parameter and returns ‘void’”

And in c#, that looks just like this:

public void MyDoItFunction( Action<string> logger ) {...}

This says, when you call MyDoItFunction, you have to pass it a Function or Delegate that takes a single string parameter. MyDoItFunction will call it with logging and tracing messages, and you do whatever you want with them. MyDoItFunction does not want to know where or how those messages ultimate end up going.

Inside of MyDoItFunction, It just sends out tracing messages as it see fits by calling the passed in Action Delegate like this:

public void MyDoItFunction( Action<string> logger )
logger("Setting up the string builders...");

As we now see, it becomes very easy to require a caller to pass in a 100% abstracted, generic function that we can write our trace messages to. This could be done in function signatures like our examples, or also constructors, properties, etc. Basically, anywhere that you could/would define and pass a variable, you can define and pass a function delegate.  This is VERY COOL!

If you’ve used Events, IObservable, IObserver, Inversion of Control, or any other approach, you will quickly see the immense simplicity of this approach.

How to pass in the Delegate

So far, so good.  Now that I can define a function delegate property that I can log my trace messages to, how does the caller of MyDoItFunction pass in a delegate?

As you can read in the MSDN Documentation for Action<T>, There are several approaches for how to create and pass in a Delegate:

  • Explicit define a delegate over pre-defined function declaration
  • Explicit Action<T> declaration
  • delegate using Anonymous methods
  • Lambda expressions

To me, the most interesting approaches are the last two: Anonymous methods and Lambda expressions. And of those two, my favorite is Lambda expressions.  I will leave you to read about the first two on your own.

Now, let’s look at a couple examples of calling our MyDoItFunction function and passing in widely varying actual output writing targets:

   1: //all examples use Lambda expressions
   3: //Write all messages to the built in .NET Tracing
   4: MyDoItFunction( msg => System.Diagnostics.Trace.Writeline( msg ) );
   6: //Write to Console
   7: MyDoItFunction( msg => Console.Writeline( msg ) );
   9: //Writes to method in the consuming class
  10: MyDoItFunction( msg => this.MyTracer( msg ) );

Yet again, we have an immensely simplistic solution. Note that there are no registrations for Events, IObservers, etc. Once again, THAT’s COOL!

What' does that have to do with Dynamics CRM again?

Recall that we are writing a DSL (Domain Specific Language) that exposes the customer’s legacy enterprise LOB applications and services to Dynamics CRM plugins and Workflows. One of the most flexible and efficient mechanisms for implementing DSLs is the use of .NET extensions methods.  If you’ve used Linq, then you’ve used Extension Methods. Simply put, Extensions Methods allow you to extend other objects with additional behavior (functions) without having to modify the original source code. That’s what allows Linq to add all those functions to all those objects.

Bringing it all together, we can take the concept of defining and passing in function delegates plus the use of Extension Methods, and we can not very trivially provide a mechanism for consumers of our DSL to provide delegates to their own logging mechanism.

Specifically, when we’re talking about custom .NET Plugin and Workflow code in the Dynamics world, Dynamics CRM introduces it’s own tracing mechanism (ITracingService) that is provided within the Plugin and Workflow IServiceProvider.

Let’s look at a DSL’s extension method that can write Dynamics CRM Entity data to an Enterprise’s LOB application’s web service:

   1: /// <summary>
   2: /// Sends updated contact person information to the ESB.
   3: /// </summary>
   4: /// <param name="contactEntity">The contact as a late-bound CRM Entity.</param>
   5: /// <param name="logger">A function that takes a string parameter that will receive tracing/logging messages.</param>
   6: public static void ESBUpdatePerson(this Entity contactEntity, Action<string> logger)
   7: {
   8:     logger("ESBUpdatePerson(Entity contactEntity) called...");
   9:     logger("Ensuring that Entity.LogicalName == contact...");
  11:     //ensure that contactEntity is a contact
  12:     if ( contactEntity.LogicalName.ToLower() != "contact" )
  13:     {
  14:         throw new InvalidPluginExecutionException(OperationStatus.Failed, string.Format("ESBUpdatePerson(this Entity contactEntity) was passed invalid Entity of '{0}' expected a 'contact'", contactEntity.LogicalName));
  15:     }
  17:     ...
  18: }

And, a sample Plugin Execute() method that consumes ESBUpdatePerson():

   1: public void Execute(IServiceProvider serviceProvider)
   2: {
   3:    //get the tracing log out of the context
   4:    var tracer = (ITracingService)serviceProvider.GetService(typeof(ITracingService));
   6:    //get the plugin execution context
   7:    var pluginExecutionContext = (IPluginExecutionContext)serviceProvider.GetService(typeof(IPluginExecutionContext));
   9:    //get the actual entity out of the context
  10:    var pluginEntity = (Microsoft.Xrm.Sdk.Entity)pluginExecutionContext.InputParameters["Target"];
  12:    //send the Entity to the ESB, 
  13:    //providing the CRM tracer for capturing trace messages
  14:    pluginEntity.ESBUpdatePerson(msg => tracer.Trace(msg));
  16: }



We have talked about the historic approaches taken (Events, IObservable, IObserver, RX library, Inversion of Control, etc.) to accomplish 100% abstracted access to logging and tracing mechanisms and frameworks from lower level code, and our desire to be able to support ANY logging and tracing implementation without having to know anything about them, and especially without having to be couples to them and have to include their distributable with our own!

We then looked at function delegates and explicit examples of using the Action<T> delegate that demonstrated the immense simplicity and flexibility of the approach of using Delegates.

And finally, we brought it back to Dynamics CRM and demonstrated how we could write a DSL using Extension Methods that could take in a Action<T> delegate for providing detailed tracing messages and information, and how we could use the DSL from a plugin and provide CRM’s own internal tracing mechanism to the DSL methods.

I hope you’ve seen the immense simplicity and flexibility of using delegates as a function abstraction for being able to support most any logging and tracing mechanism without having to know anything about them!

- It is an honor to be of service


WordPress Tags: Enterprise Library,Domain Specific Language,EntLib,DSL,Inversion of Control,IOC,IObservable,IObserver,Reactive Extensions,Linq,Lambda,Delegate,Action,Func,Workflows,Plugin,ITracingService,IServiceProvider,IPluginExecutionContext

Blogger Labels: Enterprise Library,Domain Specific Language,EntLib,DSL,Inversion of Control,IOC,IObservable,IObserver,Reactive Extensions,Linq,Lambda,Delegate,Action,Func,Workflows,Plugin,ITracingService,IServiceProvider,IPluginExecutionContext

No comments:

Post a Comment