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

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

  1. Request Id: da7ffcb2-d5a7-448f-ba92-b577fed06870 Uri: https://localhost:62631/Service1.svc?disco
  2. (no body)
  3. at 2/6/2014 2:45:47 PM --------------------------------------------
  4. Reponse Id: da7ffcb2-d5a7-448f-ba92-b577fed06870 Uri: https://localhost:62631/Service1.svc?disco
  5. <?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>
  6. at 2/6/2014 2:45:47 PM --------------------------------------------
  7. Request Id: d33bde15-8416-494e-8d06-410ffd003ad1 Uri: https://localhost:62631/Service1.svc?wsdl
  8. (no body)
  9. at 2/6/2014 2:45:47 PM --------------------------------------------
  10. Reponse Id: d33bde15-8416-494e-8d06-410ffd003ad1 Uri: https://localhost:62631/Service1.svc?wsdl
  11. <?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>
  12. at 2/6/2014 2:45:47 PM --------------------------------------------
  13. Request Id: f51373d4-9eb8-43a9-821e-1b6bd0a7cb81 Uri: https://localhost:62631/Service1.svc?xsd=xsd0
  14. (no body)
  15. at 2/6/2014 2:45:48 PM --------------------------------------------
  16. Reponse Id: f51373d4-9eb8-43a9-821e-1b6bd0a7cb81 Uri: https://localhost:62631/Service1.svc?xsd=xsd0
  17. <?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>
  18. at 2/6/2014 2:45:48 PM --------------------------------------------
  19. Request Id: 7ba26a27-031e-4dad-a41e-7d139aa4ff53 Uri: https://localhost:62631/Service1.svc?xsd=xsd2
  20. (no body)
  21. at 2/6/2014 2:45:48 PM --------------------------------------------
  22. Reponse Id: 7ba26a27-031e-4dad-a41e-7d139aa4ff53 Uri: https://localhost:62631/Service1.svc?xsd=xsd2
  23. <?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>
  24. at 2/6/2014 2:45:48 PM --------------------------------------------
  25. Request Id: dc2d0735-c3f1-427f-a00f-7c6ae1579c7c Uri: https://localhost:62631/Service1.svc?xsd=xsd1
  26. (no body)
  27. at 2/6/2014 2:45:48 PM --------------------------------------------
  28. Reponse Id: dc2d0735-c3f1-427f-a00f-7c6ae1579c7c Uri: https://localhost:62631/Service1.svc?xsd=xsd1
  29. <?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>
  30. at 2/6/2014 2:45:59 PM --------------------------------------------
  31. Request Id: 91c29544-3f8b-474c-8b57-ddfd9de2f3a9 Uri: https://localhost:62631/Service1.svc
  32. <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>
  33. at 2/6/2014 2:45:59 PM --------------------------------------------
  34. Reponse Id: 91c29544-3f8b-474c-8b57-ddfd9de2f3a9 Uri: https://localhost:62631/Service1.svc
  35. <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>