Tracing und Logging so elegant wie nie

18. Januar 2012
So hilfreich die Klasse RealProxy ist, so unbekannt ist sie.
Das Proxy-Entwurfsmuster gehört zum Wissenskanon der Informatik und ist wahrscheinlich eines der meistgenutzten Designpattern.
Im .Net-Framework ist mit der Klasse RealProxy eine Umsetzung dieses Entwurfsmusters enthalten, das elegante Lösungen für Tracing, Logging, Performancemessung und dergleichen ermöglicht. 
Im vorliegenden Artikel soll eine Implementierung vorgestellt werden, die die Verwendung der Klasse vereinfacht. Anhand eines Beispiels wird die Verwendung veranschaulicht.
Gegeben sei folgende einfache Klasse mit fünf Methoden und einem passenden Interface.

   1: using System;
   2: using System.Threading;
   3:  
   4: public class Test : ITest
   5: {
   6:     public string Methode1(string parameter1, int parameter2) { return "a"; }
   7:     public void Methode2() { Thread.Sleep(200); }
   8:     public void Methode3() { throw new Exception("Fehler"); }
   9:     public string Methode4(DateTime parameter1, out int parameter2, ref int parameter3) { parameter2 = 10; parameter3 = 20; return "b"; }
  10:     public string Methode5<T>(T parameter1, double parameter2) where T : new() { return "c"; }
  11: }
  12:  
  13: public interface ITest
  14: {
  15:     string Methode1(string parameter1, int parameter2);
  16:     void Methode2();
  17:     void Methode3();
  18:     string Methode4(DateTime parameter1, out int parameter2, ref int parameter3);
  19:     string Methode5<T>(T parameter1, double parameter2) where T : new();
  20: }

Wie lässt sich in diesen Code ein Tracing-Funktionalität einbringen? Möglich ist es, in jeder der Methoden die Eingabeparameter, den Rückgabewert, den Aufrufzeitpunkt et cetera zu erfassen und auszugeben (je nach Anforderung per Event, separater Logging-Klasse oder ähnlichem).

Nachteile dieser Umsetzung:

  • Jede Methode und jedes Tracing-Element (Durchlaufzeit, Parameter usw.) muss eigens programmatisch behandelt werden.
  • Die vorgenommen Anpassung am Code erhöhen die Programmkomplexität, was einen negativen Einfluss auf die Performance, Stabilität und Wartbarkeit impliziert.

Mit der Klasse RealProxy (Namespace System.Runtime.Remoting.Proxies) ist eine bessere Umsetzung möglich, die ohne Anpassung des vorhandenen Quellcodes auskommt und die Verwendung von Proxies (beispielsweise zur Protokollierung von Zwischenergebnissen) ungeahnt elegant macht (siehe Zeile 6, Anpassungen an Klasse Test sind nicht notwendig!):

   1: class Program 
   2: { 
   3:     static void Main(string[] args)
   4:     {
   5:         ITest test = new Test();
   6:         test = test.Wrap(new LoggingProxy(), new PerformanceProxy());
   7:  
   8:     int x, y = 10;
   9:     var r = test.Methode1("a", 10);
  10:         test.Methode2();
  11:     try { test.Methode3(); } catch { }
  12:         r = test.Methode4(DateTime.Now, out x, ref y);
  13:     r = test.Methode5(new DateTime(), 10);
  14:     } 
  15: }

Zur Umsetzung wurde zunächst die Klasse Proxy<T> von RealProxy abgeleitet. Eine Instanz dieser Klasse kennt

  • das tatsächliche Aufrufziel, also das “verpackte” Objekt

    (Property Target vom Typ T) und
  • die Listner-Proxies, die sie dazwischenschalten werden sollen (Property Proxies vom Typ IList<IProxy>).

Erwähnenswert ist außerdem die implizite Typkonvertierung und die oben verwendete Wrap-Erweiterungsmethode. Zusammen ermöglichen sie eine komfortablere Verwendung der Klasse.

   1: using System;
   2: using System.Collections.Generic;
   3: using System.Linq;
   4: using System.Reflection;
   5: using System.Runtime.Remoting.Messaging;
   6: using System.Runtime.Remoting.Proxies;
   7:  
   8:  
   9: public sealed class Proxy<T> : RealProxy
  10: {
  11:     /// <summary> Dient zur Konvertierung der Klasse in
  12:     /// den Typen T zwecks transparenter Verwendung.
  13:     /// </summary>
  14:     public static implicit operator T(Proxy<T> proxy)
  15:     {
  16:         return (T)proxy.GetTransparentProxy();
  17:     }
  18:  
  19:     /// <summary> Alle zwischengeschalteten tatsächlichen Proxies
  20:     /// </summary>
  21:     public IList<IProxy> Proxies { get; set; }
  22:  
  23:     /// <summary> Das tatsächliche, gewrappte Objekt
  24:     /// </summary>
  25:     public T Target { get; set; }
  26:  
  27:     /// <summary> Der Konstruktor setzt Target und initalisiert die
  28:     /// tatsächlichen Proxies.
  29:     /// </summary>
  30:     public Proxy(T target)
  31:         : base(typeof (T))
  32:     {
  33:         Proxies = new List<IProxy>();
  34:         Target = target;
  35:  
  36:         foreach (var proxy in Proxies) proxy.Initalize(typeof (T), Target);
  37:     }
  38:  
  39:     /// <summary> Ruft die Protokollierung an den Proxies auf bevor und nachdem 
  40:     /// die eigentliche Methode am Target-Objekt aufgerufen wird.
  41:     /// </summary>
  42:     public override IMessage Invoke(IMessage message)
  43:     {
  44:         IMethodCallMessage methodCallMessage = (IMethodCallMessage) message;
  45:  
  46:         foreach (var proxy in Proxies) proxy.BeforeInvoke(methodCallMessage);
  47:  
  48:         ReturnMessage methodReturnMessage;
  49:         try
  50:         {
  51:  
  52:             MethodInfo method;
  53:             if (!methodCallMessage.MethodBase.IsGenericMethod)
  54:             {
  55:                 method = Target.GetType().GetMethod(methodCallMessage.MethodName,
  56:                                                     (Type[]) methodCallMessage.MethodSignature);
  57:             }
  58:             else
  59:             {
  60:                 method = GetGenericMethod(methodCallMessage);
  61:             }
  62:  
  63:             if (method == null) throw new TargetInvocationException(methodCallMessage.MethodName, null);
  64:  
  65:             object result = method.Invoke(Target, methodCallMessage.Args);
  66:  
  67:             methodReturnMessage
  68:                 = new ReturnMessage(
  69:                     result,
  70:                     methodCallMessage.Args,
  71:                     methodCallMessage.Args.Length,
  72:                     methodCallMessage.LogicalCallContext,
  73:                     methodCallMessage);
  74:  
  75:             foreach (var proxy in Proxies) proxy.AfterInvoke(methodCallMessage, methodReturnMessage);
  76:  
  77:         }
  78:         catch (TargetInvocationException exception)
  79:         {
  80:             foreach (var proxy in Proxies)
  81:                 proxy.ExceptionOccurred(methodCallMessage, exception.InnerException);
  82:  
  83:             if (exception.InnerException != null)
  84:             {
  85:                 throw exception.InnerException;
  86:             }
  87:  
  88:             throw;
  89:         }
  90:  
  91:         return methodReturnMessage;
  92:     }
  93:  
  94:     /// <summary> Ermittelt beim Aufruf von generischen Methoden die
  95:     /// passenden am Target-Objekt
  96:     /// </summary>
  97:     private MethodInfo GetGenericMethod(IMethodMessage methodCallMessage)
  98:     {
  99:         Type[] genericArgumentTypes = methodCallMessage.MethodBase.GetGenericArguments();
 100:         Type[] parameterTypes = (Type[]) methodCallMessage.MethodSignature;
 101:  
 102:         IEnumerable<MethodInfo> matchingMethods
 103:             = Target.GetType().GetMethods()
 104:                 .Where(m => m.Name == methodCallMessage.MethodName
 105:                             && m.GetGenericArguments().Count() == genericArgumentTypes.Length
 106:                             && m.GetParameters().Count() == parameterTypes.Length);
 107:  
 108:         foreach (var m in matchingMethods)
 109:         {
 110:             MethodInfo method;
 111:             try
 112:             {
 113:                 method = m.MakeGenericMethod(genericArgumentTypes);
 114:             }
 115:             catch
 116:             {
 117:                 continue;
 118:             }
 119:  
 120:             bool isMatch = true;
 121:             var methodParameter = method.GetParameters();
 122:             for (int index = 0; index < methodParameter.Length; index++)
 123:             {
 124:                 if (!(isMatch &= methodParameter[index].ParameterType == parameterTypes[index])) break;
 125:             }
 126:             if (isMatch) return method;
 127:         }
 128:         return null;
 129:     }
 130: }
 131:  
 132: public static class ProxyHelper
 133: {
 134:     public static T Wrap<T>(this T target, params IProxy[] proxies) where T : class
 135:     {
 136:         return new Proxy<T>(target) { Proxies = proxies };
 137:     }
 138:  
 139: }

Methodenaufrufe passieren die Klasse Proxy und die Methode Invoke. Diese propagiert ein Nachrichtenobjekt an die Listner-Proxies (dazwischengeschalteten IProxy-Implementierungen im Property Proxies) vor und nach dem Aufruf der eigentlichen Methode an Target. Auch im Fehlerfall und bei der Initialisierung wird ein Aufruf durchgeführt.

Protokolliert werden können Aufrufe an öffentliche Methoden (solche die vom Interface, im Beispiel ITest, definiert sind).

Die Listner-Proxies implementieren folgendes Interface:

   1: using System;
   2: using System.Runtime.Remoting.Messaging;
   3:  
   4: public interface IProxy
   5: {
   6:     void BeforeInvoke(IMethodCallMessage methodCallMessage);
   7:     void Initalize(Type targetInterface, object originalTarget);
   8:     void AfterInvoke(IMethodCallMessage methodCallMessage, IMethodReturnMessage methodReturnMessage);
   9:     void ExceptionOccurred(IMethodCallMessage methodCallMessage, Exception exception);
  10: }

Ein Listner-Proxy könnte beispielsweise alle Ausnahmefehler in eine Fehlertabelle in der Datenbank schreiben, Zwischenergebnisse auf der Konsole ausgeben oder die Durchlaufzeiten von Methoden in einer Datei protokollieren.

Eine exemplarische Implementierung eines Konsolen-Loggers, der auch im Beispiel oben eingesetzt wird, soll im Folgenden aufgeführt werden. Ausgegeben werden auf der Konsole unter anderem Methodenname, Aufrufzeitpunkt, Typinformation, Methodensignatur, Parameter, Rückgabewert (auch out/ref).

   1: using System;
   2: using System.Runtime.Remoting.Messaging;
   3: using System.Text;
   4:  
   5: public class LoggingProxy : IProxy
   6: {
   7:     public void BeforeInvoke(IMethodCallMessage methodCallMessage)
   8:     {
   9:         //Ggf. Universellen XML-Serialisierer für die Methodenargumente anwenden 
  10:         string methodCallMessageParameter
  11:             = GetMethodCallMessageParameter(methodCallMessage);
  12:  
  13:         string message = string.Format(
  14:             @"-------------------------------------------------- 
  15: --> Methodeneintritt:  {4} 
  16:     Uhrzeit:           {0} 
  17:     Typinformation:    {1} 
  18:     Methodensignatur:  {2} 
  19:     Parameter: 
  20: {3} 
  21: ",
  22:             DateTime.Now.ToString("yyyy'-'MM'-'dd'T'HH':'mm':'ss.fffffffK"),
  23:             methodCallMessage.TypeName,
  24:             methodCallMessage.MethodBase,
  25:             methodCallMessageParameter,
  26:             methodCallMessage.MethodName);
  27:  
  28:         WriteLogEntry(message);
  29:     }
  30:  
  31:     public void Initalize(Type targetInterface, object originalTarget)
  32:     {
  33:         // TODO
  34:     }
  35:  
  36:  
  37:  
  38:     private string GetMethodCallMessageParameter(IMethodMessage methodCallMessage)
  39:     {
  40:         StringBuilder stringBuilderInvocationParameter
  41:             = new StringBuilder();
  42:         for (int index = 0; index < methodCallMessage.Args.Length; index++)
  43:         {
  44:             object parameter = methodCallMessage.Args[index];
  45:             string parameterMessage = String.Format(
  46:                 "                       [{0}]: {1}",
  47:                 index,
  48:                 parameter == null ? "[NULL]" : parameter.ToString());
  49:             stringBuilderInvocationParameter.AppendLine(parameterMessage);
  50:         }
  51:         return
  52:             stringBuilderInvocationParameter.ToString()
  53:                 .TrimEnd(Environment.NewLine.ToCharArray())
  54:                 .TrimEnd(',');
  55:     }
  56:  
  57:     private string GetMethodCallMessageParameterOutRef(IMethodReturnMessage methodCallMessage)
  58:     {
  59:         StringBuilder stringBuilderInvocationParameter
  60:             = new StringBuilder();
  61:         for (int index = 0; index < methodCallMessage.OutArgs.Length; index++)
  62:         {
  63:             object parameter = methodCallMessage.OutArgs[index];
  64:             string parameterMessage = String.Format(
  65:                 "                       [{0}]: {1}",
  66:                 index,
  67:                 parameter == null ? "[NULL]" : parameter.ToString());
  68:             stringBuilderInvocationParameter.AppendLine(parameterMessage);
  69:         }
  70:         return stringBuilderInvocationParameter.ToString()
  71:             .TrimEnd(Environment.NewLine.ToCharArray())
  72:             .TrimEnd(',');
  73:     }
  74:  
  75:     public void AfterInvoke(IMethodCallMessage methodCallMessage, IMethodReturnMessage methodReturnMessage)
  76:     {
  77:         string methodCallMessageParameter
  78:             = GetMethodCallMessageParameter(methodCallMessage);
  79:         string methodCallMessageParameterOutRef
  80:             = GetMethodCallMessageParameterOutRef(methodReturnMessage);
  81:         string message = string.Format(
  82:             @"-------------------------------------------------- 
  83: <-- Methodenaustritt:  {6} 
  84:     Uhrzeit:           {0} 
  85:     Typinformation:    {1} 
  86:     Methodensignatur:  {2} 
  87:     Parameter: 
  88: {3} 
  89:     Rückgabe: 
  90:                        {4} 
  91:     Rückgabe Out/Ref.: 
  92: {5} 
  93: ",
  94:             DateTime.Now.ToString("yyyy'-'MM'-'dd'T'HH':'mm':'ss.fffffffK"),
  95:             methodReturnMessage.TypeName,
  96:             methodReturnMessage.MethodBase,
  97:             methodCallMessageParameter,
  98:             methodReturnMessage.ReturnValue,
  99:             methodCallMessageParameterOutRef,
 100:             methodReturnMessage.MethodName);
 101:  
 102:         WriteLogEntry(message);
 103:     }
 104:  
 105:  
 106:     public void ExceptionOccurred(IMethodCallMessage methodCallMessage, Exception exception)
 107:     {
 108:         string methodCallMessageParameter
 109:             = GetMethodCallMessageParameter(methodCallMessage);
 110:         string message = string.Format(
 111:             @"-------------------------------------------------- 
 112: <-X Methodenaustritt:  {5} 
 113:     Uhrzeit:           {0} 
 114:     Typinformation:    {1} 
 115:     Methodensignatur:  {2} 
 116:     Parameter: 
 117: {3} 
 118:     Fehler: 
 119:                        {4} 
 120: ",
 121:             DateTime.Now.ToString("yyyy'-'MM'-'dd'T'HH':'mm':'ss.fffffffK"),
 122:             methodCallMessage.TypeName,
 123:             methodCallMessage.MethodBase,
 124:             methodCallMessageParameter,
 125:             exception,
 126:             methodCallMessage.MethodName);
 127:         WriteLogEntry(message);
 128:     }
 129:  
 130:     public void WriteLogEntry(string message)
 131:     {
 132:         Console.WriteLine(message);
 133:     }
 134: }



Fazit

Die Klasse RealProxy bzw. die hier vorgestellte Implementierung kann verwendet werden, um ein Programm mit aspektorientierten Komponenten zu erweitern.

Ohne oder nur mit geringen Anpassungen (Interface-Verwendung) kann durch Einsatz der vorgestellten Implementierung bestehender Programmcode um Tracing, Logging, Performance-Messung, Ausgabe von Zwischenergebnissen et cetera erweitert werden. Denkbar ist sogar die Manipulation des Objekts oder der Parameter und Rückgabewerte. 
Die Programmkomplexität wird durch den Einsatz der nur lose angekoppelten Komponenten kaum größer, die Wartbarkeit und Stabilität kaum beeinträchtigt.

Lediglich an der Stelle des Aufrufs oder der Objekterzeugung muss das zu inspizierende Objekt in eine Proxy-Instanz (Methode Wrap) gegeben werden. Es ist durchaus denkbar, die Objekterzeugung und diesen Schritt an einer zentralen Stelle unterzubringen, etwa durch die Möglichkeiten mancher Dependency-Injection-Frameworks (bspw. durch eine eigene BuilderStrategy in Unity). Größere Einschränkungen (bspw. dass Klassen wie beim Remoting von MarshalByRef ableiten müssen) sind nicht bekannt.

Es ist jedoch zu beachten, dass die Verwendung eines dazwischengeschalteten Proxy die Performance negativ beeinflusst.