Die WCF mit einem eigenen Nachrichten Logger erweitern
Mittwoch, 7. Oktober 2009Die WCF bietet einigen Diagnose Komfort an, um Problemen bei der Übertragung von Nachrichten auf die Spur zu kommen. Dies insbesondere wenn nicht nur WCF Dienste oder Clients beteiligt sind.
Das Message Logging kann benutzt werden, um den Inhalt von oder an Clients und Services aufzuzeichnen. Das Logging kann konfiguriert werden, um Nachrichten auf dem Service Level, dem Transport Level, oder fehlerhaft Nachrichten auszuzeichnen.
Das Logging ist per Default ausgeschaltet und kann so über die WCF Konfiguration eingeschaltet werden:
<system.serviceModel>
...
<diagnostics>
<messageLogging logEntireMessage="true"
logMalformedMessages="true"
logMessagesAtServiceLevel="true"
logMessagesAtTransportLevel="false"
maxMessagesToLog="1000">
<filters>
<clear/>
<add>/*[local-name()='Envelope']/*[local-name()='Header']/*[local-name()='Action'][text()='http://tempuri.org/Operation']</add>
</filters>
</messageLogging>
</diagnostics>
</system.serviceModel>
<system.diagnostics>
<sources>
<source name="System.ServiceModel.MessageLogging">
<listeners>
<add name="messages"
type="System.Diagnostics.XmlWriterTraceListener, System, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
initializeData="messages.svclog"/>
</listeners>
</source>
</sources>
<trace autoflush="true"/>
</system.diagnostics>
Dieses Beispiel zeichnet alle Nachrichten auf, welche über die Service Methode “Operation” ein- oder ausgehen. Diese Einschränkung kann durch den Filter als XPath Ausdruck definiert werden.
Das Log wird in einer Datei gespeichert. Diese kann dann recht komfortabel mit dem Service Trace Viewer des SDKs ausgewertet werden.
Wenn nun aber die eigentliche Applikation selber ein Log führt, kann es bei der Fehlersuche recht mühsam sein, die beiden Logs zeitlich miteinander zu korrelieren. Viel praktischer wäre es doch, die WCF Nachrichten und das Applikationslog in einem einzigen Log zu haben.
Ich verwende meistens das Logging Framework log4net.
Die umfangreichen Erweiterungsmöglichkeiten der WCF machen es nun recht einfach, die WCF Nachrichten auch in das bereits vorhandene und konfigurierte log4net Log zu schreiben. Ob das Log in einer Datei oder einer Datenbank geführt wird, ist dabei völlig dem Logging Framework übrlassen.
Die sogenannten “Custom Behaviors” ermöglichen es, Code innerhalb der WCF Runtime und der Message Pipeline ausführen zu lassen. Diese Behaviors können via Code oder Konfiguration hinzugefügt werden. Ein solches Behavior ist also ideal für einen Logging Mechanismus.
Um ein Custom Behavior zu implementieren, sind drei Schritte notwendig:
- Erstelle ein Klasse, welche ein Inspector, Selector, Formatter oder Invoker Interface implementiert. Diese Klasse definiert dann meistens auch das eigentliche Verhalten des Behaviors. Um nun alle eingehenden Nachrichten an einen Service zu loggen, kann das Interface IDispatchBehaviour implementiert werden und in dessen Methode AfterReceiveRequest die Nachricht geloggt werden. Wenn auch die vom Service oder Client gesendeten Antworten mitgeschnitten werden sollen, kann zusätzlich das Interface IClientMessageInspector implementiert werden, und die ausgehende Nachricht in dessen AfterReceiveReply Methode geloggt werden.
public class MessageInspector : IClientMessageInspector, IDispatchMessageInspector { public object BeforeSendRequest(ref Message request, IClientChannel channel) { Log.InfoFormat(GetType(), "MessageInspector::BeforeSendRequest(): Sending the following request{0}{1}", Environment.NewLine, request); return null; } public void AfterReceiveReply(ref Message reply, object correlationState) { Log.InfoFormat(GetType(), "MessageInspector::AfterReceiveReply(): Got the following reply{0}{1}", Environment.NewLine, reply); } public object AfterReceiveRequest(ref Message request, IClientChannel channel, InstanceContext instanceContext) { Log.InfoFormat(GetType(), "MessageInterceptor::AfterReceiveRequest(): Got the follwing request{0}{1}", Environment.NewLine, request); return null; } public void BeforeSendReply(ref Message reply, object correlationState) { Log.InfoFormat(GetType(), "MessageInterceptor::BeforeSendReply(): Sending the following reply{0}{1}", Environment.NewLine, reply); } } - Erstelle ein weitere Klasse, welche eines der Behavior Interfaces IServiceBehavior, IEndpointBehavior, IOperationBehavior oder IContractBehavior implementiert. Die in Schritt 1 erstellt Klasse wird nun der Liste der Behaviors hinzugefügt.
public class MessageInspectingBehavior : BehaviorExtensionElement, IEndpointBehavior { public override Type BehaviorType { get { return typeof(MessageInspectingBehavior); } } public void AddBindingParameters(ServiceEndpoint endpoint, BindingParameterCollection bindingParameters) { // Ignore } public void ApplyClientBehavior(ServiceEndpoint endpoint, ClientRuntime clientRuntime) { clientRuntime.MessageInspectors.Add(new MessageInspector()); } public void ApplyDispatchBehavior(ServiceEndpoint endpoint, EndpointDispatcher endpointDispatcher) { endpointDispatcher.DispatchRuntime.MessageInspectors.Add(new MessageInspector()); } public void Validate(ServiceEndpoint endpoint) { // Ignore } protected override object CreateBehavior() { return new MessageInspectingBehavior(); } } - Der Client oder Service kann nun konfiguriert werden, dieses neue Behavior zu verwenden:
<system.serviceModel> <services> <service name="WcfDemoService.DemoService" behaviorConfiguration="WcfDemoService.DemoServiceBehavior"> ... <endpoint address ="" binding="basicHttpBinding" contract="WcfDemoService.IDemoService" behaviorConfiguration="inspectorBehavior" /> </service> </services> ... <extensions> <behaviorExtensions> <add name="messageInspector" type="WcfLogging.MessageInspectingBehavior, WcfLogging, Version=1.0.0.0, Culture=neutral, PublicKeyToken=bb5b60893581ebcd"/> </behaviorExtensions> </extensions> <behaviors> <endpointBehaviors> <behavior name="interceptorBehavior"> <clientInterceptor /> </behavior> </endpointBehaviors> </behaviors> </system.serviceModel>
Wichtig: Das Assembly, welches das Behavior enthält, muss unbedingt signiert werden!
Das vom Service erzeugte Log enthält nun die über den Service verarbeiteten Nachrichten, sowie Logeinträge der Applikation selber:
2009-10-07 11:51:05,100 [6 ] INFO - MessageInterceptor::AfterReceiveRequest(): Got the follwing request
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
<s:Header>
<To s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">http://localhost:8731/Design_Time_Addresses/WcfDemoService/DemoService/</To>
<Action s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/IDemoService/GetData</Action>
</s:Header>
<s:Body>
<GetData xmlns="http://tempuri.org/">
<value>42</value>
</GetData>
</s:Body>
</s:Envelope>
2009-10-07 11:51:05,115 [6 ] DEBUG - DemoService::GetData(): Received 42
2009-10-07 11:51:05,116 [6 ] INFO - MessageInterceptor::BeforeSendReply(): Sending the following reply
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
<s:Header>
<Action s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/IDemoService/GetDataResponse</Action>
</s:Header>
<s:Body>
<GetDataResponse xmlns="http://tempuri.org/">
<GetDataResult>You entered: 42</GetDataResult>
</GetDataResponse>
</s:Body>
</s:Envelope>
Ein Beispielprojekt, welches so ein Behavior enthält, kann hier runtergeladen werden: WcfLogging.zip