Logging incoming requests and responses in an ASP.NET or WCF application in compatibility mode

Artikel
02/06/2014

One of our customers had a very particular problem that prevented them from using custom encoder and message inspectors in their WCF service running in ASP.NET compatibility mode. So they requested a proof of concept to save all incoming Http Request and their response in a log file. Saving in a log file in a multithreaded application brings some difficult as well since you do not want that one request is logged as part of other. Using lock in IIS is dangerous as well because any mistake can lock all threads. That is why I used Monitor.TryEnter instead of lock so log may stop working but application will still service requests. Notice that this approach should be used with caution. I am not using any criteria to log which may cause performance problems and huge log files. This approach only works with WCF because they are enabling compatibility mode. The code was implemented in Global.asax which is the default Http Module for an ASP.NET application, but it can be used in a HttpModule that is maintained separately.

Download code here: Source for Global.asax

Code below:

 using System;
 using System.Collections.Generic;
 using System.Linq;
 using System.Web;
 using System.Web.Security;
 using System.Web.SessionState;
  
 using System.Text;
 using System.IO;
  
 namespace HttpModuleWCF
 {
     //The code samples are provided AS IS without warranty of any kind. 
     // Microsoft disclaims all implied warranties including, without limitation, 
     // any implied warranties of merchantability or of fitness for a particular purpose. 
  
     /*
 
     The entire risk arising out of the use or performance of the sample scripts and documentation remains with you. 
     In no event shall Microsoft, its authors, or anyone else involved in the creation, production, or delivery of the scripts 
     be liable for any damages whatsoever (including, without limitation, damages for loss of business profits, business interruption, 
     loss of business information, or other pecuniary loss) arising out of the use of or inability to use the sample scripts 
     or documentation, even if Microsoft has been advised of the possibility of such damages.
 
     */
  
  
     public class Global : System.Web.HttpApplication
     {
        // Change this string to request the value from some configuration
  
         protected string fileNameBase = "c:\\temp\\log-";
         protected string ext = "log";
  
         // One file name per day
         protected string FileName
         {
             get
             {
                 return String.Format("{0}{1}.{2}", fileNameBase, DateTime.Now.ToString("yyyy-MM-dd"), ext);
             }
         }
  
         protected void Application_Start(object sender, EventArgs e)
         {
  
         }
  
         protected void Session_Start(object sender, EventArgs e)
         {
  
         }
  
         protected void Application_BeginRequest(object sender, EventArgs e)
         {
  
             // Creates a unique id to match Rquests with Responses
             string id = String.Format("Id: {0} Uri: {1}", Guid.NewGuid(), Request.Url);
             FilterSaveLog input = new FilterSaveLog(HttpContext.Current, Request.Filter, FileName, id);
             input.SetFilter(false);
             Request.Filter = input;
             FilterSaveLog output = new FilterSaveLog(HttpContext.Current, Response.Filter, FileName, id);
             output.SetFilter(true);
             Response.Filter = output;
  
         }
  
         protected void Application_AuthenticateRequest(object sender, EventArgs e)
         {
  
         }
  
         protected void Application_Error(object sender, EventArgs e)
         {
  
         }
  
         protected void Session_End(object sender, EventArgs e)
         {
  
         }
  
         protected void Application_End(object sender, EventArgs e)
         {
  
         }
     }
  
     class FilterSaveLog : Stream
     {
  
         protected static string fileNameGlobal = null;
         protected string fileName = null;
  
         protected static object writeLock = null;
         protected Stream sinkStream;
         protected bool inDisk;
         protected bool isClosed;
         protected string id;
         protected bool isResponse;
         protected HttpContext context;
  
         public FilterSaveLog(HttpContext Context, Stream Sink, string FileName, string Id)
         {
             // One lock per file name
             if (String.IsNullOrWhiteSpace(fileNameGlobal) || fileNameGlobal.ToUpper() != fileNameGlobal.ToUpper())
             {
                 fileNameGlobal = FileName;
                 writeLock = new object();
             }
             context = Context;
             fileName = FileName;
             id = Id;
             sinkStream = Sink;
             inDisk = false;
             isClosed = false;
         }
  
         public void SetFilter(bool IsResponse)
         {
         
  
             isResponse = IsResponse;
             id = (isResponse ? "Reponse " : "Request ")+id;
  
             //
             // For Request only read the incoming stream and log it as it will not be "filtered" for a WCF request
             //
             if (!IsResponse)
             {
                 AppendToFile(String.Format("at {0} --------------------------------------------", DateTime.Now));
                 AppendToFile(id);
  
                 if (context.Request.InputStream.Length > 0)
                 {
                     context.Request.InputStream.Position = 0;
                     byte[] rawBytes = new byte[context.Request.InputStream.Length];
                     context.Request.InputStream.Read(rawBytes, 0, rawBytes.Length);
                     context.Request.InputStream.Position = 0;
  
                     AppendToFile(rawBytes);
                 }
                 else
                 {
                     AppendToFile("(no body)");
                 }
             }
             
         }
  
         public void AppendToFile(string Text)
         {
             byte[] strArray = Encoding.UTF8.GetBytes(Text);
             AppendToFile(strArray);
    
         }
  
         public void AppendToFile(byte[] RawBytes)
         {
             bool myLock = System.Threading.Monitor.TryEnter(writeLock, 100);
  
  
             if (myLock)
             {
                 try
                 {
  
                     using (FileStream stream = new FileStream(fileName, FileMode.OpenOrCreate, FileAccess.ReadWrite))
                     {
                         stream.Position = stream.Length;
                         stream.Write(RawBytes, 0, RawBytes.Length);
                         stream.WriteByte(13);
                         stream.WriteByte(10);
  
                     }
                     
                 }
                 catch (Exception ex)
                 {
                     string str = string.Format("Unable to create log. Type: {0} Message: {1}\nStack:{2}", ex, ex.Message, ex.StackTrace);
                     System.Diagnostics.Debug.WriteLine(str);
                     System.Diagnostics.Debug.Flush();
  
  
                 }
                 finally
                 {
                     System.Threading.Monitor.Exit(writeLock);
  
  
                 }
             }
  
  
         }
  
  
         public override bool CanRead
         {
             get { return sinkStream.CanRead; }
         }
  
         public override bool CanSeek
         {
             get { return sinkStream.CanSeek; }
         }
  
         public override bool CanWrite
         {
             get { return sinkStream.CanWrite; }
         }
  
         public override long Length
         {
             get
             {
                 return sinkStream.Length;
             }
         }
  
         public override long Position
         {
             get { return sinkStream.Position; }
             set { sinkStream.Position = value; }
         }
  
  
         //
         public override int Read(byte[] buffer, int offset, int count)
         {
             int c = sinkStream.Read(buffer, offset, count);
             return c;
         }
  
         public override long Seek(long offset, System.IO.SeekOrigin direction)
         {
             return sinkStream.Seek(offset, direction);
         }
  
         public override void SetLength(long length)
         {
             sinkStream.SetLength(length);
         }
  
         public override void Close()
         {
  
                 sinkStream.Close();
                 isClosed = true;
         }
  
         public override void Flush()
         {
  
             sinkStream.Flush();
         }
  
         // For streamed responses (i.e. not buffered) there will be more than one Response (but the id will match the Request)
         public override void Write(byte[] buffer, int offset, int count)
         {
             sinkStream.Write(buffer, offset, count);
             AppendToFile(String.Format("at {0} --------------------------------------------", DateTime.Now));
             AppendToFile(id);
             AppendToFile(buffer);
         }
  
     } 
 }

This is a sample output:

Sample Log

Request Id: da7ffcb2-d5a7-448f-ba92-b577fed06870 Uri: https://localhost:62631/Service1.svc?disco
(no body)
at 2/6/2014 2:45:47 PM --------------------------------------------
Reponse Id: da7ffcb2-d5a7-448f-ba92-b577fed06870 Uri: https://localhost:62631/Service1.svc?disco
<?xml version="1.0" encoding="utf-8"?><discovery xmlns="https://schemas.xmlsoap.org/disco/"><contractRef ref="https://localhost:62631/Service1.svc?wsdl" docRef="https://localhost:62631/Service1.svc" xmlns="https://schemas.xmlsoap.org/disco/scl/"/></discovery>
at 2/6/2014 2:45:47 PM --------------------------------------------
Request Id: d33bde15-8416-494e-8d06-410ffd003ad1 Uri: https://localhost:62631/Service1.svc?wsdl
(no body)
at 2/6/2014 2:45:47 PM --------------------------------------------
Reponse Id: d33bde15-8416-494e-8d06-410ffd003ad1 Uri: https://localhost:62631/Service1.svc?wsdl
<?xml version="1.0" encoding="utf-8"?><wsdl:definitions name="Service1" targetNamespace="https://tempuri.org/" xmlns:wsdl="https://schemas.xmlsoap.org/wsdl/" xmlns:xsd="https://www.w3.org/2001/XMLSchema" xmlns:soapenc="https://schemas.xmlsoap.org/soap/encoding/" xmlns:wsu="https://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd" xmlns:soap="https://schemas.xmlsoap.org/wsdl/soap/" xmlns:soap12="https://schemas.xmlsoap.org/wsdl/soap12/" xmlns:tns="https://tempuri.org/" xmlns:wsa="https://schemas.xmlsoap.org/ws/2004/08/addressing" xmlns:wsx="https://schemas.xmlsoap.org/ws/2004/09/mex" xmlns:wsap="https://schemas.xmlsoap.org/ws/2004/08/addressing/policy" xmlns:wsaw="https://www.w3.org/2006/05/addressing/wsdl" xmlns:msc="https://schemas.microsoft.com/ws/2005/12/wsdl/contract" xmlns:wsp="https://schemas.xmlsoap.org/ws/2004/09/policy" xmlns:wsa10="https://www.w3.org/2005/08/addressing" xmlns:wsam="https://www.w3.org/2007/05/addressing/metadata"><wsdl:types><xsd:schema targetNamespace="https://tempuri.org/Imports"><xsd:import schemaLocation="https://localhost:62631/Service1.svc?xsd=xsd0" namespace="https://tempuri.org/"/><xsd:import schemaLocation="https://localhost:62631/Service1.svc?xsd=xsd1" namespace="https://schemas.microsoft.com/2003/10/Serialization/"/><xsd:import schemaLocation="https://localhost:62631/Service1.svc?xsd=xsd2" namespace="https://schemas.datacontract.org/2004/07/HttpModuleWCF"/></xsd:schema></wsdl:types><wsdl:message name="IService1_GetData_InputMessage"><wsdl:part name="parameters" element="tns:GetData"/></wsdl:message><wsdl:message name="IService1_GetData_OutputMessage"><wsdl:part name="parameters" element="tns:GetDataResponse"/></wsdl:message><wsdl:message name="IService1_GetDataUsingDataContract_InputMessage"><wsdl:part name="parameters" element="tns:GetDataUsingDataContract"/></wsdl:message><wsdl:message name="IService1_GetDataUsingDataContract_OutputMessage"><wsdl:part name="parameters" element="tns:GetDataUsingDataContractResponse"/></wsdl:message><wsdl:portType name="IService1"><wsdl:operation name="GetData"><wsdl:input wsaw:Action="https://tempuri.org/IService1/GetData" message="tns:IService1_GetData_InputMessage"/><wsdl:output wsaw:Action="https://tempuri.org/IService1/GetDataResponse" message="tns:IService1_GetData_OutputMessage"/></wsdl:operation><wsdl:operation name="GetDataUsingDataContract"><wsdl:input wsaw:Action="https://tempuri.org/IService1/GetDataUsingDataContract" message="tns:IService1_GetDataUsingDataContract_InputMessage"/><wsdl:output wsaw:Action="https://tempuri.org/IService1/GetDataUsingDataContractResponse" message="tns:IService1_GetDataUsingDataContract_OutputMessage"/></wsdl:operation></wsdl:portType><wsdl:binding name="BasicHttpBinding_IService1" type="tns:IService1"><soap:binding transport="https://schemas.xmlsoap.org/soap/http"/><wsdl:operation name="GetData"><soap:operation soapAction="https://tempuri.org/IService1/GetData" style='document'/><wsdl:input><soap:body use='literal'/></wsdl:input><wsdl:output><soap:body use='literal'/></wsdl:output></wsdl:operation><wsdl:operation name='GetDataUsingDataContract'><soap:operation soapAction='https://tempuri.org/IService1/GetDataUsingDataContract' style='document'/><wsdl:input><soap:body use='literal'/></wsdl:input><wsdl:output><soap:body use='literal'/></wsdl:output></wsdl:operation></wsdl:binding><wsdl:service name='Service1'><wsdl:port name='BasicHttpBinding_IService1' binding='tns:BasicHttpBinding_IService1'><soap:address location='https://localhost:62631/Service1.svc'/></wsdl:port></wsdl:service></wsdl:definitions>
at 2/6/2014 2:45:47 PM --------------------------------------------
Request Id: f51373d4-9eb8-43a9-821e-1b6bd0a7cb81 Uri: https://localhost:62631/Service1.svc?xsd=xsd0
(no body)
at 2/6/2014 2:45:48 PM --------------------------------------------
Reponse Id: f51373d4-9eb8-43a9-821e-1b6bd0a7cb81 Uri: https://localhost:62631/Service1.svc?xsd=xsd0
<?xml version="1.0" encoding="utf-8"?><xs:schema elementFormDefault="qualified" targetNamespace="https://tempuri.org/" xmlns:xs="https://www.w3.org/2001/XMLSchema" xmlns:tns="https://tempuri.org/"><xs:import schemaLocation="https://localhost:62631/Service1.svc?xsd=xsd2" namespace="https://schemas.datacontract.org/2004/07/HttpModuleWCF"/><xs:element name="GetData"><xs:complexType><xs:sequence><xs:element minOccurs="0" name="value" type="xs:int"/></xs:sequence></xs:complexType></xs:element><xs:element name="GetDataResponse"><xs:complexType><xs:sequence><xs:element minOccurs="0" name="GetDataResult" nillable="true" type="xs:string"/></xs:sequence></xs:complexType></xs:element><xs:element name="GetDataUsingDataContract"><xs:complexType><xs:sequence><xs:element minOccurs="0" name="composite" nillable="true" type="q1:CompositeType" xmlns:q1="https://schemas.datacontract.org/2004/07/HttpModuleWCF"/></xs:sequence></xs:complexType></xs:element><xs:element name="GetDataUsingDataContractResponse"><xs:complexType><xs:sequence><xs:element minOccurs="0" name="GetDataUsingDataContractResult" nillable="true" type="q2:CompositeType" xmlns:q2="https://schemas.datacontract.org/2004/07/HttpModuleWCF"/></xs:sequence></xs:complexType></xs:element></xs:schema>
at 2/6/2014 2:45:48 PM --------------------------------------------
Request Id: 7ba26a27-031e-4dad-a41e-7d139aa4ff53 Uri: https://localhost:62631/Service1.svc?xsd=xsd2
(no body)
at 2/6/2014 2:45:48 PM --------------------------------------------
Reponse Id: 7ba26a27-031e-4dad-a41e-7d139aa4ff53 Uri: https://localhost:62631/Service1.svc?xsd=xsd2
<?xml version="1.0" encoding="utf-8"?><xs:schema elementFormDefault="qualified" targetNamespace="https://schemas.datacontract.org/2004/07/HttpModuleWCF" xmlns:xs="https://www.w3.org/2001/XMLSchema" xmlns:tns="https://schemas.datacontract.org/2004/07/HttpModuleWCF"><xs:complexType name="CompositeType"><xs:sequence><xs:element minOccurs="0" name="BoolValue" type="xs:boolean"/><xs:element minOccurs="0" name="StringValue" nillable="true" type="xs:string"/></xs:sequence></xs:complexType><xs:element name="CompositeType" nillable="true" type="tns:CompositeType"/></xs:schema>
at 2/6/2014 2:45:48 PM --------------------------------------------
Request Id: dc2d0735-c3f1-427f-a00f-7c6ae1579c7c Uri: https://localhost:62631/Service1.svc?xsd=xsd1
(no body)
at 2/6/2014 2:45:48 PM --------------------------------------------
Reponse Id: dc2d0735-c3f1-427f-a00f-7c6ae1579c7c Uri: https://localhost:62631/Service1.svc?xsd=xsd1
<?xml version="1.0" encoding="utf-8"?><xs:schema attributeFormDefault="qualified" elementFormDefault="qualified" targetNamespace="https://schemas.microsoft.com/2003/10/Serialization/" xmlns:xs="https://www.w3.org/2001/XMLSchema" xmlns:tns="https://schemas.microsoft.com/2003/10/Serialization/"><xs:element name="anyType" nillable="true" type="xs:anyType"/><xs:element name="anyURI" nillable="true" type="xs:anyURI"/><xs:element name="base64Binary" nillable="true" type="xs:base64Binary"/><xs:element name="boolean" nillable="true" type="xs:boolean"/><xs:element name="byte" nillable="true" type="xs:byte"/><xs:element name="dateTime" nillable="true" type="xs:dateTime"/><xs:element name="decimal" nillable="true" type="xs:decimal"/><xs:element name="double" nillable="true" type="xs:double"/><xs:element name="float" nillable="true" type="xs:float"/><xs:element name="int" nillable="true" type="xs:int"/><xs:element name="long" nillable="true" type="xs:long"/><xs:element name="QName" nillable="true" type="xs:QName"/><xs:element name="short" nillable="true" type="xs:short"/><xs:element name="string" nillable="true" type="xs:string"/><xs:element name="unsignedByte" nillable="true" type="xs:unsignedByte"/><xs:element name="unsignedInt" nillable="true" type="xs:unsignedInt"/><xs:element name="unsignedLong" nillable="true" type="xs:unsignedLong"/><xs:element name="unsignedShort" nillable="true" type="xs:unsignedShort"/><xs:element name="char" nillable="true" type="tns:char"/><xs:simpleType name="char"><xs:restriction base="xs:int"/></xs:simpleType><xs:element name="duration" nillable="true" type="tns:duration"/><xs:simpleType name="duration"><xs:restriction base="xs:duration"><xs:pattern value="\-?P(\d*D)?(T(\d*H)?(\d*M)?(\d*(\.\d*)?S)?)?"/><xs:minInclusive value="-P10675199DT2H48M5.4775808S"/><xs:maxInclusive value="P10675199DT2H48M5.4775807S"/></xs:restriction></xs:simpleType><xs:element name="guid" nillable="true" type="tns:guid"/><xs:simpleType name="guid"><xs:restriction base="xs:string"><xs:pattern value="[\da-fA-F]{8}-[\da-fA-F]{4}-[\da-fA-F]{4}-[\da-fA-F]{4}-[\da-fA-F]{12}"/></xs:restriction></xs:simpleType><xs:attribute name="FactoryType" type="xs:QName"/><xs:attribute name="Id" type="xs:ID"/><xs:attribute name="Ref" type="xs:IDREF"/></xs:schema>
at 2/6/2014 2:45:59 PM --------------------------------------------
Request Id: 91c29544-3f8b-474c-8b57-ddfd9de2f3a9 Uri: https://localhost:62631/Service1.svc
<s:Envelope xmlns:s="https://schemas.xmlsoap.org/soap/envelope/"><s:Body><GetData xmlns="https://tempuri.org/"><value>46</value></GetData></s:Body></s:Envelope>
at 2/6/2014 2:45:59 PM --------------------------------------------
Reponse Id: 91c29544-3f8b-474c-8b57-ddfd9de2f3a9 Uri: https://localhost:62631/Service1.svc
<s:Envelope xmlns:s="https://schemas.xmlsoap.org/soap/envelope/"><s:Body><GetDataResponse xmlns="https://tempuri.org/"><GetDataResult>You entered: 46</GetDataResult></GetDataResponse></s:Body></s:Envelope>

Comments

Anonymous
November 01, 2014
Hi Sir, could you please share VB code for same. Thanks, Sreedhar
Anonymous
November 02, 2014
Thank you very much, it worked for me.... :)
Anonymous
November 27, 2014
Brilliant, thank you for sharing.
Anonymous
February 20, 2015
Thanks Rodney!! Works like a charm!
Anonymous
June 02, 2015
thank u!
Anonymous
August 13, 2015
Hi, how can i get WCF requested method at this approach? i need to know which method called without parsing xml coming xml.
Anonymous
August 24, 2015
Hikmet, Use IOperationBehavior instead: blogs.msdn.com/.../wcf-extensibility-behaviors.aspx
Anonymous
October 12, 2015
The comment has been removed
Anonymous
October 13, 2015
Shane: It logs request and response. See sample log in the post.
Anonymous
February 16, 2016
If it's get into catch, "System.Diagnostics.Debug.WriteLine" you mentioned, where it will gets write actually.
Anonymous
February 16, 2016
System.Diagnostics.Debug.WriteLine where it will gets write actually..
Anonymous
February 16, 2016
Debug output: Visual Studio output window, WinDbg output or SysInternals DbgView tool.
Anonymous
July 01, 2016
Very helpful article. Thanks
Anonymous
November 24, 2016
Thanks Rodney Viana! This was very helpful...

Freigeben über

Logging incoming requests and responses in an ASP.NET or WCF application in compatibility mode

Comments

Zusätzliche Ressourcen