title: Microsoft Enterprise Library Logging Application Block Formatting Incorrectly
body: <p>We're using MS Enterprise Library 5.0 Logging in our web site.</p>
  
  <p>And when an exception goes unhandled, we'd like to log it along with a piece of contextual information to assist in debugging the issue. So, we've got an <code>HttpModule</code> that sits atop the web site and whose job is to catch these and log them to the windows application event log. This is all pretty vanilla stuff.</p>
  
  <p>And it works...on our production web servers. It doesn't work properly on our test web servers.</p>
  
  <p>The issue is that the <code>LogEvent.ExtendedProperties</code> collection isn't rendered properly (or at all). Instead, the replacement tokens are just dumped, verbatim, to the event log.</p>
  
  <p>The production event logs show information like this (slightly abbreviated), with everything formatted the way you'd expect it to be:</p>
  
  <pre><code>12/10/2013 06:07:13 PM
  LogName=Application
  SourceName=Secure Website
  EventCode=1729
  EventType=2
  Type=Error
  ComputerName=WSSECURE09.website.nordstrom.com
  TaskCategory=%1
  OpCode=Info
  RecordNumber=220338
  Keywords=Classic
  Message=Message: Unhandled exception in Secure Website: System.ServiceModel.FaultException`1[Nordstrom.Contracts.Fault.ServiceFault]:
    Argument shopper is invalid.
    Email is null or empty.
    (Fault Detail is equal to Error code: InvalidArguments).
  .
  .
  .
  Extended Properties: Shopper ID - XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
  </code></pre>
  
  <p>where the last line(s) (<code>Extended Properties: ...</code>) dump the <code>ExtendedProperties</code> collection and give the ID of the shopper who encountered the problem to aid in debugging it. In our test environments, the extended properties collection doesn't get dumped at all. Instead the raw tokens from the template are written out verbatim, with no substitutions performed:</p>
  
  <pre><code>Extended Properties: {key} - {value}
  )}
  </code></pre>
  
  <p>Here's the formatter template in use, straight from the web.config file. I've added line breaks for readability, but that's the only change:</p>
  
  <pre class="lang-xml prettyprint-override"><code>&lt;formatters&gt;
    &lt;add type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging"
      template="
        Message: {message}&amp;#xA;
        Category: {category}&amp;#xA;
        Priority: {priority}&amp;#xA;
        EventId: {eventid}&amp;#xA;
        Severity: {severity}&amp;#xA;
        Title:{title}&amp;#xA;
        Machine: {machine}&amp;#xA;
        Application Domain: {appDomain}&amp;#xA;
        Process Id: {processId}&amp;#xA;
        Process Name: {processName}&amp;#xA;
        Win32 Thread Id: {win32ThreadId}&amp;#xA;
        Thread Name: {threadName}&amp;#xA;
        Extended Properties: {dictionary({key} - {value}&amp;#xA;)}
        "
      name="Text Formatter"
      /&gt;
  &lt;/formatters&gt;
  </code></pre>
  
  <p>And here's the [slightly sanitized] logging code:</p>
  
  <pre class="lang-cs prettyprint-override"><code>private static void LogHandledException( Exception ex )
  {
    HttpContext context = HttpContext.Current ;
    LogEntry    entry   = new LogEntry() ;
  
    entry.Categories.Add("Errors");
    entry.Priority = 1;
    entry.Severity = TraceEventType.Critical;
    entry.Message  = string.Format( "Unhandled exception in Secure Website: {0}" , ex ) ;
    entry.EventId  = (int) EventId.UnhandledException ;
  
    // Add shopper id to the log, if we can find it in the http context
    Shopper shopper = HttpContext.Current.Items[ "shopper" ] as Shopper ;
    if ( shopper != null )
    {
      bool hasShopperId = ! string.IsNullOrWhiteSpace( shopper.Id ) ;
      if ( hasShopperId )
      {
        KeyValuePair&lt;string,object&gt; item = new KeyValuePair&lt;string,object&gt;("ShopperID",shopper.Id) ;
        entry.ExtendedProperties.Add( item ) ;
      }
    }
  
    Logger.Write(entry);
    return ;
  }
  </code></pre>